performance issue of 4.0.0&4.0.1

[losogithub]

After upgrading from 3.9.* to 4.0.0&4.0.1, my node process's CPU usage increased by more than 200%.
Each http request which uses mongoose costs cpu % 3 times than before.
And when I downgrade back to 3.8.25, everything is OK.

[vkarpov15]

I've noticed some performance degradation, but it seems like you have some more in-depth info. I'll investigate but seeing some sample code would really help

[lbeschastny]

@losogithub do you see the following warning message when you starting your app?

Failed to load c++ bson extension, using pure JS version

If you do, then it's not a mongoose issue. And it would explain your performance issues.

[AntouanK]

@lbeschastny I get that message #2744 (comment)
Any ideas on how to fix that?

[paambaati]

@AntouanK Make sure you have all the build tools installed. Which platform are you on? If you're on OS X, that will be xcode. If you're on a Linux-based distro, that will be gcc, build and make-essential. Once that is in place, install node-gyp and rebuild your modules. That should solve your issue.

[losogithub]

@lbeschastny I had fixed the c++ bson extension issue before I encountered this performance issue. Thank u all the same.

[AntouanK]

@paambaati I'm on CoreOS but I use docker containers ( it doesn't really matter what OS the container is in ).
I'll try to get gcc, build and make-essential in the container I'm running mongoose in, and see if I get the C++ bindings.

I can get gcc, but in debian there are no build and make-essential packages...
There is a build-essential one.
I can see I have make, but still, after installing gcc and build-essential, I get the same error...

[AntouanK]

Turns out I also need the python package...

You can check out the node_modules/mongoose/node_modules/mongodb/node_modules/mongodb-core/node_modules/bson/builderror.log file to see why build fails.

[paambaati]

Oh yeah. I'd recommend 2.7.6 or higher.
On Apr 10, 2015 3:29 PM, "Antonis Karamitros" notifications@github.com
wrote:

Turns out I also need the python package...

You can check out the
node_modules/mongoose/node_modules/mongodb/node_modules/mongodb-core/node_modules/bson/builderror.log
file to see why build fails.

—
Reply to this email directly or view it on GitHub
#2809 (comment)
.

[AHgPuK]

I confirm that I experience big app slowdown - but without bson warning.
Ubuntu 14, MongoDB 3.0.2, Node 0.10.33
After downgrade also everything is OK,

[vkarpov15]

Can you provide me an example of an operation or block of code that you're experiencing a big performance degradation for? Difficult to debug when I don't have anything to go on :)

FWIW I was investigating why my tests became much slower in 4.0.0-rc3 and bisected it down to mongodb-js/mongodb-core@2dd5a5b, which adds a long timeout for some connection synchronization. If you have benchmarks that create a new connection every time you may notice a performance hit due to that.

[AHgPuK]

It is overall slowdown and memory overload. It is very difficult to understand which problem it is - mongoose or driver because one depends on another.
Our app works fine with mongoose 3.8 and crashes with "out of memory" on 4.0 on machine with 1 GB of RAM. After adding 1GB more (2GB RAM) is stopped to crash but takes x2 CPU time of nodejs.
Can you provide a way to test mongoose 4.0 against mongoDB driver 1.4?

P.S. I create persistent connection to replica set once at start of app with keepAlive option as API suggests.
A code sample I run and see degradation is simple SessionModel.findOne.

[AHgPuK]

I just saw an issue on nodejs driver:
cursor routine calls block for a long time with 2.x driver against 3.0.1 mongodb
https://jira.mongodb.org/browse/NODE-420
I think it explains that issue and it is possible to close the issue

[vkarpov15]

Re: mongoose 4 with mongodb driver 1.4, should be possible but will take a fair amount of work to set that up. I think a better approach may be to create a new benchmark suite, because right now we don't really have a working one for mongoose. I'll keep this issue open to track, we'll see how NODE-420 goes.

Also, are you seeing performance degradation just against replica set or against standalone as well?

[AHgPuK]

Oops. I checked slowdown on standalone. I did not check replica set.

[vkarpov15]

Ah I thought you were running against a replica set. Will track the node issue and work on my own benchmarks to see if I can repro. In the meantime, can you provide me a standalone code sample that demonstrates the performance reduction you're seeing? Would be very helpful :)

[AHgPuK]

