[WT-2127] Occasional slow operations due to waiting for page - MongoDB

Details

Type: Bug
Status: Resolved
Priority: Major - P3
Resolution: Fixed
Affects Version/s: None
Fix Version/s: WT2.7.0
Labels:
None

Description

In a workload that spreads many updates in a random fashion across tables in different databases, I'm seeing occasional slow search operations from WiredTiger. The definition of slow here is more than a second.

What I'm seeing is that a thread that is co-opted into doing an eviction ends up waiting in __split_parent to add the newly split pages into the in-memory internal page.

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Download All

Attachments

t.c

Oct 22 2015 01:33:05 PM +00:00

2 kB

Keith Bostic

Issue Links

is depended on by

SERVER-20408 WiredTiger changes for MongoDB 3.1.9

Closed

Activity

Comments

Ascending order - Click to sort in descending order

Hide

Permalink

Alexander Gorrod added a comment - Sep 23 2015 07:18:40 AM +00:00

I added the following debug code:

--- a/src/btree/bt_split.c

+++ b/src/btree/bt_split.c

@@ -7,6 +7,7 @@

*/

 #include "wt_internal.h"

+#include <syscall.h>

 #define        WT_MEM_TRANSFER(from_decr, to_incr, len) do {                   \

        size_t __len = (len);                                           \

@@ -190,6 +191,11 @@ __split_should_deepen(WT_SESSION_IMPL *session, WT_REF *ref)

*/

        pindex = WT_INTL_INDEX_GET_SAFE(page);

+#if 0

+       if (pindex->entries > btree->split_deepen_min_child)

+               return (true);

+#endif

/*

         * Deepen the tree if the page's memory footprint is larger than the

         * maximum size for a page in memory (presumably putting eviction

@@ -857,6 +863,8 @@ __split_parent(WT_SESSION_IMPL *session, WT_REF *ref,

        uint32_t i, j;

        uint32_t deleted_entries, parent_entries, result_entries;

        int complete, hazard;

+       struct timespec end, start;

+       uint64_t saved_split_count, yield_attempts;

        parent = NULL;                  /* -Wconditional-uninitialized */

        alloc_index = pindex = NULL;

