NodeJS + Mongodb performance issues

Question

I have a nodejs + mongodb application connecting like so:

var dbConfig = new mongo.Server(config.db.host, config.db.port, {auto_reconnect: true, poolSize: 20});

var db = new mongo.Db(config.db.name, dbConfig);

when benchmarking (using apache ab), found that it struggles(time >= 1 sec) when concurrent connections are > 20 (even 2 or more concurrent connections seems to increase the times linearly):

[
    {
        "key": "mongoQuery1",
        "min": 2,
        "max": 598,
        "mean": 387.60683760683764,
        "sd": 134.56045668980255,
        "variance": 18106.51650456823
    },
    {
        "key": "mongoQuery2",
        "min": 8,
        "max": 149,
        "mean": 73.14120370370358,
        "sd": 25.141715811881994,
        "variance": 632.1058739654371
    },
    ...
]

The above is the output from the profiling server i used to capture profiling info from the node app. So basically, i've put things like this to profile the app:

var start = new Date().getTime();

db.collection('TheCollection', query, function(err, col) {
  col.find(query).toArray(function(err, items) {
    var elapsed = new Date().getTime() - start;
    profiler.send('mongoQuery1', elapsed);
  });
});

Note the collection size is minimal (700 records), and the collections are all indexed accordingly to the queries.

I'm stuck for ideas, anyone have idea why performance is so bad?

EDIT:

for a simple query like:

db.user_permission.find({ username: 'a', permission_type: 'vehicle'})

with the user_permission having the index:

db.user_permission.ensureIndex({username: 1, permission_type: 1});

The time increases linearly with concurrent users

EDIT 2

Tried turning on profiling for mongod (--profile=2 --slowms=100)

everytime I run ab against it, the db gets corrupted, with the following in the mongod logs:

Wed Nov 21 10:41:54 [conn4] creating profile collection: knightsbridge.system.profile
Wed Nov 21 10:41:54 [FileAllocator] allocating new datafile /Users/dzhu/data/mongodb/knightsbridge.ns, filling with zeroes...
Wed Nov 21 10:41:54 [FileAllocator] creating directory /Users/dzhu/data/mongodb/_tmp
Wed Nov 21 10:41:54 [FileAllocator] done allocating datafile /Users/dzhu/data/mongodb/knightsbridge.ns, size: 16MB,  took 0.018 secs
Wed Nov 21 10:41:54 [FileAllocator] allocating new datafile /Users/dzhu/data/mongodb/knightsbridge.0, filling with zeroes...
Wed Nov 21 10:41:54 [FileAllocator] done allocating datafile /Users/dzhu/data/mongodb/knightsbridge.0, size: 64MB,  took 0.152 secs
Wed Nov 21 10:41:54 [conn5] Assertion: 10334:Invalid BSONObj size: 0 (0x00000000) first element: EOO
0x10037637b 0x1000afc2e 0x1000b005c 0x10001ea53 0x100233529 0x1002a9b0b 0x1001a0a9f 0x10069518b 0x1002a2a4e 0x1005ca15e 0x10064a0ca 0x100018681 0x10019302c 0x1005a7823 0x7fff8a42f8bf 0x7fff8a432b75 
 0   mongod                              0x000000010037637b _ZN5mongo15printStackTraceERSo + 43
 1   mongod                              0x00000001000afc2e _ZN5mongo11msgassertedEiPKc + 206
 2   mongod                              0x00000001000b005c _ZN5mongo11msgassertedEiRKSs + 12
 3   mongod                              0x000000010001ea53 _ZNK5mongo7BSONObj14_assertInvalidEv + 1475
 4   mongod                              0x0000000100233529 _ZN5mongo13unindexRecordEPNS_16NamespaceDetailsEPNS_6RecordERKNS_7DiskLocEb + 265
 5   mongod                              0x00000001002a9b0b _ZN5mongo11DataFileMgr12deleteRecordEPKcPNS_6RecordERKNS_7DiskLocEbbb + 587
 6   mongod                              0x00000001001a0a9f _ZN5mongo16NamespaceDetails11cappedAllocEPKci + 1535
 7   mongod                              0x000000010069518b _ZN5mongo16NamespaceDetails5allocEPKciRNS_7DiskLocE + 123
 8   mongod                              0x00000001002a2a4e _ZN5mongo11DataFileMgr17fast_oplog_insertEPNS_16NamespaceDetailsEPKci + 126
 9   mongod                              0x00000001005ca15e _ZN5mongo7profileERKNS_6ClientERNS_5CurOpE + 3134
 10  mongod                              0x000000010064a0ca _ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE + 4010
 11  mongod                              0x0000000100018681 _ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE + 257
 12  mongod                              0x000000010019302c _ZN5mongo3pms9threadRunEPNS_13MessagingPortE + 1084
 13  mongod                              0x00000001005a7823 thread_proxy + 163
 14  libsystem_c.dylib                   0x00007fff8a42f8bf _pthread_start + 335
 15  libsystem_c.dylib                   0x00007fff8a432b75 thread_start + 13

mongod version:

mongod --version
db version v2.2.0, pdfile version 4.5
Wed Nov 21 10:47:24 git version: f5e83eae9cfbec7fb7a071321928f00d1b0c5207

Also

Apart from the default nodejs driver poolSize of 1, does mongod place restrictions on the number of concurrent connections allowed?

Answer 1

To use mongo db and node js i found a problem with https://docs.mongodb.com documentation.

This worked for me:

• To set profiling level: const set = await db.setProfilingLevel('all')

• To read the profiling:

code

function profile (db, limit = 10) {
  const mc = db
  return new Promise((resolve, reject) => {
    mc.collection('system.profile').find().limit(limit)
      .sort({ ts: -1 }).toArray((err, res) => {
        if (err) return reject(err)
        resolve(!!res && !!res[0] && res)
      })
  })
}

Answer 2

Dzhu, A bunch of things:

• Did you try this query from the mongo shell? Can you try running it at the shell and also use the .explain() function to get an idea of the server execution time? This will help you verify that your index is correct, and should help isolate if the performance issue is at the client side or server side.

• Do you have writes happening at the same time? Is this piece of code you provided the only workload for the database while your benchmark is running, or is there more going on at the same time?

• Use the mongostat utility (see mongodb docs) while your benchmark is running. This will give you an idea of what the server is doing in real time. In particular, look at the lock %, and the qr/qw columns. The qr/qw columns tell you how many read + write operations are queued (i.e., blocked and waiting to execute).

• Be aware that turning on the mongo server profiler to level 2 (--profile=2) will cause the server to log ALL operations, which impacts database performance severely. Use --profile=1 to log only the operations slower than slowMs. Then after your benchmark is done, look at the contents of db.system.profile for details on any slow operations that the server executed.

This should help you get started.