0

I am running a GPS listener program. It receives data from GPS devices, decodes, prepares a final data object and then stores the data in Database. I am trying to insert documents to mongodb from nodejs with the following code - (using node mongodb native driver)

var mong = require('mongodb');
var MongoClient = mongo.MongoClient
, format = require('util').format;

MongoClient.connect('mongodb://user:pass@a.b.c.d:27017/dbname', function(err, db) {
        if(err) {console.log("mongo connect error " + err); throw err};

        gpsdb = db;
        console.log("Database Ready");
        listener.listen(port);
        console.log("Listener Started on: " + port);
    });

// code to generate the object to insert - d_obj

var collection = gpsdb.collection(d_obj);
d_obj._id = new mong.ObjectID;
collection.insert(d_obj, {safe:true}, function(err, docs) {
    if (err) { console.log("mongo insert query error " + err); return; }
    console.log("Inserted 1 rec " + d_obj.imei);
    console.dir(docs);

});

The inserts happen for 2-3 minutes after starting the program. After that insertion stops. However, the console logs keep coming.

Sample Log -

Inserted 1 rec 358811020044291
[ { dt_server: '2014-12-12 05:56:14',
 dt_tracker: '2014-12-12 05:56:09',
 lat: 19.123456,
 lng: 73.123456,
 angle: 81,
 speed: '47',
 signal_gsm: 3,
 signal_gps: 4,
 alarm: 'pcut',
 odo: 'y',
 offset: 0,
 time_stamp: 1418363774454,
 ltime: '2014-12-12 05:56:09',
 proto: 12,
 imei: '123456789123456',
 save_mysql: 'no',
 altitude: 0,
 _id: 548a837e4c73ebaef72d0073 } ]

The console.dir(doc) should execute only if the query was executed properly. I am not getting any errors or warnings. I am getiing this console log for every data object processed. But Inserts are not happening after the first few minutes.

When I test the program with 1 device sending data, it works flawlessly for hours. All data is inserted properly. But when I run it with about 2000 devices connected, the silent fail happens.

I have tried by removing the properties from the data object (d_obj) which has null value. That did not help.

I have not defined any schema or data types anywhere.

Possible Reason

It seems to be a locking issue for async inserts. My program on nodejs sends many parallel inserts. When I run the program normally (in async manner), following is the mongostat output -

connected to: 127.0.0.1
insert  query update delete getmore command flushes mapped  vsize    res faults        locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
138     *0      1     *0      43    28|0       0   496g   992g  10.8g      1 ilogistek:144.8%          0       4|0     0|1    93k   101k    40 rs0  PRI   00:15:12 
143     *0      1     *0      70    73|0       0   496g   992g  10.8g      1 ilogistek:176.2%          0       6|0     0|1   106k   108k    40 rs0  PRI   00:15:13 
125     *0      1     *0      60    60|0       0   496g   992g  10.9g      2 ilogistek:124.2%          0       5|0     0|1    94k    95k    40 rs0  PRI   00:15:14 
181     *0      1     *0      77    96|0       0   496g   992g    11g      0 ilogistek:149.8%          0       6|0     0|1   135k   137k    40 rs0  PRI   00:15:15 
91     *0      1     *0      47    45|0       0   496g   992g  11.1g      0 ilogistek:127.0%          0       6|0     0|1    68k    70k    40 rs0  PRI   00:15:16 
211     *0      3     *0      74    94|0       0   496g   992g  11.2g      2 ilogistek:138.6%          0       6|0     0|1   152k   156k    40 rs0  PRI   00:15:18 
250     *0      2     *0      71    86|0       0   496g   992g  11.2g      5 ilogistek:203.9%          0      10|0     0|1   174k   176k    40 rs0  PRI   00:15:19 
270     *0      3     *0      76   111|0       0   496g   992g  10.9g      3  ilogistek:99.2%          0       5|0     0|1   197k   200k    40 rs0  PRI   00:15:20 
137     *0      3     *0      54    48|0       0   496g   992g  10.9g      8 ilogistek:137.7%          0       5|0     0|1    97k   100k    40 rs0  PRI   00:15:21 
203     *0      1     *0      83   114|0       0   496g   992g    11g      9 ilogistek:154.8%          0       4|0     0|1   153k   152k    40 rs0  PRI   00:15:22 

On The other hand, when I force the writes in a synchronous manner (next write goes at the callback of the previous write), the locking does not happen and writes per second increases many times.

insert  query update delete getmore command flushes mapped  vsize    res faults       locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
1670     *0      1     *0     321   515|0       0   496g   992g  11.4g      0 ilogistek:15.7%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:47 
1830     *0      1     *0     344   621|0       0   496g   992g  11.4g      0 ilogistek:10.3%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:48 
1767     *0      1     *0     330   571|0       0   496g   992g  11.4g      1 ilogistek:14.5%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:49 
1726     *0      1     *0     337   599|0       0   496g   992g  11.4g      0 ilogistek:11.9%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:50 
1743     *0      1     *0     343   590|0       0   496g   992g  11.4g      0 ilogistek:10.9%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:51 
1758     *0      1     *0     336   605|0       0   496g   992g  11.4g      0 ilogistek:12.2%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:52 
1657     *0      1     *0     344   625|0       0   496g   992g  11.4g      0  ilogistek:9.9%          0       0|0     0|1     1m     1m    19 rs0  PRI   00:24:53 
1688     *0      1     *0     342   567|0       0   496g   992g  11.4g      0 ilogistek:10.6%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:54 
1689     *0      1     *0     344   610|0       0   496g   992g  11.4g      0 ilogistek:10.1%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:55 
1780     *0      1     *0     340   596|0       0   496g   992g  11.4g      0 ilogistek:10.8%          0       0|0     0|0     1m     1m    19 rs0  PRI   00:24:56

I cannot run my program in a synchronous manner as that will beat the very purpose of this technology stack.

Is there something obvious I am missing.

Gurus, please help!

Sudipta
  • 1
  • 1
  • Can this be a locking issue? I am using Mongo 2.6 version. There is no lock related error or warning message similar to "Lock wait timeout" message of mysql in the program log. – Sudipta Dec 12 '14 at 09:58
  • I have not enabled Journaling in the query. I do not know if it is enabled in the mongodb. Also worth mentioning is that this is a 2 machine replica setup. I am trying to write to the primary and hoping that writes will be synced to the replica system automatically without any specific code in the query. – Sudipta Dec 12 '14 at 10:00
  • I have not done any indexing on my collections except for the _id field. Will that help? From MongoDb Official Site, I read this (below) and hence did not do indexing. This is absolutely killing my read speeds, but I will cross one bridge at a time. " After every insert, update, or delete operation, MongoDB must update every index associated with the collection in addition to the data itself. Therefore, every index on a collection adds some amount of overhead for the performance of write operations." – Sudipta Dec 12 '14 at 19:06

0 Answers0