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

Very long pauses using 2.8.0-rc3 when running YCSB workload B.

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Storage
    • None
    • Fully Compatible
    • ALL

      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).

        1. mongodb.2.8.0-rc3.log
          10.62 MB
          Robert Moore
        2. run.sh
          0.4 kB
          Robert Moore
        3. run-tests.sh
          4 kB
          Robert Moore

            Assignee:
            Unassigned Unassigned
            Reporter:
            robert.j.moore@allanbank.com Robert Moore
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved: