[SERVER-19233] Performance regression for wiredTiger from build 91c9eaeae7 Created: 30/Jun/15 Updated: 14/Apr/16 Resolved: 09/Jul/15 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | WiredTiger |
| Affects Version/s: | None |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Chung-yen Chang | Assignee: | Geert Bosch |
| Resolution: | Duplicate | Votes: | 0 |
| Labels: | 32qa, mpreg | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||
| Issue Links: |
|
||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||
| Operating System: | ALL | ||||||||||||
| Steps To Reproduce: | Run the following command in the shell and the "insert" numbers reported are the ones to look. Change the value for parallel for different number of connections, and the value of seconds to adjust the run time. benchRun( { ops: [{op: "insert", ns: "test.repro19233", doc: {_id: {"#OID":1}}, writeCmd : true } ], parallel: 32, seconds: 20 } ) |
||||||||||||
| Sprint: | Quint Iteration 6 | ||||||||||||
| Participants: | |||||||||||||
| Description |
|
A performance regression was observed for some of the mongo-perf insert and updates micro-benchmarks since git hash: 91c9eaeae7. Insert.justID throughput dropped from 64,463 to 42,290. Need to investigate and fix. |
| Comments |
| Comment by Martin Bligh [ 06/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Noted David's results that seems to show that it's all fine until we drop a table then roll the epoch, at which point we seem to stop using the cache and create new cursors (and presumably sessions) all the time. Seems to be some problem with the counters, which I was planning on killing anyway. David confirmed this fixes it. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 06/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Attached full timeseries data. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 06/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I did a few experiments this morning, collecting server status information, and doing some profiling. The load actually goes up slightly in the bad configuration. Here's some interesting parts from the server status information, as run through the timeseries tool: Time period A-B are the good test period, and C-E are the bad test period. I dropped the collection in the period B-C. Notice also period D-E. I was not expecting to see that when I ran the test. While profiling the data, I see the following in the bad case, but not in the good case:
I found that code in the wiredTiger code base, but don't know anything more there. I did a couple more experiments also:
The issue reproduced in both cases. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 03/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Not silly at all daveh86 I downloaded the mongod and mongos from evergreen.
I was going to try some profiling, etc on it and see what was different on the first case compared to the second. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Hows [ 03/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Might be a silly question, but david.daly can you give a bit more background as to what OS, Hardware, GCC version, GLIBC version, etc. If OS particulars are a factor the more we know the better. I've tested locally on my Arch box (GCC 5.1 and Glibc 2.21) w/ 4 cores + 4 HT, 16GB RAM and SSD storage and was unable to reproduce the delay. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
chung-yen.chang | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Chung-yen Chang [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
david.daly, if you do a drop collection right after opening up the shell, does the first benchRun invocation also reports the regression? I wonder if we might be seeing some of the works done by collection drop in the regressed case but not the other. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The following reproduces reliably on my linux box: Git hash 91c9eaeae7dbe3ff5e5e5b369871562beda908a8 from evergreen:
Git hash 38f937036b5033bd50a9fd740e897415bd9f21db from evergreen:
I'm still trying to understand better what's going on. If I don't drop the collection in between tests, the performance doesn't drop on that bad case. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
This reproduces on my linux box, but I failed to reproduce it on a RHEL spawnhost. Trying to figure out where the difference is here. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
It would be interesting to know if the regression reproduces on a machine | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hmmm ... didn't actually try it yesterday, we just looking at the scalability. I can't repro either .... 24 CPU box. nojournal 32 threads. 354866 before, 351293 after. david.daly pointed out that he fixed a typo in the reproduce script at the top yesterday, so if you had it cached somewhere (like I did ...) you need to refresh. (location of write_cmd arg). Still doesn't repro for me though | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Martin, No oplog or journal. I'd expect my machine to be slower than yours. The I was surprised that I didn't see the difference between the old and new Alex | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Alex, are you running with or without journal and oplog? Seems to make a huge difference in the numbers - I think both off will stress it the most. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Alexander Gorrod [ 02/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I attempted to reproduce this on a local c3.4xlarge machine today, and couldn't. I'm seeing:
I see very similar performance numbers when running a local build against master. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Daly [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Updated repro to fix typo | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Geert is removing the shutdownLock, but I did that by hand (just deleted it) and it doesn't fix the perf. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Geert Bosch [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I'll wipe out the shared_mutex here and condense all sessions out / shutdown state in a single atomic variable. That should take care of this. If the atomic variable is still a bottleneck we could partition it, but I doubt we'll need that. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Oops, somehow grabbed the wrong binary - rerun numbers edited above. sorry. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Geert Bosch [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
recordGlobalTime was deleted on may 29th | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Some quick numbers (just desktop single node) threads: inserts 1:24437 | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Martin Bligh [ 01/Jul/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
geert.bosch also had a patch outstanding for this. We might want to see if that fixes the issue | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Michael Cahill (Inactive) [ 30/Jun/15 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
daveh86, can you please reproduce this slowdown (just the 8 thread case should be sufficient). Then profile with perf and/or pmp to check what is causing the slowdown. If it is mutex contention, let's talk about how to address that without going back to caching N times more sessions than are needed. |