4.7.7 -> 5.13.21 reduction performance

[0Ams]

Prerequisites

• I have written a descriptive issue title

Mongoose version

5.13.21

Node.js version

18.15.0

MongoDB version

4.4.25

Operating system

None

Operating system version (i.e. 20.04, 11.3, 10)

No response

Issue

Context

• 4.7.7 -> 5.13.21 reduction performance
• Schema validate and some features appear to be slowing down. Is it common for v5 to perform less than v4?

Test Code

const mongoose4 = require('mongoose4');
const mongoose5 = require('mongoose5');
const {getModel} = require('./model/test_model');
const DATA_AMOUNT = {min: 40, max: 400};

async function run() {
    mongoose4.Promise = global.Promise;
    await mongoose4.connect('mongodb://localhost:47017/m4', {useMongoClient: true});
    await mongoose5.connect('mongodb://localhost:47017/m5', {useNewUrlParser: true, useUnifiedTopology: true});

    const Model4 = mongoose4.model('Test', getModel(mongoose4));
    const Model5 = mongoose5.model('Test', getModel(mongoose5));

    const reps = 100;

    let m5total = 0;
    for (let i = 0; i < reps; ++i) {
        m5total += await profile(Model5);
    }
    let m4total = 0;
    for (let i = 0; i < reps; ++i) {
        m4total += await profile(Model4);
    }

    console.log(`mongoose v5 spendTime:`, m5total, 'average:', m5total / reps);
    console.log(`mongoose ${mongoose4.version} spendTime:`, m4total, 'average:', m4total / reps);
    console.log('mongoose 5 perf reduction in ms:', (m5total - m4total) / reps);

    process.exit(0);
}

async function profile(Model) {
    await Model.remove({});
    for (let i = 0; i < 100; ++i) {
        const record = new Model();
        for (let i = 0; i < Math.random() * (DATA_AMOUNT.max - DATA_AMOUNT.min) + DATA_AMOUNT.min; ++i) {
            const random = Math.random();
            record.randomNumberData.push(random);
            record.randomStringData.push(`${random}`);
        }
        await record.save();
    }

    let totalMS = 0;

    const cursor = Model.find().cursor();
    for (let doc = await cursor.next(); doc != null; doc = await cursor.next()) {
        const start = Date.now();
        await Model.findById(doc._id);
        totalMS += Date.now() - start;
    }

    return totalMS;
}

run().catch((error) => console.error(error.stack));

Result

mongoose 5.13.21 spendTime: 102740 average: 102.74
mongoose 4.7.7 spendTime: 88547 average: 88.547
mongoose 5 performance reduction in ms: 14.193

[vkarpov15]

This looks like a duplicate of #11380, there was some performance degradation specifically with push(). We have #14120 open for fixing the performance issue for 7.x. We will investigate backporting that fix to 6.x and 5.x.

[0Ams]

when #14120 was applied only, there was no significant change in mongoose v5 performance. please additionally check if there are any other factors. And apply the contents in the mongoose v5 version as well.

I will refer to your performance improvement. 🙇🏻

[github-actions]

This issue is stale because it has been open 14 days with no activity. Remove stale label or comment or this will be closed in 5 days

[0Ams]

Will other improvements be reflected in v5?

[vkarpov15]

@0Ams we aren't backporting anything other than security fixes and requested bug fixes to Mongoose 5, and Mongoose 5 is scheduled for EOL in March 2024, so about 2 months from now: https://mongoosejs.com/docs/version-support.html.

Here's the results I'm seeing from the following script:

const mongoose = require('mongoose');
const DATA_AMOUNT = {min: 40, max: 400};

async function run() {
    await mongoose.connect('mongodb://localhost:27017/mongoose_test');
    const Model = mongoose.model('Test', new mongoose.Schema({
      randomNumberData: [Number],
      randomStringData: [String]
    }));

    const reps = 100;
    
    let total = 0;
    for (let i = 0; i < reps; ++i) {
        total += await profile(Model);
    }

    console.log(`mongoose spendTime:`, total, 'average:', total / reps);

    process.exit(0);
}

async function profile(Model) {
    await Model.remove({});
    for (let i = 0; i < 100; ++i) {
        const record = new Model();
        for (let i = 0; i < Math.random() * (DATA_AMOUNT.max - DATA_AMOUNT.min) + DATA_AMOUNT.min; ++i) {
            const random = Math.random();
            record.randomNumberData.push(random);
            record.randomStringData.push(`${random}`);
        }
        await record.save();
    }

    let totalMS = 0;

    const cursor = Model.find().cursor();
    for (let doc = await cursor.next(); doc != null; doc = await cursor.next()) {
        const start = Date.now();
        await Model.findById(doc._id);
        totalMS += Date.now() - start;
    }

    return totalMS;
}

run().catch((error) => console.error(error.stack));

Mongoose 4:

mongoose spendTime: 2256 average: 22.56

Mongoose 5:

mongoose spendTime: 2773 average: 27.73

Mongoose 6:

mongoose spendTime: 3116 average: 31.16

Mongoose 7:

mongoose spendTime: 2964 average: 29.64

We're going to debug this performance degradation and see how easy this is to backport to Mongoose 5. At the very least, we will backport any performance improvements to Mongoose 6, which I would recommend you upgrade to.

[vkarpov15]

Took me way too long to notice this, but your tests are actually profiling findOne() performance, not push(), so #14120 doesn't help here

[0Ams]

did your test use the latest version of each mongoose version?
for our system to go up to "mongoose 6", we need a lot of effort at the moment.

so I'm inquiring again. is it no longer backport to mongoose 5 for information on performance improvement andpush() issue?

@add question

   const cursor = Model.find().cursor();
    for (let doc = await cursor.next(); doc !== null; doc = await cursor.next()) {
        const start = Date.now();
        await Model.findById(doc._id);
        await Model.collection.findOne({_id: doc._id}); // add function
        await Model.collection.update({_id: doc._id}, {$set: {count: 0}}); // add function
        totalMS += Date.now() - start;
    }

If findOne() and update() are added, the difference is bigger, is there any difference in each method?

mongoose 5.13.21 total spendTime: 38683 average: 386.83
mongoose 4.7.7 total spendTime: 32296 average: 322.96
mongoose 5 performance reduction in ms: 63.87

[vkarpov15]

The push() issue won't help your benchmark AFAIK because you're just profiling how long findById() takes. We will look into backporting the push() perf improvement to Mongoose 5

[0Ams]

I appreciate your help. 😄

[vkarpov15]

Looking more closely I created the following simplified script for better flamegraphs:

const mongoose = require('mongoose');
const DATA_AMOUNT = {min: 40, max: 400};

console.log(mongoose.version);

async function run() {
    await mongoose.connect('mongodb://localhost:27017/mongoose_test');
    const Model = mongoose.model('Test', new mongoose.Schema({
      randomNumberData: [Number],
      randomStringData: [String]
    }));

    if (process.env.SETUP) {
      await setup(Model);
    }

    const reps = 500;
    
    let total = 0;
    for (let i = 0; i < reps; ++i) {
        total += await profile(Model, await Model.findOne());
    }

    console.log(`mongoose spendTime:`, total, 'average:', total / reps);
    
    process.exit(0);
}

async function setup(Model) {
    //await Model.remove({});
    await Model.deleteMany({});
    for (let i = 0; i < 200; ++i) {
        const record = new Model();
        for (let i = 0; i < Math.random() * (DATA_AMOUNT.max - DATA_AMOUNT.min) + DATA_AMOUNT.min; ++i) {
            const random = Math.random();
            record.randomNumberData.push(random);
            record.randomStringData.push(`${random}`);
        }
        await record.save();
    }
    console.log('Setup done');
}

async function profile(Model, doc) {
    let totalMS = 0;

    const cursor = Model.find().cursor();
    for (let i = 0; i < 200; ++i) {
        const start = Date.now();
        await Model.findById(doc._id);
        totalMS += Date.now() - start;
    }

    return totalMS;
}

run().catch((error) => console.error(error.stack));

On 4.x:

$ node gh-14113.js 
4.13.21
(node:1191302) DeprecationWarning: `open()` is deprecated in mongoose >= 4.11.0, use `openUri()` instead, or set the `useMongoClient` option if using `connect()` or `createConnection()`. See http://mongoosejs.com/docs/4.x/docs/connections.html#use-mongo-client
(Use `node --trace-deprecation ...` to show where the warning was created)
(node:1191302) DeprecationWarning: Mongoose: mpromise (mongoose's default promise library) is deprecated, plug in your own promise library instead: http://mongoosejs.com/docs/promises.html
mongoose spendTime: 16098 average: 32.196

On 5.x:

$ node gh-14113.js 
5.13.21
(node:1255143) 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:1255143) [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.
mongoose spendTime: 20923 average: 41.846

Below is the 5.x flamegraph, which shows that the vast majority of the time is spent either in the Node driver or waiting on the MongoDB server, but there's still a decent amount of time spent in Mongoose

For comparison, here is output when using Mongoose 5 with lean():

$ node gh-14113.js 
5.13.21
(node:1257275) 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:1257275) [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.
mongoose spendTime: 17933 average: 35.866

Here is flamegraph with lean():

Still WIP, but it's looking like the issue would be in init(), so that's where we're looking.

[github-actions]

This issue is stale because it has been open 14 days with no activity. Remove stale label or comment or this will be closed in 5 days

[0Ams]

I'm still waiting for updating it