New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Memory leak in db.batch #171

Closed
fergiemcdowall opened this Issue Aug 14, 2013 · 99 comments

Comments

Projects
None yet
@fergiemcdowall
Copy link

fergiemcdowall commented Aug 14, 2013

Hei

Maintainer of search-index and Norch here :)

There seems to be a memory leak in db.batch. When inserting thousands of batch files with db.batch the memory allocation of the parent app shoots up rather alarmingly, and does not come down again.

This issue has appeared in the last few weeks

Any ways to manually free up memory or otherwise force garbage collection?

F

@dominictarr

This comment has been minimized.

Copy link
Contributor

dominictarr commented Aug 14, 2013

do you have a test example that reproduces this?
I'm seeing similar stuff running npmd - which is also doing indexing,
I think this can happen if you queue up loads of writes at once?

@dominictarr

This comment has been minimized.

Copy link
Contributor

dominictarr commented Aug 14, 2013

what I meant to say, is that I've encountered a similar problem,
but I think it was just a flow control issue (just trying todo to many things at once)
it's easy to queue up many more operations than leveldb can take.
Actually, balancing this is a problem that has been encountered in other areas.

#153

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Aug 14, 2013

Test example: reading in the test dataset in the Norch package- It generates about 400000 entries (I think) from 21000 batch files of about 150-200 entries.

Yes, in the past I have also managed to queue up way to many operations, leading to huge server hangs. Now however, search-index reads in batches in serial (one after the other). This seems to be more stable, but leads to a big memory leak in db.batch.

@dominictarr

This comment has been minimized.

Copy link
Contributor

dominictarr commented Aug 14, 2013

I've found that large batches work pretty well - how many items do you have in your batches?

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 14, 2013

We need a simple test case for this so we can replicate the behavior and track it down and also we need to know whether this is new behavior or has been present for a while. There was a LevelDOWN release this week that contains lots of new C++ which could possibly be leaky but it'd be nice to know f this is recent behavior.

Also note that LevelDB does have some behavior that can look like a leak when you're doing heavy writes. Initially it'll just climb right up and not look like its going down but it eventually comes right back down and settles there. I don't think I have a graph of this but that'd probably be helpful to weed this kind of thing out.

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Aug 15, 2013

@dominictarr its just over 21000 batch files of maybe 1-200 entries each

@rvagg OK- I will throw together a gist

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Aug 15, 2013

@rvagg See https://gist.github.com/fergiemcdowall/6239924

NOTE: this gist demonstrates the memory jump (about 3gb on my machine) when inserting many batches to levelUP, although I cant replicate the out-of-memory error I am experiencing when inserting to levelUP from Express.js- there the cleanup doesnt happen unless there is a start-stop of the application.

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 15, 2013

added an adjusted version to the gist that gives some breathing space to V8 to let the callbacks come in.

increasing the total number of batches triggers the problem you're talking about:

FATAL ERROR: JS Allocation failed - process out of memory

so there's something there but I'm not sure where and whether it's a real memory leak on our end or not (could plausibly be up the stack or down the stack!).

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Aug 15, 2013

OK- thanks for the tips- that breathing space was a good idea

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Aug 15, 2013

@rvagg could you push the adjusted version to the gist? :)

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 15, 2013

see the comment in the gist

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Aug 15, 2013

Aha- got it, cheers!

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 15, 2013

if I run the same stuff against leveldown directly I get exactly the same behaviour so it's not in levelup.

I'm still not entirely convinced this isn't a leveldb thing. if you run leak-tester.js in the tests directory of leveldown and watch it over time you'll see memory usage balloon and then settle back down again over time, it's odd behaviour but I imagine if you push hard enough you could make that ballooning push you over Node's limit. Perhaps that's what's happening here?

I've also opened a leakage branch of leveldown with some minor things I've found so far.

@No9

This comment has been minimized.

Copy link
Member

No9 commented Aug 20, 2013

The GC plot makes for scary reading https://gist.github.com/No9/fa818a9d63d22551a837 (See plot at bottom of page)
We could have hit a known issue but I need to definitively map the node.js group thread to our situation.

@No9

This comment has been minimized.

Copy link
Member

No9 commented Aug 20, 2013

Here is a flame graph of the execution over 20 mins.

The leveldb core library is out on the left which would suggest to me that our issue is in node or our JS as opposed to the leveldb code.

Alt text

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 21, 2013

that's an odd flamegraph.. for 20 mins worth of work there's a lot of string and module stuff going on in there and I can't see much related to levelup/leveldown. Can you skip the use of lorem-ipsum since it seems to be getting in the way and see what it does with plain Buffers with crypto.randomBytes(x) or Strings if you want crypto.randomBytes(x).toString('hex') (both cases are interesting since they have to do different things).

@No9

This comment has been minimized.

Copy link
Member

No9 commented Aug 21, 2013

Yup and I will also provide one that filters on doBatch so we can see if that sheds any light.

@No9 No9 referenced this issue Aug 22, 2013

Closed

Windows memory leak? #55

@No9

This comment has been minimized.

Copy link
Member

No9 commented Aug 22, 2013

@rvagg here is the flamegraph you were looking for.
This appears to be more readable This is a ten minute sample and the app Seg Faulted so I have a coredump I can run ::filtjsobjects on if I can get hold of the right V8.so.
CryptoOutput

@No9

This comment has been minimized.

Copy link
Member

No9 commented Aug 22, 2013

@dominictarr suggested compaction and now we have a clearer flamegraph that could be worth some investigation I'll run a trace on

leveldb::DBImpl::BackgroundCompaction()
leveldb::DBImpl::MaybeScheduleCompaction()
leveldb::DBImpl::FinishCompactionOutputFile()
leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*)

And try and get a correlation by timestamping the above and GC so we can see possible cause and effect:

(Edit)
See this link for more detail on the current GC metrics.
https://gist.github.com/No9/4f979544861588945788

Maybe compaction is causing demands on system resources that is forcing aggressive GC by V8?

@heapwolf

This comment has been minimized.

Copy link
Member

heapwolf commented Aug 23, 2013

As I said to @dominictarr it could be compaction kicking in, but this might not be a problem at all. Im not sure, but I think that leveldb::DBImpl::BackgroundCompaction() is designed to run when it can, as much as it can.

@No9

This comment has been minimized.

Copy link
Member

No9 commented Aug 23, 2013

OK So actual compactions over a 10min period look like the following (Milliseconds)

121.787329
993.087684
1223.09732
2774.197186
988.637749

The full range of data is available here in the funky github tsv format
https://github.com/No9/datadump/blob/master/gc-vs-comp.tsv
(You can filter for 'Do Compaction' at the top All the other compaction calls are in there too)

While nearly 3 seconds is not optimal and it isn't clear how this would be/is impacting.
(I was hoping for longer compaction throttled by GC)

I think I am going to go for looking at memory paging next but I will also keep chasing the V8.so as analysis of the core dump could be handy.

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 29, 2013

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 29, 2013

@juliangruber

This comment has been minimized.

Copy link
Member

juliangruber commented Aug 29, 2013

did you try using the chained batch, eg db.batch().put()......write() ?

@rickbergfalk

This comment has been minimized.

Copy link

rickbergfalk commented Aug 29, 2013

I'm not so sure this is just a batch issue anymore. I tried loading data via looping single puts, and I eventually hit the same out-of-memory error. Puts with {sync: true} still leak, it just takes a lot longer to get there.

var levelup = require('level');
var db = levelup('./leakydb', {valueEncoding: 'json'}); // modifying cache size here doesn't help

