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

tcmalloc is locking mongo

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Waiting For User Input
    • Priority: Major - P3
    • Resolution: Unresolved
    • Affects Version/s: 3.4.16
    • Fix Version/s: None
    • Component/s: Performance, Stability
    • Labels:
      None
    • Operating System:
      ALL

      Description

      Hello,

      We're having some trouble on our current production servers with a lot logs lines like this one:

      2019-07-03T06:40:05.648+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 10, after locks: 10, after network: 10, after opLatencies: 10, after opcounters: 10, after opcountersRepl: 10, after repl: 10, after security: 10, after storageEngine: 10, after tcmalloc: 1645, after wiredTiger: 1655, at end: 1655 }
      2019-07-03T09:10:05.637+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 1633, after wiredTiger: 1633, at end: 1643 }
      2019-07-03T10:50:05.676+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 0, after wiredTiger: 0, at end: 1674 }
      2019-07-03T13:00:05.708+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 1704, after wiredTiger: 1704, at end: 1714 }
      2019-07-03T14:40:10.106+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 1098, after wiredTiger: 1098, at end: 1108 }
       
      2019-07-03T06:40:05.648+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 10, after locks: 10, after network: 10, after opLatencies: 10, after opcounters: 10, after opcountersRepl: 10, after repl: 10, after security: 10, after storageEngine: 10, after tcmalloc: 1645, after wiredTiger: 1655, at end: 1655 }
      2019-07-03T09:10:05.637+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 1633, after wiredTiger: 1633, at end: 1643 }
      2019-07-03T10:50:05.676+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 0, after wiredTiger: 0, at end: 1674 }
      2019-07-03T13:00:05.708+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 1704, after wiredTiger: 1704, at end: 1714 }
      2019-07-03T14:40:10.106+0200 I COMMAND  [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 1098, after wiredTiger: 1098, at end: 1108 }
      

      A lot of time seems to be spent in "tcmalloc" FWICS.

      We found a lot of tickets with the similar issue:
      SERVER-34027
      SERVER-31417
      SERVER-28712
      and this detailed Circle CI postmortem: https://discuss.circleci.com/t/postmortem-march-26-april-10-workflow-delay-incidents/30060

      After reading this we tried to have more details about the locks with the serverStatus command, before, during and after the lock:

      dimelo_shard:PRIMARY> print(new Date); db.serverStatus().tcmalloc // before
      Tue Jul 02 2019 14:40:02 GMT+0200 (CEST)
      {
      	"generic" : {
      		"current_allocated_bytes" : NumberLong("117552083592"),
      		"heap_size" : NumberLong("150148108288")
      	},
      	"tcmalloc" : {
      		"pageheap_free_bytes" : NumberLong("18349326336"),
      		"pageheap_unmapped_bytes" : NumberLong("11275706368"),
      		"max_total_thread_cache_bytes" : NumberLong(1073741824),
      		"current_total_thread_cache_bytes" : 130347296,
      		"total_free_bytes" : NumberLong("2970869232"),
      		"central_cache_free_bytes" : NumberLong("2840585832"),
      		"transfer_cache_free_bytes" : 58496,
      		"thread_cache_free_bytes" : 130259936,
      		"aggressive_memory_decommit" : 0,
      		"pageheap_committed_bytes" : NumberLong("138872401920"),
      		"pageheap_scavenge_count" : 189129607,
      		"pageheap_commit_count" : 295850012,
      		"pageheap_total_commit_bytes" : NumberLong("69973171851264"),
      		"pageheap_decommit_count" : 189129607,
      		"pageheap_total_decommit_bytes" : NumberLong("69834299449344"),
      		"pageheap_reserve_count" : 25899,
      		"pageheap_total_reserve_bytes" : NumberLong("150148108288"),
      		"spinlock_total_delay_ns" : NumberLong("185564381857153"),
      		"formattedString" : "------------------------------------------------\nMALLOC:   117585679288 (112138.4 MiB) Bytes in use by application\nMALLOC: +  18315825152 (17467.3 MiB) Bytes in page heap freelist\nMALLOC: +   2840582824 ( 2709.0 MiB) Bytes in central cache freelist\nMALLOC: +        58496 (    0.1 MiB) Bytes in transfer cache freelist\nMALLOC: +    130256160 (  124.2 MiB) Bytes in thread cache freelists\nMALLOC: +    638378240 (  608.8 MiB) Bytes in malloc metadata\nMALLOC:   ------------\nMALLOC: = 139510780160 (133047.8 MiB) Actual memory used (physical + swap)\nMALLOC: +  11275706368 (10753.4 MiB) Bytes released to OS (aka unmapped)\nMALLOC:   ------------\nMALLOC: = 150786486528 (143801.2 MiB) Virtual address space used\nMALLOC:\nMALLOC:        6546367              Spans in use\nMALLOC:           1903              Thread heaps in use\nMALLOC:           4096              Tcmalloc page size\n------------------------------------------------\nCall ReleaseFreeMemory() to release freelist memory to the OS (via madvise()).\nBytes released to the OS take up virtual address space but no physical memory.\n"
      	}
      }
      dimelo_shard:PRIMARY> print(new Date); db.serverStatus().tcmalloc //during
      Tue Jul 02 2019 14:40:03 GMT+0200 (CEST)
      {
      	"generic" : {
      		"current_allocated_bytes" : NumberLong("117626126808"),
      		"heap_size" : NumberLong("150148108288")
      	},
      	"tcmalloc" : {
      		"pageheap_free_bytes" : NumberLong("18269425664"),
      		"pageheap_unmapped_bytes" : NumberLong("11280478208"),
      		"max_total_thread_cache_bytes" : NumberLong(1073741824),
      		"current_total_thread_cache_bytes" : 131302496,
      		"total_free_bytes" : NumberLong("2967829528"),
      		"central_cache_free_bytes" : NumberLong("2836261848"),
      		"transfer_cache_free_bytes" : 193376,
      		"thread_cache_free_bytes" : 131495112,
      		"aggressive_memory_decommit" : 0,
      		"pageheap_committed_bytes" : NumberLong("138869190656"),
      		"pageheap_scavenge_count" : 189129663,
      		"pageheap_commit_count" : 295850032,
      		"pageheap_total_commit_bytes" : NumberLong("69973182099456"),
      		"pageheap_decommit_count" : 189129663,
      		"pageheap_total_decommit_bytes" : NumberLong("69834312380416"),
      		"pageheap_reserve_count" : 25899,
      		"pageheap_total_reserve_bytes" : NumberLong("150148108288"),
      		"spinlock_total_delay_ns" : NumberLong("185588157938035"),
      		"formattedString" : "------------------------------------------------\nMALLOC:   117631224992 (112181.9 MiB) Bytes in use by application\nMALLOC: +  18270486528 (17424.1 MiB) Bytes in page heap freelist\nMALLOC: +   2836202536 ( 2704.8 MiB) Bytes in central cache freelist\nMALLOC: +       187232 (    0.2 MiB) Bytes in transfer cache freelist\nMALLOC: +    131617752 (  125.5 MiB) Bytes in thread cache freelists\nMALLOC: +    638378240 (  608.8 MiB) Bytes in malloc metadata\nMALLOC:   ------------\nMALLOC: = 139508097280 (133045.3 MiB) Actual memory used (physical + swap)\nMALLOC: +  11278389248 (10755.9 MiB) Bytes released to OS (aka unmapped)\nMALLOC:   ------------\nMALLOC: = 150786486528 (143801.2 MiB) Virtual address space used\nMALLOC:\nMALLOC:        6548780              Spans in use\nMALLOC:           1909              Thread heaps in use\nMALLOC:           4096              Tcmalloc page size\n------------------------------------------------\nCall ReleaseFreeMemory() to release freelist memory to the OS (via madvise()).\nBytes released to the OS take up virtual address space but no physical memory.\n"
      	}
      }
      dimelo_shard:PRIMARY> print(new Date); db.serverStatus().tcmalloc // after
      Tue Jul 02 2019 14:40:08 GMT+0200 (CEST)
      {
      	"generic" : {
      		"current_allocated_bytes" : NumberLong("117641336656"),
      		"heap_size" : NumberLong("150148108288")
      	},
      	"tcmalloc" : {
      		"pageheap_free_bytes" : NumberLong("18237587456"),
      		"pageheap_unmapped_bytes" : NumberLong("11311992832"),
      		"max_total_thread_cache_bytes" : NumberLong(1073741824),
      		"current_total_thread_cache_bytes" : 132614088,
      		"total_free_bytes" : NumberLong("2957264528"),
      		"central_cache_free_bytes" : NumberLong("2824540336"),
      		"transfer_cache_free_bytes" : 109152,
      		"thread_cache_free_bytes" : 132612808,
      		"aggressive_memory_decommit" : 0,
      		"pageheap_committed_bytes" : NumberLong("138836115456"),
      		"pageheap_scavenge_count" : 189129809,
      		"pageheap_commit_count" : 295850054,
      		"pageheap_total_commit_bytes" : NumberLong("69973193326592"),
      		"pageheap_decommit_count" : 189129809,
      		"pageheap_total_decommit_bytes" : NumberLong("69834357211136"),
      		"pageheap_reserve_count" : 25899,
      		"pageheap_total_reserve_bytes" : NumberLong("150148108288"),
      		"spinlock_total_delay_ns" : NumberLong("185588613663259"),
      		"formattedString" : "------------------------------------------------\nMALLOC:   117641320648 (112191.5 MiB) Bytes in use by application\nMALLOC: +  18237534208 (17392.7 MiB) Bytes in page heap freelist\nMALLOC: +   2824532144 ( 2693.7 MiB) Bytes in central cache freelist\nMALLOC: +       109152 (    0.1 MiB) Bytes in transfer cache freelist\nMALLOC: +    132619304 (  126.5 MiB) Bytes in thread cache freelists\nMALLOC: +    638378240 (  608.8 MiB) Bytes in malloc metadata\nMALLOC:   ------------\nMALLOC: = 139474493696 (133013.2 MiB) Actual memory used (physical + swap)\nMALLOC: +  11311992832 (10788.0 MiB) Bytes released to OS (aka unmapped)\nMALLOC:   ------------\nMALLOC: = 150786486528 (143801.2 MiB) Virtual address space used\nMALLOC:\nMALLOC:        6545889              Spans in use\nMALLOC:           1951              Thread heaps in use\nMALLOC:           4096              Tcmalloc page size\n------------------------------------------------\nCall ReleaseFreeMemory() to release freelist memory to the OS (via madvise()).\nBytes released to the OS take up virtual address space but no physical memory.\n"
      	}
      }
      dimelo_shard:PRIMARY> (after.tcmalloc.spinlock_total_delay_ns - during.tcmalloc.spinlock_total_delay_ns) / (1000*1000*1000)
      0.455725224
      dimelo_shard:PRIMARY> (during.tcmalloc.spinlock_total_delay_ns - before.tcmalloc.spinlock_total_delay_ns) / (1000*1000*1000)
      23.776080882
      

      The last command is showing how much time (~24 seconds) clients have been locked between the before and the after command.

      MongoDB version: 3.4.16
      I've a diagnostic.data archive to help you debug this if you want.

        Attachments

        1. 10min.png
          10min.png
          129 kB
        2. 1510.png
          1510.png
          29 kB
        3. Screen Shot 2019-07-10 at 1.34.32 PM.png
          Screen Shot 2019-07-10 at 1.34.32 PM.png
          266 kB
        4. Screenshot from 2019-07-03 16-12-36.png
          Screenshot from 2019-07-03 16-12-36.png
          15 kB
        5. Screenshot from 2019-07-16 17-48-53.png
          Screenshot from 2019-07-16 17-48-53.png
          17 kB
        6. Screenshot from 2019-07-16 17-49-20.png
          Screenshot from 2019-07-16 17-49-20.png
          18 kB

          Activity

            People

            • Votes:
              2 Vote for this issue
              Watchers:
              13 Start watching this issue

              Dates

              • Created:
                Updated: