memory leak in 2.0 alpha 8

[dnalborczyk]

There seems to be a memory leak being introduced in 2.0 alpha 8.

Here is a narrowed down repro:

var mysql = require( 'mysql' ),
    connection  = mysql.createConnection( {} ),
    counter = 0,
    sql = 'SELECT 0',
    execQuery = function () {
        connection.query( sql, function( err, rows ) {
            console.log( ++counter );
            execQuery();
        });
    };
execQuery();

On my box I get to about 330.000 queries with the above example, before I get an 'out-of-memory exception'. (FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory).

You get to the exception a little faster when you introduce more columns to the query, e.g.:

'SELECT ' +
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,' + 
    '0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9',

That will get you to the exception in about 5.000 round-trips - at least on my machine.

My setup, if it should matter: Windows 8 64 bit, node.js 0.10.5 64 bit, MySQL 5.5.27

The above example(s) will run forever with the 2.0 alpha 7 version. (memory is being released)

Daniel

[dnalborczyk]

I'd like to help to investigate, but I'm not able to get any node memory profiler to run on Windows boxes. :(

It probably doesn't help much other than visualizing the memory usage, but here is a (modified) GC trace. I run the trace with the longer SQL string:

Alpha 7

[8396] 34 ms: Scavenge 2.0 (34.0) -> 1.6 (35.0) MB, 1 ms [Runtime::PerformGC].
[ 10 seconds later ]
[8396] 10036 ms: Scavenge 21.1 (42.0) -> 5.5 (42.0) MB, 0 ms [Runtime::PerformGC].
[ 10 seconds later ]
[8396] 20093 ms: Scavenge 20.7 (42.0) -> 5.0 (42.0) MB, 1 / 1 ms [allocation failure].
[ 10 seconds later ]
[8396] 30008 ms: Scavenge 20.5 (42.0) -> 4.9 (42.0) MB, 0 ms [Runtime::PerformGC].
[ 10 seconds later ]
[8396] 40070 ms: Scavenge 20.6 (42.0) -> 5.0 (42.0) MB, 0 ms [allocation failure].
[ 10 seconds later ]
[8396] 50005 ms: Scavenge 20.6 (42.0) -> 5.0 (42.0) MB, 1 ms [allocation failure].
[ 10 seconds later ]
[8396] 60087 ms: Scavenge 20.4 (42.0) -> 4.8 (42.0) MB, 0 ms [allocation failure].

Alpha 8

[3684] 32 ms: Scavenge 2.0 (34.0) -> 1.6 (35.0) MB, 0 ms [allocation failure].
[ 10 seconds later ]
[3684] 10526 ms: Mark-sweep 444.3 (473.0) -> 438.3 (481.0) MB, 1 / 28 ms (+ 237 ms in 1026 steps since start of marking, biggest step 81.000000 ms) [StackGuard GC request] [GC in old space requested].
[ 10 seconds later ]
[3684] 20123 ms: Scavenge 852.6 (887.0) -> 843.6 (889.0) MB, 8 ms [allocation failure].
[ 10 seconds later ]
[3684] 30638 ms: Mark-sweep 1277.9 (1319.0) -> 1271.1 (1327.0) MB, 1 / 35 ms (+ 642 ms in 1035 steps since start of marking, biggest step 86.000000 ms) [StackGuard GC request] [GC in old space requested].
[ 4 seconds later ]
[3684] 34763 ms: Mark-sweep 1392.3 (1446.0) -> 1391.6 (1450.0) MB, 1 / 16 ms (+ 706 ms in 527 steps since start of marking, biggest step 80.000000 ms) [StackGuard GC request] [GC in old space requested].
[3684] Speed up marking because of low space left
[3684] Marking speed increased to 1000
[3684] Speed up marking because of low space left
[3684] Marking speed increased to 1000
[3684] Speed up marking because of low space left
[3684] Marking speed increased to 1000
[3684] Speed up marking because of low space left

Daniel

[dnalborczyk]

Just gave it another shot with a different system:

Ubuntu 13.04 (64 bit), Node.js 0.10.5, MySQL 5.5.31.

Same results, alpha 7 releases memory, alpha 8 doesn't.

Daniel

[kai-koch]

I can confirm this on WindowsXP 32-bit and Node v 0.8.8 and 2.0.5Alpha and 2.0.8Alpha.
One funny thing, the process that leaks memory consumes less CPU (about 2/3 less than the non-leaking), but runs faster. (I let them race in two Shells.) But that might be just that the GC can not collect anything.

[dnalborczyk]

Hey @kai-koch, thanks for the confirmation!

I think I tracked that sucker down! I just reverted the commits from alpha 8 down towards 7 until it stopped happening.

I'll post more on that soon ...

Daniel

[dnalborczyk]

shoot, wrong button ... sorry.

[dnalborczyk]

Sorry, I didn't have time to post on the weekend.

Danke Felix for fixing it!

Daniel

PS: It still makes me wonder why that even happened, I might give it a shot to figure it out... :)

[xelaz]

Thx, this Issue has fixed our leaks from 49% to 2% on Node 0.10.4
In 0.8.16 all ok without this fix.

[felixge]

Thx, this Issue has fixed our leaks from 49% to 2%

@xelaz how do you measure this?

[xelaz]

we have created over 7000 queries asynchrone :) an with top monitoring our memory, it goes after 5 min over 49% of 32Gb, so i add your fix and now we have silence in our memory