[SERVER-16575] intermittent slow inserts with WiredTiger b-tree Created: 17/Dec/14  Updated: 06/Dec/22  Resolved: 19/Nov/16

Status: Closed
Project: Core Server
Component/s: Performance, Storage, WiredTiger
Affects Version/s: 2.8.0-rc2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Mark Callaghan Assignee: Backlog - Storage Execution Team
Resolution: Done Votes: 3
Labels: wiredtiger, wttt
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File jmongoiibench$MyQuery.class     File jmongoiibench$MyReporter.class     File jmongoiibench$MyWriter.class     File jmongoiibench.class     Java Source File jmongoiibench.java     PNG File performance_output.png     File run.simple.bash.L10.Q1    
Issue Links:
Related
related to SERVER-17157 Seeing pauses in YCSB performance wor... Closed
is related to SERVER-17407 Significant performance degradation b... Closed
is related to SERVER-16665 WiredTiger b-tree uses too much space... Closed
Assigned Teams:
Storage Execution
Operating System: ALL
Steps To Reproduce:

Run iibench (https://github.com/tmcallaghan/iibench-mongodb) with 2 things changed in run.simple.bash. This uses 10 client threads to load.
export MAX_ROWS=200000000
export LENGTH_CHAR_FIELDS=2000

This problem reproduces for this configuration:
bin.tcm/mongod --config /data/mysql/mongo.28/mongo.conf --storageEngine wiredTiger --wiredTigerEngineConfig="cache_size=32G,direct_io=[data]"

And I use this mongo.conf:
processManagement:
fork: true
systemLog:
destination: file
path: /data/mysql/mongo.28/log
logAppend: true
storage:
dbPath: /data/mysql/mongo.28/data
journal:
enabled: true
mmapv1:
syncPeriodSecs: 60
journal:
commitIntervalMs: 100
I wasn't able to reproduce it for this configuration:
bin.tcm/mongod --config /data/mysql/mongo.28/mongo.conf --storageEngine wiredTiger

Participants:

 Description   

I get intermittent slow inserts with the WiredTiger b-tree in 2.8.0rc2. These are the top-10 worst ones from a test in progress. The numbers are milliseconds, so there are many inserts that take more than 100 seconds:
119597
118610
118465
117977
117437
116611
116498
116068
113909
113342

This doesn't reproduce with the WiredTiger LSM. I wonder if a slow checkpoint is the problem but I have not done the work to trigger collection of thread stacks when there is a stall, in part because my client code and the error log is printed when the stall ends.

I will repeat the test with PMP running to get thread stacks every 10 seconds to see if I get stack when the problem occurs.



 Comments   
Comment by Alexander Gorrod [ 18/Nov/16 ]

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.

Comment by Mark Callaghan [ 02/Jun/16 ]

I haven't seen this problem with 3.3.5

Comment by Mark Callaghan [ 07/Jul/15 ]

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.

Comment by Mark Callaghan [ 06/Jul/15 ]

Worst case stalls are ~6 seconds

Comment by Mark Callaghan [ 06/Jul/15 ]

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

Comment by Mark Callaghan [ 06/Jul/15 ]

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:

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

Comment by David Hows [ 06/Jul/15 ]

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?

Comment by David Daly [ 27/Apr/15 ]

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.

Comment by Tim Callaghan [ 27/Apr/15 ]

I don't understand the David Daly comment, my tests are not on capped collections and I have not enabled the oplog.

Comment by David Daly [ 27/Apr/15 ]

Related to SERVER-17407 – both related to oplog and capped collections.

Comment by David Hows [ 25/Mar/15 ]

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.

Comment by Mark Callaghan [ 24/Mar/15 ]

My test server has 40 hyperthread cores, 144G RAM and storage that can do ~50,000 IOPs

Comment by Mark Callaghan [ 24/Mar/15 ]

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

Comment by Tim Callaghan [ 24/Mar/15 ]

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.

Comment by David Hows [ 24/Mar/15 ]

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

Comment by Mark Callaghan [ 23/Mar/15 ]

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

Comment by Tim Callaghan [ 23/Mar/15 ]

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.

Comment by Mark Callaghan [ 23/Mar/15 ]

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.

Comment by Mark Callaghan [ 23/Mar/15 ]

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

Comment by Michael Cahill (Inactive) [ 23/Mar/15 ]

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?

Comment by Tim Callaghan [ 05/Mar/15 ]

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

Comment by Mark Callaghan [ 01/Mar/15 ]

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

Comment by Tim Callaghan [ 25/Feb/15 ]

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.

Comment by Mark Callaghan [ 25/Feb/15 ]

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.

Comment by Michael Cahill (Inactive) [ 25/Feb/15 ]

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.

Comment by Asya Kamsky [ 25/Feb/15 ]

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.

Comment by Mark Callaghan [ 24/Feb/15 ]

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?

Comment by Mark Callaghan [ 24/Feb/15 ]

Read that PMP output too fast. The stall in that case was a background job enforcing capped size for the oplog

Comment by Mark Callaghan [ 24/Feb/15 ]

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              

Comment by Michael Cahill (Inactive) [ 12/Feb/15 ]

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.

Comment by Mark Callaghan [ 11/Feb/15 ]

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.

Comment by Asya Kamsky [ 11/Feb/15 ]

Mark, is this test also using 10 threads? Or is it the default in iibench-mongodb (which looks like is 16)?

Comment by Mark Callaghan [ 11/Feb/15 ]

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

Comment by Mark Callaghan [ 10/Feb/15 ]

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

Comment by Michael Cahill (Inactive) [ 26/Jan/15 ]

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.

Comment by Mark Callaghan [ 20/Jan/15 ]

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.

Comment by Michael Cahill (Inactive) [ 06/Jan/15 ]

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.

Comment by Asya Kamsky [ 17/Dec/14 ]

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

Comment by Mark Callaghan [ 17/Dec/14 ]

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.