fs.createWriteStream memory leak

[ashelley]

Hello,

I'm having major problems with fs.createWriteStream in my code. It is seemingly leaking memory.

I have created a test case here:

https://github.com/ashelley/node-create-stream-test

clone the repository and then

npm install
cd tests
mocha tests.js

There are three tests in:
https://github.com/ashelley/node-create-stream-test/blob/master/tests/tests.js

The first one writes out 200KB always calling setImmediate to allow the event loop to be relieved frequently. This test is able to output 200KB albeit very slow.

The second test calls setImmediate only every 100 iterations. This test shows the problems I'm having with fs.createWriteStream. You can see it really start to churn trying to generate the stream and also flush the data to the file.

I've added memwatch to the output of this test to show the leaks occurring.

The third test is synchronous and doesn't give v8 any time to breath. You can really see the problem here.

If you go into tests.js and change 200KB to something like 50KB all the tests will complete and everything will be fine.

look for a variable called fileSize in tests\tests.js to adjust the settings.

Is there anything I am doing wrong or is this a bug? Any insight is appreciated.... Thank you.

[ashelley]

Please also note that the problem seems to occur on node 10.29 and 10.30.

[ashelley]

I created a simple replacement for fs.createWriteStream that uses stream buffers that helps work around my issue but I still think something is up with fs.createWriteStream.

https://github.com/ashelley/writable-filestream

[trevnorris]

Sorry, until you can either cause the Node process to consume more than 1.5GB of memory or cause a FATAL ERROR: Allocation failed - process out of memory then I don't consider it a "memory leak". V8 will use as much of the heap it feels like to prevent GC from halting the process.

Do you have a test case that causes either of the above to occur?

[ashelley]

After some trying I haven't been able to make node get get an out of memory error or use more than 1.5GB of ram with these simple tests . So I the topic of this issue probably should be changed to "fs.createWriteStream very slow when lots of writes".

[ashelley]

Looking into this more...

It turns out fs.createWriteStream dies if you don't respect the return value of stream.write. See here:

http://nodejs.org/api/stream.html#stream_event_drain

I still believe there is a problem with what node does when you don't handle this case but the workaround is that you must detect this condition and listen for the drain event to continue writing.

I have updated my test-case @ https://github.com/ashelley/node-create-stream-test that shows this working.

Try running the tests on master (the broken version) then try running the tests on the fixed branch to see the difference when you listen to the drain event.

I have updated the readme on the test repository with these instructions.

The documentation on this behaviour might need to be updated to document the bad things that might happen when you don't respect this return value. It may be a bit misleading to say that this return value is simply advisory rather than indicating that you must take alternative actions before writing to the stream again.

This return value is strictly advisory. You MAY continue to write, even if it returns false. However, writes will be buffered in memory, so it is best not to do this excessively. Instead, wait for the drain event before writing more data.

It may be possible that on other operating systems this code works well. I've only tested on ubuntu 13.10 64 bit and ubuntu 12.04 64bit.

[ashelley]

Just an update on this. I think there is a problem in the underlying writable stream. I've created another test suite that shows that the zlib stream has the exact same problem.

https://github.com/ashelley/node-zlib-stream-test

I've made this test suite slightly easier to see working vs none working by not doing it on a separate branch. just simply modify test.js allowDrain = true to see how the stream works when you allow it to drain properly.

This thread is marked tagged fs but it's starting to look like a generic writable stream problem. I have yet to confirm that anyone else is having these issues so i'm going to try to determine the underlying problem. Right now this is just tested on 10.29 but I assume 10.30 will have the same problem as it seems to be the same problem as with the fs.createWriteStream problem.

Obviously any in sight is appreciated.

[ashelley]

Okay....

I just compiled node from http://nodejs.org/dist/v0.10.30/node-v0.10.30.tar.gz on centos 6.5:

Linux node103 2.6.32-431.1.2.0.1.el6.x86_64 #1 SMP Fri Dec 13 13:06:13 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

And i'm having the same issue.

[ashelley]

Just compiled 0.11.3 from github

git checkout remotes/origin/v0.11.13-release

node --version
v0.11.13

same issue so far

[ashelley]

Still seeing the same problem in 0.10.0 going to start looking at my testing methodology to make sure that it's sane :(

