Repository navigation
memory leak starting with node v11.0.0-nightly20180908922a1b03b6 #28420
Description
Activity
Thanks for the report!
nothing stood out to me other than the v8 changes.
I agree, looking at e917a23...922a1b0 that seems like the only reasonable source of issues – and V8 updates are big changes, so this is likely the culprit.
Here is output from valgrind for an 11 hour run. This is the first time I've used valgrind so I don't have much to compare it with, but nothing stands out to me - there's nothing that looks like it could account for the memory growth shown in the second graph.
I agree 👍 That valgrind shows nothing of interest makes it less likely that this is a memory leak in C++, so that’s already helpful.
What can I do next to help isolate this?
The fact that this is unlikely to be a C++ memory leak makes it more likely that this is one in JS; valgrind doesn’t track memory allocated using
mmap()& co. by default, which is what V8 uses for the JS heap.First, if possible, it would be good to verify that this is the case.
process.memoryUsage(),require('v8').getHeapStatistics()andrequire('v8').getHeapSpaceStatistics()all provide potentially useful information about the memory region in which the leak occurs.Secondly, if possible, taking heap dumps at different points in time and comparing then in Chrome DevTools should help a lot with figuring out what objects are being retained and why, if this is a JS memory leak. For taking heap dumps you can use e.g. https://www.npmjs.com/package/heapdump, or, if that’s more convenient, directly attach DevTools to the process.
Given that this is likely a V8 bug, you may want to run the process with
--expose-gcand manually performglobal.gc()calls from time to time – you obviously shouldn’t do this in production, and it’s unlikely to be helpful, but if it is, then we know it’s likely an issue with V8 detecting when to run GC, and not a real memory leak, which would also be helpful.Finally, it would also be good to know if a more recent version of Node.js (e.g. current nightlies) has the same issue. V8 issues are often caught and later addressed, and it may be the case that the solution is to figure out which V8 commit fixed this issue and then backport that to the relevant Node.js versions.
The APM product comprises JavaScript, a C/C++ library, and C++ code that uses the node-addon-api.
If this does turn out to be an issue with one of the C++ parts (e.g. by seeing an increase in RSS but not the heap as reported by
process.memoryUsage()), it can still be useful to take heap dumps and compare them; I would expect that most resources allocated by addons are either tied to JS objects or would be reported by valgrind.I hope this helps!
Reacted by Rich Trott, drash-course, Nikolay Matvienko, Kyle Smith, UZHS and kevin-friedheimit would also be good to know if a more recent version of Node.js (e.g. current nightlies) has the same issue.
v13.0.0-nightly20190625e2d445be8fstill exhibits the problem. I am in the process of adding the additional metrics you suggested (v8 heap statistics and process.memoryUsage beyond RSS) and will run again with that information available.Here are the graphs using
v13.0.0-nightly20190625e2d445be8f(the righthand chart isprocess.memoryUsage().rssbut that's the only property the current app reports).
I am proceeding with the additional memory metrics and the heapdump approach as well as checking whether deliberately invoking gc helps.
graphs for
process.memoryUsage()andv8.getHeapStatistic()- I haven't includedv8.getHeapSpaceStatistics()due to the array not being compatible with the metrics reporting API I'm using. If that additional information is important I can dump them to a CSV file and graph.These runs were executed with garbage collection being called once every minute.
left chart top-to-bottom (leaves out heap_size_limit and total_available_size):
total_heap_size/total_physical_size (appear as one line on top)
used_heap_size (orange)
peak_malloced_memory
total_heap_size_executable
malloced_memory
number_of_native_contextsright chart top-to-bottom:
rss
heap
heapUsed
external@bmacnaughton It’s not fully obvious from the graphs, but I’d said that this does look like a JS memory leak because the heap size and the RSS curves in the right graph do about the same thing?
@addaleax - when you say a JS memory leak you mean v8, right? If yes, it seems that way to me. I'm adding heapdump code to the todo server now; I'll probably dump every 10 minutes or so.
I'm going to let this run a while longer before starting the version that will call heapdump every 10 minutes. I'd like to get a little longer view. I will also turn off the forced garbage collection for the next run to have a comparison to this run.
btw, the v8 heap total_available_size is slowly going down. see attached chart. I put these two values in a separate chart because their scale was very different. the top line (which is flat but is a bit of an optical illusion) is the heap_size_limit. the bottom line is the total_available_size.
OK, here's charts at the end of the previous run. It's looking pretty similar to the previous runs. The gc doesn't prevent the memory loss; it would take more work to determine whether it slows down the rate of loss. I'm going to pass on that now.
The v8.total_available_size is now down to 1.4 GB; it started at 1.5 GB. The heap_size_limit is 1.518 GB (constant)
Charts:
I'm starting a run with heap dumps every 10 minutes.
Hi, may I ask what did you use to generate the memory usage graph?
The data is coming from the JavaScript calls process.memoryUsage() and v8.getHeapStatistics(). I'm sending those to the appoptics metrics api at api.appoptics.com/v1/measurements. and they're available at my.appoptics.com in dashboards/metrics. The todo server app (my interactive test harness, not really meant for general application) is at github.com/bmacnaughton/todo. the metrics generation code is in server.js (search for argv.metrics) and lib/metrics.js.
@addaleax - I have almost 20 hours of heapdump snapshots at this time - one every 15 minutes. I haven't looked at them before but am just starting to look now; I'll see what I learn. If they would be helpful to you I can post all or specific time periods.
comparison a little over 13 hours apart. any thoughts about what specifically to look for would be appreciated.
maybe this is helpful?
Oh, the charts that can help place the snapshots in time (heap snapshots are UTC while charts are U.S. Pacific).
@bmacnaughton You’re on the right track – you typically want to look at the retainers of objects created later in time, because those are more likely part of the memory leak. (The map for
Arrayobjects, which iiuc is what you are looking at in your screenshot, is something that is expected to live forever – unless maybe you are creating a lot ofvm.Contexts?).@addaleax I am not creating any
vm.Contexts (that I am aware of). I am trying to investigate:
and within that,
system@2499219- that is the array you see (I think). Is there a good doc on understanding what is being shown here? e.g., what@55515means after an array entry, etc.?@addaleax - OK, here's a wag based on a guess. I'm guessing the @Number is sequencing of some sort so that larger numbers imply later creation. If that's workable then this object is later in time and it's retainer is related to our use of async_hooks. That seems like a likely candidate to be impacted by a v8 change. (Sorry for the miserable formatting - there's too much for a screen shot and the copy didn't format well.)
mapinObject@2941061 4100in(internal array)[]@2889197 | 6 | 229 4160 % | 1 689 2641 % | tableinMap@226307 | 5 | 320 % | 1 689 2961 % | _contextsinNamespace@236189 | 4 | 1360 % | 1360 % | ao-cls-contextinObject@168663 | 3 | 560 % | 560 % | namespacesinprocess@1239 | 2 | 240 % | 21 1520 % | process_objectinNode / Environment@108006912🗖 | 1 | 2 3840 % | 49 2690 % | processinsystem / Context@168883 | 3 | 3280 % | 6640 % | processinsystem / Context@168881 | 3 | 2800 % | 2 3040 % | processinsystem / Context@168879 | 3 | 2080 % | 6320 % | processinsystem / Context@168839 | 3 | 3920 % | 1 0640 % | _processinsystem / Context@212835 | 3 | 640 % | 640 % | processinsystem / Context@136221 | 3 | 1840 % | 1 8240 % | processinsystem / Context@70437 | 3 | 2480 % | 3 4000 % | 9in@175189 | 4 | 2 4320 % | 5 9360 % | processinsystem / Context@296149 | 4 | 1360 % | 1 0880 % | processinsystem / Context@179163 | 4 | 1840 % | 5120 % | objectinsystem / Context@170107 | 4 | 720 % | 720 % | processinsystem / Context@168529 | 4 | 2560 % | 2 0640 % | processinsystem / Context@149249 | 4 | 1120 % | 1120 % | processinsystem / Context@148233 | 4 | 5440 % | 10 0800 % | processinsystem / Context@169109 | 4 | 3840 % | 4160 % | processinsystem / Context@170047 | 4 | 4640 % | 1 8720 % | processinsystem / Context@28599 | 4 | 2720 % | 2 8000 % | processinsystem / Context@169087 | 5 | 960 % | 960 % | processinsystem / Context@169079 | 5 | 1360 % | 3920 % | processinsystem / Context@116733 | 5 | 6000 % | 4 4880 % | processinsystem / Context@146687 | 5 | 2320 % | 9920 % | processinsystem / Context@64745 | 5 | 960 % | 2 1920 % | processinsystem / Context@68209 | 5 | 5440 % | 3 9040 % | 9in@179989 | 6 | 1 5040 % | 2 8640 % | 4in@171337 | 6 | 3 9040 % | 7 5600 % | processinsystem / Context@171335 | 6 | 1920 % | 5280 % | processinsystem / Context@214235 | 6 | 1840 % | 9440 % | processinsystem / Context@213851 | 6 | 800 % | 1 1360 % | processinsystem / Context@106515 | 6 | 2400 % | 1 0080 % | processinsystem / Context@188547 | 6 | 5600 % | 227 4320 % | exportsinModule@102009 | 7 | 880 % | 5760 % | processinsystem / Context@60579 | 7 | 6320 % | 4 3040 % | processinsystem / Context@107777 | 7 | 4320 % | 4 0880 % | processinsystem / Context@106047 | 7 | 7120 % | 4 1840 % | processinsystem / Context@10703 | 7 | 1120 % | 1120 % | 6in(internal array)[]@322865 | 8 | 960 % | 960 % | processinsystem / Context@213369 | 8 | 960 % | 4320 % | processinsystem / Context@221567 | 8 | 2160 % | 6400 % | processinsystem / Context@236123 | 8 | 1600 % | 2 6560 % | processinsystem / Context@119065 | 8 | 5040 % | 11 8880 % | processinsystem / Context@116925 | 8 | 2320 % | 2 1200 % | processinsystem / Context@191171 | 8 | 3680 % | 10 8800 % | 44in@2888137 | 9 | 7 6480 % | 19 7360 % | processinsystem / Context@213883 | 9 | 2720 % | 1 6960 % | processinsystem / Context@96405 | 9 | 1280 % | 6560 % | pnainsystem / Context@53365 | 9 | 3040 % | 4 0960 % | processinsystem / Context@118915 | 9 | 3600 % | 26 4160 % | processinsystem / Context@191517 | 9 | 3200 % | 4880 % | processinsystem / Context@188041 | 9 | 6720 % | 3 9840 % | processinsystem / Context@187989 | 9 | 4800 % | 2 6560 % | pnainsystem / Context@164473 | 9 | 960 % | 4320 % | pnainsystem / Context@164523 | 9 | 3760 % | 5 3600 % | 25in@407329 | 10 | 4 4480 % | 10 7440 % | processinsystem / Context@212821 | 10 | 960 % | 3200 % | processinsystem / Context@237613 | 10 | 1520 % | 3 5920 % | processinsystem / Context@313911 | 10 | 3200 % | 1 4560 % | pnainsystem / Context@96225 | 10 | 640 % | 2320 % | processinsystem / Context@168193 | 10 | 3280 % | 2 8080 % | processinsystem / Context@43051 | 10 | 2400 % | 66 2240 % | processinsystem / Context@119653 | 10 | 2160 % | 3440 % | processinsystem / Context@119513 | 10 | 4240 % | 13 3920 % | processinsystem / Context@117197 | 10 | 1440 % | 8160 % | processinsystem / Context@17725 | 10 | 2880 % | 1 7600 % | processinsystem / Context@17659 | 10 | 1760 % | 6800 % | processinsystem / Context@68641 | 10 | 5760 % | 6 5680 % | freeProcessinsystem / Context@10795 | 10 | 1 0480 % | 20 3760 % | 40in(internal array)[]@377579 | 11 | 4160 % | 4160 % | 5in@2277855 | 11 | 2 2400 % | 3 8960 % | 19in@527441 | 11 | 3 8400 % | 10 2320 % | 24in@988155 | 11 | 3 9680 % | 10 6160 % | 6in(internal array)[]@323153 | 12 | 720 % | 720 % | 47in(Isolate)@17 | − | 00 % | 2080 % | 26in(Global handles)@31 | − | 00 % | 4 3600 % | 60insystem@168665 | 3 | 5200 % | 5200 % | 3in@240155 | 5 | 2 0480 % | 3 5680 % | namespaceinsystem / Context@225603 | 5 | 640 % | 640 % | 16in@225607 | 7 | 2 0160 % | 3 8960 % | 6in@225607 | 7 | 2 0160 % | 3 8960 % | 16in@225605 | 7 | 2 0800 % | 3 5120 % | 8in@225605 | 7 | 2 0800 % | 3 5120 % | namespaceinsystem / Context@2949321 | 8 | 640 % | 1200 % | 13in(internal array)[]@324253 | 9 | 1440 % | 1440 % | 13in(internal array)[]@324267 | 9 | 2000 % | 2000 % | 9in@240155 | 5 | 2 0480 % | 3 5680 % | 5in@240155 | 5 | 2 0480 % | 3 5680 % | 7in(internal array)[]@324295 | 7 | 800 % | 800 % | 4in@225609 | 7 | 9920 % | 1 7360 % | 3in@225607 | 7 | 2 0160 % | 3 8960 % | 3in@225605 | 7 | 2 0800 % | 3 5120 %I appreciate the time you've provided so far and any pointers you can provide me at this time.
44 remaining items
also in version 13, the problem seems to be fixed
v12.15.0 to be released soon will include the fix.
Reacted by Bruce MacNaughtonReacted by Mike Marcacci and Kyle SmithIs there an ETA on publishing 12.15.0? We're running into this now, and it would be awesome if this was published soon!
Reacted by Kyle Smith@bencripps Any time now, it is scheduled for 2020-01-28 https://github.com/nodejs/node/blob/v12.15.0-proposal/doc/changelogs/CHANGELOG_V12.md#2020-01-28-version-12150-erbium-lts-targos
Reacted by Kyle Smith and UZHSWe're going to delay 12.15.0 until a week after the upcoming security releases: nodejs/Release#494 (comment)
Has this issue been resolved in Node >=12.15.0? Can we close this issue?
Node 12.16.0 includes the fix. This issue can be closed.
Reacted by Anna Henningsen and Benjamin Crippsthe leak that i was seeing appears to be closed as well, so it appears to be the same thing.
@likev - how is it that you isolated the leak to the precise test case? i ask because i only saw it in a large system and wasn't able to isolate it.
Reacted by Rui AraújoLooks like the leak has been resolved in our application as well. Upon deploying 12.16.0 memory growth has remained steady for the past 2 weeks.
Hello, I believe this issue may still exist in one form or another in Node 12.16.1. We've observed an increasing memory usage after upgrading a production system to Node 12. The reason I believe it may be related to this issue is we're seeing the exact same 110761200 bytes of memory used in
systemobjects.
We also attempted an upgrade to Node 13, but we are still seeing a similar leaky behavior:
We don't have a minimal repro unfortunately because we are only able to exhibit this behavior on a fairly large application. It also seems to be related to the volume of work/concurrency in the program as we are unable to reproduce in staging environments.
Also likely causing googleapis/cloud-debug-nodejs#811.
uname reports the host container but the application is running in a docker container, from /etc/os-release:
PRETTY_NAME="Debian GNU/Linux 9 (stretch)"
NAME="Debian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=debian
The leak also occurs running alpine 3.9.4 in a container. I have not been able to reproduce it outside of a docker container running on a native ubuntu 18.04 machine.
I am looking for some guidance on steps I can take to help narrow this down; I don't believe that the information I currently have is enough to isolate the problem.
The situation occurs running a memory/cpu benchmark of a todo application instrumented by our APM product. The APM product comprises JavaScript, a C/C++ library, and C++ code that uses the node-addon-api. The todo application is derived from todomvc-mongodb and runs express and mongo.
The graph below shows runs against two consecutive nightly releases (the scale changes so that the increased memory usage isn't off the top of the chart).
node v11.0.0-nightly20180907e917a23d2eshows no memory leak whilenode v11.0.0-nightly20180908922a1b03b6shows a stair-step memory leak. I took a quick look at the commits between the two nightlies but nothing stood out to me other than the v8 changes. I don't know enough of v8 to evaluate them. (6.5.1 and 6.6.0 are the versions of our agent being tested. and at one time the blue line was purple but the legend didn't change.)Here is output from valgrind for an 11 hour run. This is the first time I've used valgrind so I don't have much to compare it with, but nothing stands out to me - there's nothing that looks like it could account for the memory growth shown in the second graph. Hopefully it will mean more to you.
What can I do next to help isolate this?