Details
-
Bug
-
Resolution: Duplicate
-
Major - P3
-
None
-
None
-
None
-
Fully Compatible
-
ALL
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).
Attachments
Issue Links
- related to
-
SERVER-16269 WiredTiger blocks queries and updates for many seconds.
-
- Closed
-