|
Thanks for confirming mdcallag, we also ran the test case against a recent version of MongoDB and can no longer reproduce the symptom, so I'll close the ticket.
|
|
I haven't seen this problem with 3.3.5
|
|
On the bright side, WiredTiger 3.1.5 looks much better than the 3.0.X branch for iibench
- average insert rate is better: 20,273 vs 10,822 per second
- stalls were less frequent during my test: 2409 vs 3996 operations took >= 2 seconds
- worst case stalls were similar, 6 seconds for each although there was one 12 second stall for 3.0.X
Database was ~450gb when the test ended. Test server has 144g of RAM.
|
|
Worst case stalls are ~6 seconds
|
|
Database is now larger than RAM, insert rate variance is worse...
Thread[Thread-2,5,main]301,835,310 inserts : 13,510 seconds : cum ips=22,341.49 : int ips=25,919.67 : cum avg qry=1.38 : int avg qry=2.04 : cum avg qps=723.91 : int avg qps=489.76 : exceptions=0
|
Thread[Thread-2,5,main]302,091,670 inserts : 13,520 seconds : cum ips=22,343.92 : int ips=25,618.07 : cum avg qry=1.38 : int avg qry=1.75 : cum avg qps=723.80 : int avg qps=570.40 : exceptions=0
|
Thread[Thread-2,5,main]302,358,880 inserts : 13,530 seconds : cum ips=22,347.14 : int ips=26,702.31 : cum avg qry=1.38 : int avg qry=1.74 : cum avg qps=723.69 : int avg qps=572.90 : exceptions=0
|
Thread[Thread-2,5,main]302,608,790 inserts : 13,540 seconds : cum ips=22,349.08 : int ips=24,971.02 : cum avg qry=1.38 : int avg qry=1.52 : cum avg qps=723.63 : int avg qps=654.08 : exceptions=0
|
Thread[Thread-2,5,main]302,775,330 inserts : 13,550 seconds : cum ips=22,345.03 : int ips=16,808.64 : cum avg qry=1.38 : int avg qry=4.01 : cum avg qps=723.29 : int avg qps=249.80 : exceptions=0
|
Thread[Thread-2,5,main]303,081,450 inserts : 13,560 seconds : cum ips=22,351.11 : int ips=30,587.53 : cum avg qry=1.38 : int avg qry=1.45 : cum avg qps=723.26 : int avg qps=689.85 : exceptions=0
|
Thread[Thread-2,5,main]303,276,250 inserts : 13,570 seconds : cum ips=22,348.99 : int ips=19,464.43 : cum avg qry=1.38 : int avg qry=3.35 : cum avg qps=722.93 : int avg qps=268.59 : exceptions=0
|
Thread[Thread-2,5,main]303,438,120 inserts : 13,580 seconds : cum ips=22,344.43 : int ips=16,169.21 : cum avg qry=1.38 : int avg qry=1.05 : cum avg qps=723.03 : int avg qps=859.25 : exceptions=0
|
Thread[Thread-2,5,main]303,543,700 inserts : 13,590 seconds : cum ips=22,335.74 : int ips=10,549.56 : cum avg qry=1.38 : int avg qry=0.93 : cum avg qps=723.37 : int avg qps=1,185.65 : exceptions=0
|
Thread[Thread-2,5,main]303,620,700 inserts : 13,600 seconds : cum ips=22,324.97 : int ips=7,693.84 : cum avg qry=1.38 : int avg qry=1.50 : cum avg qps=723.23 : int avg qps=532.07 : exceptions=0
|
Thread[Thread-2,5,main]303,692,680 inserts : 13,610 seconds : cum ips=22,313.84 : int ips=7,192.96 : cum avg qry=1.38 : int avg qry=1.27 : cum avg qps=723.39 : int avg qps=945.44 : exceptions=0
|
Thread[Thread-2,5,main]303,755,270 inserts : 13,620 seconds : cum ips=22,302.04 : int ips=6,254.00 : cum avg qry=1.38 : int avg qry=1.69 : cum avg qps=723.21 : int avg qps=474.42 : exceptions=0
|
Thread[Thread-2,5,main]303,811,480 inserts : 13,630 seconds : cum ips=22,289.79 : int ips=5,617.07 : cum avg qry=1.38 : int avg qry=0.87 : cum avg qps=723.61 : int avg qps=1,266.61 : exceptions=0
|
Thread[Thread-2,5,main]303,864,770 inserts : 13,640 seconds : cum ips=22,277.35 : int ips=5,324.74 : cum avg qry=1.38 : int avg qry=4.02 : cum avg qps=723.30 : int avg qps=298.16 : exceptions=0
|
Thread[Thread-2,5,main]303,910,140 inserts : 13,650 seconds : cum ips=22,264.34 : int ips=4,533.37 : cum avg qry=1.38 : int avg qry=1.07 : cum avg qps=723.38 : int avg qps=843.53 : exceptions=0
|
Thread[Thread-2,5,main]303,963,100 inserts : 13,660 seconds : cum ips=22,251.90 : int ips=5,290.71 : cum avg qry=1.38 : int avg qry=1.27 : cum avg qps=723.49 : int avg qps=864.04 : exceptions=0
|
Thread[Thread-2,5,main]304,005,290 inserts : 13,670 seconds : cum ips=22,238.86 : int ips=4,258.18 : cum avg qry=1.38 : int avg qry=0.89 : cum avg qps=723.71 : int avg qps=1,032.20 : exceptions=0
|
Thread[Thread-2,5,main]304,047,440 inserts : 13,680 seconds : cum ips=22,225.67 : int ips=4,211.21 : cum avg qry=1.38 : int avg qry=2.63 : cum avg qps=723.40 : int avg qps=304.63 : exceptions=0
|
Thread[Thread-2,5,main]304,081,630 inserts : 13,690 seconds : cum ips=22,211.92 : int ips=3,416.27 : cum avg qry=1.38 : int avg qry=2.76 : cum avg qps=723.17 : int avg qps=398.68 : exceptions=0
|
Thread[Thread-2,5,main]304,112,150 inserts : 13,700 seconds : cum ips=22,197.92 : int ips=3,049.87 : cum avg qry=1.38 : int avg qry=4.12 : cum avg qps=722.78 : int avg qps=194.16 : exceptions=0
|
Thread[Thread-2,5,main]304,154,030 inserts : 13,710 seconds : cum ips=22,184.77 : int ips=4,184.65 : cum avg qry=1.38 : int avg qry=3.98 : cum avg qps=722.47 : int avg qps=301.46 : exceptions=0
|
Thread[Thread-2,5,main]304,194,150 inserts : 13,720 seconds : cum ips=22,171.51 : int ips=4,008.79 : cum avg qry=1.38 : int avg qry=20.54 : cum avg qps=721.97 : int avg qps=38.97 : exceptions=0
|
Thread[Thread-2,5,main]304,224,470 inserts : 13,730 seconds : cum ips=22,157.56 : int ips=3,029.88 : cum avg qry=1.38 : int avg qry=17.96 : cum avg qps=721.50 : int avg qps=66.85 : exceptions=0
|
Thread[Thread-2,5,main]304,252,710 inserts : 13,740 seconds : cum ips=22,143.48 : int ips=2,821.74 : cum avg qry=1.38 : int avg qry=1.48 : cum avg qps=721.22 : int avg qps=338.33 : exceptions=0
|
Thread[Thread-2,5,main]304,291,530 inserts : 13,750 seconds : cum ips=22,130.18 : int ips=3,878.90 : cum avg qry=1.38 : int avg qry=2.86 : cum avg qps=721.07 : int avg qps=524.48 : exceptions=0
|
Thread[Thread-2,5,main]304,320,220 inserts : 13,760 seconds : cum ips=22,116.17 : int ips=2,866.99 : cum avg qry=1.39 : int avg qry=2.16 : cum avg qps=720.82 : int avg qps=370.34 : exceptions=0
|
Thread[Thread-2,5,main]304,351,290 inserts : 13,770 seconds : cum ips=22,102.36 : int ips=3,104.52 : cum avg qry=1.39 : int avg qry=13.19 : cum avg qps=720.36 : int avg qps=91.03 : exceptions=0
|
Thread[Thread-2,5,main]304,380,740 inserts : 13,780 seconds : cum ips=22,088.44 : int ips=2,942.94 : cum avg qry=1.39 : int avg qry=3.52 : cum avg qps=720.08 : int avg qps=335.47 : exceptions=0
|
Thread[Thread-2,5,main]304,457,810 inserts : 13,790 seconds : cum ips=22,078.00 : int ips=7,700.84 : cum avg qry=1.39 : int avg qry=4.98 : cum avg qps=719.69 : int avg qps=184.65 : exceptions=0
|
Thread[Thread-2,5,main]304,654,620 inserts : 13,800 seconds : cum ips=22,076.40 : int ips=19,855.73 : cum avg qry=1.39 : int avg qry=7.10 : cum avg qps=719.28 : int avg qps=151.63 : exceptions=0
|
Thread[Thread-2,5,main]304,998,780 inserts : 13,810 seconds : cum ips=22,085.33 : int ips=34,391.93 : cum avg qry=1.39 : int avg qry=2.17 : cum avg qps=719.10 : int avg qps=462.28 : exceptions=0
|
Thread[Thread-2,5,main]305,312,760 inserts : 13,820 seconds : cum ips=22,092.05 : int ips=31,366.63 : cum avg qry=1.39 : int avg qry=1.66 : cum avg qps=719.01 : int avg qps=602.60 : exceptions=0
|
Thread[Thread-2,5,main]305,616,980 inserts : 13,830 seconds : cum ips=22,098.06 : int ips=30,397.68 : cum avg qry=1.39 : int avg qry=1.39 : cum avg qps=719.01 : int avg qps=719.12 : exceptions=0
|
Thread[Thread-2,5,main]305,934,790 inserts : 13,840 seconds : cum ips=22,105.04 : int ips=31,755.60 : cum avg qry=1.39 : int avg qry=1.36 : cum avg qps=719.02 : int avg qps=733.11 : exceptions=0
|
Thread[Thread-2,5,main]306,214,710 inserts : 13,850 seconds : cum ips=22,109.28 : int ips=27,972.42 : cum avg qry=1.39 : int avg qry=2.60 : cum avg qps=718.78 : int avg qps=379.13 : exceptions=0
|
Thread[Thread-2,5,main]306,552,440 inserts : 13,860 seconds : cum ips=22,117.68 : int ips=33,739.26 : cum avg qry=1.39 : int avg qry=1.50 : cum avg qps=718.75 : int avg qps=674.43 : exceptions=0
|
|
|
Started tests for 3.1.5 and see problems early in the test. Stats are reported every 10 seconds and there is significant variance in the insert rate (the "int ips=" column).
Thread[Thread-2,5,main]14,684,350 inserts : 360 seconds : cum ips=40,782.95 : int ips=18,654.21 : cum avg qry=0.57 : int avg qry=1.56 : cum avg qps=1,737.56 : int avg qps=843.64 : exceptions=0
|
Thread[Thread-2,5,main]15,184,430 inserts : 370 seconds : cum ips=41,031.02 : int ips=49,953.05 : cum avg qry=0.57 : int avg qry=0.45 : cum avg qps=1,751.21 : int avg qps=2,239.54 : exceptions=0
|
Thread[Thread-2,5,main]15,682,150 inserts : 380 seconds : cum ips=41,260.02 : int ips=49,727.25 : cum avg qry=0.57 : int avg qry=0.49 : cum avg qps=1,758.91 : int avg qps=2,042.06 : exceptions=0
|
Thread[Thread-2,5,main]16,167,830 inserts : 390 seconds : cum ips=41,446.30 : int ips=48,519.48 : cum avg qry=0.56 : int avg qry=0.46 : cum avg qps=1,769.99 : int avg qps=2,189.01 : exceptions=0
|
Thread[Thread-2,5,main]16,586,880 inserts : 400 seconds : cum ips=41,456.84 : int ips=41,867.32 : cum avg qry=0.56 : int avg qry=0.48 : cum avg qps=1,776.18 : int avg qps=2,016.19 : exceptions=0
|
Thread[Thread-2,5,main]16,817,580 inserts : 410 seconds : cum ips=41,017.59 : int ips=23,281.86 : cum avg qry=0.55 : int avg qry=0.33 : cum avg qps=1,807.48 : int avg qps=3,065.70 : exceptions=0
|
Thread[Thread-2,5,main]16,932,550 inserts : 420 seconds : cum ips=40,313.87 : int ips=11,486.66 : cum avg qry=0.56 : int avg qry=1.18 : cum avg qps=1,782.15 : int avg qps=748.93 : exceptions=0
|
Thread[Thread-2,5,main]17,021,680 inserts : 430 seconds : cum ips=39,582.63 : int ips=8,903.21 : cum avg qry=0.57 : int avg qry=5.99 : cum avg qps=1,743.61 : int avg qps=133.45 : exceptions=0
|
Thread[Thread-2,5,main]17,533,830 inserts : 440 seconds : cum ips=39,846.17 : int ips=51,168.95 : cum avg qry=0.57 : int avg qry=0.65 : cum avg qps=1,749.71 : int avg qps=2,010.79 : exceptions=0
|
Thread[Thread-2,5,main]18,034,680 inserts : 450 seconds : cum ips=40,072.53 : int ips=50,019.97 : cum avg qry=0.57 : int avg qry=0.47 : cum avg qps=1,757.64 : int avg qps=2,104.96 : exceptions=0
|
Thread[Thread-2,5,main]18,544,590 inserts : 460 seconds : cum ips=40,309.07 : int ips=50,945.15 : cum avg qry=0.56 : int avg qry=0.47 : cum avg qps=1,765.31 : int avg qps=2,108.50 : exceptions=0
|
Thread[Thread-2,5,main]18,982,600 inserts : 470 seconds : cum ips=40,382.50 : int ips=43,757.24 : cum avg qry=0.56 : int avg qry=0.43 : cum avg qps=1,777.52 : int avg qps=2,336.56 : exceptions=0
|
Thread[Thread-2,5,main]19,469,360 inserts : 480 seconds : cum ips=40,554.58 : int ips=48,637.09 : cum avg qry=0.56 : int avg qry=0.46 : cum avg qps=1,786.15 : int avg qps=2,189.95 : exceptions=0
|
Thread[Thread-2,5,main]19,858,880 inserts : 490 seconds : cum ips=40,520.97 : int ips=38,909.20 : cum avg qry=0.55 : int avg qry=0.38 : cum avg qps=1,801.86 : int avg qps=2,552.59 : exceptions=0
|
Thread[Thread-2,5,main]20,010,940 inserts : 500 seconds : cum ips=40,013.96 : int ips=15,190.81 : cum avg qry=0.56 : int avg qry=1.98 : cum avg qps=1,774.82 : int avg qps=455.44 : exceptions=0
|
Thread[Thread-2,5,main]20,116,010 inserts : 510 seconds : cum ips=39,442.54 : int ips=10,603.49 : cum avg qry=0.57 : int avg qry=5.76 : cum avg qps=1,742.94 : int avg qps=140.28 : exceptions=0
|
Thread[Thread-2,5,main]20,200,490 inserts : 520 seconds : cum ips=38,845.83 : int ips=8,440.40 : cum avg qry=0.58 : int avg qry=4.09 : cum avg qps=1,714.94 : int avg qps=293.14 : exceptions=0
|
Thread[Thread-2,5,main]20,570,440 inserts : 530 seconds : cum ips=38,810.10 : int ips=36,954.35 : cum avg qry=0.59 : int avg qry=1.09 : cum avg qps=1,701.72 : int avg qps=1,017.38 : exceptions=0
|
Thread[Thread-2,5,main]21,082,110 inserts : 540 seconds : cum ips=39,038.27 : int ips=51,120.99 : cum avg qry=0.58 : int avg qry=0.47 : cum avg qps=1,709.48 : int avg qps=2,118.99 : exceptions=0
|
Thread[Thread-2,5,main]21,565,890 inserts : 550 seconds : cum ips=39,207.36 : int ips=48,329.67 : cum avg qry=0.58 : int avg qry=0.50 : cum avg qps=1,714.52 : int avg qps=1,985.71 : exceptions=0
|
Thread[Thread-2,5,main]21,953,830 inserts : 560 seconds : cum ips=39,199.35 : int ips=38,759.12 : cum avg qry=0.58 : int avg qry=0.40 : cum avg qps=1,728.09 : int avg qps=2,471.28 : exceptions=0
|
Thread[Thread-2,5,main]22,226,440 inserts : 570 seconds : cum ips=38,989.24 : int ips=27,233.77 : cum avg qry=0.58 : int avg qry=0.51 : cum avg qps=1,721.60 : int avg qps=1,359.34 : exceptions=0
|
Thread[Thread-2,5,main]22,351,650 inserts : 580 seconds : cum ips=38,532.41 : int ips=12,510.99 : cum avg qry=0.58 : int avg qry=1.90 : cum avg qps=1,702.74 : int avg qps=632.09 : exceptions=0
|
Thread[Thread-2,5,main]22,444,980 inserts : 590 seconds : cum ips=38,036.99 : int ips=9,324.61 : cum avg qry=0.59 : int avg qry=4.02 : cum avg qps=1,677.15 : int avg qps=198.82 : exceptions=0
|
Thread[Thread-2,5,main]22,525,690 inserts : 600 seconds : cum ips=37,537.06 : int ips=8,063.74 : cum avg qry=0.60 : int avg qry=2.50 : cum avg qps=1,657.13 : int avg qps=480.57 : exceptions=0
|
Thread[Thread-2,5,main]22,757,160 inserts : 610 seconds : cum ips=37,306.76 : int ips=23,359.57 : cum avg qry=0.61 : int avg qry=1.62 : cum avg qps=1,641.28 : int avg qps=684.02 : exceptions=0
|
Thread[Thread-2,5,main]23,255,610 inserts : 620 seconds : cum ips=37,508.38 : int ips=49,795.20 : cum avg qry=0.60 : int avg qry=0.47 : cum avg qps=1,648.99 : int avg qps=2,117.38 : exceptions=0
|
Thread[Thread-2,5,main]23,776,180 inserts : 630 seconds : cum ips=37,738.77 : int ips=52,010.19 : cum avg qry=0.60 : int avg qry=0.48 : cum avg qps=1,656.05 : int avg qps=2,092.12 : exceptions=0
|
Thread[Thread-2,5,main]24,172,040 inserts : 640 seconds : cum ips=37,767.10 : int ips=39,550.40 : cum avg qry=0.60 : int avg qry=0.40 : cum avg qps=1,669.49 : int avg qps=2,513.14 : exceptions=0
|
I set the slow op threshold to 2 seconds and 15 minutes into the test I have:
- grep WRITE log | awk '
{ print $NF }' | wc -l
78
# grep WRITE log | awk '{ print $NF }
' | tail -10
2802ms
2801ms
2801ms
2801ms
2801ms
3693ms
3694ms
3693ms
3694ms
3667ms
Test server is 40 hyperthread cores, 144G RAM, fast PCIe flash.
iibench-mongodb is https://github.com/mdcallag/iibench-mongodb with this command line:
java -cp mongo-java-driver-2.13.1.jar:/data/mysql/iibench-mongodb/src jmongoiibench iibench 10 500000000 10 -1 10 mongoiibench-500000000-10-999999-10-1-0.txt.tsv quicklz 16384 60000000000 4 100000 999999 SAFE localhost 27017 1 1000 3 50 Y 1 0 1
The iibench client command line uses:
- 10 insert threads, 1 query thread
- each doc has 1000 byte "pad" attributge
- insert 10 docs per RPC
mongo.conf is:
processManagement:
|
fork: true
|
systemLog:
|
destination: file
|
path: /data/mysql/mongo.30/log
|
logAppend: true
|
storage:
|
syncPeriodSecs: 60
|
dbPath: /data/mysql/mongo.30/data
|
journal:
|
enabled: true
|
mmapv1:
|
journal:
|
commitIntervalMs: 100
|
operationProfiling.slowOpThresholdMs: 2000
|
replication.oplogSizeMB: 2000
|
|
storage.wiredTiger.collectionConfig.blockCompressor: snappy
|
storage.wiredTiger.engineConfig.journalCompressor: none
|
mongod command line is:
numactl --interleave=all bin/mongod.315.tcm --config /data/mysql/mongo.30/mongo.conf --storageEngine wiredTiger --master
|
|
Ran the iibench workload for an hour on mongodb master as at 7eee5d26b0 (just after 3.1.5) using an r3.4xlarge.
There were no operations that exceeded 1 second. Only one operation over 1/2 a second and only 3 over 200ms.
tmcallaghan, would you be willing to re-test with a recent compile of MongoDB or the 3.1.5 development release and confirm this from your end?
|
|
Hi tmcallaghan. There seem to be a few different threads going on in this ticket. One of them is capped collection related, thus the link (see David Hows' comment above, for instance). I do see you are experiencing something without any capped collections. The link is just as a note, and we continue to investigate these issues.
|
|
I don't understand the David Daly comment, my tests are not on capped collections and I have not enabled the oplog.
|
|
Related to SERVER-17407 – both related to oplog and capped collections.
|
|
I've run a few different tests around this today and it appears that the oplog being a capped collection is likely a major factor, rather than the oplog itself being involved.
See the graphed results below, which plot throughput against time for the various configurations.

Note that the oplog (blue) and capped_only(red) tests have the same choppy behaviour with large drops in throughput.
This was done with the workload suggested by Tim and on my AZL instance. I will be following up further about what within the capped collection logic could cause these problems.
|
|
My test server has 40 hyperthread cores, 144G RAM and storage that can do ~50,000 IOPs
|
|
Some of the 'cannot reproduce' results have used direct_io, run without the oplog, maybe run without compression and ran with NUM_DOCUMENTS_PER_INSERT=1000 rather than the NUM_DOCUMENTS_PER_INSERT=1 that I have been using.
I have spent a lot of time on this. Can the reproduction attempts use the scripts I provided? Along with the scripts this is my command line to start mongod and '--master' is used to enable the oplog.
numactl --interleave=all bin/mongod --config /path/to/mongo.conf --master --storageEngine wiredTiger
|
|
David,
I'm running Ubuntu 14.04.1 LTS, and both transparent huge page settings are [never] on both of my benchmark machines.
The machines themselves are Core i7 (4 hardware threads + HT, 4Ghz), 12G RAM (lowered from 32G via grub), and each is running on a single SSD. One machine has a 512M RAID card in front of the SSD, the other is just SATA.
I'm running the Sysbench load phase (not iiBench), simultaneously into 8 collections, with the opLog disabled.
A month back I was told to use bufferedIO with WT, so that's what I've been using. Here are my worst outliers (time in ms to insert a batch of 1000 documents into one of the Sysbench collections) using bufferedIO:
60229
60926
78258
105842
153989
168716
239345
292021
310932
333355
333762
And here are the worst using directIO:
64722
66303
69968
72085
89195
98911
So it seems that directIO is now doing better for batch insert latency, but these outliers are still a large concern.
|
|
I have just completed a run with iibench-mongo.
On 3.0.1 with WiredTiger Develop, only saw 5 slow inserts, all took 2 seconds and were all at within the same second.
2015-03-24T03:06:37.204+0000 I WRITE [conn4] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2109ms
|
2015-03-24T03:06:37.487+0000 I WRITE [conn8] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2305ms
|
2015-03-24T03:06:37.498+0000 I WRITE [conn5] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2290ms
|
2015-03-24T03:06:37.521+0000 I WRITE [conn3] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2389ms
|
2015-03-24T03:06:37.551+0000 I WRITE [conn11] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2334ms
|
2015-03-24T03:06:37.569+0000 I WRITE [conn6] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2397ms
|
This compares with the following which is from 3.0.1GA
2015-03-24T03:48:33.807+0000 I WRITE [conn7] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10273ms
|
2015-03-24T03:48:33.817+0000 I WRITE [conn5] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10265ms
|
2015-03-24T03:48:33.827+0000 I WRITE [conn11] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10313ms
|
2015-03-24T03:48:33.831+0000 I WRITE [conn6] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10314ms
|
2015-03-24T03:48:33.832+0000 I WRITE [conn4] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10248ms
|
2015-03-24T03:48:33.832+0000 I WRITE [conn8] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10239ms
|
2015-03-24T03:48:33.838+0000 I WRITE [conn10] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10298ms
|
2015-03-24T03:48:33.859+0000 I WRITE [conn3] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10297ms
|
2015-03-24T03:48:33.861+0000 I WRITE [conn9] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 8961ms
|
2015-03-24T03:48:33.863+0000 I WRITE [conn12] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 10280ms
|
2015-03-24T04:17:19.380+0000 I WRITE [conn8] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2176ms
|
2015-03-24T04:17:19.380+0000 I WRITE [conn4] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2136ms
|
2015-03-24T04:17:19.407+0000 I WRITE [conn9] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2168ms
|
2015-03-24T04:17:19.408+0000 I WRITE [conn11] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2194ms
|
2015-03-24T04:17:19.430+0000 I WRITE [conn12] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2123ms
|
2015-03-24T04:17:19.453+0000 I WRITE [conn3] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2112ms
|
2015-03-24T04:17:19.507+0000 I WRITE [conn7] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2168ms
|
2015-03-24T04:17:22.729+0000 I WRITE [conn4] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2079ms
|
2015-03-24T04:17:22.984+0000 I WRITE [conn9] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2275ms
|
2015-03-24T04:17:23.010+0000 I WRITE [conn6] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2301ms
|
2015-03-24T04:17:23.060+0000 I WRITE [conn12] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2282ms
|
2015-03-24T04:17:23.066+0000 I WRITE [conn8] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2309ms
|
2015-03-24T04:17:23.132+0000 I WRITE [conn10] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2325ms
|
2015-03-24T04:17:23.841+0000 I WRITE [conn7] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 3006ms
|
2015-03-24T04:17:25.826+0000 I WRITE [conn9] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2015ms
|
2015-03-24T04:22:46.003+0000 I WRITE [conn3] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2053ms
|
2015-03-24T04:22:49.389+0000 I WRITE [conn8] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2571ms
|
2015-03-24T04:22:49.631+0000 I WRITE [conn7] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2759ms
|
2015-03-24T04:22:49.643+0000 I WRITE [conn10] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2742ms
|
2015-03-24T04:22:49.703+0000 I WRITE [conn3] insert iibench.purchases_index ninserted:1000 keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 2769ms
|
I think we need to investigate some of the differences in setup here, as I'm not re-creating the issue you have described.
Tim, can you attach the output of the following two commands
cat /sys/kernel/mm/transparent_hugepage/enabled
|
cat /sys/kernel/mm/transparent_hugepage/defrag
|
Can you confirm what capacity server this is on, and what storage is being used.
Can you also clarify how you got the oplog enabled as mentioned in your above comment?
Thanks,
David
|
|
Finished a load: 10 threads inserting 400M docs. Results for WT/snappy are similar between 3.0rc9 and 3.0.1 – ~5000 operations take >= 2 seconds and the worst stalls are ~7 seconds and this shows the variance in throughput near the end of the test. My tests all now have the oplog enabled and I think that is one of the reasons for the worst stalls – see https://jira.mongodb.org/browse/SERVER-16575
Thread[Thread-2,5,main]397,459,571 inserts : 37,650 seconds : cum ips=10,556.69 : int ips=1,712.39 : cum avg qry=2.33 : int avg qry=7.22 : cum avg qps=428.53 : int avg qps=165.33 : exceptions=0
|
Thread[Thread-2,5,main]397,477,954 inserts : 37,660 seconds : cum ips=10,554.37 : int ips=1,836.83 : cum avg qry=2.33 : int avg qry=4.52 : cum avg qps=428.47 : int avg qps=178.36 : exceptions=0
|
Thread[Thread-2,5,main]397,503,407 inserts : 37,670 seconds : cum ips=10,552.24 : int ips=2,543.52 : cum avg qry=2.33 : int avg qry=3.43 : cum avg qps=428.45 : int avg qps=347.56 : exceptions=0
|
Thread[Thread-2,5,main]397,503,907 inserts : 37,680 seconds : cum ips=10,549.46 : int ips=49.96 : cum avg qry=2.33 : int avg qry=9.48 : cum avg qps=428.35 : int avg qps=85.23 : exceptions=0
|
Thread[Thread-2,5,main]397,504,407 inserts : 37,690 seconds : cum ips=10,546.67 : int ips=49.96 : cum avg qry=2.33 : int avg qry=14.32 : cum avg qps=428.26 : int avg qps=83.23 : exceptions=0
|
Thread[Thread-2,5,main]397,504,857 inserts : 37,700 seconds : cum ips=10,543.88 : int ips=44.97 : cum avg qry=2.33 : int avg qry=10.19 : cum avg qps=428.17 : int avg qps=79.34 : exceptions=0
|
Thread[Thread-2,5,main]397,514,430 inserts : 37,710 seconds : cum ips=10,541.34 : int ips=956.63 : cum avg qry=2.33 : int avg qry=21.60 : cum avg qps=428.07 : int avg qps=55.06 : exceptions=0
|
Thread[Thread-2,5,main]397,663,334 inserts : 37,720 seconds : cum ips=10,542.49 : int ips=14,878.50 : cum avg qry=2.33 : int avg qry=2.38 : cum avg qps=428.07 : int avg qps=419.86 : exceptions=0
|
Thread[Thread-2,5,main]397,812,061 inserts : 37,730 seconds : cum ips=10,543.63 : int ips=14,862.30 : cum avg qry=2.33 : int avg qry=2.34 : cum avg qps=428.07 : int avg qps=426.20 : exceptions=0
|
Thread[Thread-2,5,main]397,944,249 inserts : 37,740 seconds : cum ips=10,544.34 : int ips=13,208.23 : cum avg qry=2.33 : int avg qry=4.18 : cum avg qps=428.02 : int avg qps=239.21 : exceptions=0
|
The zlib test is about 90% done and has ~10,000 slow operations and the worst 10 in milliseconds are
21699
|
19691
|
7860
|
6848
|
6848
|
6848
|
6848
|
6847
|
6847
|
6847
|
|
|
I can confirm that I'm still seeing long batch insert times in 3.0.1, sometimes as long as 2 minutes and often in the 10-30 seconds range in the Sysbench load process. I stopped using directIO because it performed very inconsistently compared to bufferedIO http://www.acmebenchmarking.com/2015/02/mongodb-v3-se-shootout-1a.html
I'll rerun this morning with directIO and see if it performs better.
|
|
I haven't used direct_io for a long time. I almost always use snappy or zlib compression and part of the problem has been single threaded eviction, checkpoint or capped-deletion enforcement. I think 2 of those 3 are still single threaded and that thread can fall behind from compressing data to be written/evicted/flushed.
|
|
I still get this with 3.0.1. This is output from 10 loader threads and 1 query thread. Stats are reported every 10 seconds. There is a lot of variance in the per-interval insert/second rate (int ips).
Thread[Thread-2,5,main]340,517,966 inserts : 31,190 seconds : cum ips=10,917.53 : int ips=5,256.66 : cum avg qry=2.21 : int avg qry=3.48 : cum avg qps=452.38 : int avg qps=347.80 : exceptions=0
|
Thread[Thread-2,5,main]340,563,600 inserts : 31,200 seconds : cum ips=10,915.49 : int ips=4,558.39 : cum avg qry=2.21 : int avg qry=9.61 : cum avg qps=452.26 : int avg qps=83.21 : exceptions=0
|
Thread[Thread-2,5,main]340,596,588 inserts : 31,210 seconds : cum ips=10,913.05 : int ips=3,295.50 : cum avg qry=2.21 : int avg qry=9.61 : cum avg qps=452.15 : int avg qps=124.78 : exceptions=0
|
Thread[Thread-2,5,main]340,627,556 inserts : 31,220 seconds : cum ips=10,910.54 : int ips=3,094.32 : cum avg qry=2.21 : int avg qry=3.98 : cum avg qps=452.07 : int avg qps=200.84 : exceptions=0
|
Thread[Thread-2,5,main]340,656,484 inserts : 31,230 seconds : cum ips=10,907.97 : int ips=2,889.91 : cum avg qry=2.21 : int avg qry=7.25 : cum avg qps=451.99 : int avg qps=179.22 : exceptions=0
|
Thread[Thread-2,5,main]340,681,843 inserts : 31,240 seconds : cum ips=10,905.29 : int ips=2,533.87 : cum avg qry=2.21 : int avg qry=5.25 : cum avg qps=451.88 : int avg qps=133.29 : exceptions=0
|
Thread[Thread-2,5,main]340,700,163 inserts : 31,250 seconds : cum ips=10,902.38 : int ips=1,830.54 : cum avg qry=2.21 : int avg qry=7.12 : cum avg qps=451.80 : int avg qps=182.55 : exceptions=0
|
Thread[Thread-2,5,main]340,716,404 inserts : 31,260 seconds : cum ips=10,899.41 : int ips=1,622.64 : cum avg qry=2.21 : int avg qry=2.49 : cum avg qps=451.74 : int avg qps=280.65 : exceptions=0
|
Thread[Thread-2,5,main]340,716,904 inserts : 31,270 seconds : cum ips=10,895.94 : int ips=49.97 : cum avg qry=2.21 : int avg qry=5.47 : cum avg qps=451.67 : int avg qps=219.45 : exceptions=0
|
Thread[Thread-2,5,main]340,717,401 inserts : 31,280 seconds : cum ips=10,892.47 : int ips=49.67 : cum avg qry=2.21 : int avg qry=5.11 : cum avg qps=451.57 : int avg qps=156.69 : exceptions=0
|
Thread[Thread-2,5,main]340,735,857 inserts : 31,290 seconds : cum ips=10,889.58 : int ips=1,844.31 : cum avg qry=2.21 : int avg qry=7.69 : cum avg qps=451.48 : int avg qps=155.99 : exceptions=0
|
Thread[Thread-2,5,main]340,736,357 inserts : 31,300 seconds : cum ips=10,886.11 : int ips=49.97 : cum avg qry=2.21 : int avg qry=5.26 : cum avg qps=451.38 : int avg qps=152.19 : exceptions=0
|
Thread[Thread-2,5,main]340,736,854 inserts : 31,310 seconds : cum ips=10,882.68 : int ips=50.17 : cum avg qry=2.21 : int avg qry=3.78 : cum avg qps=451.34 : int avg qps=320.48 : exceptions=0
|
Thread[Thread-2,5,main]340,891,392 inserts : 31,320 seconds : cum ips=10,884.14 : int ips=15,441.45 : cum avg qry=2.21 : int avg qry=3.77 : cum avg qps=451.29 : int avg qps=294.56 : exceptions=0
|
Thread[Thread-2,5,main]341,076,732 inserts : 31,330 seconds : cum ips=10,886.58 : int ips=18,521.04 : cum avg qry=2.21 : int avg qry=3.81 : cum avg qps=451.23 : int avg qps=262.32 : exceptions=0
|
Thread[Thread-2,5,main]341,225,781 inserts : 31,340 seconds : cum ips=10,887.86 : int ips=14,892.99 : cum avg qry=2.21 : int avg qry=1.88 : cum avg qps=451.26 : int avg qps=530.18 : exceptions=0
|
Thread[Thread-2,5,main]341,351,577 inserts : 31,350 seconds : cum ips=10,888.39 : int ips=12,569.54 : cum avg qry=2.21 : int avg qry=2.67 : cum avg qps=451.23 : int avg qps=374.00 : exceptions=0
|
Thread[Thread-2,5,main]341,480,477 inserts : 31,360 seconds : cum ips=10,889.03 : int ips=12,877.12 : cum avg qry=2.21 : int avg qry=1.67 : cum avg qps=451.28 : int avg qps=597.60 : exceptions=0
|
Thread[Thread-2,5,main]341,636,326 inserts : 31,370 seconds : cum ips=10,890.52 : int ips=15,574.00 : cum avg qry=2.21 : int avg qry=2.29 : cum avg qps=451.27 : int avg qps=432.50 : exceptions=0
|
Thread[Thread-2,5,main]341,776,199 inserts : 31,380 seconds : cum ips=10,891.51 : int ips=13,973.33 : cum avg qry=2.21 : int avg qry=3.41 : cum avg qps=451.22 : int avg qps=295.50 : exceptions=0
|
Thread[Thread-2,5,main]341,852,670 inserts : 31,390 seconds : cum ips=10,890.47 : int ips=7,641.75 : cum avg qry=2.21 : int avg qry=2.30 : cum avg qps=451.22 : int avg qps=433.90 : exceptions=0
|
Thread[Thread-2,5,main]341,951,008 inserts : 31,400 seconds : cum ips=10,890.13 : int ips=9,825.94 : cum avg qry=2.21 : int avg qry=2.80 : cum avg qps=451.19 : int avg qps=355.82 : exceptions=0
|
Thread[Thread-2,5,main]342,054,472 inserts : 31,410 seconds : cum ips=10,889.96 : int ips=10,338.13 : cum avg qry=2.21 : int avg qry=3.08 : cum avg qps=451.13 : int avg qps=283.87 : exceptions=0
|
Thread[Thread-2,5,main]342,129,590 inserts : 31,420 seconds : cum ips=10,888.88 : int ips=7,506.55 : cum avg qry=2.21 : int avg qry=5.23 : cum avg qps=451.06 : int avg qps=214.95 : exceptions=0
|
From PMP stacks it looks like https://jira.mongodb.org/browse/SERVER-17265 is a problem
I am using this mongo.conf
processManagement:
|
fork: true
|
systemLog:
|
destination: file
|
path: /data/mysql/mongo.30/log
|
logAppend: true
|
storage:
|
syncPeriodSecs: 60
|
dbPath: /data/mysql/mongo.30/data
|
journal:
|
enabled: true
|
mmapv1:
|
journal:
|
commitIntervalMs: 100
|
|
operationProfiling.slowOpThresholdMs: 2000
|
replication.oplogSizeMB: 2000
|
|
storage.wiredTiger.collectionConfig.blockCompressor: snappy
|
storage.wiredTiger.engineConfig.journalCompressor: snappy
|
I will upload the script and Java files I use
|
|
We have tried to reproduce this on an i2.2xlarge instance running 3.0.1GA with both of the provided drives attached in a RAID0 and the following MongoDB config:
storage:
|
dbPath: /var/lib/mongo
|
engine: wiredTiger
|
wiredTiger:
|
engineConfig:
|
cacheSizeGB: 32
|
configString: "direct_io=[data]"
|
systemLog:
|
destination: file
|
path: "/var/log/mongodb/mongodb.log"
|
logAppend: true
|
processManagement:
|
fork: true
|
There were 28 instances of queries running at 200ms or greater. Only 4 were over 1 second and these were all within the first 3 minutes of execution in this 1 hour run.
mdcallag and tmcallaghan, does 3.0.1 resolve this issue for you?
|
|
On 3.0.0GA I just ran Sysbench load phase, 16 collections, 25 million documents per collection, 8 concurrent inserters. WT configured for no compression.
I'm pretty sure this is the same issue as reported, so I'm not filing a new ticket.
Around 200 million inserts in I see some very slow operations finally completing (they are taking almost an hour), the following numbers are in milliseconds:
2741777
2638845
2637297
2640004
2640195
2644539
2643585
2651832
|
|
I used rc10 to insert 400M docs via 10 threads and then there is 1 more thread doing short (4 doc) range scans. The host has 20 real CPU cores and 40 with HT enabled, so clients << cores. The data below shows the number of slow operations (slow >= 2 seconds) and the slowest op in milliseconds. This shows how much worse the WT b-tree does compared to the mmap engine. From past experience the slow operations are not from the range scans.
#slow worstMs
|
147 8680 mmap
|
6233 21699 wtbt-snappy
|
13316 10219 wtbt-zlib
|
|
|
Michael, TokuMX added partitioned collections for this very reason. Far too much effort is required to keep it under a specific size, especially when the system is performing insert/update/delete operations at high velocity. The TokuMX oplog is bound by time (users declare how many hours or days worth of oplog to retain), and the oldest partition is dropped either daily or hourly.
|
|
I haven't seen stalls from journal writes, but I haven't looked either. In MySQL the oplog equivalent doesn't go through the database engine. Here it does, so for inserts we write once for the insert, write a second time for the oplog insert and both are also written to the WiredTiger redo log. So we write 4 times. Then we have to delete later to enfoce the capped collection for the oplog. So using the database engine for the replication log means there is a lot more stress on the engine and the plans explained above to reduce it sound great.
|
|
There is some work in progress (for post 3.0.0) on the WiredTiger side for stalls caused by journal writes, here:
https://github.com/wiredtiger/wiredtiger/pull/1696
We have several ideas for improving oplog handling, including switching to a specially-configured LSM tree (with merges disabled, just dropping the oldest chunk to stay under the configured size). They are also post 3.0.0.
Michael.
|
|
I can confirm that I see stalls/drop-outs like this, but only when journal is enabled - with and without oplog. I haven't seen this when there is no journal. Also, I see it with snappy also, but it takes a lot longer to get to it.
|
|
The stall is regular. I grabbed 5 PMP stacks 30 seconds apart during the next stall and all were similar to the stack above. This is from the background job doing capped delete processing. When I first filed this bug I wasn't enabling the oplog. Now I am and oplog + zlib latency looks like a problem.
Can compression and/or eviction be done by other background threads to avoid stalling the capped delete thread?
|
|
Read that PMP output too fast. The stall in that case was a background job enforcing capped size for the oplog
|
|
I still get stalls for rc9 with iibench-mongodb, 10 insert threads, 1 query thread, zlib block compressor, oplog enabled. This is a frequent pattern where "cum ips" is the average insert rate over the test, "int ips" is the insert rate over the last 10 seconds, "cum avg qps" and "int avg qps" are the same things but for queries.
Thread[Thread-2,5,main]310,697,758 inserts : 70,690 seconds : cum ips=4,395.21 : int ips=6,669.36 : cum avg qry=2.77 : int avg qry=5.00 : cum avg qps=361.31 : int avg qps=200.54 : exceptions=0
|
Thread[Thread-2,5,main]310,735,789 inserts : 70,700 seconds : cum ips=4,395.13 : int ips=3,800.06 : cum avg qry=2.77 : int avg qry=1.06 : cum avg qps=361.32 : int avg qps=449.14 : exceptions=0
|
Thread[Thread-2,5,main]310,753,871 inserts : 70,710 seconds : cum ips=4,394.76 : int ips=1,806.94 : cum avg qry=2.77 : int avg qry=4.19 : cum avg qps=361.31 : int avg qps=282.70 : exceptions=0
|
Thread[Thread-2,5,main]310,814,068 inserts : 70,720 seconds : cum ips=4,394.99 : int ips=6,014.89 : cum avg qry=2.77 : int avg qry=3.21 : cum avg qps=361.32 : int avg qps=418.17 : exceptions=0
|
Thread[Thread-2,5,main]310,880,181 inserts : 70,730 seconds : cum ips=4,395.31 : int ips=6,605.36 : cum avg qry=2.77 : int avg qry=2.40 : cum avg qps=361.31 : int avg qps=315.72 : exceptions=0
|
Thread[Thread-2,5,main]310,941,264 inserts : 70,740 seconds : cum ips=4,395.55 : int ips=6,103.42 : cum avg qry=2.77 : int avg qry=5.66 : cum avg qps=361.29 : int avg qps=211.93 : exceptions=0
|
Thread[Thread-2,5,main]311,010,024 inserts : 70,750 seconds : cum ips=4,395.90 : int ips=6,870.50 : cum avg qry=2.77 : int avg qry=6.41 : cum avg qps=361.26 : int avg qps=161.37 : exceptions=0
|
Thread[Thread-2,5,main]311,039,216 inserts : 70,760 seconds : cum ips=4,395.69 : int ips=2,916.58 : cum avg qry=2.77 : int avg qry=2.64 : cum avg qps=361.26 : int avg qps=328.40 : exceptions=0
|
Thread[Thread-2,5,main]311,047,776 inserts : 70,770 seconds : cum ips=4,395.19 : int ips=855.32 : cum avg qry=2.77 : int avg qry=7.77 : cum avg qps=361.23 : int avg qps=141.59 : exceptions=0
|
Thread[Thread-2,5,main]311,055,997 inserts : 70,780 seconds : cum ips=4,394.68 : int ips=821.36 : cum avg qry=2.77 : int avg qry=4.48 : cum avg qps=361.21 : int avg qps=232.39 : exceptions=0
|
Thread[Thread-2,5,main]311,063,879 inserts : 70,790 seconds : cum ips=4,394.18 : int ips=795.44 : cum avg qry=2.77 : int avg qry=1.95 : cum avg qps=361.21 : int avg qps=341.31 : exceptions=0
|
Thread[Thread-2,5,main]311,071,975 inserts : 70,800 seconds : cum ips=4,393.67 : int ips=808.95 : cum avg qry=2.77 : int avg qry=3.87 : cum avg qps=361.20 : int avg qps=310.25 : exceptions=0
|
Thread[Thread-2,5,main]311,072,742 inserts : 70,810 seconds : cum ips=4,393.06 : int ips=76.64 : cum avg qry=2.77 : int avg qry=5.65 : cum avg qps=361.17 : int avg qps=159.17 : exceptions=0
|
Thread[Thread-2,5,main]311,080,385 inserts : 70,820 seconds : cum ips=4,392.55 : int ips=763.69 : cum avg qry=2.77 : int avg qry=5.89 : cum avg qps=361.14 : int avg qps=186.75 : exceptions=0
|
Thread[Thread-2,5,main]311,081,107 inserts : 70,830 seconds : cum ips=4,391.94 : int ips=72.14 : cum avg qry=2.77 : int avg qry=5.81 : cum avg qps=361.11 : int avg qps=137.58 : exceptions=0
|
Thread[Thread-2,5,main]311,088,779 inserts : 70,840 seconds : cum ips=4,391.43 : int ips=766.59 : cum avg qry=2.77 : int avg qry=7.91 : cum avg qps=361.08 : int avg qps=151.68 : exceptions=0
|
Thread[Thread-2,5,main]311,089,564 inserts : 70,850 seconds : cum ips=4,390.82 : int ips=78.44 : cum avg qry=2.77 : int avg qry=3.69 : cum avg qps=361.06 : int avg qps=216.63 : exceptions=0
|
Thread[Thread-2,5,main]311,097,218 inserts : 70,860 seconds : cum ips=4,390.30 : int ips=764.79 : cum avg qry=2.77 : int avg qry=3.33 : cum avg qps=361.06 : int avg qps=360.51 : exceptions=0
|
Thread[Thread-2,5,main]311,097,789 inserts : 70,870 seconds : cum ips=4,389.69 : int ips=57.05 : cum avg qry=2.77 : int avg qry=3.88 : cum avg qps=361.04 : int avg qps=205.94 : exceptions=0
|
Thread[Thread-2,5,main]311,105,361 inserts : 70,880 seconds : cum ips=4,389.18 : int ips=756.59 : cum avg qry=2.77 : int avg qry=3.84 : cum avg qps=361.04 : int avg qps=338.33 : exceptions=0
|
Thread[Thread-2,5,main]311,105,826 inserts : 70,890 seconds : cum ips=4,388.57 : int ips=46.46 : cum avg qry=2.77 : int avg qry=3.42 : cum avg qps=361.02 : int avg qps=204.92 : exceptions=0
|
Thread[Thread-2,5,main]311,106,618 inserts : 70,900 seconds : cum ips=4,387.96 : int ips=79.14 : cum avg qry=2.77 : int avg qry=4.96 : cum avg qps=361.00 : int avg qps=241.91 : exceptions=0
|
Thread[Thread-2,5,main]311,114,135 inserts : 70,910 seconds : cum ips=4,387.45 : int ips=758.60 : cum avg qry=2.77 : int avg qry=5.31 : cum avg qps=360.97 : int avg qps=152.18 : exceptions=0
|
Thread[Thread-2,5,main]311,114,930 inserts : 70,920 seconds : cum ips=4,386.84 : int ips=79.44 : cum avg qry=2.77 : int avg qry=5.61 : cum avg qps=360.95 : int avg qps=219.42 : exceptions=0
|
Thread[Thread-2,5,main]311,115,390 inserts : 70,930 seconds : cum ips=4,386.23 : int ips=45.96 : cum avg qry=2.77 : int avg qry=3.37 : cum avg qps=360.93 : int avg qps=228.52 : exceptions=0
|
Thread[Thread-2,5,main]311,122,892 inserts : 70,940 seconds : cum ips=4,385.72 : int ips=749.60 : cum avg qry=2.77 : int avg qry=4.77 : cum avg qps=360.92 : int avg qps=251.40 : exceptions=0
|
Thread[Thread-2,5,main]311,123,656 inserts : 70,950 seconds : cum ips=4,385.11 : int ips=76.33 : cum avg qry=2.77 : int avg qry=5.21 : cum avg qps=360.89 : int avg qps=172.84 : exceptions=0
|
Thread[Thread-2,5,main]311,124,086 inserts : 70,960 seconds : cum ips=4,384.50 : int ips=42.97 : cum avg qry=2.77 : int avg qry=4.55 : cum avg qps=360.87 : int avg qps=242.01 : exceptions=0
|
Thread[Thread-2,5,main]311,131,568 inserts : 70,970 seconds : cum ips=4,383.98 : int ips=747.60 : cum avg qry=2.77 : int avg qry=4.52 : cum avg qps=360.85 : int avg qps=176.96 : exceptions=0
|
Thread[Thread-2,5,main]311,306,963 inserts : 70,980 seconds : cum ips=4,385.84 : int ips=17,525.48 : cum avg qry=2.77 : int avg qry=5.92 : cum avg qps=360.83 : int avg qps=219.62 : exceptions=0
|
Thread[Thread-2,5,main]311,307,463 inserts : 70,990 seconds : cum ips=4,385.23 : int ips=49.96 : cum avg qry=2.77 : int avg qry=5.18 : cum avg qps=360.79 : int avg qps=135.09 : exceptions=0
|
Thread[Thread-2,5,main]311,307,963 inserts : 71,000 seconds : cum ips=4,384.61 : int ips=49.96 : cum avg qry=2.77 : int avg qry=3.52 : cum avg qps=360.79 : int avg qps=340.43 : exceptions=0
|
Thread[Thread-2,5,main]311,308,463 inserts : 71,010 seconds : cum ips=4,384.00 : int ips=49.96 : cum avg qry=2.77 : int avg qry=2.79 : cum avg qps=360.79 : int avg qps=321.91 : exceptions=0
|
Thread[Thread-2,5,main]311,340,093 inserts : 71,020 seconds : cum ips=4,383.83 : int ips=3,160.79 : cum avg qry=2.77 : int avg qry=2.93 : cum avg qps=360.79 : int avg qps=411.51 : exceptions=0
|
Thread[Thread-2,5,main]311,355,687 inserts : 71,030 seconds : cum ips=4,383.44 : int ips=1,573.88 : cum avg qry=2.77 : int avg qry=2.22 : cum avg qps=360.79 : int avg qps=316.31 : exceptions=0
|
Thread[Thread-2,5,main]311,408,509 inserts : 71,040 seconds : cum ips=4,383.56 : int ips=5,278.51 : cum avg qry=2.77 : int avg qry=2.27 : cum avg qps=360.82 : int avg qps=571.80 : exceptions=0
|
Thread[Thread-2,5,main]311,469,273 inserts : 71,050 seconds : cum ips=4,383.80 : int ips=6,071.54 : cum avg qry=2.77 : int avg qry=2.15 : cum avg qps=360.83 : int avg qps=463.43 : exceptions=0
|
Thread[Thread-2,5,main]311,522,827 inserts : 71,060 seconds : cum ips=4,383.94 : int ips=5,351.12 : cum avg qry=2.77 : int avg qry=1.52 : cum avg qps=360.87 : int avg qps=658.57 : exceptions=0
|
Thread[Thread-2,5,main]311,589,274 inserts : 71,070 seconds : cum ips=4,384.26 : int ips=6,640.05 : cum avg qry=2.77 : int avg qry=1.80 : cum avg qps=360.90 : int avg qps=556.11 : exceptions=0
|
And PMP output during one of those stalls. Single eviction thread gets behind because it has to do zlib compression.
10 __lll_timedlock_wait,pthread_mutex_timedlock,deallocate,deallocate,_M_deallocate,_M_emplace_back_aux<mongo::RecoveryUnit::Change*,push_back,push_back,mongo::WiredTigerRecoveryUnit::registerChange,mongo::WiredTigerRecordStore::_increaseDataSize,mongo::WiredTigerRecordStore::insertRecord,mongo::WiredTigerRecordStore::insertRecord,mongo::Collection::insertDocument,mongo::repl::(anonymous,mongo::repl::logOp,singleInsert,insertOne,mongo::WriteBatchExecutor::execOneInsert,mongo::WriteBatchExecutor::execInserts,mongo::WriteBatchExecutor::bulkExecute,mongo::WriteBatchExecutor::executeBatch,mongo::WriteCmd::run,mongo::_execCommand,mongo::Command::execCommand,mongo::_runCommands,runCommands,mongo::runQuery,receivedQuery,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 sigwait,mongo::(anonymous,boost::(anonymous,start_thread,clone
|
1 select,mongo::Listener::initAndListen,_initAndListen,mongo::initAndListen,mongoDbMain,main
|
1 recv,mongo::Socket::_recv,mongo::Socket::unsafe_recv,mongo::Socket::recv,mongo::MessagingPort::recv,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 pwrite64,__wt_write,__wt_block_write_off,__wt_block_write,__wt_bt_write,__rec_split_write,__rec_split_finish_std,__rec_split_finish,__rec_row_leaf,__wt_reconcile,__sync_file,__wt_cache_op,__checkpoint_worker,__wt_checkpoint,__checkpoint_apply,__wt_txn_checkpoint,__session_checkpoint,__ckpt_server,start_thread,clone
|
1 pthread_cond_wait@@GLIBC_2.3.2,wait<boost::unique_lock<boost::timed_mutex>,mongo::DeadlineMonitor<mongo::V8Scope>::deadlineMonitorThread,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__sweep_server,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__log_close_server,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__evict_server,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait,timed_wait<boost::date_time::subsecond_duration<boost::posix_time::time_duration,,mongo::CondVarLockGrantNotification::wait,mongo::LockerImpl<false>::lockComplete,mongo::Lock::GlobalLock::_lock,GlobalLock,mongo::Lock::DBLock::DBLock,mongo::AutoGetDb::AutoGetDb,mongo::AutoGetCollectionForRead::AutoGetCollectionForRead,mongo::GlobalCursorIdCache::eraseCursor,mongo::CursorManager::eraseCursorGlobalIfAuthorized,mongo::CursorManager::eraseCursorGlobalIfAuthorized,mongo::receivedKillCursors,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::repl::replMasterThread,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 __lll_lock_wait,pthread_mutex_lock,??,??,??
|
1 deflate_slow,deflate,zlib_compress_raw,__rec_split_raw_worker,__rec_split_finish,__rec_row_leaf,__wt_reconcile,__evict_review,__wt_evict,__wt_evict_page,__wt_page_release_evict,__wt_page_release,__wt_page_swap_func,__wt_tree_walk,__wt_btcur_next,__curfile_next,mongo::WiredTigerRecordStore::cappedDeleteAsNeeded_inlock,_deleteExcessDocuments,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
And the top-N from perf during one drop using a 10 second sample
18.18% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] deflate_slow
|
16.00% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __rec_row_leaf_insert
|
13.88% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __rec_row_leaf
|
10.04% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] longest_match
|
6.80% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] inflate_fast
|
4.86% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __rec_cell_build_leaf_key
|
4.79% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] compress_block
|
3.99% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __wt_cell_unpack_safe.constprop.45
|
3.13% mongod.30rc9.je libc-2.20.so [.] __memmove_avx_unaligned
|
2.52% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] build_tree
|
1.57% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] adler32
|
0.96% mongod.30rc9.je [kernel.kallsyms] [k] copy_user_enhanced_fast_string
|
0.78% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __wt_cksum_hw
|
0.63% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] inflate_table
|
0.58% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __block_merge
|
0.47% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __wt_row_search
|
0.43% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __wt_block_off_remove_overlap
|
0.38% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __wt_tree_walk
|
0.36% mongod.30rc9.je libc-2.20.so [.] __memset_sse2
|
0.36% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] send_tree
|
0.33% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __block_off_remove
|
0.33% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __evict_review
|
0.31% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] __wt_page_in_func
|
0.28% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] inflate
|
0.28% mongod.30rc9.je mongod.30rc9.jem.norox.dbg [.] _tr_flush_block
|
|
|
Hi mdcallag, we have some more fixes since RC8: I'll test with that version and let you know what I see.
Also, just for the record, even if you see the "maximum page" statistic grow that large, it doesn't indicate that there is a single allocation for all of that memory. It is the sum of all of the updates that accumulate in a page.
|
|
Reproduction case is the same as recently uploaded for https://jira.mongodb.org/browse/SERVER-17141 – uses 10 threads, each thread does 1 document/insert, etc. However for this test the oplog is disabled. I wonder if the cause is stress on the memory allocator from occasionally dealing with a request for 625M of contiguous memory.
My builds use jemalloc, but I was able to reproduce the problem previously with glibc malloc and tcmalloc.
|
|
Mark, is this test also using 10 threads? Or is it the default in iibench-mongodb (which looks like is 16)?
|
|
The test ran for more time. There was one 410 second interval during which there were few inserts, like 0.1/second. And the longest stalls in milliseconds from the slowop messages in the log are listed below. The worst case was 205 seconds.
205386
205385
181474
181474
163327
163327
147990
147989
143343
143342
132777
132777
126235
126235
121574
121574
112128
112128
108140
108140
100311
100311
87868
|
|
Using rc8, oplog off, journal on with SAFE write concern, iibench-mongodb client is printing stats every 10 seconds. "int ips" is the inserts/second rate dring the 10 second interval while "cum ips" is cumulative insert per second rate. Note that cum ips is over 33,000 and there is a 70 second period during which the insert per second rate dropped under 10.
Thread[Thread-2,5,main]304,322,357 inserts : 8,980 seconds : cum ips=33,888.69 : int ips=8.29 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,422 inserts : 8,990 seconds : cum ips=33,850.96 : int ips=6.49 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,489 inserts : 9,000 seconds : cum ips=33,813.33 : int ips=6.69 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,557 inserts : 9,010 seconds : cum ips=33,775.78 : int ips=6.79 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,624 inserts : 9,020 seconds : cum ips=33,738.31 : int ips=6.69 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,693 inserts : 9,030 seconds : cum ips=33,700.93 : int ips=6.89 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,762 inserts : 9,040 seconds : cum ips=33,664.00 : int ips=6.96 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
Thread[Thread-2,5,main]304,322,828 inserts : 9,050 seconds : cum ips=33,626.77 : int ips=6.59 : cum avg qry=0.00 : int avg qry=0.00 : cum avg qps=0.00 : int avg qps=0.00 : exceptions=0
|
|
|
Is this still an issue with RC6 and the evict_dirty_target configuration you have been using?
To be clear, we still plan to do more work to avoid stalls caused by checkpoints. I just want to confirm that you are no longer seeing any inserts take over 100s.
|
|
To be clear, I don't think direct IO is the root cause. Most of my tests run with buffered IO and all of them get stalls. I ended up changing the client-side socketTimeout from 60 to 600 seconds to avoid exceptions from long waits.
|
|
Hi mdcallag, from that pmp output, the problem here is that direct I/O slows down checkpoints because every write is synchronous. The result is that other threads fill the cache with dirty pages before the checkpoint completes, and then stall.
This is related to SERVER-16665 in that to fix it properly, we need to bound the I/O required in the single-threaded part of a checkpoint.
|
|
Mark, it's possible these are during either checkpoint or eviction of pages - we're tracking what may be similar intermittent latency spikes in SERVER-16269 - there is also SERVER-16492 (which I suspect may be the same thing at heart or something related).
|
|
I ran PMP in a loop and these are thread stacks from one of the delays. From the log file I see there is a window when all inserts stall...
2014-12-17T12:49:30.327-0800 I WRITE [conn224] insert iibench.purchases_index ninserted:1000 keyUpdates:0 38345ms
|
2014-12-17T12:49:33.923-0800 I WRITE [conn216] insert iibench.purchases_index ninserted:1000 keyUpdates:0 41936ms
|
2014-12-17T12:49:34.286-0800 I WRITE [conn221] insert iibench.purchases_index ninserted:1000 keyUpdates:0 42289ms
|
2014-12-17T12:49:37.208-0800 I WRITE [conn220] insert iibench.purchases_index ninserted:1000 keyUpdates:0 45212ms
|
2014-12-17T12:49:45.411-0800 I WRITE [conn225] insert iibench.purchases_index ninserted:1000 keyUpdates:0 53302ms
|
2014-12-17T12:49:53.398-0800 I WRITE [conn219] insert iibench.purchases_index ninserted:1000 keyUpdates:0 58513ms
|
2014-12-17T12:49:53.709-0800 I WRITE [conn223] insert iibench.purchases_index ninserted:1000 keyUpdates:0 59158ms
|
2014-12-17T12:50:05.040-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:16652 #226 (11 connections now open)
|
2014-12-17T12:50:05.040-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:16694 #227 (12 connections now open)
|
2014-12-17T12:50:07.553-0800 I WRITE [conn218] insert iibench.purchases_index ninserted:1000 keyUpdates:0 64157ms
|
2014-12-17T12:50:07.553-0800 I NETWORK [conn218] end connection 127.0.0.1:58084 (11 connections now open)
|
2014-12-17T12:50:09.646-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:16753 #228 (12 connections now open)
|
2014-12-17T12:50:10.261-0800 I WRITE [conn215] insert iibench.purchases_index ninserted:1000 keyUpdates:0 68798ms
|
2014-12-17T12:50:10.261-0800 I NETWORK [conn215] end connection 127.0.0.1:58023 (11 connections now open)
|
2014-12-17T12:50:17.729-0800 I WRITE [conn217] insert iibench.purchases_index ninserted:1000 keyUpdates:0 68185ms
|
2014-12-17T12:50:17.729-0800 I NETWORK [conn217] end connection 127.0.0.1:58054 (10 connections now open)
|
2014-12-17T12:50:30.482-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:16941 #229 (11 connections now open)
|
2014-12-17T12:50:30.714-0800 I WRITE [conn224] insert iibench.purchases_index ninserted:1000 keyUpdates:0 60339ms
|
2014-12-17T12:50:30.714-0800 I NETWORK [conn224] end connection 127.0.0.1:61778 (10 connections now open)
|
2014-12-17T12:50:33.109-0800 I WRITE [conn221] insert iibench.purchases_index ninserted:1000 keyUpdates:0 58773ms
|
2014-12-17T12:50:34.049-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:16972 #230 (11 connections now open)
|
2014-12-17T12:50:35.388-0800 I WRITE [conn216] insert iibench.purchases_index ninserted:1000 keyUpdates:0 61420ms
|
2014-12-17T12:50:35.388-0800 I NETWORK [conn216] end connection 127.0.0.1:58042 (10 connections now open)
|
2014-12-17T12:50:35.714-0800 I WRITE [conn220] insert iibench.purchases_index ninserted:1000 keyUpdates:0 58461ms
|
2014-12-17T12:50:41.941-0800 I WRITE [conn225] insert iibench.purchases_index ninserted:1000 keyUpdates:0 56483ms
|
2014-12-17T12:50:53.555-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:17168 #231 (11 connections now open)
|
2014-12-17T12:50:53.860-0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:17171 #232 (12 connections now open)
|
2014-12-17T12:50:58.914-0800 I WRITE [conn219] insert iibench.purchases_index ninserted:1000 keyUpdates:0 65472ms
|
I had script that got thread stacks every 20 or 30 seconds and for this time range I see...
Thread stacks at 12:49:12 where the format is <#threads> <comma separated call stack>
|
5 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__cursor_enter,__curfile_enter,__cursor_func_init,__wt_btcur_insert,__curfile_insert,mongo::WiredTigerIndexStandard::_insert,mongo::WiredTigerIndex::insert,mongo::BtreeBasedAccessMethod::insert,mongo::IndexCatalog::_indexRecord,mongo::IndexCatalog::indexRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
4 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__session_begin_transaction,mongo::WiredTigerRecoveryUnit::_txnOpen,mongo::WiredTigerRecoveryUnit::getSession,mongo::WiredTigerCursor::_init,mongo::WiredTigerRecordStore::insertRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 __wt_page_is_modified,__evict_walk_file,__evict_walk,__evict_lru_walk,__evict_pass,__evict_server,start_thread,clone
|
1 sigwait,mongo::(anonymous,boost::(anonymous,start_thread,clone
|
1 select,mongo::Listener::initAndListen,_initAndListen,mongo::initAndListen,mongoDbMain,main
|
1 pwrite64,__wt_write,__wt_block_write_off,__wt_block_write,__wt_bt_write,__rec_split_write,__rec_split_finish_std,__rec_split_finish,__rec_row_leaf,__wt_reconcile,__sync_file,__wt_cache_op,__checkpoint_worker,__wt_checkpoint,__checkpoint_apply,__wt_txn_checkpoint,__session_checkpoint,__ckpt_server,start_thread,clone
|
1 pthread_cond_wait@@GLIBC_2.3.2,wait<boost::unique_lock<boost::timed_mutex>,mongo::DeadlineMonitor<mongo::V8Scope>::deadlineMonitorThread,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__cursor_enter,__curfile_enter,__cursor_func_init,__wt_btcur_insert,__curfile_insert,mongo::WiredTigerIndexUnique::_insert,mongo::WiredTigerIndex::insert,mongo::BtreeBasedAccessMethod::insert,mongo::IndexCatalog::_indexRecord,mongo::IndexCatalog::indexRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__sweep_server,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 __lll_lock_wait,_L_lock_943,pthread_mutex_lock,__wt_spin_lock,__log_archive_once,__log_archive_server,start_thread,clone
|
Thread stack at 12:49:53
5 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__session_begin_transaction,mongo::WiredTigerRecoveryUnit::_txnOpen,mongo::WiredTigerRecoveryUnit::getSession,mongo::WiredTigerCursor::_init,mongo::WiredTigerRecordStore::insertRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
5 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__cursor_enter,__curfile_enter,__cursor_func_init,__wt_btcur_insert,__curfile_insert,mongo::WiredTigerIndexStandard::_insert,mongo::WiredTigerIndex::insert,mongo::BtreeBasedAccessMethod::insert,mongo::IndexCatalog::_indexRecord,mongo::IndexCatalog::indexRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 __wt_hazard_set,__wt_page_in_func,__wt_page_swap_func,__wt_tree_walk,__evict_walk_file,__evict_walk,__evict_lru_walk,__evict_pass,__evict_server,start_thread,clone
|
1 sigwait,mongo::(anonymous,boost::(anonymous,start_thread,clone
|
1 select,mongo::Listener::initAndListen,_initAndListen,mongo::initAndListen,mongoDbMain,main
|
1 pwrite64,__wt_write,__wt_block_write_off,__wt_block_write,__wt_bt_write,__rec_split_write,__rec_split_finish_std,__rec_split_finish,__rec_row_leaf,__wt_reconcile,__sync_file,__wt_cache_op,__checkpoint_worker,__wt_checkpoint,__checkpoint_apply,__wt_txn_checkpoint,__session_checkpoint,__ckpt_server,start_thread,clone
|
1 pthread_cond_wait@@GLIBC_2.3.2,wait<boost::unique_lock<boost::timed_mutex>,mongo::DeadlineMonitor<mongo::V8Scope>::deadlineMonitorThread,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__sweep_server,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 __lll_lock_wait,_L_lock_943,pthread_mutex_lock,__wt_spin_lock,__log_archive_once,__log_archive_server,start_thread,clone
|
Thread stack at 12:50:35
7 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__cursor_enter,__curfile_enter,__cursor_func_init,__wt_btcur_insert,__curfile_insert,mongo::WiredTigerIndexStandard::_insert,mongo::WiredTigerIndex::insert,mongo::BtreeBasedAccessMethod::insert,mongo::IndexCatalog::_indexRecord,mongo::IndexCatalog::indexRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
3 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__wt_cache_full_check,__session_begin_transaction,mongo::WiredTigerRecoveryUnit::_txnOpen,mongo::WiredTigerRecoveryUnit::getSession,mongo::WiredTigerCursor::_init,mongo::WiredTigerRecordStore::insertRecord,mongo::Collection::_insertDocument,mongo::Collection::insertDocument,mongo::checkAndInsert,mongo::insertMulti,mongo::receivedInsert,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
|
1 __wt_tree_walk,__evict_walk_file,__evict_walk,__evict_lru_walk,__evict_pass,__evict_server,start_thread,clone
|
1 sigwait,mongo::(anonymous,boost::(anonymous,start_thread,clone
|
1 select,mongo::Listener::initAndListen,_initAndListen,mongo::initAndListen,mongoDbMain,main
|
1 __rec_txn_read,__rec_row_leaf_insert,__rec_row_leaf,__wt_reconcile,__sync_file,__wt_cache_op,__checkpoint_worker,__wt_checkpoint,__checkpoint_apply,__wt_txn_checkpoint,__session_checkpoint,__ckpt_server,start_thread,clone
|
1 pthread_cond_wait@@GLIBC_2.3.2,wait<boost::unique_lock<boost::timed_mutex>,mongo::DeadlineMonitor<mongo::V8Scope>::deadlineMonitorThread,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__sweep_server,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
|
1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 nanosleep,mongo::sleepsecs,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
|
1 __lll_lock_wait,_L_lock_943,pthread_mutex_lock,__wt_spin_lock,__log_archive_once,__log_archive_server,start_thread,clone
|
|
Generated at Thu Feb 08 03:41:31 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.