node --version
v0.10.0

[ashelley]

@trevnorris I believe this thread is now a dupe of #6623

[ashelley]

i just checked out master... the problem still exists:

node --version
v0.13.0-pre

[trevnorris]

You're correct. It is a dup. There's an issue in the Stream API and how we always immediately call the callback in specific cases. When that happens memory begins to fill until the write is complete. Thanks for looking into this more. Going to close this.

[ashelley]

I checked out node 0.10 and started doing some diagnostics.

https://github.com/joyent/node/blob/163ca274230fce536afe76c64676c332693ad7c1/lib/_stream_writable.js#L275-L303

After reviewing the code I feel as if draining WriteReq's after calling .end should have similar throughput as if you originally were writing chunks to the stream. It does not.

Here is a patch against v0.10.0 that i'm using to try to visualize the problem:

https://gist.github.com/ashelley/1aff66c7a45011343cd1

It seems to me that based on the information output from these diagnostics that something is slowing down between doWrite and onwriteStateUpdate. I haven't yet determined why this is happening and I still need to verify that my diagnostics are accurate but so far it looks like the the calls to onwrite are delayed subtly (by something) which causes this problem.

Here is some output from my zlib tests:

time from first write to calling .end 6042
averate doWriteSpeed before calling .end 0.02694951607150709
total number of times clearBuffer called before calling .end 204679
total number of times doWrite called before calling .end 204679
total number of times clearBuffer called 204799
total time since first write 6048
total number of doWrites 204799
averate doWriteSpeed 0.026958139444040255 <-----
amount of time between doWrite calls on average 0.029126118779876854
amount of time between clearBuffer calls on average 0.029067524743773162
    ✓ should not die setImmediate always (6054ms)

time from first write to calling .end 8998
averate doWriteSpeed before calling .end 4.38427734375
total number of times clearBuffer called before calling .end 2048
total number of times doWrite called before calling .end 2048
total number of times clearBuffer called 204799
total time since first write 413865
total number of doWrites 204799
averate doWriteSpeed 2.0122412707093296 <------
amount of time between doWrite calls on average 2.019961034965991
amount of time between clearBuffer calls on average 2.018896576643441
    ✓ should not die setImmediate sometimes (413867ms)

time from first write to calling .end 1
averate doWriteSpeed before calling .end NaN
total number of times clearBuffer called before calling .end 0
total number of times doWrite called before calling .end 0
total number of times clearBuffer called 204799
total time since first write 352793
total number of doWrites 204799
averate doWriteSpeed 1.716038652532483 <-----
amount of time between doWrite calls on average 1.7220250098877437
amount of time between clearBuffer calls on average 1.7212730530910796

here is some output from my fs tests:

time from first write to calling .end 7942
averate doWriteSpeed before calling .end 0.036176774883178144
total number of times clearBuffer called before calling .end 203943
total number of times doWrite called before calling .end 203943
total number of times clearBuffer called 204799
total time since first write 7965
total number of doWrites 204799
averate doWriteSpeed 0.03613298893061001 <------
amount of time between doWrite calls on average 0.03854511008354533
amount of time between clearBuffer calls on average 0.038496281720125584
    ✓ should not die setImmediate always (7971ms)

time from first write to calling .end 9074
averate doWriteSpeed before calling .end 4.425012212994626
total number of times clearBuffer called before calling .end 2047
total number of times doWrite called before calling .end 2047
total number of times clearBuffer called 204799
total time since first write 359472
total number of doWrites 204799
averate doWriteSpeed 1.7481530671536483 <----
amount of time between doWrite calls on average 1.7545154029072407
amount of time between clearBuffer calls on average 1.7538366886557064
    ✓ should not die setImmediate sometimes (359476ms)

time from first write to calling .end 0
averate doWriteSpeed before calling .end NaN
total number of times clearBuffer called before calling .end 0
total number of times doWrite called before calling .end 0
total number of times clearBuffer called 204799
total time since first write 369284
total number of doWrites 204799
averate doWriteSpeed 1.7961659969042818 <----
amount of time between doWrite calls on average 1.802406261749325
amount of time between clearBuffer calls on average 1.8018984467697596
    ✓ should not die in tight loop (370006ms)