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 Performance Regression 4.13 -> 5.5 #7895

Closed
mpseay opened this issue Jun 13, 2019 · 13 comments
Closed

Mongoose Performance Regression 4.13 -> 5.5 #7895

mpseay opened this issue Jun 13, 2019 · 13 comments
Milestone

Comments

@mpseay
Copy link

mpseay commented Jun 13, 2019

Hey Guys! I've found a few documented cases where a performance regression was found. Specifically, #6065 lead me to checking on the versions for mongodb and mongodb-core. After troubleshooting this for most the day, our database has been totally fine, but, the mongoose upgrade is clearly bottlenecking somewhere I can't seem to figure out. Any help in the right direction would be greatly appreciated!

System Setup
Node Version: 6.11
Database Version: 3.6
npm mongoose versions: 4.13 / 5.5.13
npm mongodb: 3.2.7
npm mongodb-core: 3.2.7

Sample Code

//Test Coverage Status: Done
app.get('/api/1/jobs/:id', function (req, res) {
  model.findById(req.params.id, (data) => {
    if (!data) {
      return res.send(404);
    }
    return res.send({result: data});
  }, (e) => {
    return res.send(500);
  });
});

Testcase Description
An express app doing a super basic findById() lookup.

Notice the large difference between the versions.
Mongoose 4.13

$ ab -n 1000 -c 50 http://localhost:3050/api/1/jobs/518d9cabd80f1f0200000008
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests

Server Software:
Server Hostname:        localhost
Server Port:            3050

Document Path:          /api/1/jobs/518d9cabd80f1f0200000008
Document Length:        30875 bytes

