[SERVER-16355] Extended pauses with heavy write load under WiredTiger Created: 30/Nov/14  Updated: 18/Dec/14  Resolved: 15/Dec/14

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 2.8.0-rc1
Fix Version/s: 2.8.0-rc3

Type: Bug Priority: Major - P3
Reporter: Bruce Lucas (Inactive) Assignee: Alexander Gorrod
Resolution: Done Votes: 0
Labels: wiredtiger
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File asya.png     PNG File pauses.png     PNG File rc1.png     PNG File rc2.png    
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

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.


 Comments   
Comment by Bruce Lucas (Inactive) [ 12/Dec/14 ]

Yes, it is considerably improved.

rc1:

rc2:

  • rc1 shows frequent pauses of up to 15 s or so (size of pauses is indicated by length of long queries logged by mongod, shown in the "mongod max logged queries" graph.
  • rc2 is much better. The pauses have mostly gone away, and overall rate is much higher at about 60k inserts per second. There is still a pause of about 9 seconds that seems to be associated with the end of checkpoints, and the checkpoint took a very long time, about 2.5 minutes; but those seem like separate issues so I'll open a separate ticket with more details.
Generated at Thu Feb 08 03:40:47 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.