[SERVER-16619] Very long pauses using 2.8.0-rc3 when running YCSB workload B. Created: 20/Dec/14  Updated: 24/Jan/15  Resolved: 31/Dec/14

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Robert Moore Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongodb.2.8.0-rc3.log     File run-tests.sh     File run.sh    
Issue Links:
Related
related to SERVER-16269 WiredTiger blocks queries and updates... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

While running benchmarking using YCSB to drive 2.8.0-rc2 I am seeing very long pauses when using the wiredTiger storage engine.

Below is an example for one pause while using 50 connections to submit requests to MongoDB. You can see that there are 49 active readers and 1 active writer but no actual activity for more than 30 seconds.

    *0    58   3510     *0       0     3|0 832.0m 558.0m   0|0  49|1    4m   509k   52 17:54:58
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:54:59
    *0     1     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1  160b    15k   52 17:55:00
    *0     2     *0     *0       0     2|0 832.0m 558.0m   0|0  49|1  295b    16k   52 17:55:01
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:02
    *0    *0     *0     *0       0     3|0 832.0m 558.0m   0|0  49|1  196b    14k   52 17:55:03
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:04
insert query update delete getmore command  vsize    res qr|qw ar|aw netIn netOut conn     time
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:05
    *0    *0     *0     *0       0     2|0 832.0m 558.0m   0|0  49|1  133b    14k   52 17:55:06
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:07
    *0    *0     *0     *0       0     3|0 832.0m 558.0m   0|0  49|1  196b    14k   52 17:55:08
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:09
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:10
    *0    *0     *0     *0       0     2|0 832.0m 558.0m   0|0  49|1  133b    14k   52 17:55:11
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:12
    *0    *0     *0     *0       0     3|0 832.0m 558.0m   0|0  49|1  196b    14k   52 17:55:13
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:14
insert query update delete getmore command  vsize    res qr|qw ar|aw netIn netOut conn     time
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:15
    *0    *0     *0     *0       0     2|0 832.0m 558.0m   0|0  49|1  133b    14k   52 17:55:16
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:17
    *0    *0     *0     *0       0     3|0 832.0m 558.0m   0|0  49|1  196b    14k   52 17:55:18
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:19
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:20
    *0    *0     *0     *0       0     2|0 832.0m 558.0m   0|0  49|1  133b    14k   52 17:55:21
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:23
    *0    *0     *0     *0       0     4|0 832.0m 558.0m   0|0  49|1  254b    15k   52 17:55:24
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:25
insert query update delete getmore command  vsize    res qr|qw ar|aw netIn netOut conn     time
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:26
    *0    *0     *0     *0       0     2|0 832.0m 558.0m   0|0  49|1  133b    14k   52 17:55:27
    *0    *0     *0     *0       0     1|0 832.0m 558.0m   0|0  49|1   79b    13k   52 17:55:28
    *0    *0     *0     *0       0     3|0 832.0m 558.0m   0|0  49|1  196b    14k   52 17:55:29
    *0  7679    460     *0       0     1|0 832.0m 558.0m   0|0   1|0  749k     9m   52 17:55:30

The log for the same time contains:

2014-12-20T17:55:00.244-0500 I QUERY    [conn4748] query ycsb.usertable query: { _id: "user7451509487272215972" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 1415ms
2014-12-20T17:55:01.257-0500 I QUERY    [conn4736] query ycsb.usertable query: { _id: "user3227454442640408640" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 2433ms
2014-12-20T17:55:29.214-0500 I QUERY    [conn4744] query ycsb.usertable query: { _id: "user6166968228214299628" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30386ms
2014-12-20T17:55:29.214-0500 I QUERY    [conn4746] query ycsb.usertable query: { _id: "user8191443625511902077" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30386ms
2014-12-20T17:55:29.214-0500 I QUERY    [conn4749] query ycsb.usertable query: { _id: "user6487733026444452781" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30386ms
2014-12-20T17:55:29.214-0500 I QUERY    [conn4724] query ycsb.usertable query: { _id: "user2226736668874946663" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30381ms
2014-12-20T17:55:29.218-0500 I QUERY    [conn4721] query ycsb.usertable query: { _id: "user5894492235159234502" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30419ms
2014-12-20T17:55:29.214-0500 I QUERY    [conn4709] query ycsb.usertable query: { _id: "user1373595748404263629" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30414ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4748] query ycsb.usertable query: { _id: "user4950147756295652640" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 28959ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4720] query ycsb.usertable query: { _id: "user2055593758111674847" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30415ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4730] query ycsb.usertable query: { _id: "user56014800527503739" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1186 30378ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4718] query ycsb.usertable query: { _id: "user5897614011721353210" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30415ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4728] query ycsb.usertable query: { _id: "user5354495927861598392" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30382ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4713] query ycsb.usertable query: { _id: "user1496313878094450776" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30415ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4717] query ycsb.usertable query: { _id: "user8161110198689116684" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30381ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4737] query ycsb.usertable query: { _id: "user8240817027074190729" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30388ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4729] query ycsb.usertable query: { _id: "user5397446005716489464" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30382ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4705] query ycsb.usertable query: { _id: "user4943221732227823167" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30414ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4731] query ycsb.usertable query: { _id: "user604599733608267843" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1187 30351ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4712] query ycsb.usertable query: { _id: "user2701672944642353252" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30412ms
2014-12-20T17:55:29.215-0500 I QUERY    [conn4745] query ycsb.usertable query: { _id: "user4628288935854360350" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30388ms
2014-12-20T17:55:29.215-0500 I WRITE    [conn4700] update ycsb.usertable query: { _id: "user6896671575243275940" } update: { $set: { field5: BinData(0, 372A383C3C3F342A2137353620233E38333B3C2531323D212727333F3C24382521372E3C353B2D202F38383E302A2E27233E313829343D302A3E222B2A222522242C2E2A3634...) } } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 fastmod:1 keyUpdates:0  30406ms
2014-12-20T17:55:29.222-0500 I QUERY    [conn4700] command ycsb.$cmd command: update { update: "usertable", ordered: true, updates: [ { q: { _id: "user6896671575243275940" }, u: { $set: { field5: BinData(0, 372A383C3C3F342A2137353620233E38333B3C2531323D212727333F3C24382521372E3C353B2D202F38383E302A2E27233E313829343D302A3E222B2A222522242C2E2A3634...) } } } ] } keyUpdates:0  reslen:55 30414ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4742] query ycsb.usertable query: { _id: "user6854659256357746326" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30355ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4701] query ycsb.usertable query: { _id: "user6291227256020253263" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30417ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4706] query ycsb.usertable query: { _id: "user7734622211336177249" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30415ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4719] query ycsb.usertable query: { _id: "user7235484549089463787" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30382ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4715] query ycsb.usertable query: { _id: "user3148637402766075822" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30416ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4740] query ycsb.usertable query: { _id: "user8394176476071135764" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30381ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4733] query ycsb.usertable query: { _id: "user2385260537134353526" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30355ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4726] query ycsb.usertable query: { _id: "user2579538282805689038" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30382ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4716] query ycsb.usertable query: { _id: "user8901683629238130264" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30417ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4703] query ycsb.usertable query: { _id: "user8708356895527758009" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30416ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4714] query ycsb.usertable query: { _id: "user2756122143976828381" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30417ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4707] query ycsb.usertable query: { _id: "user3085002793272340418" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30416ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4735] query ycsb.usertable query: { _id: "user4685787614305946398" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30355ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4723] query ycsb.usertable query: { _id: "user1594640659903397749" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30383ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4743] query ycsb.usertable query: { _id: "user6166968228214299628" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30355ms
2014-12-20T17:55:29.216-0500 I QUERY    [conn4711] query ycsb.usertable query: { _id: "user3035668607045802873" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30416ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4736] query ycsb.usertable query: { _id: "user8709897793643524497" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 27942ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4722] query ycsb.usertable query: { _id: "user388721632843354825" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1187 30418ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4708] query ycsb.usertable query: { _id: "user8102804954222647272" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30384ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4734] query ycsb.usertable query: { _id: "user7175316432505811419" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30356ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4739] query ycsb.usertable query: { _id: "user3155229635536791041" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30382ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4732] query ycsb.usertable query: { _id: "user4844758358469980612" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30356ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4704] query ycsb.usertable query: { _id: "user8886618246763559422" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30413ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4738] query ycsb.usertable query: { _id: "user5699680427788900301" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30390ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4725] query ycsb.usertable query: { _id: "user6135322463962533215" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30383ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4710] query ycsb.usertable query: { _id: "user5139005051377844896" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30417ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4727] query ycsb.usertable query: { _id: "user1345798238818314737" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30384ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4747] query ycsb.usertable query: { _id: "user6131835534764733457" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30389ms
2014-12-20T17:55:29.217-0500 I QUERY    [conn4741] query ycsb.usertable query: { _id: "user8044863363164947348" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30357ms
2014-12-20T17:55:29.706-0500 I QUERY    [conn4702] query ycsb.usertable query: { _id: "user4895333404325496461" } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0  nreturned:1 reslen:1188 30910ms

The start of the log file is:

2014-12-20T15:45:39.988-0500 I CONTROL  [initandlisten] MongoDB starting : pid=998 port=27017 dbpath=/home/rjmoore/ycsb/data-2.8.0-rc3 64-bit host=eeyore.allanbank.lan
2014-12-20T15:45:39.988-0500 I CONTROL  [initandlisten] db version v2.8.0-rc3
2014-12-20T15:45:39.988-0500 I CONTROL  [initandlisten] git version: 2d679247f17dab05a492c8b6d2c250dab18e54f2
2014-12-20T15:45:39.988-0500 I CONTROL  [initandlisten] build info: Linux build4.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2014-12-20T15:45:39.988-0500 I CONTROL  [initandlisten] allocator: tcmalloc
2014-12-20T15:45:39.988-0500 I CONTROL  [initandlisten] options: { net: { port: 27017 }, processManagement: { fork: true }, storage: { dbPath: "/home/rjmoore/ycsb/data-2.8.0-rc3", engine: "wiredTiger", journal: { enabled: false } }, systemLog: { destination: "file", path: "/home/rjmoore/ycsb/mongodb.2.8.0-rc3.log", quiet: true } }
2014-12-20T15:45:39.989-0500 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3G,session_max=20000,extensions=[local=(entry=index_collator_extension)],statistics=(all),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2014-12-20T15:45:40.393-0500 I NETWORK  [initandlisten] waiting for connections on port 27017

We saw similar, shorter, pauses with rc2 but thought the issue was SERVER-16296.

I will attach the full log file and script (run-tests.sh) being used to run YCSB with different workloads and combination of threads and connections.

I have also include the script to start the mongod process (run.sh).



 Comments   
Comment by Daniel Pasette (Inactive) [ 31/Dec/14 ]

robert.j.moore@allanbank.com, there are still some things we're working on for RC5, but closing this out as a duplicate.

Thanks

Comment by Robert Moore [ 21/Dec/14 ]

Agree - looks very similar.

Comment by Daniel Pasette (Inactive) [ 21/Dec/14 ]

likely duplicate of SERVER-16269. will leave open until we can confirm.

Generated at Thu Feb 08 03:41:41 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.