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.

    • 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
        2. run.sh
          0.4 kB
        3. run-tests.sh
          4 kB

            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: