Info

Capped collection insert rate begins to decline steadily once it is full and deletions start. Restarting mongod (without disturbing the collection) restores inserts to the original rate, but insert rate then begins to decline to a fraction of the initial rate: 20486 mb, 72577 ins/s 20489 mb, 63780 ins/s 20494 mb, 61213 ins/s 20495 mb, 55644 ins/s 20491 mb, 50556 ins/s 20494 mb, 46906 ins/s 20493 mb, 39926 ins/s 20496 mb, 36380 ins/s 20496 mb, 34873 ins/s 20496 mb, 43359 ins/s 20492 mb, 36704 ins/s 20491 mb, 25022 ins/s 20493 mb, 26334 ins/s 20494 mb, 27420 ins/s 20496 mb, 26594 ins/s 20493 mb, 25970 ins/s 20496 mb, 27202 ins/s 20496 mb, 25868 ins/s 20492 mb, 26571 ins/s 20491 mb, 26460 ins/s 20496 mb, 26840 ins/s 20496 mb, 26273 ins/s 20491 mb, 25883 ins/s 20496 mb, 25342 ins/s 20491 mb, 25477 ins/s 20496 mb, 24753 ins/s 20496 mb, 24196 ins/s 20492 mb, 24092 ins/s 20491 mb, 23656 ins/s 20496 mb, 23656 ins/s 20495 mb, 23213 ins/s 20496 mb, 22776 ins/s 20496 mb, 23280 ins/s 20495 mb, 22710 ins/s 20496 mb, 22352 ins/s 20492 mb, 22554 ins/s Seems to be worse with larger documents and with larger collections: doc size cap initial final final/ rate rate initial 200 2GB 194 160 82% 1000 10GB 140 84 60% 1000 20GB 140 63 45% 2000 20GB 115 50 43% 4000 20GB 83 23 27% Stack trace excepts showing involvement of WT delete (complete stack traces attached as capped-delete.html):

Top User Comments

martin.bligh commented on Thu, 30 Jul 2015 11:49:36 +0000: Are you guys running with or w/o oplog? alexander.gorrod commented on Thu, 30 Jul 2015 02:22:30 +0000: bruce.lucas@10gen.com I've been running this workload and don't see as significant a drop off as you once capping starts happening. The drop off I see is around 30%. Having said that my throughput rate appears lower than yours from the start (around 17k ops/sec). The script I'm using to test the performance is based on the snippets you included above: item_size = 4000 function create() { db.c.drop() db.createCollection('c', {capped:true, size:20*1024*1024*1024}) } function insert() { x = '' for (var i=0; i<item_size; i++) x += 'x' last_time = Date.now(); every = 10000 for (var i=0; ; ) { var bulk = db.c.initializeUnorderedBulkOp(); for (var j=0; j<every; j++, i++) bulk.insert({x:x}); bulk.execute(); if (i % 100000 == 0) { size = (i * item_size) / (1024 * 1024 * 1024) this_time = Date.now(); elapsed_ms = this_time - last_time; ops_sec = 100000 / (elapsed_ms / 1000); print(i + " at time: " + elapsed_ms + " ms. ops/sec: " + ops_sec.toFixed(2) + " inserted: " + size.toFixed(2) + " GB") last_time = this_time; } } } create() insert() From looking at the profiling and the implementation of capped collection deletes, that's the sort of performance difference I expect to see. I agree that there is work we could do on improving the performance of capped collections, it feels as though that belongs in a different ticket to me. dan@10gen.com commented on Wed, 29 Jul 2015 14:18:57 +0000: Author: {u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexg@wiredtiger.com'} Message: SERVER-19522 Cleanup properly on error when reconciling internal pages. We were leaving the WT_PAGE_SPLIT_LOCKED flag set. Branch: develop https://github.com/wiredtiger/wiredtiger/commit/31058f483e0c34d9c141b83352481a18ae337eb8 xgen-internal-githook commented on Tue, 28 Jul 2015 23:51:20 +0000: Author: {u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexander.gorrod@mongodb.com'} Message: Merge pull request #2091 from wiredtiger/intl-page-empty SERVER-19522 Try to evict internal pages with no useful child pages. Branch: develop https://github.com/wiredtiger/wiredtiger/commit/fb8739f423a824b76e1a26cbaa28c1edaa2f2f7d xgen-internal-githook commented on Tue, 28 Jul 2015 23:51:19 +0000: Author: {u'username': u'keithbostic', u'name': u'Keith Bostic', u'email': u'keith@wiredtiger.com'} Message: WT-2024: acquire the WT_PAGE_SCANNING lock in all cases, __wt_update_serial doesn't acquire the page lock when scanning for obsolete updates. SERVER-19522: lift the WT_PAGE_SPLIT_LOCKED flag out of the __rec_row_int and __rec_col_int functions, lock at the top-level when acquiring the rest of our locks. Branch: develop https://github.com/wiredtiger/wiredtiger/commit/e2cdf33370da23e5198e89e27b7d64892c5831c8 xgen-internal-githook commented on Tue, 28 Jul 2015 23:51:16 +0000: Author: {u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'} Message: SERVER-19522 Try to evict internal pages with no useful child pages. Branch: develop https://github.com/wiredtiger/wiredtiger/commit/3f231c090c623107a93b44cd1975e7fbf17f5448 alexander.gorrod commented on Tue, 28 Jul 2015 07:40:57 +0000: bruce.lucas@10gen.com I have reproduced the problem on 3.0. After some debugging it appears as though the problem is that WiredTiger ends up with a lot of internal pages with only references to deleted pages at the start of a tree. Walking those pages during the capped delete is slow, which causes the significant slowdown you see. We are working on a fix. bruce.lucas@10gen.com commented on Fri, 24 Jul 2015 17:12:17 +0000: Verified after applying the patch for SERVER-19535 that this problem exists in 3.1.6 as well. michael.cahill commented on Thu, 23 Jul 2015 02:06:27 +0000: bruce.lucas@mongodb.com, there is an attempt to clean up internal pages as well as leaf pages but it is possible that code isn't working well for this workload. What the stacks suggest is that the cursor walk that figures out the next truncation point is spending a lot of time doing (pointless) eviction. That causes other threads to be throttled so that the oplog size is kept under control. All of that code is eliminated by martin.bligh's work on "oplogStones" in SERVER-18875 and https://mongodbcr.appspot.com/6570003/ – can you retest with that patch, or after those changes are merged, to see whether this workload performs as expected (and keeps the oplog size bounded)? bruce.lucas@10gen.com commented on Wed, 22 Jul 2015 15:57:57 +0000: Above stack traces and the numbers showing declining rate were obtained with 20 GB capped collection, 4 KB documents, 24 threads, on a machine with 12 cores / 24 cpus, 64 GB memory. Code: function create() { db.c.drop() db.createCollection('c', {capped:true, size:20*1024*1024*1024}) } function insert() { x = '' for (var i=0; i<4000; i++) x += 'x' every = 10000 for (var i=0; ; ) { var bulk = db.c.initializeUnorderedBulkOp(); for (var j=0; j<every; j++, i++) bulk.insert({x:x}); bulk.execute(); //print(i) } }

Steps to Reproduce