var putOne = function (i) {
    var i = i + 1;
    // log a little message every 10,000 puts
    if (i % 10000 == 0) {
        console.log(i + " ops   " + (new Date()).toISOString());
    }
    // if we're under 9,000,001 ops, do another put, otherwise stop
    if (i < 9000001) {
        var keyFriendlyI = i + 1000000; // add a million so its sort friendly
        var key = "aKeyLabel~" + keyFriendlyI;
        var value = {
            i: i,
            createdDate: new Date(),
            someText: "I thought that maybe single puts would make it further than the batch approach",
            moreText: "but that isn't necessarily true.",
            evenMoreText: "This hits a FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory."
        };
        // tried setting {sync: true} here and we still run out of memory 
        // it just takes a lot longer to get there
        db.put(key, value, function (err) {
            if (err) {
                console.log(err);
            } else {
                putOne(i);
            }
        });
    } else {
        console.log("Finished!");
    }
};
putOne(0);
@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 29, 2013

I concur, my initial testing suggests it's deeper than batch

@dominictarr

This comment has been minimized.

Copy link
Contributor

dominictarr commented Aug 29, 2013

hmm, so, what happens if you run leveldown directly, without levelup?

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Aug 29, 2013

@tjfontaine I think we need some SmartOS magic to hunt down some kind of memory leak. It's likely in the C++ of LevelDOWN, perhaps even has something to do with the way Node interacts with LevelDB. How's that blog post coming along about finding leaks? Some pointers would be nice.

@tjfontaine

This comment has been minimized.

Copy link

tjfontaine commented Aug 29, 2013

I haven't finished the blog post, so here is a list of steps, some are obvious they are not meant to be patronizing, just for those who also might wander into this thread.

  • mlogin
    • requires an active joyent account, or if you already have a smartos/illumos based instance somewhere else get there
  • git clone ...
  • npm install
  • UMEM_DEBUG=default node myLeakyScript.js &
    • you can also use screen or tmux instead of running in the background, the point is it should be running for the next steps
    • if you're using a library that doesn't link against libumem or links against something else for its memory allocation you can use LD_PRELOAD=libumem.so UMEM_DEBUG=default node myLeakyScript.js to force the dependency chain to use libumem allocators.
  • ps -ef | grep node
    • find the pid of your node process
  • gcore <pid>
    • creates a file named core.<pid> in $CWD
  • mdb core.<pid>
  • ::findleaks
    • This is only going to show you leaks it can verify on the C/C++ side of things, it's not going to be able to diagnose JS leaks
    • You're looking for output that looks roughly like

CACHE LEAKED BUFCTL CALLER 08072c90 1 0807dd08 buf_create+0x12 08072c90 1 0807dca0 func_leak+0x12 08072c90 1 0807dbd0 main+0x12

  • 0807dd08::bufctl_audit
    • The third field is a bucket you can diagnose, the result of this will show you the stack trace for where the leaked memory was alloc'd

Catch me in IRC if there are more details you need or want an extra pair of eyes

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Oct 9, 2013

@maxogden I have leveldown-hyper fixed up and released, you'll have to let me know if there are any compile errors (or even warnings actually, it'd be nice to get rid of those too) on OSX, it's compiling on Linux but it's a stab in the dark for me for OSX.

use level-hyper in place of level, it should be a drop-in replacement so you don't have to mess around with plugging leveldown-hyper in to levelup.

@mcollina mcollina referenced this issue Oct 14, 2013

Closed

Memleak #40

@nornagon

This comment has been minimized.

Copy link

nornagon commented Oct 29, 2013

fwiw, I hit FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory trying to transform a 3-million-row database with ReadStream and WriteStream. The leak also appears to be there with batch(); I'm working around it for now by exec()ing another node once process.memoryUsage() exceeds a certain amount. But this sucks :(

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Oct 29, 2013

@nornagon chained batch or array batch?

@nornagon

This comment has been minimized.

Copy link

nornagon commented Oct 29, 2013

Array.

On Tuesday, 29 October 2013, Rod Vagg wrote:

@nornagon https://github.com/nornagon chained batch or array batch?


Reply to this email directly or view it on GitHubhttps://github.com//issues/171#issuecomment-27284281
.

j

@brycebaril

This comment has been minimized.

Copy link
Member

brycebaril commented Oct 29, 2013

You definitely want chained batch for that -- switching to it here https://github.com/brycebaril/level-bufferstreams/blob/master/write.js#L41 made a vast improvement on memory.

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Oct 31, 2013

We are getting the same FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory in LevelGraph too. Sigh. The discussion is here: levelgraph/levelgraph#40.

It gets two different behavior on levelup 0.12 and 0.17.

On 0.12 it gets to a halt after writing around 1.200.000 records, the CPU skyrockets but the memory usage stay steady, then write something more and then stops again. It continues doing so, on and off, for every of the following 300.000 records.

On 0.17 it keeps writing, but the memory usage explodes. In the heap I see my keys, values and callbacks passed to batch (I'm using level-writestream). It is writing to the database, as I see it growing. As far as I see it, LevelDown is not freeing some stuff, or it is calling the batch callback too early.

Anybody has any clue on this?

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 3, 2013

I think I made some serious progress. I actually was able to insert 12 millions non-ordered pairs into levelup using only 300MB of RAM. I used by branch of level-ws (Level/level-ws#1) that uses the chainable batch instead of the array batch. So, I used regular streams.

The same code segfault on node v0.10.21, but it works perfectly on node v0.11.8.
It segfault reliably at some point, but I cannot reproduce it on pure leveldown/levelup: as my data is coming from a file, I'm guessing something weird is going on.
Anybody with some serious C++-fu to take it from here? Or to guide me to the culprit.

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 3, 2013

This is the backtrace I am getting from gdb.

#1  leveldb::WriteBatchInternal::ByteSize () at /Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.9.sdk/usr/include/c++/4.2.1/bits/basic_string.h:36
#2  0x0000000103911d54 in leveldb::DBImpl::BuildBatchGroup (this=0x100c00b10, last_writer=0x103b7ad88) at ../deps/leveldb/leveldb-1.14.0/db/db_impl.cc:1228
#3  0x00000001039117d2 in leveldb::DBImpl::Write (this=0x100c00b10, options=@0x110e5c980, my_batch=<value temporarily unavailable, due to optimizations>) at ../deps/leveldb/leveldb-1.14.0/db/db_impl.cc:1177
#4  0x0000000103904a0b in leveldown::Database::WriteBatchToDatabase (this=<value temporarily unavailable, due to optimizations>, options=0x1018a8c00, batch=0xc) at ../src/database.cc:74
#5  0x0000000103902e7f in leveldown::Batch::Write (this=<value temporarily unavailable, due to optimizations>) at ../src/batch.cc:30
#6  0x00000001039043c5 in leveldown::BatchWriteWorker::Execute (this=0x1138e8300) at ../src/batch_async.cc:25
#7  0x000000010012c8d8 in worker (arg=<value temporarily unavailable, due to optimizations>) at ../deps/uv/src/unix/threadpool.c:74
#8  0x00000001001232e3 in uv__thread_start (ctx_v=<value temporarily unavailable, due to optimizations>) at ../deps/uv/src/uv-common.c:322
#9  0x00007fff88706899 in _pthread_body ()
#10 0x00007fff8870672a in _pthread_start ()
#11 0x00007fff8870afc9 in thread_start ()
@ralphtheninja

This comment has been minimized.

Copy link
Member

ralphtheninja commented Nov 3, 2013

static size_t ByteSize(const WriteBatch* batch) {
  return batch->rep_.size();
}

There's basically two things that can go wrong here. Either the batch parameter is NULL, or it's pointing to dead memory, i.e. someone has deleted the pointer.

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 3, 2013

I think it's NULL:

Program received signal EXC_BAD_ACCESS, Could not access memory.
Reason: 13 at address: 0x0000000000000000
[Switching to process 37040 thread 0x2503]
std::string::size () at basic_string.h:605
605           size() const
@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 3, 2013

OK, it's not NULL, as it is asserted, so it's dead memory.

I'm hitting this precondition:

// REQUIRES: Writer list must be non-empty
// REQUIRES: First writer must have a non-NULL batch
WriteBatch* DBImpl::BuildBatchGroup(Writer** last_writer) {
  assert(!writers_.empty());
  Writer* first = writers_.front();
  WriteBatch* result = first->batch;
  assert(result != NULL);

  size_t size = WriteBatchInternal::ByteSize(first->batch);

It seems the rep_ gets GCed after the write, but leveldb internals still need it.

@ralphtheninja

This comment has been minimized.

Copy link
Member

ralphtheninja commented Nov 3, 2013

From node-leveldown/deps/leveldb/leveldb-1.14.0/db/db_impl.cc

// REQUIRES: Writer list must be non-empty
// REQUIRES: First writer must have a non-NULL batch
WriteBatch* DBImpl::BuildBatchGroup(Writer** last_writer) {
  assert(!writers_.empty());
  Writer* first = writers_.front();
  WriteBatch* result = first->batch;
  assert(result != NULL);

  size_t size = WriteBatchInternal::ByteSize(first->batch);
..
}

We need to make sure that's the case. Before ByteSize() is called above add a logging line, e.g.:

  printf("batch pointer: %x\n", first->batch);
@ralphtheninja

This comment has been minimized.

Copy link
Member

ralphtheninja commented Nov 3, 2013

Ok, nevermind my last comment. I wrote it before I saw your comment :)

@ralphtheninja

This comment has been minimized.

Copy link
Member

ralphtheninja commented Nov 3, 2013

Do you know for sure that the asserts fire if something is wrong? Some only enable asserts in e.g. debug mode.

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 3, 2013

Confirming it. the first->batch pointer is there.

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 3, 2013

While debugging my segfault issue, I think I got the problem for the memory footprint of batches. Given my scarce C++ skills I might be wrong, but check out Level/leveldown#70.

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Nov 11, 2013

@tjfontaine managed to track down a missing HandleScope in core, I'm not sure yet if this impacts us (I honestly don't understand what HandleWrap::Close & HandleWrap::OnClose are used for).

Until this makes it into a release, someone on this thread who can reproduce this problem could try patching Node source and running against that. See the patch here https://gist.github.com/tjfontaine/7394912 - basically you just need HandleScope scope above the MakeCallback in src/handle_wrap.cc.

Had anyone come up with a very simple script that will reproduce this problem reliably so the rest of us can dig?

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Nov 11, 2013

oh, and that dtrace script in the gist might be helpful, but currently we're (naughtily) not using MakeCallback yet, but we need to do this, particularly to properly support domains I believe, see Level/leveldown#62

@tjfontaine

This comment has been minimized.

Copy link

tjfontaine commented Nov 11, 2013

I am working to make the script more generic, but the way v8 inlines a bunch of things it's difficult to get the probe point to work on handle creation, but I'm hoping to have a good solution for it soon.

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Nov 11, 2013

and ftr, the last mem leak we squashed in leveldown was a missing HandleScope although I did a bit of an audit then to look for any more and nothing stood out

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Nov 18, 2013

I believe this is fixed now in LevelDOWN@0.10.0 which comes with LevelUP/Level@0.18.0. Can everyone who's had the problem try it out and report back so I can close this?

@rickbergfalk

This comment has been minimized.

Copy link

rickbergfalk commented Nov 18, 2013

I tried this out and I think its resolved! Thanks everyone!

I loaded a 4 million document/2.6 GB leveldb with level 0.18.0 and it finished successfully. My node process started at 160 MB and finished at 240 MB. With previous versions my process would hit 1.6 GB after loading the initial 10% of my documents, slow to a crawl and then die shortly after that.

@fergiemcdowall

This comment has been minimized.

Copy link
Author

fergiemcdowall commented Nov 18, 2013

Wow! So fast! So little memory!

Works for me, so closing issue...

Thanks for the great fix!

F

fergiemcdowall added a commit to fergiemcdowall/search-index that referenced this issue Nov 18, 2013

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Nov 18, 2013

Just to point out that I got an overall 25% increase in writing speed. I'm writing around 120.000 k-v pair per second in LevelGraph.
It was really worth the work! 👯

@rvagg

This comment has been minimized.

Copy link
Member

rvagg commented Nov 18, 2013

I wrote details here if you want the gory innards of what's in leveldown@0.10 http://r.va.gg/2013/11/leveldown-v0.10-managing-gc-in-native-v8-programming.html

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment