leak from plugin when using toString on large data

[psnider]

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 !

[mcdonnelldean]

@mcollina Any high level thoughts on this?

[psnider]

FWIW, here are some relevant node.js bugs:

• Fatal Error (Abort) creating string larger than 268435440 bytes
• src: fix memory leak in ExternString

[psnider]

Also, I changed generateLargeBuffer() to use 10% of the size, 4363201, and I still see the problem.

[psnider]

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.

// 4k * 4k ~= 4 * 4MB
for (var i = 0 ; i < 4*1024 ; ++i) {
    test()
}

So it doesn't appear to be related to the size.

[psnider]

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]

@mcollina @rjrodger Before I go spelunky on this one. Do either of ye have any comments on this?

[rjrodger]

does this also happen with seneca({actcache: {active: false}}) ?

[mcdonnelldean]

Let me try that and get back.

[mcollina]

@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 _.clone in Seneca, and I think those are the main culprit (if there is no actcache).

[psnider]

I agree that 40MB is too large, but I have no control over what the external service sends.

Given that there are no leaks for small strings

Are you suggesting that 4k is a long string? If so, what is a reasonable maximum length? Please reference: https://github.com/senecajs/seneca/issues/401#issuecomment-212223976

[mcollina]

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]

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]

@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]

I need to consider how to handle very large messages in terms of graceful degredation.

[rjrodger]

See also: https://github.com/senecajs/seneca/issues/627