Repository navigation
leak from plugin when using toString on large data #401
Description
I've encountered a severe memory leak when an external service started sending very large XML responses (~40MB).
Note that there are some bug reports in node with very large strings leaking, but they must be around 250MB, and seem to be unrelated to this issue. Also , I couldn't reproduce this problem when I don't use seneca.
node v5.0.0
seneca ^1.3.0
Here is minimal code I use from a REPL that reproduces the issue reliably.
Enable garbage collection API to help with testing:
node --expose-gc
// if true, toString() is called within the plugin code, if false, it is called within the triggering act callback
var perform_toString_within_plugin
function generateLargeBuffer() {
const buf = new Buffer(43632013)
buf.fill(0)
return buf
}
/////// SIMPLE PLUGLIN
var fs = require('fs')
function leaking_plugin( options ) {
const PLUGIN_NAME = 'leaking'
this.add('role:test,cmd:leak', (msg, respond) => {
var data = generateLargeBuffer()
if (perform_toString_within_plugin) {
var contents = data.toString()
console.log('toString() in leaking_plugin')
} else {
var contents = data
}
respond(null, {contents})
})
this.add( {init: PLUGIN_NAME}, function( args, done ) {
done()
})
return PLUGIN_NAME
}
function senecaAction(msg, done) {
seneca.act(msg, (error, response) => {
if (!error) {
if (perform_toString_within_plugin) {
var s = response.contents
} else {
s = response.contents.toString()
console.log('toString() in senecaAction()')
}
console.log('OK to process data')
} else {
console.log('error=' + error);
}
done(error, s)
})
}
fs = require('fs')
SENECA = require('seneca')
var seneca = SENECA({
"log": "silent",
"default_plugins": {
"mem-store": true
},
"debug": {
"undead": true
},
"timeout": 99999
})
seneca.use(leaking_plugin)
seneca.error((error) => {
console.log('Seneca error: ' + error)
})
function test() {
senecaAction({role: 'test',cmd: 'leak'}, function(error, s) {
console.log('test finished...')
})
}
Find the base heap size:
global.gc()
process.memoryUsage()
For me this gives: { rss: 52281344, heapTotal: 32966400, heapUsed: 26,996,888 }
Then excercise the above code from the REPL with combinations of tests and measurements and running the GC.
perform_toString_within_plugin = false
test()
test()
test()
test()
Wait for the tests to finish, then run:
process.memoryUsage()
For me this gives: { rss: 293875712, heapTotal: 152241920, heapUsed: 115,433,200 }
Verify that this memory can be reclaimed by running the GC:
global.gc()
process.memoryUsage()
For me this gives: { rss: 182329344, heapTotal: 31946496, heapUsed: 26,413,976 }
So it appears that memory is reclaimed correctly.
Now switch to performing the toString() from within the plugin:
perform_toString_within_plugin = true
test()
test()
test()
test()
Again, wait for the tests to finish, then run:
process.memoryUsage()
For me this gives: { rss: 527720448, heapTotal: 206558208, heapUsed: 198,439,760 }
Now confirm that the GC cannot reclaim this memory any longer.
global.gc()
process.memoryUsage()
For me this gives: { rss: 523902976, heapTotal: 204523008, heapUsed: 198,208,656 }
In contrast to before, it has dropped only by about 200k !
Activity
mcdonnelldean commentedon Apr 19, 2016
@mcollina Any high level thoughts on this?
psnider commentedon Apr 20, 2016
FWIW, here are some relevant node.js bugs:
psnider commentedon Apr 20, 2016
Also, I changed generateLargeBuffer() to use 10% of the size, 4363201,
and I still see the problem.
psnider commentedon Apr 20, 2016
And changing generateLargeBuffer() to use a smaller size buffer of 4*1024, with enough calls to match the volume of memory of the preceding ~4MB test, yields similar results.
So it doesn't appear to be related to the size.
psnider commentedon Apr 20, 2016
And I have confirmed that when I rework my main program
to make direct calls instead of using seneca for the one problematic message,
memory management works as expected.
mcdonnelldean commentedon May 13, 2016
@mcollina @rjrodger Before I go spelunky on this one. Do either of ye have any comments on this?
rjrodger commentedon May 13, 2016
does this also happen with
seneca({actcache: {active: false}})?mcdonnelldean commentedon May 13, 2016
Let me try that and get back.
mcollina commentedon May 13, 2016
@psnider I suggest you to reconsider your architecture. Sending 40MB of data from Node.js will likely cause you problems in other places as well. The solution to this issue is uploading that file to S3 or another blob storage, and then send a URL to your caller.
This has the added benefit of allowing better caching.
Given that there are no leaks for small strings, I presume it's some bad interaction with long strings and Seneca. There are quite a few
_.clonein Seneca, and I think those are the main culprit (if there is no actcache).psnider commentedon May 13, 2016
I agree that 40MB is too large, but I have no control over what the external service sends.
Are you suggesting that 4k is a long string? If so, what is a reasonable maximum length?
Please reference: #401 (comment)
mcollina commentedon May 13, 2016
Receiving 40MB in your process for a live transaction is probably a bad idea anyway. You will get a much more performing user experience by 1) having the client return an original URL or 2) uploading that data somewhere else in a batch/queue fashion.
Regarding the bug, I expressed myself badly. Given there is no problem with "normal" strings and objects, this should be tightly correlated with buffers.
Also, why you need to convert it to a String? Keeping it as a buffer will definitely help in memory management.
psnider commentedon May 13, 2016
I believe that there is a serious memory leak in this use case.
I don't know if Seneca is involved, but it seems to be.
If it is related to Seneca, it would help to know what the cause is.
BTW, I worked carefully on the examples I gave in the initial report to decouple it from all other aspects of my app.
mcdonnelldean commentedon May 13, 2016
@psnider Let me first check the cache stuff, if that's the issue it's fairly simple to fix. I'll report back soon.
rjrodger commentedon Apr 18, 2017
I need to consider how to handle very large messages in terms of graceful degredation.
rjrodger commentedon May 3, 2017
See also: #627