MongoDB find doesn't close the segment

[peeter-tomberg]

app.js

var newrelic = require ('newrelic');
var MongoClient = require('mongodb').MongoClient;

MongoClient.connect('mongodb://test:[email protected]:10080/newrelic', {}, function (error, db) {

    if (error) {
        console.error(error);
        return;
    }

    newrelic.agent.tracer.transactionProxy(function () {
        var transaction = newrelic.agent.tracer.getTransaction();
        var cursor = db.collection('user').find({});
        cursor.toArray(function (err, results) {
            if (err) {
                console.error(err);
                return false;
            }
            console.log(results);
            cursor.close(function () {
                console.log('Cursor closed....');
            });
            setTimeout(function() {
                console.log('Transaction end...');
                transaction.setName('Testing')
                transaction.end();
            }, 2000)
        });
    })();

});

package.json

{
  "name": "newrelic-mongo-bug",
  "version": "0.0.0",
  "description": "",
  "main": "app.js",
  "repository": "",
  "author": "Peeter Tomberg",
  "dependencies": {
    "newrelic": "~1.2.0",
    "mongodb": "~1.3.23"
  }
}

Results in:

[othiym23]

Thanks for filing this, Peeter!

Fixing this issue would definitely make Mongo numbers more accurate and useful, but requires a couple minor but significant changes to the module's architecture. Right now there's one timer per trace segment, and it can only be stopped once. Proper exclusive time calculation (for transaction breakdowns) requires multiple timers per trace for stream-like objects like MongoDB's cursors, so, for example, that each callback involved as part of consuming the cursor as a document stream gets timed. Switching to timing the segment in terms of the last time a MongoDB cursor was accessed instead of waiting for the entire result set to be consumed would more accurately map to how people actually use MongoDB, especially with Mongoose.

There's a bunch of weird edge cases related to getting all this right in Node's async world, especially because the underlying representation used by New Relic is pretty unfriendly to async concurrency. As such, it may take a little while to get addressed, and may be done as part of a larger project to make New Relic deal better with the async data coming from Node. Patience is advised.

[othiym23]

We made a change (139de31) that should address this issue in New Relic for Node.js 1.4.0, although it's not the 100% fix (which requires the architectural changes I mentioned above). For now, the segments will be closed. Getting accurate exclusive timings is deferred for a later date. I'm going to close this for now, and you can reopen or file a new ticket if the fix we came up with doesn't work for your case.