[SERVER-21585] Cache usage exceeds configured value, operations stall, WiredTigerLAS.wt grows Created: 20/Nov/15  Updated: 22/Dec/15  Resolved: 24/Nov/15

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: 3.2.0-rc3
Fix Version/s: 3.2.0-rc4

Type: Bug Priority: Major - P3
Reporter: Bruce Lucas (Inactive) Assignee: Keith Bostic (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File ex1.png     PNG File ex2.png     PNG File ex3.png     PNG File oplog-stalls.png     PNG File stalls.png     File update_repro.js     PNG File update_repro.png    
Issue Links:
Depends
is depended on by WT-1973 MongoDB changes for WiredTiger 2.7.0 Closed
Duplicate
Related
is related to SERVER-21652 Stalls during checkpoints Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

Multiple tests are seeing a cluster of apparently related symptoms:

  • During the last portion of a checkpoint cache usage grows to well above the configured maximum
  • Operations stall, probably as a result of cache exceeding maximum
  • The WiredTigerLAS.wt file grows without bound, and circumstantial evidence related to the use of the WT lookaside cache connects this with the previous two symptoms.
  • FTDC data capture stalls

Three examples from two different apps:



 Comments   
Comment by Bruce Lucas (Inactive) [ 24/Nov/15 ]

Spun off SERVER-21652.

Comment by Daniel Pasette (Inactive) [ 23/Nov/15 ]

Bruce, let's spin it off.

Comment by Bruce Lucas (Inactive) [ 23/Nov/15 ]

Running with the patch build with an insert-only repro of the issue, it appears that the unbounded growth of the LAS file and of the cache are no longer occurring, although we are still seeing significant stalls of zero throughput associated with checkpoints, up to 30s in this test.

I believe this is a regression relative to 3.0. Should we continue that on this ticket, or spin off a separate ticket?

Comment by Ramon Fernandez Marina [ 23/Nov/15 ]

Using update_repro.js and Keith's changes the WiredTigerLAS.wt file has grown to 28MB after 1h and it's holding steady, so I've merged these changes into the mongo tree.

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'name': u'Ramon Fernandez', u'email': u'ramon@mongodb.com'}

Message: Import wiredtiger-wiredtiger-mongodb-3.2.0-rc3-199-g4d72349.tar.gz from wiredtiger branch mongodb-3.2

ref: 4898aa4..4d72349

2cf57a6 SERVER-21585 Don't use the lookaside file until the cache is stuck full.
4ad8df7 SERVER-21585 Clean up LAS based on the current count of inserted records
Branch: master
https://github.com/mongodb/mongo/commit/e3cd63fcae3deb1140941a51c85564f098062a23

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'name': u'Ramon Fernandez', u'email': u'ramon@mongodb.com'}

Message: Import wiredtiger-wiredtiger-mongodb-3.2.0-rc3-199-g4d72349.tar.gz from wiredtiger branch mongodb-3.2

ref: 4898aa4..4d72349

2cf57a6 SERVER-21585 Don't use the lookaside file until the cache is stuck full.
4ad8df7 SERVER-21585 Clean up LAS based on the current count of inserted records
Branch: master
https://github.com/mongodb/mongo/commit/e3cd63fcae3deb1140941a51c85564f098062a23

Comment by Bruce Lucas (Inactive) [ 23/Nov/15 ]

Here's what I see when I run update_repro.js:

  • reproduces reduced throughput of the updates during the last part of a checkpoint, although it doesn't look quite as severe as we saw in the other tests
  • reproduces apparently unbounded LAS file growth
  • but does not repro the unbounded cache growth we saw in the other tests, nor the ftdc stalls

So I think we need to carefully test anything that fixes this repro against the other tests as well.

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'username': u'keithbostic', u'name': u'Keith Bostic', u'email': u'keith.bostic@mongodb.com'}

Message: Merge pull request #2328 from wiredtiger/las-only-when-stuck

SERVER-21585 Don't use the lookaside file until the cache is stuck full.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/2cf57a6fbfc220c704b5138bf3e71a439beedcaa

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexg@wiredtiger.com'}

Message: SERVER-21585 Don't use the lookaside file until the cache is stuck full.

Also only write into the lookaside file from internal (aka eviction)
threads, so application threads don't pay the performance cost.

It is possible that the cache stuck check is too restrictive, but using
only the eviction aggressive flag can result in writing a lot of content
to the lookaside file when pages can still be evicted.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/5eb3df72b825dbbd6f4dcacc519016aa6a45d026

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'username': u'keithbostic', u'name': u'Keith Bostic', u'email': u'keith.bostic@mongodb.com'}

Message: Merge pull request #2327 from wiredtiger/SERVER-21585-las-cleanup

SERVER-21585 Clean up LAS based on the current count of inserted records
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/4ad8df7281c6016e7d590e8bd74e63e550d5d200

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'username': u'keithbostic', u'name': u'Keith Bostic', u'email': u'keith.bostic@mongodb.com'}

Message: Merge pull request #2327 from wiredtiger/SERVER-21585-las-cleanup

SERVER-21585 Clean up LAS based on the current count of inserted records
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/4ad8df7281c6016e7d590e8bd74e63e550d5d200

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'username': u'keithbostic', u'name': u'Keith Bostic', u'email': u'keith@wiredtiger.com'}

Message: SERVER-21585: Don't search for the same key twice, we could get stuck at the
end of the LAS file, where every search ends up hitting the end of the table
and we could be stuck there for some time.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/7c7259af931990f1103e2514239f34119d3c8def

Comment by Githook User [ 23/Nov/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-21585 Clean up LAS based on the current count of inserted records.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/e064ff4d434cb4903941e0a7f47d700765e408a4

Comment by Daniel Pasette (Inactive) [ 23/Nov/15 ]

I adapted the script Max included to use an update workload to bound disk usage and I'm able to trigger LAS usage quickly.

run with mongo --nodb update_repro.js. If you want to adjust any of the mongod options, e.g. dbpath, edit the nodeOptions line as:
nodeOptions: {dbpath:'YOUR_PATH', nojournal: '', wiredTigerCacheSizeGB: 4}

Comment by Keith Bostic (Inactive) [ 21/Nov/15 ]

dan@10gen.com, max.hirschhorn, I've been trying to repro on an AWS c3.4xlarge instance since last night, using a variety of loads and oplog sizes, and I can't reproduce the LAS growth; I can get it to about 20MB, but that's all.

Comment by Bruce Lucas (Inactive) [ 21/Nov/15 ]

When I try running that repro on a similarly configured machine I'm not seeing the cache growth or LAS file growth.

I do see excessive oplog growth (SERVER-21553), erratic throughput, ftdc stalls, and extended checkpoint, until I ran out of disk space. Do you still have a diagnostic.data directory from a case where you reproduced the cache growth and LAS file growth for comparison to see if we can spot the difference, which may give a clue about the cause.

Comment by Daniel Pasette (Inactive) [ 20/Nov/15 ]

Not as cool as bruce's spark graphs , but shows some interesting correlation with truncate and LAS
Worth tracking down why WT perhaps thinks we should be holding onto some of the truncated data.

Comment by Max Hirschhorn [ 20/Nov/15 ]

I'm seeing that the WiredTigerLAS.wt file starts to grow immediately after MongoDB does several WT truncate operations on the oplog within the span of a single second. This matches when the "% dirty" statistic reported by mongostat starts to decrease.

mongod output

2015-11-20T18:05:42.890-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(0) and RecordId(6219373074245006205) to remove approximately 241497 records totaling to 268435805 bytes
2015-11-20T18:06:32.698-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373074245006205) and RecordId(6219373074245247699) to remove approximately 241494 records totaling to 268435620 bytes
2015-11-20T18:06:32.870-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373074245247699) and RecordId(6219373078540032662) to remove approximately 241494 records totaling to 268435655 bytes
2015-11-20T18:06:32.908-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373078540032662) and RecordId(6219373078540274117) to remove approximately 241494 records totaling to 268435542 bytes
2015-11-20T18:06:32.922-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373078540274117) and RecordId(6219373082835046002) to remove approximately 241494 records totaling to 268435576 bytes
2015-11-20T18:06:32.927-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373082835046002) and RecordId(6219373082835287496) to remove approximately 241494 records totaling to 268435465 bytes
2015-11-20T18:06:33.000-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373082835287496) and RecordId(6219373087130062962) to remove approximately 241494 records totaling to 268435682 bytes
2015-11-20T18:06:33.019-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373087130062962) and RecordId(6219373087130304476) to remove approximately 241495 records totaling to 268436398 bytes
2015-11-20T18:06:33.040-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373087130304476) and RecordId(6219373091425062552) to remove approximately 241494 records totaling to 268435747 bytes
2015-11-20T18:06:33.043-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373091425062552) and RecordId(6219373095719830397) to remove approximately 241495 records totaling to 268436573 bytes
2015-11-20T18:06:33.046-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373095719830397) and RecordId(6219373095720071932) to remove approximately 241494 records totaling to 268435572 bytes
2015-11-20T18:06:33.094-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373095720071932) and RecordId(6219373100014851992) to remove approximately 241494 records totaling to 268435504 bytes
2015-11-20T18:06:33.097-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373100014851992) and RecordId(6219373100015093535) to remove approximately 241494 records totaling to 268435705 bytes
2015-11-20T18:06:33.117-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373100015093535) and RecordId(6219373104309858087) to remove approximately 241495 records totaling to 268436504 bytes
2015-11-20T18:06:33.121-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373104309858087) and RecordId(6219373104310099581) to remove approximately 241494 records totaling to 268435678 bytes
2015-11-20T18:06:33.125-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373104310099581) and RecordId(6219373108604905792) to remove approximately 241494 records totaling to 268435509 bytes
2015-11-20T18:06:33.180-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373108604905792) and RecordId(6219373112899687939) to remove approximately 241495 records totaling to 268436514 bytes
2015-11-20T18:06:33.233-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373112899687939) and RecordId(6219373112899929340) to remove approximately 241494 records totaling to 268435651 bytes
2015-11-20T18:06:33.249-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373112899929340) and RecordId(6219373117194689262) to remove approximately 241494 records totaling to 268435521 bytes
2015-11-20T18:06:33.252-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373117194689262) and RecordId(6219373117194930756) to remove approximately 241494 records totaling to 268435619 bytes
2015-11-20T18:06:33.343-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373117194930756) and RecordId(6219373121489709640) to remove approximately 241494 records totaling to 268435511 bytes
2015-11-20T18:06:33.395-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373121489709640) and RecordId(6219373121489951134) to remove approximately 241494 records totaling to 268435558 bytes
2015-11-20T18:06:33.455-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373121489951134) and RecordId(6219373125784752910) to remove approximately 241494 records totaling to 268435664 bytes
2015-11-20T18:06:33.460-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373125784752910) and RecordId(6219373125784994405) to remove approximately 241495 records totaling to 268436571 bytes
2015-11-20T18:06:33.464-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373125784994405) and RecordId(6219373130079767567) to remove approximately 241494 records totaling to 268435627 bytes
2015-11-20T18:06:33.469-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373130079767567) and RecordId(6219373134374556789) to remove approximately 241494 records totaling to 268435602 bytes
2015-11-20T18:06:33.474-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373134374556789) and RecordId(6219373134374798459) to remove approximately 241495 records totaling to 268436553 bytes
2015-11-20T18:06:33.711-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373134374798459) and RecordId(6219373138669599824) to remove approximately 241494 records totaling to 268435637 bytes
2015-11-20T18:06:33.777-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373138669599824) and RecordId(6219373138669841344) to remove approximately 241494 records totaling to 268435525 bytes
2015-11-20T18:06:33.800-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373138669841344) and RecordId(6219373142964644491) to remove approximately 241494 records totaling to 268435552 bytes
2015-11-20T18:07:49.517-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373142964644491) and RecordId(6219373147259432921) to remove approximately 241495 records totaling to 268436558 bytes
2015-11-20T18:09:03.029-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373147259432921) and RecordId(6219373147259674415) to remove approximately 241494 records totaling to 268435521 bytes
2015-11-20T18:09:03.572-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373147259674415) and RecordId(6219373151554433967) to remove approximately 241494 records totaling to 268435740 bytes
2015-11-20T18:09:04.156-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373151554433967) and RecordId(6219373151554675619) to remove approximately 241494 records totaling to 268435572 bytes
2015-11-20T18:09:04.725-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373151554675619) and RecordId(6219373155849454905) to remove approximately 241494 records totaling to 268435578 bytes
2015-11-20T18:09:06.981-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373155849454905) and RecordId(6219373155849696619) to remove approximately 241494 records totaling to 268435517 bytes
2015-11-20T18:09:10.129-0500 D STORAGE  [WT RecordStoreThread: local.oplog.rs] Truncating the oplog between RecordId(6219373155849696619) and RecordId(6219373160144492125) to remove approximately 241494 records totaling to 268435578 bytes

WiredTigerLAS.wt size

Timestamp                  WiredTigerLAS.wt
Fri Nov 20 18:05:22        4.0K
Fri Nov 20 18:05:23        4.0K
Fri Nov 20 18:05:24        4.0K
Fri Nov 20 18:05:25        4.0K
Fri Nov 20 18:05:25        4.0K
Fri Nov 20 18:05:26        4.0K
Fri Nov 20 18:05:27        4.0K
Fri Nov 20 18:05:27        4.0K
Fri Nov 20 18:05:28        4.0K
Fri Nov 20 18:05:28        4.0K
Fri Nov 20 18:05:29        4.0K
Fri Nov 20 18:05:30        4.0K
Fri Nov 20 18:05:30        4.0K
Fri Nov 20 18:05:31        4.0K
Fri Nov 20 18:05:32        4.0K
Fri Nov 20 18:05:32        4.0K
Fri Nov 20 18:05:33        4.0K
Fri Nov 20 18:05:34        4.0K
Fri Nov 20 18:05:34        4.0K
Fri Nov 20 18:05:35        4.0K
Fri Nov 20 18:05:36        4.0K
Fri Nov 20 18:05:43        4.0K
Fri Nov 20 18:05:43        4.0K
Fri Nov 20 18:05:44        4.0K
Fri Nov 20 18:05:45        4.0K
Fri Nov 20 18:05:45        4.0K
Fri Nov 20 18:05:46        4.0K
Fri Nov 20 18:05:49        4.0K
Fri Nov 20 18:05:50        4.0K
Fri Nov 20 18:05:51        4.0K
Fri Nov 20 18:05:51        4.0K
Fri Nov 20 18:05:52        4.0K
Fri Nov 20 18:05:52        4.0K
Fri Nov 20 18:05:53        4.0K
Fri Nov 20 18:06:19        4.0K
Fri Nov 20 18:06:21        4.0K
Fri Nov 20 18:06:22        4.0K
Fri Nov 20 18:06:23        4.0K
Fri Nov 20 18:06:24        4.0K
Fri Nov 20 18:06:25        4.0K
Fri Nov 20 18:06:29        4.0K
Fri Nov 20 18:06:29        4.0K
Fri Nov 20 18:06:30        4.0K
Fri Nov 20 18:06:31        4.0K
Fri Nov 20 18:06:32        4.0K
Fri Nov 20 18:06:32        8.0K
Fri Nov 20 18:06:33        12K
Fri Nov 20 18:06:34        36K
Fri Nov 20 18:06:35        80K
Fri Nov 20 18:06:36        80K
Fri Nov 20 18:06:37        80K
Fri Nov 20 18:06:37        80K
Fri Nov 20 18:06:38        80K
Fri Nov 20 18:06:39        80K
Fri Nov 20 18:06:40        128K
Fri Nov 20 18:06:42        128K
Fri Nov 20 18:06:43        128K
Fri Nov 20 18:06:44        128K
Fri Nov 20 18:06:44        9.8M
Fri Nov 20 18:06:45        234M
Fri Nov 20 18:06:46        234M
Fri Nov 20 18:06:47        234M
Fri Nov 20 18:06:52        240M
Fri Nov 20 18:06:53        240M
Fri Nov 20 18:06:56        248M
Fri Nov 20 18:06:58        251M
Fri Nov 20 18:07:00        253M
Fri Nov 20 18:07:03        358M
Fri Nov 20 18:07:04        495M
Fri Nov 20 18:07:05        673M
Fri Nov 20 18:07:05        787M
Fri Nov 20 18:07:06        941M
Fri Nov 20 18:07:07        982M
Fri Nov 20 18:07:08        983M
Fri Nov 20 18:07:09        1.1G
Fri Nov 20 18:07:10        1.2G
Fri Nov 20 18:07:11        1.2G
Fri Nov 20 18:07:11        1.2G
Fri Nov 20 18:07:12        1.2G
Fri Nov 20 18:07:13        1.2G
Fri Nov 20 18:07:14        1.2G
Fri Nov 20 18:07:15        1.2G
Fri Nov 20 18:07:18        1.3G
Fri Nov 20 18:07:19        1.4G
Fri Nov 20 18:07:21        1.4G
Fri Nov 20 18:07:22        1.4G
Fri Nov 20 18:07:23        1.5G
Fri Nov 20 18:07:24        1.5G
Fri Nov 20 18:07:25        1.5G
Fri Nov 20 18:07:28        1.7G
Fri Nov 20 18:07:29        1.7G
Fri Nov 20 18:07:33        2.0G
Fri Nov 20 18:07:34        2.0G
Fri Nov 20 18:07:35        2.1G
Fri Nov 20 18:07:36        2.1G
Fri Nov 20 18:07:37        2.1G
Fri Nov 20 18:07:38        2.1G
Fri Nov 20 18:07:39        2.2G
Fri Nov 20 18:07:39        2.2G

