Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-5831

server stops processing requests during periodic flush

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 2.0.4, 2.1.1
    • Component/s: Concurrency
    • Environment:
      multiple. have run on my mac and on aws.
    • ALL

      client is inserting records as quickly as it can.
      seeing the insert rate drop to zero while background flushes happen.
      have tested on 2.0.4 and 2.1.1 and see same behavior.

      mongostat output:
      ...

      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time 
       23300      0      0      0       0       1       0   1.8g  6.01g   872m     93.7          0       0|0     0|1    12m     1k     2   15:59:24 
       22900      0      0      0       0       1       0   1.8g  6.01g   883m      105          0       0|0     0|1    12m     1k     2   15:59:25 
       23900      0      0      0       0       1       0   1.8g  6.01g   896m     98.7          0       0|0     0|1    12m     1k     2   15:59:26 
       22100      0      0      0       0       1       0   1.8g  6.01g   910m     96.4          0       0|0     0|1    11m     1k     2   15:59:27 
       18900      0      0      0       0       1       0   1.8g  6.01g   920m     95.7          0       0|0     0|1    10m     1k     2   15:59:28 
       16300      0      0      0       0       1       0   1.8g  6.01g   928m      106          0       0|0     0|0     8m     1k     2   15:59:29 
       17400      0      0      0       0       1       0   1.8g  6.01g   937m     99.2          0       0|0     0|1     9m     1k     2   15:59:30 
        9500      0      0      0       0       1       0   1.8g  6.01g   944m     52.6          0       0|0     0|1     5m     1k     2   15:59:31 
           0      0      0      0       0       1       0   1.8g  6.01g   944m        0          0       1|1     0|1    62b     1k     2   15:59:32 
           0      0      0      0       0       1       0   1.8g  6.01g   944m        0          0       1|1     0|1    62b     1k     2   15:59:33 
      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time 
       11600      0      0      0       0       1       1   2.8g  8.01g   949m      345          0       0|0     0|1     6m     1k     2   15:59:34 
        9300      0      0      0       0       1       0   2.8g  8.01g   956m     95.4          0       0|0     0|1     4m     1k     2   15:59:35 
      

      You can see that during the few seconds before the flush happens, inserts drop to zero.

      then about a minute later we see it again

      16200      0      0      0       0       1       0   2.8g  8.01g  1.25g     93.1          0       0|0     0|1     8m     1k     2   16:00:24 
       16200      0      0      0       0       1       0   2.8g  8.01g  1.25g     95.3          0       0|0     0|1     8m     1k     2   16:00:25 
       17900      0      0      0       0       1       0   2.8g  8.01g  1.26g      109          0       0|0     0|1     9m     1k     2   16:00:26 
       17200      0      0      0       0       1       0   2.8g  8.01g  1.27g     96.9          0       0|0     0|1     9m     1k     2   16:00:27 
        8100      0      0      0       0       1       0   2.8g  8.01g  1.28g     60.6          0       0|0     0|1     4m     1k     2   16:00:28 
           0      0      0      0       0       1       0   2.8g  8.01g  1.28g        0          0       0|1     0|1    62b     1k     2   16:00:29 
        2700      0      0      0       0       1       1   2.8g  8.01g  1.28g      235          0       0|0     0|1     1m     1k     2   16:00:30 
       16200      0      0      0       0       1       0   2.8g  8.01g  1.29g     91.5          0       0|0     0|1     8m     1k     2   16:00:31 
       18900      0      0      0       0       1       0   2.8g  8.01g   1.3g      108          0       0|0     0|1    10m     1k     2   16:00:32 
      

      I've attached the test program that recreates this.

        1. sync delay analysis.xlsx
          136 kB
          Jared Rosoff
        2. writer.py
          1.0 kB
          Jared Rosoff

            Assignee:
            schwerin@mongodb.com Andy Schwerin
            Reporter:
            jsr Jared Rosoff
            Votes:
            2 Vote for this issue
            Watchers:
            11 Start watching this issue

              Created:
              Updated:
              Resolved: