Uploaded image for project: 'Node.js Driver'
  1. Node.js Driver
  2. NODE-487

WiredTiger memory leak

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Critical - P2 Critical - P2
    • 2.0.34
    • Affects Version/s: None
    • Component/s: None
    • Labels:

      I am doing simple tests to evaluate if to migrate to MongoDb and i am facing with memory leak (i suppose).
      MongoDB using all memory then it's killing the process. VM i am using for test have 4 GBs of ram. Basically it's done on benchmark in which i am only doing 2 queries on two small collections which return small amount of same data all the time.
      I can reproduce this every time.

      If i am reading correctly serverStatus then it's not cache problem.

      With fresh started mongod instance have vsize 187 MB and res 45 MB.

      As you can see:

      It goes up to 2.5 GB of res and 2.5 GB of vsize in ~20 seconds. If i would continue the benchmark it would go up to full memory usage and kill the process.

      Collection sizes:

      "db" : "test",
      	"collections" : 6,
      	"objects" : 3177626,
      	"avgObjSize" : 85.97832753130797,
      	"dataSize" : 273206969,
      	"storageSize" : 107515904,
      	"numExtents" : 0,
      	"indexes" : 12,
      	"indexSize" : 47673344,
      	"ok" : 1
      

      Server status:

      > db.serverStatus()
      {
      	"host" : "debian",
      	"version" : "3.0.3",
      	"process" : "mongod",
      	"pid" : NumberLong(18930),
      	"uptime" : 289,
      	"uptimeMillis" : NumberLong(289083),
      	"uptimeEstimate" : 274,
      	"localTime" : ISODate("2015-06-15T19:38:59.340Z"),
      	"asserts" : {
      		"regular" : 0,
      		"warning" : 0,
      		"msg" : 0,
      		"user" : 0,
      		"rollovers" : 0
      	},
      	"connections" : {
      		"current" : 9,
      		"available" : 51191,
      		"totalCreated" : NumberLong(16)
      	},
      	"cursors" : {
      		"note" : "deprecated, use server status metrics",
      		"clientCursors_size" : 12000,
      		"totalOpen" : 12000,
      		"pinned" : 0,
      		"totalNoTimeout" : 0,
      		"timedOut" : 0
      	},
      	"extra_info" : {
      		"note" : "fields vary by platform",
      		"heap_usage_bytes" : -1810706720,
      		"page_faults" : 102
      	},
      	"globalLock" : {
      		"totalTime" : NumberLong(289059000),
      		"currentQueue" : {
      			"total" : 0,
      			"readers" : 0,
      			"writers" : 0
      		},
      		"activeClients" : {
      			"total" : 14,
      			"readers" : 0,
      			"writers" : 0
      		}
      	},
      	"locks" : {
      		"Global" : {
      			"acquireCount" : {
      				"r" : NumberLong(24519),
      				"w" : NumberLong(9),
      				"W" : NumberLong(4)
      			}
      		},
      		"Database" : {
      			"acquireCount" : {
      				"r" : NumberLong(24516),
      				"R" : NumberLong(3),
      				"W" : NumberLong(9)
      			}
      		},
      		"Collection" : {
      			"acquireCount" : {
      				"r" : NumberLong(24536)
      			}
      		}
      	},
      	"network" : {
      		"bytesIn" : 2819838,
      		"bytesOut" : 15011546,
      		"numRequests" : 24163
      	},
      	"opcounters" : {
      		"insert" : 0,
      		"query" : 24001,
      		"update" : 0,
      		"delete" : 0,
      		"getmore" : 0,
      		"command" : 164
      	},
      	"opcountersRepl" : {
      		"insert" : 0,
      		"query" : 0,
      		"update" : 0,
      		"delete" : 0,
      		"getmore" : 0,
      		"command" : 0
      	},
      	"storageEngine" : {
      		"name" : "wiredTiger"
      	},
      	"wiredTiger" : {
      		"uri" : "statistics:",
      		"LSM" : {
      			"sleep for LSM checkpoint throttle" : 0,
      			"sleep for LSM merge throttle" : 0,
      			"rows merged in an LSM tree" : 0,
      			"application work units currently queued" : 0,
      			"merge work units currently queued" : 0,
      			"tree queue hit maximum" : 0,
      			"switch work units currently queued" : 0,
      			"tree maintenance operations scheduled" : 0,
      			"tree maintenance operations discarded" : 0,
      			"tree maintenance operations executed" : 0
      		},
      		"async" : {
      			"number of allocation state races" : 0,
      			"number of operation slots viewed for allocation" : 0,
      			"current work queue length" : 0,
      			"number of flush calls" : 0,
      			"number of times operation allocation failed" : 0,
      			"maximum work queue length" : 0,
      			"number of times worker found no work" : 0,
      			"total allocations" : 0,
      			"total compact calls" : 0,
      			"total insert calls" : 0,
      			"total remove calls" : 0,
      			"total search calls" : 0,
      			"total update calls" : 0
      		},
      		"block-manager" : {
      			"mapped bytes read" : 0,
      			"bytes read" : 286720,
      			"bytes written" : 184320,
      			"mapped blocks read" : 0,
      			"blocks pre-loaded" : 455,
      			"blocks read" : 63,
      			"blocks written" : 27
      		},
      		"cache" : {
      			"tracked dirty bytes in the cache" : 0,
      			"tracked bytes belonging to internal pages in the cache" : 95081,
      			"bytes currently in the cache" : 212470,
      			"tracked bytes belonging to leaf pages in the cache" : 1073646743,
      			"maximum bytes configured" : 1073741824,
      			"tracked bytes belonging to overflow pages in the cache" : 0,
      			"bytes read into cache" : 85038,
      			"bytes written from cache" : 98014,
      			"pages evicted by application threads" : 0,
      			"checkpoint blocked page eviction" : 0,
      			"unmodified pages evicted" : 0,
      			"page split during eviction deepened the tree" : 0,
      			"modified pages evicted" : 0,
      			"pages selected for eviction unable to be evicted" : 0,
      			"pages evicted because they exceeded the in-memory maximum" : 0,
      			"pages evicted because they had chains of deleted items" : 0,
      			"failed eviction of pages that exceeded the in-memory maximum" : 0,
      			"hazard pointer blocked page eviction" : 0,
      			"internal pages evicted" : 0,
      			"maximum page size at eviction" : 0,
      			"eviction server candidate queue empty when topping up" : 0,
      			"eviction server candidate queue not empty when topping up" : 0,
      			"eviction server evicting pages" : 0,
      			"eviction server populating queue, but not evicting pages" : 0,
      			"eviction server unable to reach eviction goal" : 0,
      			"pages split during eviction" : 0,
      			"pages walked for eviction" : 0,
      			"eviction worker thread evicting pages" : 0,
      			"in-memory page splits" : 0,
      			"percentage overhead" : 8,
      			"tracked dirty pages in the cache" : 0,
      			"pages currently held in the cache" : 37,
      			"pages read into cache" : 37,
      			"pages written from cache" : 13
      		},
      		"connection" : {
      			"pthread mutex condition wait calls" : 6367,
      			"files currently open" : 26,
      			"memory allocations" : 743544,
      			"memory frees" : 76355,
      			"memory re-allocations" : 24471,
      			"total read I/Os" : 104,
      			"pthread mutex shared lock read-lock calls" : 138156,
      			"pthread mutex shared lock write-lock calls" : 317,
      			"total write I/Os" : 42
      		},
      		"cursor" : {
      			"cursor create calls" : 125941,
      			"cursor insert calls" : 13,
      			"cursor next calls" : 135,
      			"cursor prev calls" : 60041,
      			"cursor remove calls" : 0,
      			"cursor reset calls" : 72284,
      			"cursor search calls" : 108292,
      			"cursor search near calls" : 48007,
      			"cursor update calls" : 0
      		},
      		"data-handle" : {
      			"connection dhandles swept" : 0,
      			"connection candidate referenced" : 2,
      			"connection sweeps" : 44,
      			"connection time-of-death sets" : 15,
      			"session dhandles swept" : 2,
      			"session sweep attempts" : 12049
      		},
      		"log" : {
      			"log buffer size increases" : 0,
      			"total log buffer size" : 1048576,
      			"log bytes of payload data" : 2948,
      			"log bytes written" : 3968,
      			"yields waiting for previous log file close" : 0,
      			"total size of compressed records" : 2843,
      			"total in-memory size of compressed records" : 4470,
      			"log records too small to compress" : 5,
      			"log records not compressed" : 0,
      			"log records compressed" : 4,
      			"maximum log file size" : 104857600,
      			"pre-allocated log files prepared" : 1,
      			"number of pre-allocated log files to create" : 1,
      			"pre-allocated log files used" : 0,
      			"log read operations" : 0,
      			"log release advances write LSN" : 9,
      			"records processed by log scan" : 10,
      			"log scan records requiring two reads" : 0,
      			"log scan operations" : 5,
      			"consolidated slot closures" : 0,
      			"logging bytes consolidated" : 0,
      			"consolidated slot joins" : 0,
      			"consolidated slot join races" : 0,
      			"slots selected for switching that were unavailable" : 0,
      			"record size exceeded maximum" : 0,
      			"failed to find a slot large enough for record" : 0,
      			"consolidated slot join transitions" : 0,
      			"log sync operations" : 8,
      			"log sync_dir operations" : 1,
      			"log server thread advances write LSN" : 0,
      			"log write operations" : 9
      		},
      		"reconciliation" : {
      			"page reconciliation calls" : 13,
      			"page reconciliation calls for eviction" : 0,
      			"split bytes currently awaiting free" : 0,
      			"split objects currently awaiting free" : 0
      		},
      		"session" : {
      			"open cursor count" : 53902,
      			"open session count" : 12047
      		},
      		"thread-yield" : {
      			"page acquire busy blocked" : 0,
      			"page acquire eviction blocked" : 0,
      			"page acquire locked blocked" : 0,
      			"page acquire read blocked" : 0,
      			"page acquire time sleeping (usecs)" : 0
      		},
      		"transaction" : {
      			"transaction begins" : 24129,
      			"transaction checkpoints" : 5,
      			"transaction checkpoint generation" : 5,
      			"transaction checkpoint currently running" : 0,
      			"transaction checkpoint max time (msecs)" : 26,
      			"transaction checkpoint min time (msecs)" : 0,
      			"transaction checkpoint most recent time (msecs)" : 0,
      			"transaction checkpoint total time (msecs)" : 47,
      			"transactions committed" : 3,
      			"transaction failures due to cache overflow" : 0,
      			"transaction range of IDs currently pinned by a checkpoint" : 0,
      			"transaction range of IDs currently pinned" : 1,
      			"transactions rolled back" : 24128
      		},
      		"concurrentTransactions" : {
      			"write" : {
      				"out" : 0,
      				"available" : 128,
      				"totalTickets" : 128
      			},
      			"read" : {
      				"out" : 1,
      				"available" : 127,
      				"totalTickets" : 128
      			}
      		}
      	},
      	"writeBacksQueued" : false,
      	"mem" : {
      		"bits" : 64,
      		"resident" : 2390,
      		"virtual" : 2538,
      		"supported" : true,
      		"mapped" : 0
      	},
      	"metrics" : {
      		"commands" : {
      			"dbStats" : {
      				"failed" : NumberLong(0),
      				"total" : NumberLong(1)
      			},
      			"getnonce" : {
      				"failed" : NumberLong(0),
      				"total" : NumberLong(3)
      			},
      			"isMaster" : {
      				"failed" : NumberLong(0),
      				"total" : NumberLong(15)
      			},
      			"ping" : {
      				"failed" : NumberLong(0),
      				"total" : NumberLong(27)
      			},
      			"serverStatus" : {
      				"failed" : NumberLong(0),
      				"total" : NumberLong(118)
      			}
      		},
      		"cursor" : {
      			"timedOut" : NumberLong(0),
      			"open" : {
      				"noTimeout" : NumberLong(0),
      				"pinned" : NumberLong(0),
      				"total" : NumberLong(12000)
      			}
      		},
      		"document" : {
      			"deleted" : NumberLong(0),
      			"inserted" : NumberLong(0),
      			"returned" : NumberLong(36000),
      			"updated" : NumberLong(0)
      		},
      		"getLastError" : {
      			"wtime" : {
      				"num" : 0,
      				"totalMillis" : 0
      			},
      			"wtimeouts" : NumberLong(0)
      		},
      		"operation" : {
      			"fastmod" : NumberLong(0),
      			"idhack" : NumberLong(0),
      			"scanAndOrder" : NumberLong(0),
      			"writeConflicts" : NumberLong(0)
      		},
      		"queryExecutor" : {
      			"scanned" : NumberLong(36000),
      			"scannedObjects" : NumberLong(36000)
      		},
      		"record" : {
      			"moves" : NumberLong(0)
      		},
      		"repl" : {
      			"apply" : {
      				"batches" : {
      					"num" : 0,
      					"totalMillis" : 0
      				},
      				"ops" : NumberLong(0)
      			},
      			"buffer" : {
      				"count" : NumberLong(0),
      				"maxSizeBytes" : 268435456,
      				"sizeBytes" : NumberLong(0)
      			},
      			"network" : {
      				"bytes" : NumberLong(0),
      				"getmores" : {
      					"num" : 0,
      					"totalMillis" : 0
      				},
      				"ops" : NumberLong(0),
      				"readersCreated" : NumberLong(0)
      			},
      			"preload" : {
      				"docs" : {
      					"num" : 0,
      					"totalMillis" : 0
      				},
      				"indexes" : {
      					"num" : 0,
      					"totalMillis" : 0
      				}
      			}
      		},
      		"storage" : {
      			"freelist" : {
      				"search" : {
      					"bucketExhausted" : NumberLong(0),
      					"requests" : NumberLong(0),
      					"scanned" : NumberLong(0)
      				}
      			}
      		},
      		"ttl" : {
      			"deletedDocuments" : NumberLong(0),
      			"passes" : NumberLong(4)
      		}
      	},
      	"ok" : 1
      }
      
      

            Assignee:
            christkv Christian Amor Kvalheim
            Reporter:
            cronos Gal Waleczny
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved: