Repository navigation
Is node-addon-api@1.2.0 leaking memory? #237
Description
Activity
My first guess is that you may just be missing some required cleanup after your async event runs or you create so many objects so quickly that they just don't get to run fast enough and you get a large backlog an eventually run out of memory due to that backlog
I'm travelling today but will to take a closer look later in the week.
My first guess is that you may just be missing some required cleanup after your async event runs
This would be good. Unfortunately I can't see anything that's missing although I've looked at everything many times.
or you create so many objects so quickly that they just don't get to run fast enough and you get a large backlog an eventually run out of memory due to that backlog
Only one instance of MyObject is created from JavaScript and it's async
openmethods is called approx. 18000000 times. This means that approx. 18000000 instances ofOpenAsyncWorkerwill be created. However, each call to the asyncopenmethod (except the first call) occurs in the completion callback of the previous call toopen. If I understand the code in AsyncWorker::OnWorkComplete correctly then it deletes the current instance ofOpenAsyncWorkerimmediately after calling the completion callback. If I'm not mistaken this means that there will never be more than two instances ofOpenAsyncWorkerat any time.I'm travelling today but will to take a closer look later in the week.
Excellent, no rush.
I don't want to send you on a wild goose chase here but this issue reminds me a bit of this one. However, I have no idea if the issues are in any way related.
@mhdawson Were you able to verify whether or not there's a memory leak here?
I've not had time to investigate yet. Have a lot of things on my plate, sorry.
Some investigation using the existing asyncworker
const assert = require('assert'); test(require(`./build/${buildType}/binding.node`)); test(require(`./build/${buildType}/binding_noexcept.node`)); function test(binding) { binding.asyncworker.doWork(true, function (e) { assert.strictEqual(typeof e, 'undefined'); assert.strictEqual(typeof this, 'object'); assert.strictEqual(this.data, 'test data'); }, 'test data'); binding.asyncworker.doWork(false, function (e) { assert.ok(e instanceof Error); assert.strictEqual(e.message, 'test error'); assert.strictEqual(typeof this, 'object'); assert.strictEqual(this.data, 'test data'); }, 'test data'); let count = 0; function open() { binding.asyncworker.doWork(true, () => { count += 1; if (count % 100000 === 0) { console.log(count); } open(); },'test data'); }; open(); }Running under valgrind with 5000 and 1000 interations showed:
5000
LEAK SUMMARY:
==16094== definitely lost: 5,008 bytes in 294 blocks
==16094== indirectly lost: 80 bytes in 1 blocks
==16094== possibly lost: 304 bytes in 1 blocks
==16094== still reachable: 74,395 bytes in 1,153 blocks
==16094== suppressed: 0 bytes in 0 blocks
==16094== Reachable blocks (those to which a pointer was found) are not shown.
==16094== To see them, rerun with: --leak-check=full --show-leak-kinds=all10000
==16109== LEAK SUMMARY:
==16109== definitely lost: 4,944 bytes in 292 blocks
==16109== indirectly lost: 80 bytes in 1 blocks
==16109== possibly lost: 304 bytes in 1 blocks
==16109== still reachable: 74,395 bytes in 1,153 blocks
==16109== suppressed: 0 bytes in 0 blocks
==16109== Reachable blocks (those to which a pointer was found) are not shown.
==16109== To see them, rerun with: --leak-check=full --show-leak-kinds=allSo I don't see an obvious leak on the native side.
The heap does seem to grow but running with
node --trace-gc --max_old_space_size=128 asyncworker.js
seems to grow to the max heap size and then continue to run and the virtual and resident sizes stay consistent.From this don't think its something on the asyncworker side, so willl need to integrate the use of ObjectWrap to see if we get unbounded memory growth with that.
Existing asyncworker test case with use of object wrap integrated:
asyncworker.cc
#include "napi.h" using namespace Napi; class TestWorker : public AsyncWorker { public: static void DoWork(const CallbackInfo& info) { bool succeed = info[0].As<Boolean>(); Function cb = info[1].As<Function>(); Value data = info[2]; TestWorker* worker = new TestWorker(cb); worker->Receiver().Set("data", data); worker->_succeed = succeed; worker->Queue(); } TestWorker(Function cb) : AsyncWorker(cb), _succeed(true) {} protected: void Execute() override { if (!_succeed) { SetError("test error"); } } private: bool _succeed; }; class MyObject : public Napi::ObjectWrap<MyObject> { public: static Napi::Object Init(Napi::Env env, Napi::Object exports); MyObject(const Napi::CallbackInfo& info); private: static Napi::FunctionReference constructor; void Open(const Napi::CallbackInfo& info); }; Napi::FunctionReference MyObject::constructor; Napi::Object MyObject::Init(Napi::Env env, Napi::Object exports) { Napi::HandleScope scope(env); Napi::Function func = DefineClass(env, "MyObject", { InstanceMethod("open", &MyObject::Open) }); constructor = Napi::Persistent(func); constructor.SuppressDestruct(); exports.Set("MyObject", func); return exports; } MyObject::MyObject(const Napi::CallbackInfo& info) : Napi::ObjectWrap<MyObject>(info) { } void MyObject::Open(const Napi::CallbackInfo& info) { Napi::Function cb = info[0].As<Napi::Function>(); TestWorker* worker = new TestWorker(cb); worker->Queue(); } Object InitAsyncWorker(Env env) { Object exports = Object::New(env); exports["doWork"] = Function::New(env, TestWorker::DoWork); return MyObject::Init(env, exports); }
asyncworker.js
'use strict'; const buildType = process.config.target_defaults.default_configuration; const assert = require('assert'); test(require(`./build/${buildType}/binding.node`)); test(require(`./build/${buildType}/binding_noexcept.node`)); function test(binding) { binding.asyncworker.doWork(true, function (e) { assert.strictEqual(typeof e, 'undefined'); assert.strictEqual(typeof this, 'object'); assert.strictEqual(this.data, 'test data'); }, 'test data'); binding.asyncworker.doWork(false, function (e) { assert.ok(e instanceof Error); assert.strictEqual(e.message, 'test error'); assert.strictEqual(typeof this, 'object'); assert.strictEqual(this.data, 'test data'); }, 'test data'); const myObject = new binding.asyncworker.MyObject(); let count = 0; function open() { myObject.open(() => { count += 1; if (count % 1000000 === 0) { console.log(count); } open(); }); } open(); }
using the following to limit the number of loops in the open() function:
if (count < X) { open(); }
Valgrind on 10000
==25463== HEAP SUMMARY: ==25463== in use at exit: 164,324 bytes in 1,470 blocks ==25463== total heap usage: 181,094 allocs, 179,624 frees, 52,618,468 bytes allocated ==25463== ==25463== LEAK SUMMARY: ==25463== definitely lost: 5,160 bytes in 298 blocks ==25463== indirectly lost: 72 bytes in 2 blocks ==25463== possibly lost: 76,425 bytes in 15 blocks ==25463== still reachable: 82,667 bytes in 1,155 blocks ==25463== suppressed: 0 bytes in 0 blocks ==25463== Rerun with --leak-check=full to see details of leaked memory
Valgrind on 20000
==25478== HEAP SUMMARY: ==25478== in use at exit: 164,324 bytes in 1,470 blocks ==25478== total heap usage: 341,518 allocs, 340,048 frees, 64,446,004 bytes allocated ==25478== ==25478== LEAK SUMMARY: ==25478== definitely lost: 5,136 bytes in 298 blocks ==25478== indirectly lost: 96 bytes in 2 blocks ==25478== possibly lost: 76,425 bytes in 15 blocks ==25478== still reachable: 82,667 bytes in 1,155 blocks ==25478== suppressed: 0 bytes in 0 blocks ==25478== Rerun with --leak-check=full to see details of leaked memory ==25478==
So I don't see any native memory leak based on number of times open is called.
Running with
node --trace-gc --max_old_space_size=128 asyncworker.jsand watching memory with top, memory increases and then stabilizes at (shown at about 14 mins into the run) ~
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 25500 mhdawson 20 0 1290348 236352 12132 R 174.6 1.4 14:11.08 node 1583 jsbuild 20 0 7664760 186020 15260 S 0.7 1.1 33:11.52 java 123 root 20 0 0 0 0 S 0.3 0.0 4:42.11 kworker/3:1
gc activity also stabilizes at frequent gc's freeing about 6MB each time
[25500:0x2c2dd60] 512946 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 176.4 / 33.3 ms (+ 173.2 ms in 193 steps since start of marking, biggest step 61.9 ms, walltime since start of marking 383 ms) finalize incremental marking via task GC in old space requested [25500:0x2c2dd60] 513336 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 181.5 / 40.5 ms (+ 175.8 ms in 193 steps since start of marking, biggest step 63.0 ms, walltime since start of marking 390 ms) finalize incremental marking via task GC in old space requested [25500:0x2c2dd60] 513718 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 175.1 / 34.5 ms (+ 172.6 ms in 190 steps since start of marking, biggest step 61.3 ms, walltime since start of marking 382 ms) finalize incremental marking via task GC in old space requested [25500:0x2c2dd60] 514100 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 175.5 / 34.5 ms (+ 172.9 ms in 193 steps since start of marking, biggest step 61.7 ms, walltime since start of marking 381 ms) finalize incremental marking via task GC in old space requested [25500:0x2c2dd60] 514487 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 178.8 / 33.8 ms (+ 174.3 ms in 193 steps since start of marking, biggest step 62.4 ms, walltime since start of marking 386 ms) finalize incremental marking via task GC in old space requested [25500:0x2c2dd60] 514868 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 173.3 / 33.5 ms (+ 173.7 ms in 196 steps since start of marking, biggest step 61.7 ms, walltime since start of marking 380 ms) finalize incremental marking via task GC in old space requested [25500:0x2c2dd60] 515249 ms: Mark-sweep 126.5 (132.3) -> 126.5 (132.3) MB, 175.9 / 33.4 ms (+ 172.0 ms in 192 steps since start of marking, biggest step 61.1 ms, walltime since start of marking 381 ms) finalize incremental marking via task GC in old space requested
These were done with the lastest node master and current node-addon-api repo.
@fivdi can you take a look at the code I used above, I think I integrated your example properly but it does not look like there is memory leaking to me.
I see you are on a raspberry pi which might not have as much memory as I do. Can you try with --max_old_space_size=128 to see if the process still gets terminated?
@fivdi can you take a look at the code I used above, I think I integrated your example properly but it does not look like there is memory leaking to me.
It looks like the examples was integrated correctly into
asyncworker.ccbut it still looks like there is a memory leak to me (see below.)I see you are on a raspberry pi which might not have as much memory as I do. Can you try with --max_old_space_size=128 to see if the process still gets terminated?
Yes, it's a Raspberry Pi 3 with 1GB of RAM. I tried --max_old_space_size=128 with my example from the original post, here's the output:
pi@raspberrypi:~/node-addon-api-leak/node_modules/node-addon-api-leak/test $ node --max_old_space_size=128 leak.js 100000 200000 300000 400000 500000 600000 700000 800000 900000 1000000 1100000 1200000 1300000 1400000 1500000 1600000 1700000 1800000 1900000 2000000 2100000 2200000 2300000 2400000 2500000 2600000 2700000 2800000 2900000 3000000 3100000 3200000 3300000 3400000 3500000 3600000 3700000 3800000 3900000 4000000 4100000 4200000 4300000 4400000 4500000 4600000 <--- Last few GCs ---> [20259:0x2297110] 28022182 ms: Mark-sweep 126.6 (133.2) -> 126.6 (133.2) MB, 1649.2 / 91.2 ms allocation failure GC in old space requested [20259:0x2297110] 28023559 ms: Mark-sweep 126.6 (133.2) -> 126.6 (133.2) MB, 1376.2 / 127.0 ms last resort GC in old space requested [20259:0x2297110] 28024989 ms: Mark-sweep 126.6 (133.2) -> 126.6 (133.2) MB, 1430.3 / 142.5 ms last resort GC in old space requested <--- JS stacktrace ---> ==== JS stack trace ========================================= Security context: 0x33914c4d <JSObject> 1: open(aka open) [/home/pi/node-addon-api-leak/node_modules/node-addon-api-leak/test/leak.js:~7] [pc=0x4f16e8b8](this=0x51404185 <undefined>) 2: /* anonymous */ [/home/pi/node-addon-api-leak/node_modules/node-addon-api-leak/test/leak.js:13] [bytecode=0x51d7d779 offset=66](this=0x4d9ef199 <Object map = 0x3de841c9>) ==== Details ================================================ [1]: open(aka... FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory Aborted pi@raspberrypi:~/node-addon-api-leak/node_modules/node-addon-api-leak/test $leak.jswas modified to displaycountevery 1e5 iterations rather than every 1e6 iterations. As can be seen there is fatal error as the JavaScript heap runs out of memory.The program was running for several hours before the error occurred. The displaying of
countto the console got slower and slower as time went on. Everything looked stable withtop.@mhdawson I did the last test with v10.0.0-nightly2018040653aaa55a3a and
npm i fivdi/node-addon-api-leak.@mhdawson When the example you posted above is integrated into asyncworker.cc and asyncworker.js is modified to:
'use strict'; const buildType = process.config.target_defaults.default_configuration; const assert = require('assert'); test(require(`./build/${buildType}/binding.node`)); test(require(`./build/${buildType}/binding_noexcept.node`)); function test(binding) { binding.asyncworker.doWork(true, function (e) { assert.strictEqual(typeof e, 'undefined'); assert.strictEqual(typeof this, 'object'); assert.strictEqual(this.data, 'test data'); }, 'test data'); binding.asyncworker.doWork(false, function (e) { assert.ok(e instanceof Error); assert.strictEqual(e.message, 'test error'); assert.strictEqual(typeof this, 'object'); assert.strictEqual(this.data, 'test data'); }, 'test data'); const myObject = new binding.asyncworker.MyObject(); let count = 0; function open() { myObject.open(() => { count += 1; if (count % 100000 === 0) { console.log(count + ' ' + new Date().toISOString()); } open(); }); } open(); }
The output is:
pi@raspberrypi:~/node-addon-api/test $ node --max_old_space_size=128 asyncworker.js 100000 2018-04-11T20:30:05.281Z 100000 2018-04-11T20:30:05.290Z 200000 2018-04-11T20:30:10.371Z 200000 2018-04-11T20:30:10.371Z 300000 2018-04-11T20:30:15.231Z 300000 2018-04-11T20:30:15.232Z 400000 2018-04-11T20:30:20.144Z 400000 2018-04-11T20:30:20.145Z 500000 2018-04-11T20:30:24.726Z 500000 2018-04-11T20:30:24.727Z 600000 2018-04-11T20:30:29.805Z 600000 2018-04-11T20:30:29.806Z 700000 2018-04-11T20:30:34.455Z 700000 2018-04-11T20:30:34.456Z 800000 2018-04-11T20:30:39.716Z 800000 2018-04-11T20:30:39.717Z 900000 2018-04-11T20:30:44.406Z 900000 2018-04-11T20:30:44.406Z 1000000 2018-04-11T20:30:49.086Z 1000000 2018-04-11T20:30:49.087Z 1100000 2018-04-11T20:30:54.502Z 1100000 2018-04-11T20:30:54.503Z 1200000 2018-04-11T20:30:59.169Z 1200000 2018-04-11T20:30:59.169Z 1300000 2018-04-11T20:31:03.859Z 1300000 2018-04-11T20:31:03.859Z 1400000 2018-04-11T20:31:09.655Z 1400000 2018-04-11T20:31:09.656Z 1500000 2018-04-11T20:31:14.203Z 1500000 2018-04-11T20:31:14.204Z 1600000 2018-04-11T20:31:18.920Z 1600000 2018-04-11T20:31:18.920Z 1700000 2018-04-11T20:31:23.567Z 1700000 2018-04-11T20:31:23.568Z 1800000 2018-04-11T20:31:29.596Z 1800000 2018-04-11T20:31:29.596Z 1900000 2018-04-11T20:31:34.549Z 1900000 2018-04-11T20:31:34.549Z 2000000 2018-04-11T20:31:40.967Z 2000000 2018-04-11T20:31:40.968Z 2100000 2018-04-11T20:31:47.194Z 2100000 2018-04-11T20:31:47.195Z 2200000 2018-04-11T20:32:03.977Z 2200000 2018-04-11T20:32:03.977Z 2300000 2018-04-11T20:39:06.460Z 2300000 2018-04-11T20:39:14.743Z <--- Last few GCs ---> [1404:0x2f16118] 23992123 ms: Mark-sweep 127.1 (133.7) -> 127.1 (133.7) MB, 1648.1 / 91.4 ms allocation failure GC in old space requested [1404:0x2f16118] 23993549 ms: Mark-sweep 127.1 (133.7) -> 127.1 (133.7) MB, 1425.7 / 142.4 ms last resort GC in old space requested [1404:0x2f16118] 23994948 ms: Mark-sweep 127.1 (133.7) -> 127.1 (133.7) MB, 1398.6 / 142.5 ms last resort GC in old space requested <--- JS stacktrace ---> ==== JS stack trace ========================================= Security context: 0x41194c4d <JSObject> 1: open(aka open) [/home/pi/node-addon-api/test/asyncworker.js:~25] [pc=0x20b6e8f4](this=0x5a004185 <undefined>) 2: /* anonymous */ [/home/pi/node-addon-api/test/asyncworker.js:31] [bytecode=0x207c461d offset=100](this=0x49f6be45 <Object map = 0x4d4841c9>) ==== Details ================================================ [1]: open(aka open) [/home/pi/node-addon-api/test/asyncworker.js:~25] [pc... FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory Aborted pi@raspberrypi:~/node-addon-api/test $After
2300000 2018-04-11T20:39:14.743Zwas logged to the console the program ran for several hours before the fatal error "JavaScript heap out of memory" occurred.I found this issue when trying to pinpoint my own memory leak, which I believe is caused by the same problem. While I am fairly new with native add-on things, I'd like to add one observation hoping it is helpful.
The same symptom can be observed on both my application and @fivdi 's https://github.com/fivdi/node-addon-api-leak repo. So I am using node-addon-api-leak as the example. By running
node --inspect test/leak.jsand then attaching to it with the chrome dev tools' allocation timeline tool, it can be seen that sometimes when an AsyncWorker instance is constructed(fivdi's test case shows this very consistently), there is anObject(56 bytes in size and retained by GC root) left in the heap. Over time they add up and I believe this also causes my own app's memory leak(I could be wrong of course). See the screenshot attached. With my limited experience, I couldn't figure out where these objects are from. While the AsyncWorker constructor creates a new object as the receiver(if not given), that doesn't seem to be the object in question.BTW, all this is on macOS and I haven't tried it on any other os. Node-addon-api version is 1.3.0.
I ran node-addon-api-leak on my laptop, and it seems to top off at 7.8% memory usage, and it stops printing after 26000000. It continues running at 100%.
4 remaining items
@mhdawson and I backed the JS part of the node-addon-api-leak test with the following native code, lacking an AsyncResource, and it did not leak:
#include <stdio.h> #include "uv.h" #include "node.h" using namespace v8; typedef struct { uv_work_t uv_work; Persistent<Function> perma_cb; } MyWork; static void do_work(uv_work_t* work) {} static void done_work(uv_work_t* work, int status) { auto isolate = Isolate::GetCurrent(); HandleScope scope(isolate); auto context = isolate->GetCurrentContext(); node::CallbackScope cb_scope(isolate, Object::New(isolate), node::async_context()); MyWork* my_work = reinterpret_cast<MyWork*>(work); Local<Function> js_cb = Local<Function>::New(isolate, my_work->perma_cb); js_cb->Call(context, context->Global(), 0, nullptr).ToLocalChecked(); my_work->perma_cb.Reset(); delete my_work; } static void MyObject(const FunctionCallbackInfo<Value>& info) {} static void MyObject_open(const FunctionCallbackInfo<Value>& info) { MyWork *work = new MyWork; work->perma_cb.Reset(Isolate::GetCurrent(), info[0].As<Function>()); uv_loop_t *loop = uv_default_loop(); if (uv_queue_work(loop, reinterpret_cast<uv_work_t*>(work), do_work, done_work) != 0) { fprintf(stderr, "Failed to create work\n"); } } static void Init(Local<Object> exports, Local<Value> module) { auto isolate = Isolate::GetCurrent(); auto context = isolate->GetCurrentContext(); auto js_class = FunctionTemplate::New(isolate, MyObject); auto js_method = FunctionTemplate::New(isolate, MyObject_open, Local<Value>(), Signature::New(isolate, js_class)); js_class->PrototypeTemplate()->Set(isolate, "open", js_method); exports->Set(isolate->GetCurrentContext(), String::NewFromUtf8(isolate, "MyObject", NewStringType::kNormal) .ToLocalChecked(), js_class->GetFunction(context).ToLocalChecked()).FromJust(); } NODE_MODULE(NODE_GYP_MODULE_NAME, Init)
Thanks @mhdawson for the quick turnaround!
- added a commit that references this issue
on May 14, 2018 - added 2 commits that reference this issue
on Jul 9, 2018 - added a commit that references this issue
on Aug 16, 2018 - added a commit that references this issue
on Jul 27, 2026

If the following addon:
my-object.h
my-object.cc
addon.cc
is tested with the following JavaScript:
then the memory usage of the node process keeps increasing and increasing and the process ends up crashing after the async
openmethod has been called about 18 million times.Here's the output of the program:
The complete addon can be seen here.