[SERVER-18788] wiredtiger 10x slower than mmap replica instance Created: 02/Jun/15  Updated: 15/Jun/15  Resolved: 15/Jun/15

Status: Closed
Project: Core Server
Component/s: Performance
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: navin kumar Assignee: Sam Kleinman (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:
  • mongodb 3.0.3
  • 4x 244GiB servers on Amazon's cloud (r3.8xlarge running Ubuntu 14.04.1 LTS)
  • 2 shards, s01 and s02
    db.shards.find() { "_id" : "s01", "host" : "s01/s01r01.mongo.shopcade.com:27018,s01r02.mongo.shopcade.com:27018", "tags" : [ "main" ] } { "_id" : "s02", "host" : "s02/s02r01.mongo.shopcade.com:27018,s02r02.mongo.shopcade.com:27018", "tags" : [ "products" ] }
  • s01r01 and s02r01 are MMAP
  • s01r02 and s02r02 are wiredTiger.
    The MMAP instances are primaries.

Attachments: PNG File Screenshot 2015-06-04 10.33.37.png     PNG File Screenshot 2015-06-04 10.38.20.png     Zip Archive mongo-engine-comparisons.zip     Text File mongod.log    
Issue Links:
Related
related to SERVER-17364 Idle cursors shouldn't hold storage e... Closed
Operating System: Linux
Participants:

 Description   

When we switch primaries to be the wiredTiger instances, while there
is almost no additional stress on the machines, the time taken for
queries goes out of whack.

For our homepage, https://www.shopcade.com/, to load for a logged in
user (me), about 200 mongo queries execute in 200 ms. Please find
attached a screen capture (homepage-mongo-debug.png) from our in-house
web-request level profiling tool.
When we switch our primaries to the wiredTiger instances, the time on
average for each query goes up by a factor of 10/20 times. There
aren't a few queries that are slow, but all of them, compared to MMAP.
The total load time for the page goes from 1-2 seconds into 10s of
seconds.

I've got only marginal improvements changing to the following configuration
wiredTiger:
collectionConfig:
blockCompressor: "none"
engineConfig:
cacheSizeGB: 180
journalCompressor: "none"
indexConfig:
prefixCompression: false



 Comments   
Comment by Sam Kleinman (Inactive) [ 15/Jun/15 ]

Glad to hear that you resolved this issue!

Cheers,
sam

Comment by navin kumar [ 15/Jun/15 ]

Problem solved!
I have now tested for a few days. All queries now have acceptable times. Thank you very much for your help, Sam, Asya, Keith.

Notes:

  • The single biggest problem was the large number of immortal cursors
  • enabled block compression and prefix compression, with no drop in performance
  • eliminated/optimised most scanning queries - they were mostly from our backend cron jobs, (oddly, MMAP seemed to have acceptable times on large scans)

Best,
Navin

Comment by navin kumar [ 09/Jun/15 ]

Sam, Asya,
Thank you very much for your feedback.

I'm working on your inputs, and have varying results at this point. Will get back to you with performance data. Fingers crossed!

Comment by Sam Kleinman (Inactive) [ 04/Jun/15 ]

Reviewing your logs, it looks like the MMAP is subject to similar kinds of slow queries: inefficient use of an index or collection scans, etc. as on WiredTiger. This is expected, and while this isn't the issue you're experiencing, I'm confident that you'll see improved and more consistent performance if you modify your indexes or queries. This is outside of the scope of this ticket, but the following documentation may help:

Second, the data size you provided looks like is from the output of db.stats(), I just want to confirm that you've included a sum of all databases on this replica set. The main difference that I can see between these deployments is that the MMAP instance effectively has the whole machine's ram to use for in-memory cache, if the entire data set fits in RAM, as it looks like it does from these numbers. At the same time the WiredTiger instance is limited to 180 GB, and so there's more churn on the cache, which could explain the performance effects you're seeing. You could restart the wiredTiger instance with a larger cache (i.e. 230-240 GB) and see if that resolves the issue.

If it turns out that this is a cache size issue; in the future, with better index utilization you may be able to reduce the cache size alloted to MongoDB.

Third, it looks like your instance has a large number of open cursors, which can impact performance. From the serverStatus output that you include, it looks like your application opened about 10,000 curors with the noTimeout option at the top of the hour, and about 10,000 other cursors are timing out every hour. If you can modify your application to not open cursors with the noTimeout option, you may see improved performance. Shortening timeouts or closing cursors when the application is done with them may also help.

As you test this, if you end up with a wiredTiger primary and MMAP secondaries, I might encourage you to increase the write concern: wiredTiger can typically handle a higher volume of writes than MMAP, and you should make sure that the secondaries can replicate operations fast enough.

In general, we would expect a database server running wiredTiger to use more CPU resources (particularly with compression) than one running MMAP: as a result the differences in system load reporting may not indicate an issue.

To summarize, I think we may be able to explain the performance effect you're seeing, may be attributable to the following factors:

  • cache size,
  • inefficient queries and table scans.
  • number of open cursors.

I hope this helps. At this point I'm not inclined to think that there is a specific bug with MongoDB+WT. Please let us know if you still see a performance degradation with wiredTiger after modifying your application and deployment.

Regards,
sam

Comment by Asya Kamsky [ 04/Jun/15 ]

vain

I happened to notice that you seem to have a large number of cursors that don't get closed - there seem to be quite a few that time out after being idle for the timeout period, and it looks like you have a large number of "noTimeout" cursors accumulating after a while. Can you explain how you are using cursors in the application code?

Asya

Comment by navin kumar [ 03/Jun/15 ]

Sam,
Thanks for your reply.

1. Do these queries and count operations also have similar characteristics with an MMAP primary? Could you upload a similar segment of the log from a primary that uses MMAP?

no, on MMAP, there are hardly any slow queries. more details below

2. Would it be possible to paste the output of db.getIndexes(); in this ticket?

I've added it in the attached zip file

3. Did you observe this effect when compression was enabled? Why inspired you to change this setting?

No, turning off compression was something I was testing - not sure it had any impact

4. For your write operations, what level of write concern do you specify?

1 - Acknowledged

5. How much RAM does the system have? How much data is stored in MongoDB?

each of our mongo servers have 244GiB of RAM. For shard s01:
on the wiredTiger instance:
> "dataSize" : 100168049112,
> "storageSize" : 106178719744,
> "indexSize" : 48765927424,
on the MMAP instance:
> "dataSize" : 163739003696,
> "storageSize" : 230548450400,
> "indexSize" : 87954497344,

This morning, to generate more data, I switched the primary again to be wiredTiger. It took about half an hour for performance to drop for the same queries. I've attached details from this time below. Do have a look inside the mongo-query-times-compared directory. I am sorry to upload such large images, but I feel they best illustrate the problem.

Hope this helps, and thank you very much.

-----------------------
files in mongo-engine-comparisons.zip

    • db-indexes.txt
    • db-serverStatus-polled-every-minute
    • mmap.log
    • wiredTiger.log
    • system-load-average-both-machines.png

the following are query times for a page load:

    • mongo-query-times-compared/0911-UTC-homepage-mmap.png
    • mongo-query-times-compared/0922-UTC-homepage-wiredTiger-on-switchover.png
    • mongo-query-times-compared/0934-UTC-homepage-wiredTiger-2.png
    • mongo-query-times-compared/1006-UTC-homepage-wiredTiger-8.png
    • mongo-query-times-compared/1008-UTC-homepage-wiredTiger-9.png
    • mongo-query-times-compared/1012-UTC-homepage-back-to-mmap.png

more like the above, can ignore

    • mongo-query-times-compared/more-page-query-times/0943-UTC-homepage-wiredTiger-3.png
    • mongo-query-times-compared/more-page-query-times/0951-UTC-homepage-wiredTiger-4.png
    • mongo-query-times-compared/more-page-query-times/0955-UTC-homepage-wiredTiger-5.png
    • mongo-query-times-compared/more-page-query-times/0959-UTC-homepage-wiredTiger-6.png
    • mongo-query-times-compared/more-page-query-times/1003-UTC-homepage-wiredTiger-7.png
Comment by navin kumar [ 02/Jun/15 ]

After turning off prefix compression, re-syncing data from scratch, and making wiredTiger primary, there was only about an hour of fast performance. That was at the time of my tweet. However query times quickly deteriorated after that. So I doubt prefix compression is the issue. I jumped the gun with that tweet, apologies.

Comment by Keith Bostic (Inactive) [ 02/Jun/15 ]

Navin, your original tweet made me think prefix compression was an issue, was that based on measurements with/without index prefix compression configured? Or did that not have much of an effect?

Comment by Sam Kleinman (Inactive) [ 02/Jun/15 ]

From looking over the logs I see a number of factors that might contribute to degraded performance. I'm not sure if these can, alone, explain the performance impact that you see, but it would be good to remove potential factors as we troubleshoot.

First, I see some queries that are not able to use an index effectively, (e.g. high absolute nscannedObjects values, high ratios of nscannedObjects to nscanned, and scanAndOrder operations which do in-memory sorts.) For example:

2015-05-29T15:58:25.689+0000 I QUERY    [conn17848] query shopcade.lists query: { $query: { pc: { $gte: 6 } }, $orderby: { lpa: -1 } } planSummary: IXSCAN { pc: 1.0, lpa: -1.0 }, IXSCAN { pc: 1.0, lpa: -1.0 } cursorid:322462517267 ntoreturn:5 ntoskip:0 nscanned:26912 nscannedObjects:26912 scanAndOrder:1 keyUpdates:0 writeConflicts:0 numYields:210 nreturned:5 reslen:895 locks:{ Global: { acquireCount: { r: 211 } }, Database: { acquireCount: { r: 211 } }, Collection: { acquireCount: { r: 211 } } } 339ms
 
2015-05-29T15:59:40.650+0000 I QUERY    [conn17935] query shopcade.brands query: { $query: { nb_prods.GB: { $gte: 3 }, _id: { $regex: "^C", $options: "i" } }, $orderby: { pop: -1 } } planSummary: IXSCAN { nb_prods.GB: 1.0, pop: -1.0 } cursorid:133281854156 ntoreturn:0 ntoskip:0 nscanned:21900 nscannedObjects:21900 scanAndOrder:1 keyUpdates:0 writeConflicts:0 numYields:171 nreturned:101 reslen:11939 locks:{ Global: { acquireCount: { r: 172 } }, Database: { acquireCount: { r: 172 } }, Collection: { acquireCount: { r: 172 } } } 109ms
 
2015-05-29T16:08:46.118+0000 I QUERY    [conn17911] query shopcade.brands query: { $query: { nb_prods.US: { $gte: 3 }, _id: { $regex: "^O", $options: "i" } }, $orderby: { pop: -1 } } planSummary: IXSCAN { nb_prods.US: 1.0, pop: -1.0 } cursorid:135280524753 ntoreturn:0 ntoskip:0 nscanned:34148 nscannedObjects:34148 scanAndOrder:1 keyUpdates:0 writeConflicts:0 numYields:267 nreturned:101 reslen:9683 locks:{ Global: { acquireCount: { r: 268 } }, Database: { acquireCount: { r: 268 } }, Collection: { acquireCount: { r: 268 } } } 138ms

Second there a large number of count operations that must inspect a many number of documents, and are hitting yields:

2015-05-29T16:00:39.492+0000 I COMMAND  [conn17838] command shopcade.$cmd command: count { count: "followers", query: { following: ObjectId('524497ff458719e82cd7d5e0'), type: "user" } } planSummary: IXSCAN { following: 1.0, _id: -1.0 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:491 reslen:104 locks:{ Global: { acquireCount: { r: 492 } }, Database: { acquireCount: { r: 492 } }, Collection: { acquireCount: { r: 492 } } } 121ms
 
2015-05-29T17:15:17.175+0000 I COMMAND  [conn17753] command shopcade.$cmd command: count { count: "activity_collector", query: { _id: { $gte: ObjectId('5565e33b0000000000000000') }, a: ObjectId('51a4dde8458719bc3a0002ad'), ac: { $in: [ 60 ] } } } planSummary: IXSCAN { a: 1.0, _id: -1.0 } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:104 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 206419 } }, Collection: { acquireCount: { r: 1 } } } 206ms

  1. Do these queries and count operations also have similar characteristics with an MMAP primary? Could you upload a similar segment of the log from a primary that uses MMAP?
  2. Would it be possible to paste the output of db.getIndexes(); in this ticket?
  3. Did you observe this effect when compression was enabled? Why inspired you to change this setting?
  4. For your write operations, what level of write concern do you specify?
  5. How much RAM does the system have? How much data is stored in MongoDB?

Thanks for your patience, and I hope we can get to the bottom of this quickly.

Cheers,
sam

Comment by navin kumar [ 02/Jun/15 ]

before switching to the configuration, i had all values at their defaults.

I've attached the mongo log for when wiredTiger was primary

Comment by Ramon Fernandez Marina [ 02/Jun/15 ]

vain, since this issue pertains to the MongoDB server we've moved the ticket to the SERVER project.

Do you have logs from the WiredTiger primary when serving those slow queries? What configuration where you using before switching to the one above?

Thanks,
Ramón.

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