-
Type:
Bug
-
Resolution: Incomplete
-
Priority:
Critical - P2
-
None
-
Affects Version/s: 3.2.5, 3.2.6, 3.2.7
-
Component/s: Performance
-
ALL
-
Hello.
I have a software (a realtime analytics) that uses MongoDB with heavy reading/writing (millions per day). This software needs to make aggregations/counts/finds based on several filters (we've around 10-40 indexes in each collection) and we have many distributed machines inserting and updating data.
The application has several collections (about 700), with up to 8 millions documents, but most of the collections have less than 10 thousand documents. The amount of collections grows depending on the application use, but it is rarely created more than 5 collections in a day.
This application doesn't have any collection drop (only very few exceptions).
My present architecture in ReplicaSet - that have only MongoDB running:
1 Primary (Dedicated): OS: Ubuntu 14.04.4 LTS RAM: 128GB DDR4 ECC 2133 CPU: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz 12 cores DISK: 2x480 GB SSD - 960GB software RAID 0 (ext4) MongoDB version: v3.2.4 with WiredTiger Network: 1Gbps 1 Secondary (Dedicated): OS: Ubuntu 14.04.4 LTS RAM: 128GB DDR4 ECC 2133 CPU: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz 12 cores DISK: 2x480 GB SSD - 960GB software RAID 0 (ext4) MongoDB version: v3.2.4 with WiredTiger Network: 1Gbps 1 Arbiter (Virtual) OS: Ubuntu 14.04.3 LTS MongoDB version: v3.2.0 WiredTiger + nojournal
I have been using MongoDB in this application for a long time and I've never had the problem I will say here.
Recently we realized that our database was growing and the two disks at RAID 0 wouldn't support for a long time. My infrastructure team started to see other machines so that we could migrate our database at our last horizontal scale, so we would be able to plan and start our shard process.
The problem: all machines we tested showed a VERY degraded performance. With little runtime (maximum 5 hours) ALL operations began to take a very long time to run (operations that once run on 110m, was taking 20000+ms) and this made our application unusable.
I would firstly like to clarify that strict hardware tests (disk, CPU, RAM, etc) were done in all machines by my infrastructure team and they had no errors.
Here are the machines we've tested and their results:
Machine 1: OS: Ubuntu 14.04.4 LTS RAM: 128GB DDR4 ECC 2133 CPU: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz 12 cores DISK: 4x800 GB SSD - 3200GB hardware RAID 0 (ext4) MongoDB version: v3.2.7 with WiredTiger Network: 1Gbps
Result: degraded performance. We think that the cause could be 4 disks with RAID 0 (MongoDB production notes sugests RAID 10). Then we tested the second machine:
Machine 2:
OS: Ubuntu 14.04.4 LTS
RAM: 256GB DDR3 2Rx4
CPU: 2x 2GHz Intel Xeon-SandyBridge (E5-2620-HexCore)
DISK: 6x1.2 TB GB SSD - 3.3T hardware RAID 10 (ext4)
MongoDB version: v3.2.7 with WiredTiger
Network: 1Gbps
Machine 3:
OS: Ubuntu 14.04.4 LTS
RAM: 512GB RAM DDR3
CPU: 4x Xeon E7-4850 (10 cores 2GHz)
Disk: 6x1.2 TB SSD - 3.3T hardware RAID 10 (ext4)
MongoDB version: v3.2.7 with WiredTiger
Network: 1GBps
Same result. Here we started to think that the cause could be the RAID type (hardware) or the high number of disks used. We even believed that our application needed more RAM/CPU (then we test the third machine), but it wasn't.
After that, we tested the fourth machine (although not with SSD):
Machine 4: OS: Ubuntu 14.04.4 LTS RAM: 256 GB DDR4 ECC 2133 CPU: 2x Intel Xeon E5-2660v3 20c/40t 2.6/3.3 GHz DISK: 2x4 TB SAS - 8 TB software RAID 0 (ext4) MongoDB version: v3.2.7 with WiredTiger Network: 1Gbps
This one degraded even faster (by being SAS disks) and didn't work as expected too.
Now we tried a fifth machine!! This machine have the same configuration as our current one (present architecture), differing only by disks size and by the hardware RAID. Result: degraded performance. This one we let running for 17 hours and 19 minutes and created a 313MB logfile (many requests above 100ms).
At this point we became confused about what could be. We tried lots of different machines and all had the same result. We conclude two things: MongoDB can't run in hardware RAID and our application demand more IO that one SAS can provide (which was expected but was nice to test).
I was verifying MongoDB logs and I noted all operations were taking a long time to execute.
For example, one grep in a single command (one of the fastest in my current architecture) in the fifth machine with degraded performance:
2016-06-19T18:14:51.401-0500 I COMMAND [conn1430] query shipyard.current_universes query: { account_id: 5704147139559424, universe_id: 5942933362573312 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5090 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6339285 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 14257ms
Collection stats:
{
"ns" : "shipyard.current_universes",
"count" : 515,
"size" : 1323315,
"avgObjSize" : 2569,
"storageSize" : 1486848,
"capped" : false,
"nindexes" : 4,
"totalIndexSize" : 188416,
"ok" : 1
}
It is quite obvious this type of request shouldn't take so long in this collection.
This timeAcquiringMicros in global lock was unbelievable. After checking the MongoDB release notes and in revision 3.2.5 has changes in Global Lock system (SERVER-22964) and I think this is the cause.
Now, a grep from a part of the log that can show the increase over time (just few seconds!!) of the response time. I focused in this request because it is fast but this happens in the entire log and operations (I will upload it here):
2016-06-19T18:14:25.230-0500 I COMMAND [conn1551] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 177ms
2016-06-19T18:14:25.230-0500 I COMMAND [conn1547] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 175ms
2016-06-19T18:14:25.231-0500 I COMMAND [conn1535] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6403331475898368 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:670 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 174ms
2016-06-19T18:14:25.472-0500 I COMMAND [conn1577] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6403331475898368 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:670 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 714ms
2016-06-19T18:14:29.148-0500 I COMMAND [conn1431] query shipyard.current_universes query: { account_id: 5704147139559424, universe_id: 5942933362573312 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5090 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 211664 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 3046ms
2016-06-19T18:14:29.148-0500 I COMMAND [conn1533] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 382ms
2016-06-19T18:14:29.148-0500 I COMMAND [conn1427] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2985ms
2016-06-19T18:14:29.148-0500 I COMMAND [conn1528] query shipyard.current_universes query: { account_id: 5389779860455424, universe_id: 6100803039264768 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:2481 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2984ms
2016-06-19T18:14:29.149-0500 I COMMAND [conn1428] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2984ms
2016-06-19T18:14:29.149-0500 I COMMAND [conn1429] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2984ms
2016-06-19T18:14:29.149-0500 I COMMAND [conn1577] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6688873937633280 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:653 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2308ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1432] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2328ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1430] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2310ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1536] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2308ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1426] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2311ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1576] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2986ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1529] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2310ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1516] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6403331475898368 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:670 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2986ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1534] query shipyard.current_universes query: { account_id: 4734030863925248, universe_id: 4965384511815680 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5715 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2637ms
2016-06-19T18:14:29.153-0500 I COMMAND [conn1433] query shipyard.current_universes query: { account_id: 6652771465953280, universe_id: 6024704036962304 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:3124 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 1378ms
2016-06-19T18:14:32.214-0500 I COMMAND [conn1529] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 609ms
2016-06-19T18:14:32.215-0500 I COMMAND [conn1543] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 464ms
2016-06-19T18:14:32.215-0500 I COMMAND [conn1577] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6688873937633280 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:653 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 563ms
2016-06-19T18:14:32.215-0500 I COMMAND [conn1516] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 563ms
2016-06-19T18:14:32.215-0500 I COMMAND [conn1537] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 577ms
2016-06-19T18:14:32.215-0500 I COMMAND [conn1426] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 609ms
2016-06-19T18:14:32.216-0500 I COMMAND [conn1434] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6403331475898368 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:670 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 606ms
2016-06-19T18:14:34.233-0500 I COMMAND [conn1534] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 1953ms
2016-06-19T18:14:34.233-0500 I COMMAND [conn1516] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 1948ms
2016-06-19T18:14:34.618-0500 I COMMAND [conn1543] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6403331475898368 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:670 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2310ms
2016-06-19T18:14:35.388-0500 I COMMAND [conn1551] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 1902ms
2016-06-19T18:14:35.389-0500 I COMMAND [conn1576] query shipyard.current_universes query: { account_id: 6652771465953280, universe_id: 6024704036962304 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:3124 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2673ms
2016-06-19T18:14:35.488-0500 I COMMAND [conn1433] query shipyard.current_universes query: { account_id: 5704147139559424, universe_id: 5942933362573312 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5090 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 2764ms
2016-06-19T18:14:39.588-0500 I COMMAND [conn1426] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 4899ms
2016-06-19T18:14:39.588-0500 I COMMAND [conn1554] query shipyard.current_universes query: { account_id: 5766858980458496, universe_id: 5519831352737792 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:736 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 5301ms
2016-06-19T18:14:39.588-0500 I COMMAND [conn1535] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 4899ms
2016-06-19T18:14:39.590-0500 I COMMAND [conn1428] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 4908ms
2016-06-19T18:14:51.401-0500 I COMMAND [conn1430] query shipyard.current_universes query: { account_id: 5704147139559424, universe_id: 5942933362573312 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5090 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6339285 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 14257ms
2016-06-19T18:14:51.401-0500 I COMMAND [conn1551] query shipyard.current_universes query: { account_id: 5704147139559424, universe_id: 5942933362573312 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5090 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6337315 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15440ms
2016-06-19T18:14:51.401-0500 I COMMAND [conn1516] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6403331475898368 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:670 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 6337664 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15849ms
2016-06-19T18:14:51.401-0500 I COMMAND [conn1576] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6340964 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15970ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1531] query shipyard.current_universes query: { account_id: 5389779860455424, universe_id: 6100803039264768 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:2481 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6340091 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15181ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1433] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 6340505 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15846ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1432] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 6341490 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15950ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1573] query shipyard.current_universes query: { account_id: 6566762430595072, universe_id: 6688873937633280 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:653 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 6340672 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15950ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1537] query shipyard.current_universes query: { account_id: 5888892137897984, universe_id: 6728455165050880 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:916 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 6339975 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15949ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1534] query shipyard.current_universes query: { account_id: 5704147139559424, universe_id: 5942933362573312 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:5090 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6340494 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15580ms
2016-06-19T18:14:51.402-0500 I COMMAND [conn1527] query shipyard.current_universes query: { account_id: 5345363120619520, universe_id: 6278419935395840 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:1931 locks:{ Global: { acquireCount: { r: 4 }, acquireWaitCount: { r: 1}, timeAcquiringMicros: { r: 6336434 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 15950ms
What did I do after that? I used the fifth machine and I went back to MongoDB 3.2.4. There it is!! Problem solved. MongoDB perfectly works in Hardware RAID. And probably all machines tested before (with the exception of the SAS) would work with the performance we were used to.
We try to keep the most recent revision of our release (MongoDB production notes/checklist sugestions) and I hadn't thought that it could have such a sudden drop in performance after updating a REVISION (not a entire version) of MongoDB.
I'm sure that the problem wasn't with my indexes or with my documents, since the fifth machine is working perfectly fine with MongoDB 3.2.4 and it has always worked in my current architecture.
Just to prove. Here is the longest request of the same type showed in previous logs after downgrading to MongoDB 3.2.4 at the fifth machine (3 days running so far and 67MB of logfile, as primary node):
2016-06-23T22:47:37.752-0500 I COMMAND [conn599] query shipyard.current_universes query: { account_id: 5335678606901248, universe_id: 5368858286227456 } planSummary: IXSCAN { universe_id: 1, account_id: 1 } ntoskip:0 keysExamined:1 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:638 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 116ms
I know we process some slow aggregations (rarely 200 secs), but not in the same level that was at the machine 5 with MongoDB 3.2.7.
I don't want to get stuck in MongoDB 3.2.4 and I want, at least, an explanation about what is happening in MongoDB 3.2 revision 5+ that almost DESTROYED my entire application because this happened in my production set at the first few times.
Lastly, I would like to apply myself to be a tester of new versions of MongoDB (mostly versions of ReplicaSet in high performance systems).
