3

I'm testing performance of Node.js with MongoDB. I know each of these is fine independent of the other, but I'm trying a handful of tests to get a feel for them. I ran across this issue and I'm having trouble determining the source.

The Problem

I'm trying to insert 1,000,000 records in a single Node.js program. It absolutely crawls. We're talking 20 minute execution time. This occurs whether it's my Mac or CentOS, although the behavior is marginally different between the two. It does eventually complete.

The effect is similar to swapping, although it's not (memory never exceeds 2 GB). There are only 3 connections open to MongoDB, and most of the time there's no data being inserted. It appears to be doing a lot of context switching, and the Node.js CPU core is maxed out.

The effect is similar to the one mentioned in this thread.

I try the same using PHP and it finishes in 2-3 minutes. No drama.

Why?

Possible Causes

I currently believe this is either a Node.js socket issue, something going on with libev behind the scenes, or some other node-mongodb-native issue. I may be totally wrong, so I'm looking for a little guidance here.

As for other Node.js MongoDB adapters, I have tried Mongolian and it appears to queue documents in order to batch insert them, and it ends up running out of memory. So that's out. (Side note: I have no idea why on this, either, since it doesn't even come close to my 16 GB box limit--but I haven't bothered investigating much further on that.)

I should probably mention that I did in fact test a master/worker cluster with 4 workers (on a quad-core machine) and it finished in 2-3 minutes.

The Code

Here's my Node.js CoffeeScript program:

mongodb = require "mongodb"
microtime = require "microtime"
crypto = require "crypto"

times = 1000000
server = new mongodb.Server "127.0.0.1", 27017
db = mongodb.Db "test", server
db.open (error, client) ->
  throw error if error?

  collection = mongodb.Collection client, "foo"

  for i in [0...times]
    console.log "Inserting #{i}..." if i % 100000 == 0

    hash = crypto.createHash "sha1"
    hash.update "" + microtime.now() + (Math.random() * 255 | 0)
    key = hash.digest "hex"

    doc =
      key: key,
      foo1: 1000,
      foo2: 1000,
      foo3: 1000,
      bar1: 2000,
      bar2: 2000,
      bar3: 2000,
      baz1: 3000,
      baz2: 3000,
      baz3: 3000

    collection.insert doc, safe: true, (error, response) ->
      console.log error.message if error

And here's the roughly equivalent PHP program:

<?php
$mongo = new Mongo();
$collection = $mongo->test->foo;

$times = 1000000;
for ($i = 0; $i < $times; $i++) {
    if ($i % 100000 == 0) {
        print "Inserting $i...\n";
    }

    $doc = array(
        "key" => sha1(microtime(true) + rand(0, 255)),
        "foo1" => 1000,
        "foo2" => 1000,
        "foo3" => 1000,
        "bar1" => 2000,
        "bar2" => 2000,
        "bar3" => 2000,
        "baz1" => 3000,
        "baz2" => 3000,
        "baz3" => 3000
    );
    try {
        $collection->insert($doc, array("safe" => true));
    } catch (MongoCursorException $e) {
        print $e->getMessage() . "\n";
    }
}
Community
  • 1
  • 1
Matthew Ratzloff
  • 4,518
  • 1
  • 31
  • 35
  • Well, to be fair you don't really know my use case. This is merely a test, one of several. I came across an interesting result and wondered if it applied to Node.js as a whole or this particular module. Either way, understanding the cause helps me better understand how to use Node.js and/or this module more effectively. :-) – Matthew Ratzloff Jun 20 '12 at 00:34
  • Well true point, this can be the client library as well. – hakre Jun 20 '12 at 00:36
  • If the node.js CPU core is maxed out haven't you already found the problem. Any single process JS based application server isn't going to achieve anything near maximum throughput. What happens if you start multiple node.js processes on the same box? To be honest I'm completely mystified as to why node.js is getting any traction on the more professional end of the web app development spectrum for exactly these sorts of reasons but hey. – Remon van Vliet Jun 20 '12 at 08:16
  • The question is why a single-threaded PHP process outperforms a single-threaded Node.js process (of course, with Node "single-threaded" is in quotes) for a given task using the node-mongodb-native adapter. The pegged CPU is only a symptom of the problem. I should probably mention that I did in fact test a master/worker cluster with 4 workers (on a quad-core machine) and it finished in 3 minutes. – Matthew Ratzloff Jun 20 '12 at 16:35
  • Here's what I suspect. My single process crawls because Node is launching a lot of event threads in the background and is repeatedly polling them to see which ones complete. It's the cost of polling behind the scenes that causes it to slow down dramatically. As the number of callbacks increases, it appears the execution time increases logarithmically. – Matthew Ratzloff Jun 20 '12 at 17:06

2 Answers2

2

It sounds like you're running into the default heap limit in V8. I wrote a blog post about removing this limitation.

The garbage collector is probably going crazy and chewing on CPU, since it will constantly execute until you're under the 1.4GB limit.

mensi
  • 9,580
  • 2
  • 34
  • 43
caustik
  • 166
  • 3
  • Perfect, this is the answer I was looking for. On Node.js 0.8.0 I ran `node --trace-gc` (after discovering this option) and found that once it reaches a certain point it will constantly attempt to speed up marking to 1000 (presumably a hard-coded maximum). Of course it continues to fall behind, so it tries to speed up marking again... Eventually, it will VERY slowly begin to mark-sweep again. – Matthew Ratzloff Jun 25 '12 at 20:58
1

What happens if you explicitly return a value at the end of the db.open callback function? Your generated javascript code is pushing all of your collection.insert returns onto a big "_results" array, which would get slower and slower, I imagine.

db.open(function(error, client) {
  var collection, doc, hash, i, key, _i, _results;
  if (error != null) {
    throw error;
  }
  collection = mongodb.Collection(client, "foo");
  _results = [];
  for (i = _i = 0; 0 <= times ? _i < times : _i > times; i = 0 <= times ? ++_i : --_i) {
    ...
    _results.push(collection.insert(doc, {
      safe: true
    }, function(error, response) {
      if (error) {
        return console.log(error.message);
      }
    }));
  }
  return _results;
});

Try adding this at the end of your coffeescript:

    collection.insert doc, safe: true, (error, response) ->
      console.log error.message if error

  return

*Update: * So, I actually tried to run your program, and noticed a few more issues:

The biggest problem is you're trying to spawn a million inserts in a synchronous fashion, which will really kill your RAM, and eventually stop inserting (at least, it did for me). I killed it at 800MB RAM or so.

You need to change the way you're calling collection.insert() so that it works asynchronously.

I rewrote it like so, breaking out a couple of functions for clarity:

mongodb = require "mongodb"
microtime = require "microtime"
crypto = require "crypto"

gen  = () ->
  hash = crypto.createHash "sha1"
  hash.update "" + microtime.now() + (Math.random() * 255 | 0)
  key = hash.digest "hex"

  key: key,
  foo1: 1000,
  foo2: 1000,
  foo3: 1000,
  bar1: 2000,
  bar2: 2000,
  bar3: 2000,
  baz1: 3000,
  baz2: 3000,
  baz3: 3000

times = 1000000
i = times

insertDocs = (collection) ->
  collection.insert gen(), {safe:true}, () ->
    console.log "Inserting #{times-i}..." if i % 100000 == 0
    if --i > 0
      insertDocs(collection)
    else
      process.exit 0
  return

server = new mongodb.Server "127.0.0.1", 27017
db = mongodb.Db "test", server
db.open (error, db) ->
  throw error if error?
  db.collection "foo", (err, collection) ->
    insertDocs(collection)
    return
  return

Which finished in ~3 minutes:

wfreeman$ time coffee mongotest.coffee
Inserting 0...
Inserting 100000...
Inserting 200000...
Inserting 300000...
Inserting 400000...
Inserting 500000...
Inserting 600000...
Inserting 700000...
Inserting 800000...
Inserting 900000...

real    3m31.991s
user    1m55.211s
sys 0m23.420s

Also, it has the side benefit of using <100MB of RAM, 70% CPU on node, and 40% CPU on mongod (on a 2 core box, so it looks like it wasn't maxing out the CPU).

Eve Freeman
  • 32,467
  • 4
  • 86
  • 101
  • That is a good catch and it does reduce the memory footprint by about 150 MB for part of the life of the program, but the problem unfortunately isn't memory. Still, it's definitely a good thing to keep in mind when developing in CoffeeScript and working with large sets. – Matthew Ratzloff Jun 20 '12 at 17:44
  • It should speed it up, also. No? – Eve Freeman Jun 20 '12 at 17:48
  • No--it is CPU bound, not memory bound. The memory does not impact the process in this case. – Matthew Ratzloff Jun 20 '12 at 17:53
  • I'm pretty new to node myself, but it looks like the way to do it is more asynchronously. – Eve Freeman Jun 20 '12 at 22:15
  • Thank you for your addendum. You are correct that in normal cases serializing the inserts is how code like this should be structured, but I was more concerned with WHY this suboptimal code performed badly. @caustik nailed it, but your answer is the practical answer for solving it (that, plus parallelization). – Matthew Ratzloff Jun 25 '12 at 21:03