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

Extended pauses with heavy write load under WiredTiger

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 2.8.0-rc3
    • Affects Version/s: 2.8.0-rc1
    • Component/s: Storage
    • Labels:
    • Fully Compatible
    • ALL

      Under heavy write load from many threads, there are occasional several-second pauses where the insert rate drops to 0. Test consists of standalone mongod with 100 threads of the following:

      function insert(thread, show) {
          count = 100000
          every = 1000
          var t = new Date()
          for (var i=0; i<count; ) {
              var bulk = db.c.initializeUnorderedBulkOp();
              for (var j=0; j<every; j++, i++)
                  bulk.insert({})
              bulk.execute();
              if (thread%show==0) {
                  var tt = new Date()
                  print(tt, thread, show, i, Math.floor(every / (tt-t) * 1000))
                  t = tt
              }
          }
      }
      

      Top four graphs below are derived from wt statistics and mongod log. Remainder is call tree obtained by sampling with gdb; graphs next to each call site show number of threads at that call site over time (on log scale).

      • (1) insert rate as indicated by wt btree insert/s statistic drops to 0. Starting at this time the call graph shows multiple threads are queueing at (A) in __wt_page_in_func, while one thread is executing in (B) in __wt_evict_page.
      • (2) inserts resume, mongod log reports 100 inserts finish reporting a time of at least 5s. These are probably the inserts finishing that were queued at (A) starting at (1).
      • (3) one insert finishes reporting a time of >10000ms (16983ms in one case). This is probably the insert that was executing at (B) starting at (1).
      • Same pattern is repeated at 4-5-6 and 7-8-9.

      Reducing memory_page_max from the default of 100MB to 10MB eliminates the extended pauses. Turning off compression also reduces the length of the pauses. The call stack seems to indicate that in this particular test (on a machine with SSD drives) this is all CPU time, as no i/o operations show up in the gdb stack samples.

      So it appears that

      • one insert blocks for an extended time doing a page eviction, apparently related to memory_page_max.
      • for about the first half this interval all other inserts are blocked, apparently about from the entry to __wt_rec_evict to the entry to __wt_split_evict.

        1. asya.png
          asya.png
          408 kB
        2. pauses.png
          pauses.png
          719 kB
        3. rc1.png
          rc1.png
          55 kB
        4. rc2.png
          rc2.png
          74 kB

            Assignee:
            alexander.gorrod@mongodb.com Alexander Gorrod
            Reporter:
            bruce.lucas@mongodb.com Bruce Lucas (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            15 Start watching this issue

              Created:
              Updated:
              Resolved: