Repository navigation
Memory leak when calling fs.write() in long synchronous loop #11289
Description
- Version: v0.12.9 - v7.5.0
- Platform: Linux hostname 4.4.0-59-generic Adding more specific README URLs to io.js, keeping node in too #80~14.04.1-Ubuntu SMP Fri Jan 6 18:02:02 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
- Subsystem: fs?
I think I found a memory leak when using fs.write() from a long synchronous loop. Here is the script that I used to reproduce:
var fs = require('fs')
var f = fs.openSync('/tmp/toto', 'w')
var line = 'hello\n'
for (var i = 0; i < 2000000; i++) {
fs.write(f, line)
}
console.log('finished sync loop')
fs.fsync(f, function(){
fs.close(f, function(){
global.gc()
console.log('closed')
})
})
// Avoid script exit
setTimeout(function(){}, 600000)
With node v0.12.9:
% node --expose-gc t4.js
finished sync loop
closed
^C
%
After the process closed the file, there is 1.1 GB used by the process:
The file contains all the lines:
% wc -l toto
2000000 toto
The file has 12 MB so I would eventually expect the node process to take around 70 MB of memory given that it takes 17 with an empty vm:
% ls -lh toto
-rw-rw-r-- 1 alex alex 12M Feb 10 15:59 toto
%
If I don't call the gc manually I get:
With node v7.5.0:
% node --expose-gc t4.js
<--- Last few GCs --->
[12644:0x2dea9c0] 50672 ms: Mark-sweep 1403.9 (1473.8) -> 1403.9 (1473.8) MB, 1299.8 / 1.1 ms allocation failure GC in old space requested
[12644:0x2dea9c0] 51970 ms: Mark-sweep 1403.9 (1473.8) -> 1403.9 (1442.8) MB, 1297.4 / 2.2 ms last resort gc
[12644:0x2dea9c0] 53382 ms: Mark-sweep 1403.9 (1442.8) -> 1403.9 (1442.8) MB, 1411.4 / 1.1 ms last resort gc
<--- JS stacktrace --->
==== JS stack trace =========================================
Security context: 0x27bc2abc0d39 <JS Object>
1: write [fs.js:~669] [pc=0x2e9d77e4b286](this=0x1cdf3f4ab721 <an Object with map 0x37f0aa419701>,fd=9,buffer=0x15b7a55fff89 <String[19]\: 0.6831274126925666\n>,offset=0x27bc2ab04311 <undefined>,length=0x27bc2ab04311 <undefined>,position=0x27bc2ab04311 <undefined>,callback=0x27bc2ab04311 <undefined>)
2: arguments adaptor frame: 2->6
3: /* anonymous */ [/tmp/t4.js:~1] [pc=0x2e9d77e50...
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
1: node::Abort() [node]
2: 0x126389c [node]
3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
5: v8::internal::Factory::NewRawOneByteString(int, v8::internal::PretenureFlag) [node]
6: v8::internal::String::SlowFlatten(v8::internal::Handle<v8::internal::ConsString>, v8::internal::PretenureFlag) [node]
7: v8::internal::String::Flatten(v8::internal::Handle<v8::internal::String>, v8::internal::PretenureFlag) [node]
8: v8::String::WriteUtf8(char*, int, int*, int) const [node]
9: node::StringBytes::Write(v8::Isolate*, char*, unsigned long, v8::Local<v8::Value>, node::encoding, int*) [node]
10: 0x1288fe9 [node]
11: 0x2e9d77e47b2f
zsh: abort (core dumped) node --expose-gc t4.js
I have also noticed that v7.5.0 is several times slower when writing to file.
Activity
mscdex commentedon Feb 10, 2017
I think this is probably expected. You're continuously queuing up write requests to the thread pool, which has a fixed number of threads available.
If you write synchronously (
fs.writeSync()) instead, or you limit the number of outstanding write requests (e.g. equal to the size of the thread pool -- which is 4 by default IIRC), you should not run into this problem.aalexgabi commentedon Feb 10, 2017
@mscdex I understand that some structures may accumulate in memory as long as the buffer is not flushed but note that the memory leak is still present AFTER everything has been wrote to the file and the file was closed.
From:
What unsafe means here? Should the documentation be more specific?
bnoordhuis commentedon Feb 12, 2017
Quite possibly a variation on #8871 (comment) (summary: memory fragmentation, not memory leak) but could also be #11077.
Trott commentedon Jul 26, 2017
Is this close-able at this point or should this remain open?
bnoordhuis commentedon Jul 26, 2017
I don't think there is anything actionable. I'll close it out. Thanks for the bug report, @aalexgabi.
jorangreef commentedon Jul 26, 2017
I think it's actionable if it's an issue with fragmentation.
@aalexgabi's gist should work with Node. Sure, it's pushing the edge with so many temporary buffers but it's a reasonable stress test. Node should be able to handle these kinds of edge cases without being fragile.
This could be fixed through a better allocator.
bnoordhuis commentedon Jul 26, 2017
There are two things here:
Point 1 is not a bug but a peculiarity: since the test case doesn't pass a callback to
fs.write()(which is deprecated), node.js callsprocess.emitWarning()2 million times, exacerbated by 2 million calls toError.captureStackTrace()that cause running time and memory usage to explode. If you add a callback, the test completes in seconds flat.(Should
process.emitWarning()do rate limiting? Maybe, maybe not; that's a complexity/commonality trade-off. I don't expect you would normally hit such pathological behavior in a real-world program.)A non-deprecated calling pattern shows #8871 (comment), memory fragmentation. You say "could be fixed through a better allocator", I say that's not our bug to fix. Take it up with glibc or experiment with
MALLOC_MMAP_THRESHOLD_and friends.EDIT: To be clear, a custom allocator is not out of the question but for other reasons than as a workaround for a glibc deficiency.
jorangreef commentedon Jul 26, 2017
Yes, this is the thing.
Perhaps jemalloc would be another way forward.
Antirez has some comments on moving to jemalloc from glibc a few years back: http://oldblog.antirez.com/post/everything-about-redis-24.html).
Also, Jason Evans from 2011 (https://www.facebook.com/notes/facebook-engineering/scalable-memory-allocation-using-jemalloc/480222803919):
bnoordhuis commentedon Jul 26, 2017
I'm not rabidly opposed to jemalloc (libc interop issues aside) but the "other reasons" I alluded to are exploiting known facts about allocations; e.g., that most memory is allocated and freed on the main thread (no synchronization needed), or that memory for a fs request should come from a different bin because it stays around longer than the temp storage used for flattening a string. That kind of thing.
aalexgabi commentedon Jul 27, 2017
Adding a callback:
Avoids the crash but the leak/fragmentation is still there:
bnoordhuis commentedon Jul 28, 2017
@aalexgabi Yes, I mentioned that in #11289 (comment).
aalexgabi commentedon Sep 15, 2020
To be honest I'm disappointed with the closure of this issue.
The first imagined "real world" example that comes to mind it's a logger used by a service with a highly variable workload. This means that during intense workload if the cpu is faster than the disk for a given period of time, all the memory queued log write calls will generate leaks that will never be recovered in the lifetime of the service.
In a way this means that node applications are "required" to be restarted/killed from time to time if there is no way to implement a back-pressure mechanism for handling IO writes.