Concurrency Level:      50
Time taken for tests:   12.381 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      31328000 bytes
HTML transferred:       30875000 bytes
Requests per second:    80.77 [#/sec] (mean)
Time per request:       619.042 [ms] (mean)
Time per request:       12.381 [ms] (mean, across all concurrent requests)
Transfer rate:          2471.06 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.4      0       3
Processing:    45  610 123.0    594    1000
Waiting:       42  571 115.5    566     928
Total:         45  610 123.1    595    1000

Percentage of the requests served within a certain time (ms)
  50%    595
  66%    631
  75%    672
  80%    718
  90%    788
  95%    820
  98%    843
  99%    910
 100%   1000 (longest request)

Mongoose 5.5.13

$ ab -n 1000 -c 50 http://localhost:3050/api/1/jobs/518d9cabd80f1f0200000008
This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:
Server Hostname:        localhost
Server Port:            3050

Document Path:          /api/1/jobs/518d9cabd80f1f0200000008
Document Length:        30875 bytes

Concurrency Level:      50
Time taken for tests:   45.707 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      31328000 bytes
HTML transferred:       30875000 bytes
Requests per second:    21.88 [#/sec] (mean)
Time per request:       2285.372 [ms] (mean)
Time per request:       45.707 [ms] (mean, across all concurrent requests)
Transfer rate:          669.34 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.3      0       2
Processing:   160 2245 593.3   2227    4247
Waiting:      158 2046 561.3   2071    4173
Total:        161 2246 593.3   2227    4247

Percentage of the requests served within a certain time (ms)
  50%   2227
  66%   2408
  75%   2549
  80%   2705
  90%   3062
  95%   3262
  98%   3470
  99%   3568
 100%   4247 (longest request)
@mpseay
Copy link
Author

mpseay commented Jun 13, 2019

Quick Update: It appears under the same conditions, using lean() in 5.x provided significant improvement.

This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:
Server Hostname:        localhost
Server Port:            3050

Document Path:          /api/1/jobs/518d9cabd80f1f0200000008
Document Length:        20184 bytes

Concurrency Level:      50
Time taken for tests:   11.581 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      20638000 bytes
HTML transferred:       20184000 bytes
Requests per second:    86.34 [#/sec] (mean)
Time per request:       579.073 [ms] (mean)
Time per request:       11.581 [ms] (mean, across all concurrent requests)
Transfer rate:          1740.22 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       2
Processing:    49  565 101.7    546     868
Waiting:       47  565 101.8    546     867
Total:         49  566 101.7    546     868

Percentage of the requests served within a certain time (ms)
  50%    546
  66%    606
  75%    630
  80%    653
  90%    708
  95%    726
  98%    771
  99%    789
 100%    868 (longest request)

@mpseay
Copy link
Author

mpseay commented Jun 13, 2019

So, it looks like our best bet is to roll with the suggested http://plugins.mongoosejs.io/plugins/lean-virtuals from the docs. Feel free to close this issue. Otherwise, I will tomorrow in case anyone has any additional ideas or comments :) Thanks!

One last test under the same dependencies (5.x) + concurrency (2)

This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:
Server Hostname:        localhost
Server Port:            3050

Document Path:          /api/1/jobs/518d9cabd80f1f0200000008
Document Length:        20184 bytes

Concurrency Level:      50
Time taken for tests:   8.360 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      20638000 bytes
HTML transferred:       20184000 bytes
Requests per second:    119.61 [#/sec] (mean)
Time per request:       418.010 [ms] (mean)
Time per request:       8.360 [ms] (mean, across all concurrent requests)
Transfer rate:          2410.74 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.3      0       3
Processing:    55  405  60.1    398     570
Waiting:       53  404  60.0    398     570
Total:         57  405  59.9    398     570

Percentage of the requests served within a certain time (ms)
  50%    398
  66%    424
  75%    441
  80%    451
  90%    484
  95%    496
  98%    520
  99%    532
 100%    570 (longest request)

@Fonger
Copy link
Contributor

Fonger commented Jun 13, 2019

@mpseay can you try res.send({result: data.toJSON({ virtuals: true })}); without .lean() in the query and see the benchmark results? I guess this won't help but I'm just curious.

@mpseay
Copy link
Author

mpseay commented Jun 13, 2019

Sure thing! Same test with res.send({result: data.toJSON({ virtuals: true })});. Pretty consistent with the initial 5.x test.

This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:
Server Hostname:        localhost
Server Port:            3050

Document Path:          /api/1/jobs/518d9cabd80f1f0200000008
Document Length:        31406 bytes

Concurrency Level:      50
Time taken for tests:   55.952 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      31858000 bytes
HTML transferred:       31406000 bytes
Requests per second:    17.87 [#/sec] (mean)
Time per request:       2797.584 [ms] (mean)
Time per request:       55.952 [ms] (mean, across all concurrent requests)
Transfer rate:          556.04 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   3.4      0     108
Processing:   142 2721 327.8   2734    3689
Waiting:      141 2714 327.8   2725    3653
Total:        144 2722 327.9   2734    3689

Percentage of the requests served within a certain time (ms)
  50%   2734
  66%   2769
  75%   2790
  80%   2801
  90%   2850
  95%   3211
  98%   3412
  99%   3508
 100%   3689 (longest request)

@mpseay
Copy link
Author

mpseay commented Jun 13, 2019

It's worth mentioning some additional conditions around this test. The model I am using is a little larger than you might expect. But, more importantly, it contains document references to other collections and takes advantage of the mongoose .populate() functionality.

I wanted to get an idea of the overhead, and, as expected, the more .populate() calls you have, the slower the test ran. Don't ask why, but, the model I'm testing with has about 9 .populate() with 2 of those having a sub .populate(). Unfortunately, that's the schema design we're working with. But, thought I'd add some additional color to the findings. above.

@mpseay
Copy link
Author

mpseay commented Jun 13, 2019

And lastly, some insight to response times upon release and revert.

Screen Shot 2019-06-13 at 10 09 59 AM

Hopefully, this saves even a single person a little bit of time. Cheers ya'll!

@mpseay mpseay closed this as completed Jun 13, 2019
@Fonger
Copy link
Contributor

Fonger commented Jun 13, 2019 via email

@mpseay
Copy link
Author

mpseay commented Jun 13, 2019

Happy to share more results. But, poolSize didn't make a difference in this case.

This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:
Server Hostname:        localhost
Server Port:            3050

Document Path:          /api/1/jobs/518d9cabd80f1f0200000008
Document Length:        30875 bytes

Concurrency Level:      50
Time taken for tests:   45.278 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      31329000 bytes
HTML transferred:       30875000 bytes
Requests per second:    22.09 [#/sec] (mean)
Time per request:       2263.918 [ms] (mean)
Time per request:       45.278 [ms] (mean, across all concurrent requests)
Transfer rate:          675.70 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       2
Processing:   142 2211 592.9   2233    4437
Waiting:      139 2207 591.3   2232    4411
Total:        142 2212 592.8   2233    4437

Percentage of the requests served within a certain time (ms)
  50%   2233
  66%   2376
  75%   2563
  80%   2669
  90%   2937
  95%   3124
  98%   3436
  99%   3708
 100%   4437 (longest request)

@vkarpov15
Copy link
Collaborator

Realistically, I'm not going to be able to repro this without taking a look at what your schema looks like. Below script gives similar perf results for me between Mongoose 4 and Mongoose 5:

const express = require('express');
const mongoose = require('mongoose');

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

async function run() {
  await mongoose.connect('mongodb://localhost:27017/test', { useNewUrlParser: true });
  await mongoose.connection.dropDatabase();

  const Model = mongoose.model('Test', mongoose.Schema({ name: String }));
  const doc = await Model.create({ name: 'test' });

  const app = express();

  app.get('*', function(req, res) {
    Model.findById(doc._id).exec((data) => {
      if (!data) {
        return res.send(404);
      }
      return res.send({result: data});
    }, (e) => {
      return res.send(500);
    });
  });

  await app.listen(3000);
  console.log('Listening on port 3000');
}

Mongoose 5:

$ ab -n 1000 -c 50 http://localhost:3000/
This is ApacheBench, Version 2.3 <$Revision: 1706008 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        9 bytes

Concurrency Level:      50
Time taken for tests:   0.557 seconds
Complete requests:      1000
Failed requests:        0
Non-2xx responses:      1000
Total transferred:      215000 bytes
HTML transferred:       9000 bytes
Requests per second:    1795.01 [#/sec] (mean)
Time per request:       27.855 [ms] (mean)
Time per request:       0.557 [ms] (mean, across all concurrent requests)
Transfer rate:          376.88 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   0.8      0       5
Processing:    12   27   6.8     26      51
Waiting:       11   24   6.2     23      48
Total:         12   28   7.4     26      56
WARNING: The median and mean for the initial connection time are not within a normal deviation
        These results are probably not that reliable.

Percentage of the requests served within a certain time (ms)
  50%     26
  66%     28
  75%     30
  80%     31
  90%     35
  95%     50
  98%     54
  99%     54
 100%     56 (longest request)
$ 

Mongoose 4:

$ ab -n 1000 -c 50 http://localhost:3000/
This is ApacheBench, Version 2.3 <$Revision: 1706008 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests


Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        9 bytes

Concurrency Level:      50
Time taken for tests:   0.584 seconds
Complete requests:      1000
Failed requests:        0
Non-2xx responses:      1000
Total transferred:      215000 bytes
HTML transferred:       9000 bytes
Requests per second:    1711.66 [#/sec] (mean)
Time per request:       29.211 [ms] (mean)
Time per request:       0.584 [ms] (mean, across all concurrent requests)
Transfer rate:          359.38 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.8      0       6
Processing:     2   28  11.7     26      91
Waiting:        2   25  11.9     23      90
Total:          2   29  12.3     27      96

Percentage of the requests served within a certain time (ms)
  50%     27
  66%     29
  75%     30
  80%     31
  90%     35
  95%     60
  98%     78
  99%     80
 100%     96 (longest request)
$ 

@vkarpov15 vkarpov15 added the can't reproduce Mongoose devs have been unable to reproduce this issue. Close after 14 days of inactivity. label Jul 5, 2019
@vkarpov15 vkarpov15 removed this from the 5.6.4 milestone Jul 5, 2019
@vkarpov15 vkarpov15 added the needs clarification This issue doesn't have enough information to be actionable. Close after 14 days of inactivity label Jul 5, 2019
@brettkiefer
Copy link

brettkiefer commented Jul 27, 2019

I'm also seeing what looks like a performance regression between 4.13 and 5.6 (in my case specifically 4.13.8 and 5.6.5), under real workloads. CPU usage looks elevated by about 30% in 5.6.5 over 4.13.8, and there is a perceptible effect on response time. I did some performance analysis on a realistic simulation of our production workload, and it looks like 5.6 is spending a lot of time in Document.__init, particularly when subdocuments are involved. I wrote a little script to compare .init() performance between 4 and 5. Subdoc array init looked like it might have something to do with it, so I used a fairly beefy subdoc array:

'use strict';

const mongoose = require('mongoose');

const subdocs = 100;
const reps = 5000;

const SubdocSchema = mongoose.Schema({ a: String, b: String, c: String, d: String, e: String  });
const Schema = mongoose.Schema({ name: String, subdocs: { type: [SubdocSchema] } });
const Model = mongoose.model('Test', Schema);
const data = {
  _id: new mongoose.Types.ObjectId(),
  name: 'test',
  subdocs: Array(subdocs).fill({a: 'a', b: 'b', c: 'c', d: 'd', e: 'e' })
};
const model = new Model();

for (let i = 0; i < reps; i++) {
  model.init(data);
}

In mongoose 4.13.8, running that generally gives:

$ time node perf.js

real    0m6.177s
user    0m9.760s
sys     0m0.947s

In mongoose 5.6.5 (5.6.7 is about the same), I get:

$ time node perf.js

real    0m10.277s
user    0m15.425s
sys     0m1.236s

... and that's pretty consistent across several runs, so that'd be document init taking about 1.5 times as much time (and, since synchronous, probably CPU as well) as it did under Mongoose 4.

Does that seem like it might be a lead? It looks like our application is fairly sensitive to Mongoose document init performance, and I would imagine that the other reporters' might be as well.

@vkarpov15 vkarpov15 removed can't reproduce Mongoose devs have been unable to reproduce this issue. Close after 14 days of inactivity. needs clarification This issue doesn't have enough information to be actionable. Close after 14 days of inactivity labels Jul 29, 2019
@vkarpov15 vkarpov15 added this to the 5.6.8 milestone Jul 29, 2019
@vkarpov15
Copy link
Collaborator

@brettkiefer that was very helpful, helped confirm that the perf issue here was with document arrays. I put in a PR: #8037 that expands on the work in #7798 and shaves off 30% on the perf.js file you posted.

@brettkiefer
Copy link

brettkiefer commented Jul 30, 2019

@vkarpov15 That looks great! For the above perf script on my test setup, 11ce670 runs much faster than 5.6.5 and only slightly slower than 4.13.8 under node 10.15.3, so that should translate to big improvements for our real-world workload. Thanks for looking at it.

@mpseay
Copy link
Author

mpseay commented Jul 31, 2019

Awesome news!

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

No branches or pull requests

5 participants