Loading...

Type: Bug
Resolution: Duplicate
Priority: Major - P3
Fix Version/s: None
Affects Version/s: None
Component/s: Storage
Labels:
None

Backwards Compatibility:
Fully Compatible
Operating System:
ALL
CAR Domain/s:
None

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name(s):
None
Goal Link:
None

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

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

mongodb.2.8.0-rc3.log
10.62 MB
Dec 20 2014 11:13:27 PM UTC
run.sh
0.4 kB
Dec 20 2014 11:13:27 PM UTC
run-tests.sh
4 kB
Dec 20 2014 11:13:27 PM UTC

related to

SERVER-16269 WiredTiger blocks queries and updates for many seconds.

Closed

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates