Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mongoose execution time increased 2 times after upgrading 4 to 6 #11380

Closed
ekorolevanyrun opened this issue Feb 11, 2022 · 19 comments
Closed

Mongoose execution time increased 2 times after upgrading 4 to 6 #11380

ekorolevanyrun opened this issue Feb 11, 2022 · 19 comments

Comments

@ekorolevanyrun
Copy link

ekorolevanyrun commented Feb 11, 2022

Do you want to request a feature or report a bug?

Probably bug

What is the current behavior?

Execution time increased after upgrading mongoose (4.13.21 -> 6.2.1) in 2 times

If the current behavior is a bug, please provide the steps to reproduce.

We have 2 mongodb replicas (primary and two secondary ones). You can reproduce the problem with a simple script:

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

const options = {
    socketTimeoutMS: 15000,
    keepAlive: true,
    ...(mongoose.version === '6.2.1'
    ? { minPoolSize: 32, maxPoolSize: 64 }
    : { poolSize: 64 }),
    ignoreUndefined: true,
  };

const connectionOpts = {
    set: [ { ip: 'mongo_1', port: 27017 }, { ip: 'mongo_2', port: 27017 } ],
    db: 'meteor',
    username: 'docker',
    pass: 'dockerpass',
    rs: 'rs0',
    ssl: false,
    sslCA: '',
    sslCert: ''
}
const connectionString = 'mongodb://docker:dockerpass@mongo_1:27017,mongo_2:27017/meteor?authSource=admin&replicaSet=rs0'
const mongoOptions = {
    ...options,
    ...(connectionOpts.ssl && {
        ssl: true,
        sslValidate: true,
        sslCA: connectionOpts.sslCA,
        sslCert: connectionOpts.sslCert,
        sslKey: connectionOpts.sslCert,
    }),
};

const slowsaveSchema = new mongoose.Schema({
    randomData: [Number,],
});
const slowsaveModel = mongoose.model('slowsave_experiment', slowsaveSchema);

let last100_count=0, last100_sum=0, total_count=0, total_sum=0;
async function addData() {
    const record = new slowsaveModel();
    for (let i = 0; i < Math.random()*(DATA_AMOUNT.max-DATA_AMOUNT.min) + DATA_AMOUNT.min; ++i) {
        record.randomData.push(Math.random());
    };

    const startTime = Date.now();
    await record.save();
    const time= Date.now()-startTime;;
    
    last100_count++; total_count++;
    last100_sum+=time; total_sum+=time;
    if (last100_count>=100) {
        console.log(`l100.avg=${last100_sum/last100_count}, total.avg=${total_sum/total_count}`)
        last100_count=0;
        last100_sum=0;
    }
};

async function main() {
    await mongoose.connect(connectionString, mongoOptions);

    for (let i = 0; i < RECORDS_AMOUNT; i++) {
        setTimeout(async () => {
            await addData();
        }, Math.floor(Math.random()*2000 + 2000));
    }
};

main();

You can replace await record.save() to await slowsaveModel.deleteOne({}) and the results doesn't change. It doesn't matter which function do you use, it seems execution time has been increased for all methods.

What is the expected behavior?

Here are result of script with mongoose@4.13.21:

latest1000.avg=5447.967, total.avg=5447.967
latest1000.avg=5362.839, total.avg=5405.403
latest1000.avg=5426.518, total.avg=5412.441333333333
latest1000.avg=4837.46, total.avg=5268.696
latest1000.avg=3824.57, total.avg=4979.8708
latest1000.avg=3089.016, total.avg=4664.7283333333335
latest1000.avg=2649.487, total.avg=4376.836714285714
latest1000.avg=1943.853, total.avg=4072.71375
latest1000.avg=1712.102, total.avg=3810.4235555555556
latest1000.avg=1100.57, total.avg=3539.4382

Result with mongoose@6.2.1 (note that it is the same script with the same databases):

latest1000.avg=11765.535, total.avg=11765.535
latest1000.avg=10716.812, total.avg=11241.1735
latest1000.avg=9688.8, total.avg=10723.715666666667
latest1000.avg=8665.442, total.avg=10209.14725
latest1000.avg=7642.599, total.avg=9695.8376
latest1000.avg=6624.543, total.avg=9183.955166666667
latest1000.avg=5591.398, total.avg=8670.732714285714
latest1000.avg=4539.596, total.avg=8154.340625
latest1000.avg=3529.14, total.avg=7640.429444444444
latest1000.avg=2513.022, total.avg=7127.6887

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version.
Node: v14.18.3
MongoDB server version: 5.0.6
Mongoose: 4.13.21 & 6.2.1

@Uzlopak
Copy link
Collaborator

Uzlopak commented Feb 12, 2022

Nice Issue. I do love performance investigation tasks. So first of all thank you for your script. Especially because you have an example regarding MongooseArrays, because I think they are a big performance eater.

But it can be an issue on multiple levels.

E.g. We use Proxy for MongooseArrays, which can have a performance hit.
But also we have from v4 to v6 upgraded mongo driver package. So we have to determine first if they are not the potential performance eater. This could be done by not using save but using model.collection.insertOne and compare the potential performance loss. If they are not different or neglectable we have the issue on mongoose level. Also we can determine by this the overhead added by mongoose save method and see how much we could improve.

We could use your sample script to --inspect and see where the most cycles are wasted, use deoptigate to determine if we have somewhere heavy deoptimizations and using 0x to look on flame graphs.

But then again we could have usual performance tradeoffs. E.g. I think using Arrays as Document Attributes slows mongoose heavily down, because of the Proxy. But there are some potential perf improvements existing.e.g.

mongooseArrayMethods.set.call(proxy, prop, value, false);

Instead of passing the proxy we could directly refence the internal Object and see if it is improving the performance.
Or we could check if we can use instead of classical for loops over the proxy the built in forEach and map methods to avoid crossing the Proxy layer over and over.

Maybe the issue is not the Proxy but something else, like heavily creating useless intermediate variables, which have to be later garbage collected and they sum up heavily and as such slow down the perf. I have some benchmarks were i have like 70% of runtime wasted in the garbage collector. Not nice.

But these are some ideas...

@vkarpov15 vkarpov15 added this to the 6.2.4 milestone Feb 12, 2022
@Uzlopak
Copy link
Collaborator

Uzlopak commented Feb 13, 2022

I checked that with a git bisect. The issue first time the performance heavily broke down was with Commit d9c2a46 where mongooses upgraded mongodb native driver from 3.0.2 to 3.0.3.

We maybe had other performance degredations, but it is quite too late to figure this out anymore without a lot of heavy lifting. mongodb native driver was just too much heavily changed, so that I can not figure out where mongoose maybe added performance degredations additional to the performance degredation implemented by the native driver.

@ekorolevanyrun
Copy link
Author

Hi, thank you for answer! I'm glad to see that there is a hope to fix that issue (I've spent many hours to find out how I broke ours system performance).

Using insertOne instead of save

It seems the problem is relevant to mongodb driver. Thats why. Testing results with Model.collection.insertOne (mongoose@4):

latest1000.avg=3709.555, total.avg=3709.555
latest1000.avg=2604.291, total.avg=3156.923
latest1000.avg=4415.895, total.avg=3576.5803333333333
latest1000.avg=3393.906, total.avg=3530.91175
latest1000.avg=3069.68, total.avg=3438.6654
latest1000.avg=1569.069, total.avg=3127.066
latest1000.avg=2559.021, total.avg=3045.916714285714
latest1000.avg=2144.467, total.avg=2933.2355
latest1000.avg=1612.763, total.avg=2786.5163333333335
latest1000.avg=1710.629, total.avg=2678.9276

Results with mongoose@6:

latest1000.avg=6003.562, total.avg=6003.562
latest1000.avg=5773.063, total.avg=5888.3125
latest1000.avg=5316.366, total.avg=5697.663666666666
latest1000.avg=4843.807, total.avg=5484.1995
latest1000.avg=4402.527, total.avg=5267.865
latest1000.avg=3937.905, total.avg=5046.205
latest1000.avg=3460.984, total.avg=4819.744857142857
latest1000.avg=3000.857, total.avg=4592.383875
latest1000.avg=2535.936, total.avg=4363.889666666667
latest1000.avg=2092.11, total.avg=4136.7117

Get rid of arrays:

I tried to remove array field from the model (I just replaced randomData: [Nubmer,], with randomData: Number. And there is the result with .save():
mongoose@6: total average time: 1669ms
mongoose@4: total average time: 451ms

And there is the result with .insertOne():
mongoose@6: total.avg=261.5608
mongoose@4: total.avg=48.2793

So, how do you think is it needed to public issue on node-mongodb-native project?

@Uzlopak
Copy link
Collaborator

Uzlopak commented Feb 14, 2022

You can have a look at this

mongodb/js-bson#490

@ekorolevanyrun
Copy link
Author

@Uzlopak, I have to ask, will that PR fix the perfomance issue? I just would know if I should pick another tasks and hold the mongoose perfomance issue while better time?

@Uzlopak
Copy link
Collaborator

Uzlopak commented Feb 15, 2022

First of all the mongodb dev team is very slow. So probably this PR will not land very soon.
Also i did some benchmarks, and it seems that it does not have a significant impact on the performance. So there is a an even bigger bottleneck somewhere in their code.

My advice is, that you should think what you want to prioritize: security or performance.
if security is your main concern, than upgrade to latest mongoose
If performance is your main concern, consider even using node 10 with mongo 5.0.7 or so. Its the last version, were the performance was according to my research the best and node10 does have a faster buffer implementation.

Other than that I can not really say, that the underlying performance will improve in the next months. Like I wrote: mongodb team is slow. My PR will foreseeable not be accepted, because they want first benchmarks etc.. Thats quite abstract requirement, so probably they wont have a near future.

If you are totally crazy about performance, than have a look alternatives from @marcj in https://github.com/deepkit/deepkit-framework/tree/master/packages/mongo
He basically wrote his own mongodriver and doesnt need to handle all that technical debt from original mongodb team. He even offered to refactor js-bson in 3-4 days, which I kind of think is possible, but they shut him down (would you give somebody your OK to refactor a whole project in 3-4 days, probably showing that you dont know what you do :D).

@ekorolevanyrun
Copy link
Author

Thank you for so detailed answer, very appreciate.

I can't believe that thouthands of mongodb users are facing with 2x perfomance degradations since mongoose@4!

@marcj
Copy link

marcj commented Feb 15, 2022

I can't believe that thouthands of mongodb users are facing with 2x perfomance degradations since mongoose@4!

Actually there are millions, and the vast majority does not care as they are dead hobby projects/no business, are one of the 90% of startups that fail, have very low traffic, or have other reasons to simply not care about performance. High performance in web affects only the upper 99 percentile high-revenue, high-traffic, or some edge case businesses, some even optimise for that without actual need aka premature optimisation. There is mostly no point in providing an expensive high performance implementation of something if the target audience is for 99% users that can't care less if you have 10ms response time or 100ms, except if the program is otherwise too slow or you have a fetish for efficient software. If you have however a need though then performance is suddenly worth tons of money - then you should look for the right tools/vendors. So I'm not surprised that no one cares if they have such a performance drop in a OSS library that literally never cared about performance since the very beginning.

@vkarpov15 vkarpov15 modified the milestones: 6.2.4, 6.2.5 Feb 28, 2022
@vkarpov15 vkarpov15 modified the milestones: 6.2.5, 6.2.6, 6.2.7 Mar 9, 2022
vkarpov15 added a commit that referenced this issue Mar 12, 2022
@vkarpov15
Copy link
Collaborator

Thanks for the detailed benchmark @ekorolevanyrun . 94d77c2 makes some substantial improvements by avoiding running validation on array elements if there's no validators to run. Before we'd have O(N) checks for "are there any validators to run for randomData.n?".

Before:

l100.avg=8518.56, total.avg=8518.56
l100.avg=8436.43, total.avg=8477.495
l100.avg=8360.9, total.avg=8438.63
l100.avg=8284.55, total.avg=8400.11
l100.avg=8207.94, total.avg=8361.676
l100.avg=8132.41, total.avg=8323.465
l100.avg=8057.25, total.avg=8285.434285714286
l100.avg=7981.96, total.avg=8247.5
l100.avg=7906.72, total.avg=8209.635555555555
l100.avg=7831.78, total.avg=8171.85
l100.avg=7758.31, total.avg=8134.255454545455
l100.avg=7689.76, total.avg=8097.214166666667
l100.avg=7617.03, total.avg=8060.276923076923
l100.avg=7533.41, total.avg=8022.643571428572
l100.avg=7459.16, total.avg=7985.078
l100.avg=7382.81, total.avg=7947.43625
l100.avg=7310.33, total.avg=7909.959411764706
l100.avg=7240.47, total.avg=7872.765555555556
l100.avg=7167.9, total.avg=7835.667368421053
l100.avg=7095.08, total.avg=7798.638
l100.avg=7020.24, total.avg=7761.571428571428
l100.avg=6946.7, total.avg=7724.531818181818
l100.avg=6870.46, total.avg=7687.398260869565
l100.avg=6796.14, total.avg=7650.2625
l100.avg=6723.7, total.avg=7613.2
l100.avg=6649.32, total.avg=7576.127692307692
l100.avg=6576.1, total.avg=7539.08962962963
l100.avg=6503.96, total.avg=7502.120714285715
l100.avg=6430.93, total.avg=7465.183103448276
l100.avg=6355.59, total.avg=7428.196666666667
l100.avg=6277.76, total.avg=7391.085806451613
l100.avg=6199.61, total.avg=7353.8521875
l100.avg=6125.13, total.avg=7316.618181818182
l100.avg=6052.03, total.avg=7279.424411764706
l100.avg=5979.61, total.avg=7242.286857142857
l100.avg=5907.22, total.avg=7205.201666666667
l100.avg=5834.44, total.avg=7168.154054054054
l100.avg=5747.84, total.avg=7130.777368421052
l100.avg=5673.13, total.avg=7093.401794871795
l100.avg=5598.64, total.avg=7056.03275
l100.avg=5523.83, total.avg=7018.661951219512
l100.avg=5450.3, total.avg=6981.32
l100.avg=5379.04, total.avg=6944.057674418605
l100.avg=5296.28, total.avg=6906.608181818182
l100.avg=5224.1, total.avg=6869.2191111111115
l100.avg=5150.97, total.avg=6831.8658695652175
l100.avg=5079.3, total.avg=6794.577234042553
l100.avg=5010.96, total.avg=6757.418541666667
l100.avg=4938.73, total.avg=6720.302448979592
l100.avg=4866.56, total.avg=6683.2276
l100.avg=4794.27, total.avg=6646.189215686274
l100.avg=4722.34, total.avg=6609.192115384615
l100.avg=4652.69, total.avg=6572.276981132076
l100.avg=4582.07, total.avg=6535.4212962962965
l100.avg=4508.99, total.avg=6498.577090909091
l100.avg=4436.39, total.avg=6461.752321428571
l100.avg=4368.53, total.avg=6425.029122807017
l100.avg=4297.98, total.avg=6388.3558620689655
l100.avg=4225.13, total.avg=6351.691016949153
l100.avg=4153.65, total.avg=6315.057
l100.avg=4081.91, total.avg=6278.448032786885
l100.avg=4011.61, total.avg=6241.886129032258
l100.avg=3939.71, total.avg=6205.34365079365
l100.avg=3866.48, total.avg=6168.79890625
l100.avg=3794.62, total.avg=6132.273076923077
l100.avg=3721.82, total.avg=6095.7510606060605
l100.avg=3651.62, total.avg=6059.271492537314
l100.avg=3581.93, total.avg=6022.84
l100.avg=3509.76, total.avg=5986.4185507246375
l100.avg=3438.99, total.avg=5950.026714285715
l100.avg=3366.77, total.avg=5913.642816901409
l100.avg=3295.36, total.avg=5877.277777777777
l100.avg=3225.9, total.avg=5840.957534246575
l100.avg=3156.42, total.avg=5804.68
l100.avg=3086.11, total.avg=5768.4324
l100.avg=3013.73, total.avg=5732.186315789474
l100.avg=2943.69, total.avg=5695.972077922078
l100.avg=2872.44, total.avg=5659.772948717949
l100.avg=2800.71, total.avg=5623.5822784810125
l100.avg=2728.53, total.avg=5587.394125
l100.avg=2656.66, total.avg=5551.212222222222
l100.avg=2586.09, total.avg=5515.052195121952
l100.avg=2514.58, total.avg=5478.901927710844
l100.avg=2442.08, total.avg=5442.749285714286
l100.avg=2371.38, total.avg=5406.615529411764
l100.avg=2300.87, total.avg=5370.502209302325
l100.avg=2231.36, total.avg=5334.420114942529
l100.avg=2161.43, total.avg=5298.363409090909
l100.avg=2062.82, total.avg=5262.008988764045
l100.avg=1970.99, total.avg=5225.442111111111
l100.avg=1900.22, total.avg=5188.901208791209
l100.avg=1827.5, total.avg=5152.364239130435
l100.avg=1755.13, total.avg=5115.834838709678
l100.avg=1682.89, total.avg=5079.314148936171
l100.avg=1609.02, total.avg=5042.784736842105
l100.avg=1536.33, total.avg=5006.259166666667
l100.avg=1468.21, total.avg=4969.784432989691
l100.avg=1398.96, total.avg=4933.347448979592
l100.avg=1324.79, total.avg=4896.8973737373735
l100.avg=1250.25, total.avg=4860.4309

After:

l100.avg=5695.58, total.avg=5695.58
l100.avg=5635.33, total.avg=5665.455
l100.avg=5578.24, total.avg=5636.383333333333
l100.avg=5524.62, total.avg=5608.4425
l100.avg=5477, total.avg=5582.154
l100.avg=5424.53, total.avg=5555.883333333333
l100.avg=5379.53, total.avg=5530.69
l100.avg=5335.67, total.avg=5506.3125
l100.avg=5289.05, total.avg=5482.172222222222
l100.avg=5241.04, total.avg=5458.059
l100.avg=5195.65, total.avg=5434.203636363636
l100.avg=5152.9, total.avg=5410.761666666666
l100.avg=5102.7, total.avg=5387.0646153846155
l100.avg=5054.38, total.avg=5363.301428571429
l100.avg=5010.72, total.avg=5339.796
l100.avg=4964.45, total.avg=5316.336875
l100.avg=4919.84, total.avg=5293.0135294117645
l100.avg=4878.1, total.avg=5269.962777777778
l100.avg=4832.69, total.avg=5246.948421052632
l100.avg=4776.11, total.avg=5223.4065
l100.avg=4715.01, total.avg=5199.197142857143
l100.avg=4669.55, total.avg=5175.1222727272725
l100.avg=4625.33, total.avg=5151.218260869565
l100.avg=4581.9, total.avg=5127.496666666667
l100.avg=4537.82, total.avg=5103.9096
l100.avg=4494.53, total.avg=5080.471923076923
l100.avg=4450.28, total.avg=5057.131481481481
l100.avg=4408.26, total.avg=5033.9575
l100.avg=4364.72, total.avg=5010.880344827586
l100.avg=4319.38, total.avg=4987.830333333333
l100.avg=4275.93, total.avg=4964.865806451613
l100.avg=4230.84, total.avg=4941.9275
l100.avg=4185.43, total.avg=4919.003333333333
l100.avg=4139.51, total.avg=4896.077058823529
l100.avg=4096.83, total.avg=4873.2414285714285
l100.avg=4051.06, total.avg=4850.4030555555555
l100.avg=3993.77, total.avg=4827.25081081081
l100.avg=3935.18, total.avg=4803.775263157895
l100.avg=3888.86, total.avg=4780.315897435898
l100.avg=3841.41, total.avg=4756.84325
l100.avg=3795.92, total.avg=4733.4060975609755
l100.avg=3752.15, total.avg=4710.042857142857
l100.avg=3709.37, total.avg=4686.771395348837
l100.avg=3666.57, total.avg=4663.585
l100.avg=3624.51, total.avg=4640.4944444444445
l100.avg=3582.68, total.avg=4617.49847826087
l100.avg=3540.81, total.avg=4594.590212765957
l100.avg=3498.23, total.avg=4571.749375
l100.avg=3452.83, total.avg=4548.914285714286
l100.avg=3408.16, total.avg=4526.0992
l100.avg=3365.26, total.avg=4503.337647058824
l100.avg=3321.71, total.avg=4480.614038461538
l100.avg=3280.79, total.avg=4457.975849056604
l100.avg=3238.29, total.avg=4435.389074074074
l100.avg=3197.14, total.avg=4412.875454545455
l100.avg=3155.9, total.avg=4390.429464285714
l100.avg=3114.31, total.avg=4368.0414035087715
l100.avg=3072.53, total.avg=4345.705
l100.avg=3028.86, total.avg=4323.385593220339
l100.avg=2987.09, total.avg=4301.114
l100.avg=2946.21, total.avg=4278.902459016394
l100.avg=2902.78, total.avg=4256.706935483871
l100.avg=2860.7, total.avg=4234.548095238095
l100.avg=2817.54, total.avg=4212.40734375
l100.avg=2774.14, total.avg=4190.280153846154
l100.avg=2731.47, total.avg=4168.1769696969695
l100.avg=2688.01, total.avg=4146.084925373134
l100.avg=2646.21, total.avg=4124.02794117647
l100.avg=2603.32, total.avg=4101.988695652174
l100.avg=2559.87, total.avg=4079.9584285714286
l100.avg=2516.12, total.avg=4057.932535211268
l100.avg=2471.62, total.avg=4035.900416666667
l100.avg=2427.9, total.avg=4013.87301369863
l100.avg=2384.77, total.avg=3991.858108108108
l100.avg=2343.31, total.avg=3969.877466666667
l100.avg=2296.16, total.avg=3947.8548684210527
l100.avg=2223.52, total.avg=3925.460909090909
l100.avg=2180.11, total.avg=3903.0846153846155
l100.avg=2136.7, total.avg=3880.7253164556964
l100.avg=2093.46, total.avg=3858.3845
l100.avg=2049.69, total.avg=3836.054938271605
l100.avg=2006.39, total.avg=3813.741951219512
l100.avg=1960.23, total.avg=3791.410481927711
l100.avg=1916.17, total.avg=3769.0861904761905
l100.avg=1874.59, total.avg=3746.798
l100.avg=1832.03, total.avg=3724.5332558139535
l100.avg=1788.45, total.avg=3702.2794252873564
l100.avg=1745.31, total.avg=3680.0411363636363
l100.avg=1703.5, total.avg=3657.832808988764
l100.avg=1658.64, total.avg=3635.6195555555555
l100.avg=1615.78, total.avg=3613.4235164835163
l100.avg=1572.5, total.avg=3591.2395652173914
l100.avg=1528.25, total.avg=3569.0568817204303
l100.avg=1485.21, total.avg=3546.8882978723404
l100.avg=1444.23, total.avg=3524.755052631579
l100.avg=1402.21, total.avg=3502.6452083333334
l100.avg=1357, total.avg=3480.525154639175
l100.avg=1315.18, total.avg=3458.4297959183673
l100.avg=1270.6, total.avg=3436.330505050505
l100.avg=1224.38, total.avg=3414.211

For comparison's sake, here's what I get if I just do insertOne():

l100.avg=4269.49, total.avg=4269.49
l100.avg=4336.63, total.avg=4303.06
l100.avg=4296.94, total.avg=4301.02
l100.avg=4262.59, total.avg=4291.4125
l100.avg=4227.98, total.avg=4278.726
l100.avg=4192.58, total.avg=4264.368333333333
l100.avg=4159.72, total.avg=4249.418571428571
l100.avg=4128.81, total.avg=4234.3425
l100.avg=4093.55, total.avg=4218.698888888889
l100.avg=4058.69, total.avg=4202.698
l100.avg=4023.97, total.avg=4186.45
l100.avg=3992.31, total.avg=4170.2716666666665
l100.avg=3958.66, total.avg=4153.993846153846
l100.avg=3923.99, total.avg=4137.565
l100.avg=3893.78, total.avg=4121.312666666667
l100.avg=3856.3, total.avg=4104.749375
l100.avg=3821.41, total.avg=4088.0823529411764
l100.avg=3790.31, total.avg=4071.5394444444446
l100.avg=3759, total.avg=4055.09
l100.avg=3728.46, total.avg=4038.7585
l100.avg=3692.91, total.avg=4022.289523809524
l100.avg=3659.82, total.avg=4005.8136363636363
l100.avg=3625.46, total.avg=3989.2765217391307
l100.avg=3592.79, total.avg=3972.75625
l100.avg=3562.47, total.avg=3956.3448
l100.avg=3533.11, total.avg=3940.0665384615386
l100.avg=3500.81, total.avg=3923.797777777778
l100.avg=3469.1, total.avg=3907.558571428571
l100.avg=3435.2, total.avg=3891.270344827586
l100.avg=3400.57, total.avg=3874.913666666667
l100.avg=3359.89, total.avg=3858.3
l100.avg=3326.58, total.avg=3841.68375
l100.avg=3290.07, total.avg=3824.9681818181816
l100.avg=3255.71, total.avg=3808.225294117647
l100.avg=3223.76, total.avg=3791.5262857142857
l100.avg=3189.88, total.avg=3774.813888888889
l100.avg=3156.74, total.avg=3758.1091891891892
l100.avg=3125.77, total.avg=3741.468684210526
l100.avg=3098.28, total.avg=3724.9766666666665
l100.avg=3067.54, total.avg=3708.54075
l100.avg=3038.98, total.avg=3692.21
l100.avg=3011.73, total.avg=3676.0080952380954
l100.avg=2982.13, total.avg=3659.8713953488373
l100.avg=2948.93, total.avg=3643.7136363636364
l100.avg=2915.57, total.avg=3627.5326666666665
l100.avg=2882.25, total.avg=3611.330869565217
l100.avg=2848.13, total.avg=3595.0925531914895
l100.avg=2813.97, total.avg=3578.8191666666667
l100.avg=2780.76, total.avg=3562.532244897959
l100.avg=2747.81, total.avg=3546.2378
l100.avg=2717.47, total.avg=3529.987450980392
l100.avg=2684.65, total.avg=3513.7309615384615
l100.avg=2651.76, total.avg=3497.467358490566
l100.avg=2617.11, total.avg=3481.1644444444446
l100.avg=2586.76, total.avg=3464.9025454545454
l100.avg=2554.54, total.avg=3448.6460714285713
l100.avg=2523.06, total.avg=3432.4077192982454
l100.avg=2489.24, total.avg=3416.1462068965516
l100.avg=2456.25, total.avg=3399.876779661017
l100.avg=2423.07, total.avg=3383.596666666667
l100.avg=2390.19, total.avg=3367.3113114754096
l100.avg=2356.44, total.avg=3351.006935483871
l100.avg=2322.54, total.avg=3334.6820634920637
l100.avg=2288.04, total.avg=3318.32828125
l100.avg=2253.77, total.avg=3301.9504615384617
l100.avg=2220.22, total.avg=3285.560606060606
l100.avg=2187.12, total.avg=3269.1659701492536
l100.avg=2154.24, total.avg=3252.77
l100.avg=2120.76, total.avg=3236.3640579710145
l100.avg=2086.88, total.avg=3219.942857142857
l100.avg=2053.67, total.avg=3203.5164788732395
l100.avg=2019.48, total.avg=3187.0715277777776
l100.avg=1986.58, total.avg=3170.6264383561643
l100.avg=1953.57, total.avg=3154.17972972973
l100.avg=1920.43, total.avg=3137.729733333333
l100.avg=1886.93, total.avg=3121.271842105263
l100.avg=1851, total.avg=3104.774805194805
l100.avg=1818.38, total.avg=3088.2825641025643
l100.avg=1785.82, total.avg=3071.795696202532
l100.avg=1751.9, total.avg=3055.297
l100.avg=1718.64, total.avg=3038.795061728395
l100.avg=1687.53, total.avg=3022.316219512195
l100.avg=1653.01, total.avg=3005.8185542168676
l100.avg=1617.74, total.avg=2989.2938095238096
l100.avg=1584.85, total.avg=2972.7709411764704
l100.avg=1551.77, total.avg=2956.2476744186047
l100.avg=1517.9, total.avg=2939.7149425287357
l100.avg=1483.87, total.avg=2923.17125
l100.avg=1450.47, total.avg=2906.62404494382
l100.avg=1417.54, total.avg=2890.078666666667
l100.avg=1383.54, total.avg=2873.5232967032966
l100.avg=1349.43, total.avg=2856.957065217391
l100.avg=1316.11, total.avg=2840.388817204301
l100.avg=1281.78, total.avg=2823.8078723404255
l100.avg=1248.41, total.avg=2807.2247368421054
l100.avg=1215.83, total.avg=2790.6477083333334
l100.avg=1182.31, total.avg=2774.0669072164947
l100.avg=1148.36, total.avg=2757.47806122449
l100.avg=1114.35, total.avg=2740.880808080808
l100.avg=1079.28, total.avg=2724.2648

There's still some overhead left, but considerably less than before.

@Uzlopak
Copy link
Collaborator

Uzlopak commented Mar 12, 2022

I also think that we can not improve it further as it is clearly a driver performance bottleneck.

@vkarpov15
Copy link
Collaborator

That's true. I'd like to minimize the overhead relative to the Node driver, and there's still a decent amount of overhead that we can shave off. But given that some of the issue comes down to bson serialization, there isn't much we can do about that unless we use a custom version of bson.

@ekorolevanyrun
Copy link
Author

@vkarpov15

I'm glad to see the progress on the issue, thank you.
What do you this about that reply? So, in the mongoose source code a custom bson serializer might be used with overrides

@vkarpov15
Copy link
Collaborator

@ekorolevanyrun that's something we'll consider. However, is there anything blocking you from using overrides in your codebase?

@vkarpov15 vkarpov15 modified the milestones: 6.2.7, 6.2.9 Mar 16, 2022
@ekorolevanyrun
Copy link
Author

@vkarpov15 , nothing blocks us except the fact that I don't know which package should be used to substitude :)
I assume that the Uzlopak's fork could be used to substitude, but I'm not sure

So, what is needed is add in my package.json something like this, right?

{
  "overrides": {
    "mongoose": {
      "mongodb": {
        "js-bson": "github:Uzlopak/js-bson#add-benchmark"
      }
    }
  }
}

@Uzlopak
Copy link
Collaborator

Uzlopak commented Mar 22, 2022

Just want to add that you should do performance tests. I tested bson serializing and in bson it was fast but using native driver etc. I maybe did not have the right benchmark, but it was actually still slow. So please bechmark.

@vkarpov15
Copy link
Collaborator

Added some more perf optimizations, we're about as close as we're going to get to the MongoDB driver without using @Uzlopak 's bson improvements. Hooks and cloning take up virtually the entire time difference between native driver and Mongoose right now as far as I can tell.

@vkarpov15 vkarpov15 removed this from the 6.2.9 milestone Mar 28, 2022
@vkarpov15 vkarpov15 added this to the 6.2.12 milestone Mar 28, 2022
@vkarpov15 vkarpov15 modified the milestones: 6.3.1, 6.3.2 Apr 20, 2022
@vkarpov15 vkarpov15 removed this from the 6.3.2 milestone May 2, 2022
@ekorolevanyrun
Copy link
Author

Hi! I had to pospone this task, but there was some free minutes and I made fresh perfomance tests. Mongodb-driver 4.9.0 and mongoose 6.5.2 is used.

As for previous tests some data is generated:

    const record = {
        randomData: [],
    };
    for (let i=0; i<Math.random()*(DATA_AMOUNT.max-DATA_AMOUNT.min)+DATA_AMOUNT.min;i++) {
        record.randomData.push(Math.random());
    }

then I made 10.000 operations

    const startTime = Date.now();
    // In case when I test mongoose perfomance:
    await slowsaveModel.collection.insertOne({ randomData: record.randomData });
    // in case when I test mongodb-driver:
    await collection.insertOne(record);
    const time= Date.now()-startTime;;

Results

Mongodb driver:

latest1000.avg=203.552, total.avg=203.552
latest1000.avg=306.4, total.avg=254.976
latest1000.avg=335.049, total.avg=281.667
latest1000.avg=321.716, total.avg=291.67925
latest1000.avg=300.065, total.avg=293.3564
latest1000.avg=232.129, total.avg=283.15183333333334
latest1000.avg=152.128, total.avg=264.43414285714283
latest1000.avg=67.838, total.avg=239.859625
latest1000.avg=12.003, total.avg=214.54222222222222
latest1000.avg=0.957, total.avg=193.1837

Mongoose@6.5.2:

latest1000.avg=4922.653, total.avg=4922.653
latest1000.avg=4633.762, total.avg=4778.2075
latest1000.avg=4293.072, total.avg=4616.495666666667
latest1000.avg=3921.028, total.avg=4442.62875
latest1000.avg=3541.683, total.avg=4262.4396
latest1000.avg=3167.321, total.avg=4079.9198333333334
latest1000.avg=2799.407, total.avg=3896.9894285714286
latest1000.avg=2425.623, total.avg=3713.068625
latest1000.avg=2012.791, total.avg=3524.148888888889
latest1000.avg=1630.405, total.avg=3334.7745

Mongoose@4, by the way:

latest1000.avg=1321.778, total.avg=1321.778
latest1000.avg=1342.531, total.avg=1332.1545
latest1000.avg=1352.08, total.avg=1338.7963333333332
latest1000.avg=1371.553, total.avg=1346.9855
latest1000.avg=1383.123, total.avg=1354.213
latest1000.avg=1281.841, total.avg=1342.151
latest1000.avg=1292.289, total.avg=1335.027857142857
latest1000.avg=1301.515, total.avg=1330.83875
latest1000.avg=1308.647, total.avg=1328.373
latest1000.avg=1315.786, total.avg=1327.1143

So, there is still an impressive difference between mongoose insertOne and clean mongodb-driver insertOne.

@thandaanda
Copy link

#13456 (comment)

@vkarpov15
Copy link
Collaborator

I took a look and it looks like the performance got much better in 6.2.7:

With latest 4.x:

l100.avg=456.5, total.avg=2628.8028

With 6.2.1:

l100.avg=971.43, total.avg=4926.9134

With 6.2.7:

l100.avg=967.14, total.avg=3266.9515

With 6.12.3:

l100.avg=1176.18, total.avg=3135.8095

With 8.0.1:

l100.avg=1243.15, total.avg=3456.0278

So try upgrading to 6.2.7 to see if that works better for you. In the meantime, we'll investigate and see how we can improve this performance.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Development

No branches or pull requests

6 participants