exports.validate = function(token, callback) {
"use strict";
logger.debug("Session handler :: validate");

token = new TokenModel(token).toJSON();

// Fix token structure to keep consistence with index
var query = {
        token: {
            instanceId: token.instanceId,
            deviceId: token.deviceId,
            time: token.time,
        }
    };


SessionModel.findOne(query)
.exec()
.then(function(doc){

    if(!doc)
    {
        throw new Error('Invalid session');
    }

    logger.debug('Session validated! %j', token);
    callback(null, doc);
})
.onReject(function(err) {
    logger.error(err);
    callback(err);
});

};

[AHgPuK]

I investigated performance issue with node-inspector.
Using mongoose 3.8.25 it works x3 slower than without.
Using mongoose 4.0.1 it works x10 slower.
Results of performance without mongoose using only mongodb driver did not make a difference between versions.

Screenshot using mongoose 4.0.1

Screenshot without mongoose:

As I see - the intensive processing happens in define function of document.js
It is not optimized at all because garbage collector takes a lot of time to work.

My decision for now - can not continue to use mongoose.

[lbeschastny]

@AHDPuK could you please share the code you've used to run your benchmarks?

[AHgPuK]

@lbeschastny
The code I used with mongoose is in previous post.
The only change I did to skip mongoose is to replace findOne to

SessionModel.collection.findOne(query, function(err, doc){

    if(err)
    {
        logger.error(err);
    }
    else
    {
        logger.debug('Session validated! %j', token);
    }

    callback(err, doc);

})

[lbeschastny]

I created my own benchmark to reproduce this performance issue: https://github.com/lbeschastny/mongoose-benchmark

My benchmark creates a MongoDB document with 3000 randomly-filled fields (Strings, Numbers and Dates) and uses this document to benchmark Model.findById and collection.findOne methods with different node.js and mongoose versions.

Here are my results:

Node.js v0.10.30 Mongoose@3.8.26
Benchmark started
        Model.findById:
                rss: 106.6 MB
                heapTotal: 94.34 MB
                heapUsed: 63.54 MB
                elapsed time: 43.55 ms
        collection.findOne:
                rss: 90.76 MB
                heapTotal: 73.7 MB
                heapUsed: 47.06 MB
                elapsed time: 6.69 ms

Node.js v0.10.30 Mongoose@4.0.1
Benchmark started
        Model.findById:
                rss: 114.18 MB
                heapTotal: 104.66 MB
                heapUsed: 52.19 MB
                elapsed time: 42.25 ms
        collection.findOne:
                rss: 89.11 MB
                heapTotal: 73.7 MB
                heapUsed: 43.65 MB
                elapsed time: 3.36 ms

Node.js v0.12.0 Mongoose@3.8.26
Benchmark started
        Model.findById:
                rss: 162.09 MB
                heapTotal: 150.51 MB
                heapUsed: 26.79 MB
                elapsed time: 50.1 ms
        collection.findOne:
                rss: 92.11 MB
                heapTotal: 76.21 MB
                heapUsed: 45.78 MB
                elapsed time: 7.93 ms

Node.js v0.12.0 Mongoose@4.0.1
Benchmark started
        Model.findById:
                rss: 145.59 MB
                heapTotal: 134 MB
                heapUsed: 39.93 MB
                elapsed time: 48.75 ms
        collection.findOne:
                rss: 89.35 MB
                heapTotal: 75.18 MB
                heapUsed: 54.92 MB
                elapsed time: 6.98 ms

I found no trace of performance degradation between versions 3.8 and 4.0.

@AHDPuK, @losogithub, could you please provide more information about your performance problems, including information about your system (OS, node.js and MongoDB versions, etc)?

Could you also run my benchmark on your system to check if it'll reproduce your problem?

It'll be really helpful if we will see some complete code example to reproduce aforementioned performance degradation, including database initialization.

[AHgPuK]

I can guess what is the central problem in my case. This is a response document size. I keep user sessions in collection "sessions". This is only collection with extra large documents because I need to store cached info for each session and not generate data with each request. Size of one document is approximately 1Mb. Exactly post processing of response makes a difference in my case.
Here is an example of document: https://www.dropbox.com/s/svqphdbe0qq1eze/session.zip?dl=0

Schema definition:
var Session = new Schema({
schemaVersion: {
type: String,
"default": "2.00"
},
token: {
type: Token,
index: true,
unique: true
},
createdAt: {
type: Date,
"default": Date.now
},
lastUpdate: {
type: Date,
expires: 3600 * 3,
"default": Date.now
},
apps: {
type: [String],
"default": []
},
search: {
type: [String]
},
appsToCrawl: {
type: [String]
},
userId: {
type: ObjectId,
},
SAID: {
type: ObjectId
},
news: {
type: Object
},
forYou: {
type: Object
},
userData: {
friends: {
type: [ObjectId]
},
friendsApps: {
type: [
{
_id: String,
friends: Number
}
]
},
userId: {
type: ObjectId
},
users: {
type: Number
},
apps: {
counters: {
installed: {
type: Number
},
profile: {
type: Object
}
}
},
recommended: {
type: [String]
},
unfollow: {
type: Array,
"default": []
},
follow: {
type: Array,
"default": []
},
newFollow: {
type: Array,
"default": []
},
followCount: Number,
feature: Object,
},
leaders: {
type: Array,
"default": []
},
searchUser: {
type: Array,
"default": []
},
clientVersion: {
type: Number
},
people: {
around_me: {
type: Object,
"default": null
},
top_followed: {
type: Object,
"default": null
},
like_me: {
type: Object,
"default": null
},
may_know: {
type: Object,
"default": null
}
},
info: {
country: {
type: String
},
deviceName: {
type: String
},
deviceVersion: {
type: String
},
deviceCommonName : {
type: String
},
deviceProperties:{
type:Object
},
lang: {
type: String
},
deviceLang: {
type: String,
},
geo: {
type: Object
},
IPv4: {
type: String
},
IPv6: {
type: String
},
ipCountry: {
type: String
},
ipCountryCode: {
type: String
},
isTablet: {
type: Boolean
}
}
},
{
_id: false
});

[AHgPuK]

P.S. I run it with the same results I described before
Windows 7 and Ubuntu,
mongoDB 3.0.2,
nodejs 0.10.33, 0.12.2

module n is not supported on Windows.

[lbeschastny]

@AHDPuK tahnx!

I replaced my dummy model and randomly-generated data with your example and thus reproduced performance degradation.

I created new branch for you data:
https://github.com/lbeschastny/mongoose-benchmark/tree/real-data

Here are my new results:

Node.js v0.10.30 Mongoose@3.8.26
Benchmark started
        Model.findById:
                rss: 47.03 MB
                heapTotal: 32.96 MB
                heapUsed: 19.64 MB
                elapsed time: 71.78 ms
        collection.findOne:
                rss: 71.77 MB
                heapTotal: 53.06 MB
                heapUsed: 30.12 MB
                elapsed time: 35.68 ms

Node.js v0.10.30 Mongoose@4.0.1
Benchmark started
        Model.findById:
                rss: 174.39 MB
                heapTotal: 158.11 MB
                heapUsed: 107.01 MB
                elapsed time: 209.98 ms
        collection.findOne:
                rss: 78.36 MB
                heapTotal: 56.16 MB
                heapUsed: 24.76 MB
                elapsed time: 13.1 ms

Node.js v0.12.0 Mongoose@3.8.26
Benchmark started
        Model.findById:
                rss: 138.46 MB
                heapTotal: 121.62 MB
                heapUsed: 56.95 MB
                elapsed time: 72.26 ms
        collection.findOne:
                rss: 85.06 MB
                heapTotal: 55.57 MB
                heapUsed: 21.48 MB
                elapsed time: 32.23 ms

Node.js v0.12.0 Mongoose@4.0.1
Benchmark started
        Model.findById:
                rss: 157.42 MB
                heapTotal: 141.21 MB
                heapUsed: 29.78 MB
                elapsed time: 191.6 ms
        collection.findOne:
                rss: 74.3 MB
                heapTotal: 55.57 MB
                heapUsed: 21.63 MB
                elapsed time: 21.62 ms

[lbeschastny]

@AHDPuK I played a bit with your data and boiled it down to the userData.friendsApps field. The rest of your schema have no impact on mongoose performance.

[lbeschastny]

@AHDPuK with your help I found a minimal example reproducing this performance degradation:

var Schems = new mongoose.Schema({
  data: {
    type: [{
      s: String
    }]
  }
});

I also added it to my benchmark: lbeschastny/mongoose-benchmark@f492557

Here are my benchmarking results for a document containing 1000-elements long array of objects (aka sub-documents):

Node.js v0.10.30 Mongoose@3.8.26
Benchmark started
        Model.findById:
                rss: 91.73 MB
                heapTotal: 77.83 MB
                heapUsed: 41.83 MB
                elapsed time: 55.75 ms
        collection.findOne:
                rss: 67.95 MB
                heapTotal: 52.03 MB
                heapUsed: 28.19 MB
                elapsed time: 3.18 ms

Node.js v0.10.30 Mongoose@4.0.1
Benchmark started
        Model.findById:
                rss: 168.67 MB
                heapTotal: 155.01 MB
                heapUsed: 85.08 MB
                elapsed time: 456.54 ms
        collection.findOne:
                rss: 68.55 MB
                heapTotal: 53.06 MB
                heapUsed: 19.5 MB
                elapsed time: 1.51 ms

Node.js v0.12.0 Mongoose@3.8.26
Benchmark started
        Model.findById:
                rss: 141.9 MB
                heapTotal: 128.84 MB
                heapUsed: 75.37 MB
                elapsed time: 64.85 ms
        collection.findOne:
                rss: 71.03 MB
                heapTotal: 56.61 MB
                heapUsed: 31.19 MB
                elapsed time: 4.3 ms

Node.js v0.12.0 Mongoose@4.0.1
Benchmark started
        Model.findById:
                rss: 149.73 MB
                heapTotal: 132.97 MB
                heapUsed: 96.25 MB
                elapsed time: 385.04 ms
        collection.findOne:
                rss: 70.1 MB
                heapTotal: 55.57 MB
                heapUsed: 31.19 MB
                elapsed time: 4.51 ms

[vkarpov15]

Thanks for the repro guys, looks like document arrays are the problem. Your help is much appreciated, I'll look into this over the weekend / early next week.

[lbeschastny]

@vkarpov15 I run another couple of benchmarks, truing to get to the bottom of this issue.

I found that lean queries are not affected by this performance issue, so I assumed that the problem is somewhere in Document#init:

Node.js v0.12.0 Mongoose@4.0.1
Benchmark started
        Document#init:
                rss: 136.16 MB
                heapTotal: 122.64 MB
                heapUsed: 98.71 MB
                elapsed time: 196.95 ms
        Model.findById+lean:
                rss: 68.58 MB
                heapTotal: 56.61 MB
                heapUsed: 21.03 MB
                elapsed time: 5.08 ms
        Model.findById:
                rss: 155.53 MB
                heapTotal: 140.18 MB
                heapUsed: 79.39 MB
                elapsed time: 390.19 ms

Hope you'll find out what's wrong here and fix it.

[lbeschastny]

@vkarpov15 I narrowed it down to DocumentArray#cast function:

        DocumentArray#cast:
                rss: 198.61 MB
                heapTotal: 185.6 MB
                heapUsed: 155.84 MB
                elapsed time: 226 ms

[vkarpov15]

Thanks for the extra info. I don't quite have time to dive into this today but I'll take a look over the weekend if you haven't resolved it by then. PRs are most welcome :)

[lbeschastny]

I narrowed it even more, not to the EmbeddedDocument constructor:

        EmbeddedDocument.constructor:
                rss: 117.28 MB
                heapTotal: 103.04 MB
                heapUsed: 22.76 MB
                elapsed time: 150.34 ms

[lbeschastny]

@vkarpov15, found it!

The most of it was caused by 6ce5a6c commit where you moved a heavy prototype manipulation to the object constructor, which was a very bad idea.

[lbeschastny]

@vkarpov15 just realized that you already fixed it in #2821.

[lbeschastny]

@vkarpov15 I found another troublemaker - it's a Document#$__registerHooksFromSchema.

The problem is that Mongoose sets pre-save and pre-validate hooks for each sub-document in an array. Not sure how to fix it, though.

I think, you should try to do all this validation routine without heavy hooks. Or, you should try to figure out how to move initialization of those build-in hooks out from Document constructor. Even if there is no other way to deal with user-defined hooks, there must be a way to move build-in hooks initialization to the prototype level.

[lbeschastny]

Looks like that's all. All our performance troubles was caused by those two things, and one of them is already fixed with #2863 PR.

@vkarpov15 I'll leave the rest to you.

[vkarpov15]

Thanks for finding these issues. Good catch re: my mistakes with 6ce5a6c, that was far from my best work. The second issue will be ameliorated slightly by #2894, which removes the extra pre('validate') hook (its redundant). But you're right, we should probably avoid adding that pre('save') validate to sub-documents, that's unnecessary because the first thing the hook does is check if its a subdoc.

And I agree about not registering hooks for a document every single time one is created. That's one of the numerous reasons why the plan is to ditch the hooks library entirely and instead use kareem to have more fine-grained control over what context hooks run in. However, in the wise words of Jesse Ventura in Predator, hooks are dug in like an Alabama tick and removing the library is more of a long-term project than a quick bug fix.

[vkarpov15]

Gonna mark this as closed since @lbeschastny solved the regression - the hooks issue goes back to 3.8 and should be fixed by #2754

[lbeschastny]

@vkarpov15 let's be honest, it was already fixed by #2863 PR by the time I've started investigating the problem. 🐱