[SERVER-24824] Mongo 3.0.12 with MMAPv1 can't serve more than 1k qps Created: 28/Jun/16  Updated: 17/Aug/16  Resolved: 17/Aug/16

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

Type: Bug Priority: Major - P3
Reporter: Abhishek Amberkar Assignee: Kelsey Schubert
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File host_info2.txt     Text File host_info3.txt     Text File iostat2.log     Text File iostat3.log     Text File mongo44.log     PNG File mongo_resident_mem.png     PNG File network_activity.png     PNG File ops_per_second.png     PNG File pagefaults_per_sec.png     Text File ss2.log     Text File ss3.log    
Issue Links:
Duplicate
duplicates SERVER-23798 Increased ns file IO in 3.0 Closed
Related
related to SERVER-24514 Global IX Lock for more than 4 minute... Closed
Operating System: ALL
Participants:

 Description   

Hello All,

The setup
I am running a replica set in production without sharding. All nodes are running latest stable mongo 2.6 except one hidden node which has mongo 3.0 with MMAPv1.

The data
I have around 4TB worth of data on each node (MMAPv1), with close to 7000 databases.

The plan
I decided to upgrade to 3.2 and as an intermediate step, I have to upgrade to 3.0 first. Initially I had used wiredTiger with this node, but encountered a problem when I sent prod traffic to that node. Here's the full description on the JIRA issue - SERVER-24514. For not being blocked on the issue, I decided to go ahead with 3.0.12 with MMAPv1 instead of wiredTiger. So to start with that, I added the aforementioned hidden member to the existing replica set. I started sending prod like read query traffic to this node to check if it will be able to withstand that much load. I did this for over a week.

The plan was to roll out 3.0 on all secondaries if latencies and rps are close to prod like pattern.

The observation
It was observed that the node couldn't entertain the read traffic at a consistent rate. It can be seen that the node entertains ~1k queries per seconds, shoots to ~3.5k qps for a very brief moment of time and drops back to ~1k qps. (Please check Operations Per Second graph). This particular pattern is not observed when same traffic is sent to 2.6.x nodes. Those nodes can entertain same traffic at ~4k qps consistently.
In the process of understanding what exactly is happening, I ran db.currentOp() on that node. I didn't find anything in particular. But some queries took ~200ms to return. For those queries "timeAcquiringMicros" is ~198ms. According to the docs it is the "cumulative time in microseconds that the operation had to wait to acquire the locks". I would appreciate any help here.



 Comments   
Comment by Abhishek Amberkar [ 17/Aug/16 ]

Thank you Thomas.

Comment by Kelsey Schubert [ 17/Aug/16 ]

Hi abhishek.amberkar,

Thank you for uploading the server status and iostat logs.

After reviewing the data you provided, I have identified that the issue you are encountering is tracked in SERVER-23798. In MongoDB 3.0, a change was introduced that changed how ns files are loaded into memory. Please watch SERVER-23798 for updates regarding this behavior.

Thanks again for your help,
Thomas

Comment by Abhishek Amberkar [ 29/Jul/16 ]

Hello Thomas,

Here's a thread on mongodb-dev mailing list my colleague had opened few days ago.

https://groups.google.com/d/msg/mongodb-dev/k1fYIgDd-ck/2Mv6hZK_BAAJ

Please let me know if you find anything from the logs and information provided which is relevant to my issue.

Thank you.

Comment by Abhishek Amberkar [ 25/Jul/16 ]

Hello Thomas,

I have attached all the files as requested. I have removed "locks" and "recordStatus" info from "2.6" logs, since ss2.log was running in GBs. Let me know if you need to have a look at that output as well.

Also please check the description of the ticket where I have mentioned how I am running this whole setup. Let me know if you need any more information.

Comment by Kelsey Schubert [ 21/Jul/16 ]

Hi abhishek.amberkar,

Thanks for uploading the logs - we're continuing to investigate this issue. To help us, would you please provide the following information?

  1. Please run the following script on the 3.0.12 node for an hour

    delay=1
    mongo --eval "while(true) {print(JSON.stringify(db.serverStatus())); sleep(1000*$delay)}" >ss3.log &
    iostat -k -t -x $delay >iostat3.log &
    

  2. Similarly, please run the following script on the 2.6.x node for an hour

    delay=1
    mongo --eval "while(true) {print(JSON.stringify(db.serverStatus())); sleep(1000*$delay)}" >ss2.log &
    iostat -k -t -x $delay >iostat2.log &
    

  3. Please upload ss2.log, iostat2.log, ss3.log, and iostat3.log.

Additionally, please provide the output of the following commands:

db.adminCommand({buildInfo: true})
db.adminCommand({hostInfo: true})

Finally, if you could provide additional details about your workload, or could provide a workload that reproduces this issue, it would greatly speed our investigation.

Thank you for your help,
Thomas

Comment by Abhishek Amberkar [ 21/Jul/16 ]

Hello Ramón,

Can I get any help here?

I tried throwing more memory to this node and it started performing as expected. I wonder why 3.0.12 needs more memory than 2.6.x while serving the same amount of traffic. Could you please shed some light on this behaviour?

Thank you.

Comment by Abhishek Amberkar [ 28/Jun/16 ]

Hello Ramón,

I have attached the log as well as the memory graph. Hardware specs are same as 2.6 secondaries.

Comment by Ramon Fernandez Marina [ 28/Jun/16 ]

abhishek.amberkar, can you please upload the logs for this 3.0.12 node during the time you're conducting your measurements? Also, what are the hardware specs for this node? Are they the same as for your 2.6 secondaries?

Thanks,
Ramón.

Generated at Thu Feb 08 04:07:31 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.