Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-24775

Degraded performance in 3.2.7 (probably after 3.2.5) - GlobalLock?

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical - P2
    • Resolution: Incomplete
    • Affects Version/s: 3.2.5, 3.2.6, 3.2.7
    • Fix Version/s: None
    • Component/s: Performance
    • Labels:
    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      Upgrade MongoDB to 3.2.7 from 3.2.4. I have not tested in versions 3.2.5 and 3.2.6 but if SERVER-22964 is the cause probably 3.2.5 and 3.2.6 have same problem.

      Show
      Upgrade MongoDB to 3.2.7 from 3.2.4. I have not tested in versions 3.2.5 and 3.2.6 but if SERVER-22964 is the cause probably 3.2.5 and 3.2.6 have same problem.

      Description

      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).

        Attachments

        1. 3.2.4100uptime.png
          3.2.4100uptime.png
          41 kB
        2. diagnostic.7z
          69.95 MB
        3. mongologs.7z
          23.90 MB
        4. s24775.png
          s24775.png
          47 kB
        5. updatetry.png
          updatetry.png
          79 kB

          Activity

            People

            Assignee:
            kelsey.schubert Kelsey T Schubert
            Reporter:
            lucasoares Lucas
            Participants:
            Votes:
            8 Vote for this issue
            Watchers:
            27 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: