Why do Mongoose v6 and v7 cause a significant increase in garbage collections and event loop latency compared to v5?

[emilisaksson]

Prerequisites

• I have written a descriptive issue title
• I have searched existing issues to ensure the performance issue has not already been reported

Last performant version

5.12.4

Slowed down in version

6.11.1

Node.js version

16.18.0

🦥 Performance issue

Background:
We have been trying to migrate from Mongoose v5 to v6 in our SaaS platform for the past year with no luck. The issues described here also occurs when running Mongoose 7.
Our software have a decent amount of web traffic(about 25 requests per second) and is using a single MongoDB Atlas cluster where each SaaS client is using its own database.
The software is hosted on Heroku.

The issue:
When we deploy a version of our software that is using Mongoose 6 or 7 it runs fine for up to an hour, then we start to see an increase in number of garbage collections, time spent in garbage collection, and event loop latency. This continues until the servers event loop is completely hogged and cannot handle any more incoming requests.
The memory usage is unaffected, so it doesn't seem to be a memory leak.

Steps to Reproduce

The code:

Upon start, we create a database connection with a pool of 300 connections:

global.databaseConnection = await mongoose.createConnection(global.config.dbConnectionString, {
	maxPoolSize: 300,
	minPoolSize: 300
});

When a request for a specific client is received, a connection to that specific clients database is drawn from the connection pool using the useDb-function:

clientDatabaseConnection = global.databaseConnection.useDb(`client-${client.databaseName}`, {
	noListener: true,
	useCache: true
});

The client database connection is then used to do various quesries required by the request, for example:

let clientUserCollection = connection.model<IClientUserModel>("ClientUser", ClientUserSchema, 'users');
let user = await clientUserCollection.findById(userId).exec();

This is basically the structure of the application. What is it that is different in v6 and v7 compared to v5 that could cause these performance implications?

Expected Behavior

No response

[hasezoey]

This is basically the structure of the application. What is it that is different in v6 and v7 compared to v5 that could cause these performance implications?

one of the biggest changes from v5 to v6 was that mongodb (the underlying driver) was completely re-written in typescript, which could be a likely cause

[thandaanda]

We are also experiencing the same issue. We are restarting our servers every 24 hours. Memory seems fine. CPU hovers around 50%., but app becomes completely useless till we restart.

[samirkatyar]

I'm also facing this issue.
@vkarpov15 when this will resolved ?

[billouboq]

This might be a js-bson issue. Already made a PR to improve performance a bit but PR is not merged yet

[aykutbulca]

Are there any updates on the status of this issue? We also faced a similar performance problem after upgrading mongoose from v5.13.20 to v7.6.6.

[vkarpov15]

Realistically, without more information there's no way for us to repro this. There's no significant difference in useDb() between 5.x and 6.x: the only difference is that Mongoose 6 doesn't have a listen() function.

Similar with connection.model(): 5.x vs 6.x.

@aykutbulca are you able to create a repro script or project that demonstrates the issue you're seeing? Or at least provide some more substantial code samples?

[aykutbulca]

Realistically, without more information there's no way for us to repro this. There's no significant difference in useDb() between 5.x and 6.x: the only difference is that Mongoose 6 doesn't have a listen() function.

Similar with connection.model(): 5.x vs 6.x.

@aykutbulca are you able to create a repro script or project that demonstrates the issue you're seeing? Or at least provide some more substantial code samples?

We have been trying to isolate the issue and identified a significant performance disparity between MongoDB drivers v3 and v6 — the issue does not seem related to mongoose regarding our internal tests. We started discussions with the MongoDB team, but nothing so far (they think it is related to BSON deserialization).

To replicate the issue, we use the following script. Running this script with MongoDB driver versions 3.7.4 and 6.3.0 clearly demonstrates the performance difference. We consistently observed at least a 15% increase in query time when using 6.3.0. This percentage rises with the volume of data retrieved. For instance, if the inserted documents contain larger fields, such as lengthy strings (enableUtf8Validation: false did not help), the performance differential can exceed 50%.

It's worth noting that the replication script operates without the mongoose library and directly utilizes the MongoDB Node.js driver. However, you get similar results if you run a similar script with mongoose v5 vs. v7.

const mongodb = require('mongodb');
const { MongoClient } = mongodb;

const uri = 'mongodb://localhost:27017/test?directConnection=true';
const client = new MongoClient(uri);

async function removeAllDocuments(db) {
    const collection = db.collection('test');
    await collection.deleteMany({});
}
// insert 10k documents to collection 'test'
async function insertDocuments(db) {
    const collection = db.collection('test');
    const docs = [];
    for (let i = 0; i < 10000; i++) {
        docs.push({
            a: i,
            b: i + 1,
            c: i + 2,
            d: i + 3,
            e: i + 4,
            f: i + 5,
            g: i + 6
        });
    }
    await collection.insertMany(docs);
}

async function main() {
    // connect and insert documents
    await client.connect();
    const db = client.db('test');
    await removeAllDocuments(db);
    await insertDocuments(db);
    console.log("insert 10k documents completed");
    // read 10k documents at once, time the operation
    // average 100 fetches and calculate the average time spent

    const numAttempts = 1000;
    const times = [];
    for (let i = 0; i < numAttempts; i++) {
        const start = Date.now();
        const cursor = db.collection('test').find();
        const docs = await cursor.toArray();
        const end = Date.now();
        times.push(end - start);
    }
    const sum = times.reduce((a, b) => a + b, 0);
    const avg = sum / numAttempts;
    console.log(`Average time spent: ${avg} ms`);
}

main().catch(console.error);

[aykutbulca]

Hey @vkarpov15 👋

I've modified your script with a more complex schema, and the results are similar to our previous findings:

const { dependencies } = require('./package.json');
const mongoose = require('mongoose');
const { ObjectId } = mongoose.Schema.Types;

const schema = new mongoose.Schema({
    groupKey: {
        type: String,
        required: true
    },
    groupId: {
        type: ObjectId,
        required: true
    },
    actionName: {
        type: String,
        required: true
    },
    userId: {
        type: ObjectId,
        required: true
    },
    content: String,
    metadata: {
        source: {
            _id: ObjectId,
            email: String,
            username: String,
            bio: String,
            fullName: String,
            emotar: String,
            avatar: String
        },
        project: {
            _id: ObjectId,
            type: {
                type: String,
                enum: [
                    "android",
                    "ios",
                    "web",
                    "osx"
                ]
            },
            name: String
        },
        screen: {
            _id: ObjectId,
            name: String,
            latestVersion: {
                _id: ObjectId,
                snapshotFragment: {
                    url: String,
                    width: {
                        type: Number
                    },
                    height: {
                        type: Number
                    }
                }
            }
        },
        dot: {
            _id: ObjectId,
            name: String,
            status: {
                type: String,
                enum: [
                    "open",
                    "resolved"
                ]
            },
            note: String
        },
        comment: {
            _id: ObjectId,
            name: String,
            note: String
        }
    }
}, {
    toJSON: {
        getters: true,
        virtuals: false
    },
    toObject: {
        getters: true,
        virtuals: false
    },
    timestamps: {
        createdAt: "created",
        updatedAt: "updated"
    }
});

const Test = mongoose.model('Test', schema);

function getBaseData() {
    return {
        actionName: "Action",
        groupId: new mongoose.Types.ObjectId(),
        groupKey: "Group-",
        userId: new mongoose.Types.ObjectId(),
        content: "annotation.text",
        metadata: {
            project: {
                _id: new mongoose.Types.ObjectId(),
                type: "web",
                name: "project.name"
            },
            source: {
                _id: new mongoose.Types.ObjectId(),
                email: "mail@email.com",
                username: "source.username",
                bio: "source.bio",
                fullName: "source.fullName",
                emotar: "source.emotar",
                avatar: "source.avatar"
            },
            dot:  {
                _id: new mongoose.Types.ObjectId(),
                name: "dot.name",
                status: "open",
                note: "comment.note"
            },
            comment: {
                _id: new mongoose.Types.ObjectId()
            },
            screen: {
                _id: new mongoose.Types.ObjectId(),
                name: "screen.name",
                latestVersion: {
                    _id: new mongoose.Types.ObjectId(),
                    snapshotFragment: {
                        url: "latestVersion.snapshotFragment.url",
                        width: 120,
                        height: 240
                    }
                }
            }
        }
    };
}

// insert 10k documents to collection 'test'
async function insertDocuments() {
    const docs = [];
    for (let i = 0; i < 10000; i++) {
        const base = getBaseData();
        const newItem = new Test({...base});
        newItem.groupKey += (i % 20);
        docs.push(newItem);
    }
    await Test.insertMany(docs);
}

async function main() {
    // connect and insert documents
    await mongoose.connect('mongodb://127.0.0.1:27017/mongoose_test');
    await Test.deleteMany({});
    await insertDocuments();
    console.log("insert 10k documents completed");
    // read 10k documents at once, time the operation
    // average 100 fetches and calculate the average time spent
    const numAttempts = 100;
    const times = [];
    for (let i = 0; i < numAttempts; i++) {
        const start = Date.now();
        const docs = await Test.find().lean().exec();
        const end = Date.now();
        console.log(i, end - start);
        times.push(end - start);
    }
    const sum = times.reduce((a, b) => a + b, 0);
    const avg = sum / numAttempts;
    console.log(`Mongo DB Server 5.0.23 + Node 20 + mongoose version ${dependencies.mongoose} - Average time spent: ${avg} ms`);
    process.exit(0);
}

main().catch(console.error);

Mongo DB Server 5.0.23 + Node 20 + mongoose version 5.13.20 - Average time spent: ~135 ms
Mongo DB Server 5.0.23 + Node 20 + mongoose version 6.12.5 - Average time spent: ~170 ms
Mongo DB Server 5.0.23 + Node 20 + mongoose version 7.6.6 - Average time spent: ~170 ms

It looks like Mongoose version 5 is still the fastest in my local environment, and the results are similar to our experiments with the underlying MongoDB driver. So, I still think the root cause of the issue is with the MongoDB NodeJS driver (probably BSON serialization), and Mongoose's performance aligns with that.

[aykutbulca]

Hey @vkarpov15 👋

We got the confirmation from the MongoDB team that NodeJS driver version 6 (and 4 + 5) is almost %30 less performance than the driver version 3 due to BSON deserializing. They shared the following projects to improve it, but I don't think this will happen soon:

• https://jira.mongodb.org/browse/NODE-2674
• https://jira.mongodb.org/browse/NODE-5792

We recently upgraded our apps to use Mongoose v7.6 because MongoDB Server 5.0 was not compatible with Mongoose v5.13 (the compatibility page is changed btw, it was like the attached screenshot before), and since then, we have seen this performance problem. I doubt there is anything we can do with Mongoose v7.6, but we are open to suggestions.

[billouboq]

A few PR have been merged that will increase both serialize and deseralize performance :

mongodb/js-bson#645
mongodb/js-bson#642

And also an other PR might be merge soon improving deserialisation performance, with maybe some more hanging fruits (see comments) :
mongodb/js-bson#611

[billouboq]

Version 6.4 of the node mongodb driver is available, it has a lot of performance improvements in the js-bson library so it might reduce the slow-down, maybe even increase performance, can we try again with the new version ?

[kmonagle]

Version 6.4 of the node mongodb driver is available, it has a lot of performance improvements in the js-bson library so it might reduce the slow-down, maybe even increase performance, can we try again with the new version ?

thanks @billouboq . In short, I'm not seeing any improvement with 6.4.0.

We recently attempted an upgrade from mongodb 3.6.6 to 5.9.2, in conjunction with moving mongoose from 5.13 to 7.4.

Luckily we caught the issue before going to prod, but we're seeing the kind of slowdowns described above. 5.9.2 is about 30% slower from the start, but it unfortunately gets progressively slower as I repeat my fairly modest load tests.

The slowdown seems to happen at the mongodb driver level, I agree generally with the conclusions above that mongoose doesn't seem to be a major factor.

Memory looks good, so I don't get why things steadily degrade...we have some consulting time coming up with Mongo and this is number one on the agenda.

[billouboq]

Version 6.4 of the node mongodb driver is available, it has a lot of performance improvements in the js-bson library so it might reduce the slow-down, maybe even increase performance, can we try again with the new version ?

thanks @billouboq . In short, I'm not seeing any improvement with 6.4.0.

We recently attempted an upgrade from mongodb 3.6.6 to 5.9.2, in conjunction with moving mongoose from 5.13 to 7.4.

Luckily we caught the issue before going to prod, but we're seeing the kind of slowdowns described above. 5.9.2 is about 30% slower from the start, but it unfortunately gets progressively slower as I repeat my fairly modest load tests.

The slowdown seems to happen at the mongodb driver level, I agree generally with the conclusions above that mongoose doesn't seem to be a major factor.

Memory looks good, so I don't get why things steadily degrade...we have some consulting time coming up with Mongo and this is number one on the agenda.

Yeah it is a mongodb driver issue but that's weird that you don't see any improvement by bumping node mongodb driver to version 6.4, it really have some nice performance improvements that might be the cause of the initial slowdown

[kmonagle]

This was the cause of all of our pain:

We had a bit of code that was removing a model from the mongoose connection "models" POJO before creating a new model. Perhaps this was to avoid an exception if the model existed.

delete conn.models['simple'];
model = conn.model('simple', simpleSchema);

This is legacy code, and without getting into a discussion of whether this pattern is advisable, this created a nightmare of an issue when we upgraded from Mongoose 5 to 7.

In short, no ill effects were observed with 5. With 7, every time that code was executed (and it was executed a lot) a new idGetter was added to the getters array of the "id" virtual. So as the app ran that array grew continuously, the event loop lag grew as thousands of redundant idGetter functions were executed synchronously, and idGetter executions grew into the billions with moderate load tests.

So this is not BSON or the mongo driver. The symptoms I observed were identical to those described by other folks when moving past 5.x, where performance gradually slows down while memory looks OK. I'm wondering if there are other scenarios besides mine in which this might happen, and whether there's a bug or two in the code that adds those getters in.

[vkarpov15]

@kmonagle we recommend avoiding recreating models, conn.model('simple', simpleSchema) is a fairly slow operation and we normally recommend not running that in transactional code.

[huksley]

Found this thread because I trying to debug connection timeouts with my app and AWS Lambdas. I upgraded to MongoDB package 5.9.2 and MoongooseJS 7.6.7 and started to get unpredictable sometimes slow connection. It is not related to the load, it just happens sometimes

    "mongodb": "^5.9.2",
    "mongoose": "^7.6.7",

Exactly on 2024-02-16, I deployed a new version to the staging, and one week ago into production. The average lambda execution time jumped significantly, and now also, sometimes, it times out exceeding 30 and more...

Important note that staging is on a shared cluster, but production is M10 dedicated instance... Both have been affected, albeit M10 to a lesser degrees.

[kmonagle]

@vkarpov15 agreed but it seems like a bug was introduced in 6.x around that. In 5.x it was inefficient. In 6+ it was inefficient and killing my app.

[vkarpov15]

@kmonagle im sorry for the inconvenience. Is there some content you read that indicated it was correct to delete and recreate models on every lambda invocation? If so, can you please provide a link?

[vkarpov15]

I took a look at this repro and it looks like Mongoose 8 is now the fastest:

$ node gh-13456-mongoose.js 
insert 10k documents completed
Average time spent: 69.84 ms
$ node gh-13456-mongoose.js 
insert 10k documents completed
Average time spent: 68.43 ms
$ node gh-13456-mongoose.js 
insert 10k documents completed
Average time spent: 67.5 ms

vs Mongoose 7:

$ node gh-13456-mongoose.js 
insert 10k documents completed
Average time spent: 82.86 ms
$ node gh-13456-mongoose.js 
insert 10k documents completed
Average time spent: 86.01 ms
$ node gh-13456-mongoose.js 
insert 10k documents completed
Average time spent: 84.54 ms

and Mongoose 5:

$ node gh-13456-mongoose.js 
(node:71636) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
(Use `node --trace-deprecation ...` to show where the warning was created)
(node:71636) [MONGODB DRIVER] Warning: Current Server Discovery and Monitoring engine is deprecated, and will be removed in a future version. To use the new Server Discover and Monitoring engine, pass option { useUnifiedTopology: true } to the MongoClient constructor.
insert 10k documents completed
Average time spent: 117.75 ms
$ node gh-13456-mongoose.js 
(node:71648) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
(Use `node --trace-deprecation ...` to show where the warning was created)
(node:71648) [MONGODB DRIVER] Warning: Current Server Discovery and Monitoring engine is deprecated, and will be removed in a future version. To use the new Server Discover and Monitoring engine, pass option { useUnifiedTopology: true } to the MongoClient constructor.
insert 10k documents completed
Average time spent: 123.8 ms

The idGetter duplication issue from #13456 (comment) was fixed in #14492, so I'm going to mark this issue as closed. If you're running into similar issues, please open a new issue with detailed repro instructions.