@@ -880,6 +888,9 @@ __split_parent(WT_SESSION_IMPL *session, WT_REF *ref,

         * reason to use a different lock if we have to block reconciliation

         * anyway.

*/

+       WT_RET(__wt_epoch(session, &start));

+       yield_attempts = 0;

+       saved_split_count = ref->home->split_count;

        for (;;) {

                parent = ref->home;

                F_CAS_ATOMIC(parent, WT_PAGE_RECONCILIATION, ret);

@@ -907,8 +918,22 @@ __split_parent(WT_SESSION_IMPL *session, WT_REF *ref,

*/

                if (S2BT(session)->checkpointing)

                        return (EBUSY);

+               ++yield_attempts;

                __wt_yield();

+       WT_TRET(__wt_epoch(session, &end));

+       if (WT_TIMEDIFF(end, start) > 1000 * WT_MILLION) {

+               fprintf(stdout, "%d:%d: %s:%d:"

+                   " WiredTiger split_parent page lock: duration: %lu us, parent entries %"PRIu32" yields: %" PRIu64

+                   ", start split count: %" PRIu64

+                   ", end split count: %" PRIu64

+                   " db: %s\n",

+                   (int) time(NULL), (int)syscall(SYS_gettid), __FILE__, __LINE__,

+                   WT_TIMEDIFF(end, start) / 1000,

+                   WT_INTL_INDEX_GET_SAFE(parent)->entries, yield_attempts,

+                   saved_split_count, parent->split_count, S2C(session)->home);

+       }

I run the workload for a while, and see messages like:

1442990251:1586: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1733123 us, parent entries 72648 yields: 420289, start split count: 9450, end split count: 9531 db: test1

1442990260:1588: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1241189 us, parent entries 74021 yields: 241051, start split count: 9942, end split count: 10002 db: test1

1442990261:1491: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1149624 us, parent entries 74191 yields: 224866, start split count: 10020, end split count: 10063 db: test1

1442990262:1589: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1146363 us, parent entries 74215 yields: 796563, start split count: 10038, end split count: 10070 db: test1

1442990265:1588: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1190670 us, parent entries 74635 yields: 582800, start split count: 10169, end split count: 10221 db: test1

1442990268:1491: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1292470 us, parent entries 75009 yields: 351951, start split count: 10314, end split count: 10360 db: test1

1442990275:1586: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1689342 us, parent entries 75947 yields: 539404, start split count: 10613, end split count: 10709 db: test1

1442991595:1573: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1227839 us, parent entries 25750 yields: 219975, start split count: 3822, end split count: 3879 db: test0

1442991596:1571: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1135503 us, parent entries 25779 yields: 223677, start split count: 3853, end split count: 3908 db: test0

Interesting things:

The page has an enormous number of entries - over 70,000
The thread is waiting for around 40 other __split_parent operations to complete before it gets a chance.
I'm suspicious that a single page often causes this problem. I often see a group of messages from the same database with steadily increasing parent entries counts, before I stop seeing the messages (presumably a deepen happens, or possibly the internal page is evicted).

I'd like to understand better why the parent is updated so many times before this thread gets a chance. Each database has 11 application threads operating concurrently. when I captured this in a debugger it appears as though there are only three threads evicting from the tree (one in checkpoint write leaves, two in __split_parent for the same page.

I plan to push a change that limits how wide we let in-memory internal pages grow. Since __split_parent is building an entire new page each time through having so many entries makes it a heavy weight operation.

Show

Alexander Gorrod added a comment - Sep 23 2015 07:18:40 AM +00:00 I added the following debug code: --- a/src/btree/bt_split.c +++ b/src/btree/bt_split.c @@ -7,6 +7,7 @@ */ #include "wt_internal.h" +#include <syscall.h> #define WT_MEM_TRANSFER(from_decr, to_incr, len) do { \ size_t __len = (len); \ @@ -190,6 +191,11 @@ __split_should_deepen(WT_SESSION_IMPL *session, WT_REF *ref) */ pindex = WT_INTL_INDEX_GET_SAFE(page); +#if 0 + if (pindex->entries > btree->split_deepen_min_child) + return (true); +#endif + /* * Deepen the tree if the page's memory footprint is larger than the * maximum size for a page in memory (presumably putting eviction @@ -857,6 +863,8 @@ __split_parent(WT_SESSION_IMPL *session, WT_REF *ref, uint32_t i, j; uint32_t deleted_entries, parent_entries, result_entries; int complete, hazard; + struct timespec end, start; + uint64_t saved_split_count, yield_attempts; parent = NULL; /* -Wconditional-uninitialized */ alloc_index = pindex = NULL; @@ -880,6 +888,9 @@ __split_parent(WT_SESSION_IMPL *session, WT_REF *ref, * reason to use a different lock if we have to block reconciliation * anyway. */ + WT_RET(__wt_epoch(session, &start)); + yield_attempts = 0; + saved_split_count = ref->home->split_count; for (;;) { parent = ref->home; F_CAS_ATOMIC(parent, WT_PAGE_RECONCILIATION, ret); @@ -907,8 +918,22 @@ __split_parent(WT_SESSION_IMPL *session, WT_REF *ref, */ if (S2BT(session)->checkpointing) return (EBUSY); + ++yield_attempts; __wt_yield(); } + WT_TRET(__wt_epoch(session, &end)); + if (WT_TIMEDIFF(end, start) > 1000 * WT_MILLION) { + fprintf(stdout, "%d:%d: %s:%d:" + " WiredTiger split_parent page lock: duration: %lu us, parent entries %"PRIu32" yields: %" PRIu64 + ", start split count: %" PRIu64 + ", end split count: %" PRIu64 + " db: %s\n", + (int) time(NULL), (int)syscall(SYS_gettid), __FILE__, __LINE__, + WT_TIMEDIFF(end, start) / 1000, + WT_INTL_INDEX_GET_SAFE(parent)->entries, yield_attempts, + saved_split_count, parent->split_count, S2C(session)->home); + } I run the workload for a while, and see messages like: 1442990251:1586: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1733123 us, parent entries 72648 yields: 420289, start split count: 9450, end split count: 9531 db: test1 1442990260:1588: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1241189 us, parent entries 74021 yields: 241051, start split count: 9942, end split count: 10002 db: test1 1442990261:1491: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1149624 us, parent entries 74191 yields: 224866, start split count: 10020, end split count: 10063 db: test1 1442990262:1589: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1146363 us, parent entries 74215 yields: 796563, start split count: 10038, end split count: 10070 db: test1 1442990265:1588: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1190670 us, parent entries 74635 yields: 582800, start split count: 10169, end split count: 10221 db: test1 1442990268:1491: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1292470 us, parent entries 75009 yields: 351951, start split count: 10314, end split count: 10360 db: test1 1442990275:1586: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1689342 us, parent entries 75947 yields: 539404, start split count: 10613, end split count: 10709 db: test1 1442991595:1573: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1227839 us, parent entries 25750 yields: 219975, start split count: 3822, end split count: 3879 db: test0 1442991596:1571: ../src/btree/bt_split.c:933: WiredTiger split_parent page lock: duration: 1135503 us, parent entries 25779 yields: 223677, start split count: 3853, end split count: 3908 db: test0 Interesting things: The page has an enormous number of entries - over 70,000 The thread is waiting for around 40 other __split_parent operations to complete before it gets a chance. I'm suspicious that a single page often causes this problem. I often see a group of messages from the same database with steadily increasing parent entries counts, before I stop seeing the messages (presumably a deepen happens, or possibly the internal page is evicted). I'd like to understand better why the parent is updated so many times before this thread gets a chance. Each database has 11 application threads operating concurrently. when I captured this in a debugger it appears as though there are only three threads evicting from the tree (one in checkpoint write leaves, two in __split_parent for the same page. I plan to push a change that limits how wide we let in-memory internal pages grow. Since __split_parent is building an entire new page each time through having so many entries makes it a heavy weight operation.

8 older comments

Hide

Permalink

Alexander Gorrod added a comment - Oct 30 2015 02:06:41 AM +00:00

when it passes WT_SPLIT_DEEPEN_MIN_CHILD_DEF entries, but maybe there's something else going on here

The old code would only split once the page had both exceeded the minimum child constraint and exceeded memory page max.

An append-only workload makes it hard to split evenly without rebalancing the tree; there's some magic in the split_deepen code to try and fight that off, but there's only so much you can do

Ack. I've attempted to understand that code without much luck. I'll need to dig deeper to see why it isn't working as I expect.

Show

Alexander Gorrod added a comment - Oct 30 2015 02:06:41 AM +00:00 when it passes WT_SPLIT_DEEPEN_MIN_CHILD_DEF entries, but maybe there's something else going on here The old code would only split once the page had both exceeded the minimum child constraint and exceeded memory page max. An append-only workload makes it hard to split evenly without rebalancing the tree; there's some magic in the split_deepen code to try and fight that off, but there's only so much you can do Ack. I've attempted to understand that code without much luck. I'll need to dig deeper to see why it isn't working as I expect.

Hide

Permalink

Alexander Gorrod added a comment - Oct 30 2015 03:46:24 AM +00:00

I was confused about the output, the 860,000 is the page size. The root page has around 75,000 entries when it splits. Which is still a lot, but an order of magnitude less concerning.

Show

Alexander Gorrod added a comment - Oct 30 2015 03:46:24 AM +00:00 I was confused about the output, the 860,000 is the page size. The root page has around 75,000 entries when it splits. Which is still a lot, but an order of magnitude less concerning.

Hide

Permalink

Githook User added a comment - Oct 30 2015 04:11:36 AM +00:00

Author:

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

Message: ~~WT-2127~~ Back out some of a change to split internal pages sooner.

We aren't doing an awesome job of balancing trees built via append
workloads, especially when splitting the root. Avoid splitting the
root until it grows large.

The work in ~~WT-2182~~ should help with our tree shape.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/915d7ee3ad2a9ef07828797ff426cbf3e4d71536

Show

Githook User added a comment - Oct 30 2015 04:11:36 AM +00:00 Author: {u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexg@wiredtiger.com'} Message: WT-2127 Back out some of a change to split internal pages sooner. We aren't doing an awesome job of balancing trees built via append workloads, especially when splitting the root. Avoid splitting the root until it grows large. The work in WT-2182 should help with our tree shape. Branch: develop https://github.com/wiredtiger/wiredtiger/commit/915d7ee3ad2a9ef07828797ff426cbf3e4d71536

Hide

Permalink

Githook User added a comment - Oct 30 2015 04:11:37 AM +00:00

Author:

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

Message: Merge pull request #2276 from wiredtiger/backout-split-sooner

~~WT-2127~~ Back out some of a change to split internal pages sooner.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/04da9bbc5b5db4dc2e16dfdf11281c6b1ccd26f1

Show

Githook User added a comment - Oct 30 2015 04:11:37 AM +00:00 Author: {u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'} Message: Merge pull request #2276 from wiredtiger/backout-split-sooner WT-2127 Back out some of a change to split internal pages sooner. Branch: develop https://github.com/wiredtiger/wiredtiger/commit/04da9bbc5b5db4dc2e16dfdf11281c6b1ccd26f1

Hide

Permalink

Michael Cahill added a comment - Nov 12 2015 11:57:48 PM +00:00

The original issue has been fixed, lots of followup work including ~~WT-2182~~.

Show

Michael Cahill added a comment - Nov 12 2015 11:57:48 PM +00:00 The original issue has been fixed, lots of followup work including WT-2182 .

People

Assignee:

Alexander Gorrod

Reporter:

Alexander Gorrod

Votes:

0 Vote for this issue

Watchers:

4 Start watching this issue

Dates

Created:

Sep 23 2015 07:08:41 AM +00:00

Updated:

Nov 12 2015 11:57:48 PM +00:00

Resolved:

Nov 12 2015 11:57:48 PM +00:00

Agile

View on Board