mongostat output

insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn         set repl     time
159088    *0     *0     *0       0   160|0    93.7   96.0       0 17.9G 17.3G   0|1   0|5  161m    39k    7 server21553  PRI 18:06:24
123896    *0     *0     *0       0   125|0    93.3   95.9       0 17.9G 17.3G   0|1   0|5  126m    35k    7 server21553  PRI 18:06:25
232312    *0     *0     *0       0   239|0    95.0   95.7       0 17.9G 17.3G   0|1   0|5  240m    50k    7 server21553  PRI 18:06:26
170536    *0     *0     *0       0   171|0    94.8   95.9       0 17.9G 17.3G   0|1   0|5  172m    41k    7 server21553  PRI 18:06:27
178744    *0     *0     *0       0   185|0    95.0   95.4       0 17.9G 17.3G   0|1   0|5  183m    42k    7 server21553  PRI 18:06:28
 36552    *0     *0     *0       0    37|0    95.0   95.5       0 17.9G 17.3G   0|2   0|3   37m    23k    7 server21553  PRI 18:06:29
 21680    *0     *0     *0       0    24|0    95.0   95.8       0 17.9G 17.3G   0|1   1|5   23m    21k    7 server21553  PRI 18:06:30
    *0    *0     *0     *0       0     1|0    95.0   95.7       0 17.9G 17.3G   0|1   1|5   79b    18k    7 server21553  PRI 18:06:31
    *0    *0     *0     *0       0     1|0    95.0   95.7       0 17.9G 17.3G   0|1   1|5   79b    18k    7 server21553  PRI 18:06:32
 30360    *0     *0     *0       0    33|0    94.7   96.0       0 17.9G 17.4G   0|1   0|5   32m    23k    7 server21553  PRI 18:06:33
insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn         set repl     time
  3984    *0     *0     *0       0     3|0    93.4   96.0       0 17.9G 17.4G   0|0   0|5    2m    19k    7 server21553  PRI 18:06:34
  1656    *0     *0     *0       0     4|0    93.9   97.0       0 18.0G 17.5G   0|0   1|5    3m    19k    7 server21553  PRI 18:06:35
  1000    *0     *0     *0       0     3|0    93.2   95.8       0 18.0G 17.5G   0|0   0|5    1m    19k    7 server21553  PRI 18:06:36
    *0    *0     *0     *0       0     1|0    92.5   94.4       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:37
    64    *0     *0     *0       0     2|0    91.8   94.3       0 18.0G 17.5G   0|0   0|5  133b    18k    7 server21553  PRI 18:06:38
    *0    *0     *0     *0       0     1|0    91.1   94.3       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:39
   256    *0     *0     *0       0     1|0    90.7   94.5       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:40
    64    *0     *0     *0       0     1|0    90.1   94.5       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:41
    *0    *0     *0     *0       0     1|0    89.5   94.5       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:42
    *0    *0     *0     *0       0     2|0    88.9   94.5       0 18.0G 17.5G   0|0   0|5  133b    18k    7 server21553  PRI 18:06:43
insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn         set repl     time
   256    *0     *0     *0       0     1|0    88.3   94.5       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:44
    64    *0     *0     *0       0     1|0    86.2   93.1       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:45
    *0    *0     *0     *0       0     1|0    85.6   93.1       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:46
   256    *0     *0     *0       0     1|0    85.2   93.3       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:47
    64    *0     *0     *0       0     2|0    84.8   93.4       0 18.0G 17.5G   0|0   0|5  133b    18k    7 server21553  PRI 18:06:48
    *0    *0     *0     *0       0     1|0    84.2   93.4       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:49
    *0    *0     *0     *0       0     1|0    83.7   93.4       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:50
   256    *0     *0     *0       0     1|0    83.2   93.5       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:51
    64    *0     *0     *0       0     1|0    83.0   94.0       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:52
    *0    *0     *0     *0       0     2|0    82.4   93.9       0 18.0G 17.5G   0|0   0|5  133b    18k    7 server21553  PRI 18:06:53
insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn         set repl     time
   256    *0     *0     *0       0     1|0    81.7   93.9       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:54
    *0    *0     *0     *0       0     1|0    81.3   94.1       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:55
    64    *0     *0     *0       0     1|0    80.9   94.3       0 18.0G 17.5G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:56
    40    *0     *0     *0       0     2|0    80.3   94.3       0 18.0G 17.5G   0|0   0|5    1m    19k    7 server21553  PRI 18:06:57
   192    *0     *0     *0       0     2|0    80.3   94.9       0 18.1G 17.6G   0|0   0|5  133b    18k    7 server21553  PRI 18:06:58
    64    *0     *0     *0       0     1|0    80.0   95.1       0 18.1G 17.6G   0|0   0|5   79b    18k    7 server21553  PRI 18:06:59
    64    *0     *0     *0       0     1|0    79.3   95.1       0 18.1G 17.6G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:00
   128    *0     *0     *0       0     1|0    78.7   95.1       0 18.1G 17.6G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:01
   384    *0     *0     *0       0     1|0    79.8   96.8       0 18.4G 17.9G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:02
  2464    *0     *0     *0       0     6|0    78.9   96.5       0 18.6G 18.1G   0|1   0|4    4m    19k    7 server21553  PRI 18:07:03
insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn         set repl     time
  2728    *0     *0     *0       0     2|0    78.2   96.5       0 18.6G 18.1G   0|0   0|5    1m    19k    7 server21553  PRI 18:07:04
  1848    *0     *0     *0       0     4|0    76.8   95.6       0 18.6G 18.1G   0|0   0|5    3m    19k    7 server21553  PRI 18:07:05
    *0    *0     *0     *0       0     2|0    76.0   95.4       0 18.6G 18.1G   0|0   0|5  137b    19k    7 server21553  PRI 18:07:06
    40    *0     *0     *0       0     2|0    74.8   94.7       0 18.6G 18.1G   0|0   0|5    1m    19k    7 server21553  PRI 18:07:07
    *0    *0     *0     *0       0     2|0    74.3   94.7       0 18.6G 18.1G   0|0   0|5  133b    18k    7 server21553  PRI 18:07:08
   256    *0     *0     *0       0     1|0    72.9   93.9       0 18.6G 18.1G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:09
    *0    *0     *0     *0       0     1|0    71.6   93.2       0 18.6G 18.1G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:10
    64    *0     *0     *0       0     1|0    71.0   93.2       0 18.6G 18.1G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:11
   256    *0     *0     *0       0     1|0    70.3   93.2       0 18.6G 18.1G   0|0   0|5   79b    18k    7 server21553  PRI 18:07:12
    *0    *0     *0     *0       0     2|0    69.9   93.2       0 18.6G 18.1G   0|0   0|5  133b    18k    7 server21553  PRI 18:07:13

Comment by Max Hirschhorn [ 20/Nov/15 ]

I was able to reproduce this issue by running the following script. Note that it is the same as repro_server21553.js with a 50GB oplog instead of a 5GB oplog.

  • 12 cores, 24 CPUs, 32GB memory
  • 1-member replica set
  • oplog size 50 GB, default cache
  • data on SSD, running without a journal
  • 5 threads inserting 1KB random docs as fast as possible
  • recent nightly build
Steps to reproduce:

Run the following JavaScript in a mongo shell started with --nodb.
Copy the test to a file repro.js and execute using ./mongo --nodb repro.js

(function() {
    'use strict';
 
    Random.setRandomSeed();
 
    var replSetName = 'server21553';
    var rst = new ReplSetTest({
        name: replSetName,
        nodes: 1,
        oplogSize: 50 * 1024,
        nodeOptions: {nojournal: ''}
    });
 
    var nodes = rst.startSet();
    rst.initiate();
 
    nodes[0].setLogLevel(1, 'storage');
 
    var docs = [];
    for (var i = 0; i < 1000; i++) {
        var x = '';
        while (x.length < 1000) {
            x += Random.rand();
        }
        docs.push({x: x});
    }
    var ops = [{
        op: 'insert',
        ns: 'test.c',
        doc: docs,
        safe: true,
    }];
    var res = benchRun({
        host: nodes[0].host,
        ops: ops,
        seconds: 10000,
        parallel: 5
    });
    printjson(res);
 
    rst.stopSet();
})();


db version v3.2.0-rc3-88-gd2b49fe
git version: d2b49fe116b8d8012220fbbe0419fd2f57265054

Generated at Thu Feb 08 03:57:47 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.