10x slowdown on Windows when upgrading from Mongoose 4 to 5.

[deklanw]

My tests are taking 10x as long on Windows when I upgrade from Mongoose 4 to 5. The slowdown doesn't appear to happen on my Ubuntu laptop.

I created a repo with two branches to illustrate the problem,
https://github.com/deklanw/pensieve-mongoose-4-to-5-speed-testing

I included the .env file for testing. If need be just change this line
MONGODB_URI=mongodb://localhost:27017/pensieve-test
to reflect your testing environment.

Just,
yarn install
yarn test

I tested on my Windows desktop and laptop to make sure. They're both Windows 10 x64. The problem occurred on both. The problem doesn't occur on my Ubuntu laptop.

Here are the versions:
Windows 10 x64 laptop: mongodb v3.6.5 node v10.1.0 yarn v1.6.0
Windows 10 x64 desktop: mongodb v3.6.3 node v10.3.0 yarn v1.7.0
The Ubuntu laptop has the same versions of everything as the Windows 10 desktop.

@lineus Tested this on OSX, I believe, and didn't find the slowdown. So it appears to be Windows related.

[deklanw]

Here are the test outputs for the Mongoose 4 and 5 branches, respectively, on my Windows 10 desktop. Running the tests repeatedly gave similar results.

✨  Test database loaded  Cards controller
    GET /api/cards
GET /api/cards 200 21.914 ms - 345
      √ should return array of cards for user (44ms)
    POST /api/cards
POST /api/cards 200 24.228 ms - 278
      √ should create single card for user
    DELETE /api/cards/:id
DELETE /api/cards/5b195db0dd72452680504f5c 200 2.678 ms - 14
      √ should delete single card for user

  Decks controller
    GET /api/decks
GET /api/decks 400 0.135 ms - 64
      √ should return 400 if no authentication provided
GET /api/decks 200 7.843 ms - 335
      √ should return decks if token is provided
    POST /api/decks
POST /api/decks 200 2.426 ms - 275
      √ should create single deck for user
    DELETE /api/decks/:id
DELETE /api/decks/5b195db0dd72452680504f6d 200 2.033 ms - 14
      √ should delete single deck for user

  Sessions controller
    GET /api/sessions/:id
GET /api/sessions/5b195db0dd72452680504f67 200 4.788 ms - 368
      √ should return a single session for user

  Users controller
    POST /api/users/login
POST /api/users/login 200 62.342 ms - 384
      √ should return user if authentication is valid (65ms)
POST /api/users/login 200 58.972 ms - 384
      √ should return token if authentication is valid (61ms)
    POST /api/users/signup
POST /api/users/signup 200 82.471 ms - 363
      √ should create user if signup is valid (84ms)
    GET /api/users/profile
GET /api/users/profile 200 2.203 ms - 128
      √ should return user for valid token
    PUT /api/user/profile
PUT /api/users/profile 200 4.476 ms - 128
      √ should update single user for valid token

  recallRate
    getRecallRate
      √ should return rate of 50% for current review date
      √ should return recall rate of 100% for current reviewed timestamp
    getCardAverage
      √ should return average recall rate for array of cards

  Server
GET / 302 1.067 ms - 27
    √ GET / redirects to /docs
GET /invalid 404 1.272 ms - 146
    √ response to 404 unsupported routes

  Card model
    get
      √ should return single card for user
    getAll
      √ should return all cards for user
    countAll
      √ should return the length of all cards for a user
    create
      √ should create single card for user
    update
      √ should update single card for user
    delete
      √ should delete single card for user
    deleteAllByDeck
      √ should delete all cards for a deck

  Deck model
    get
      √ should return single deck for user
    all
      √ should return all decks for user
    new
      √ should create single deck for user
    update
      √ should update single deck for user
      √ should not update fields that are not defined

  Review model
    create
      √ should create new review object for user
    get
      √ should return review object by id

  Session model
    get
      √ should return single session object for user
      √ should return populated card objects for session
    create
      √ should create single session object for user

  User model
    get
      √ should return user with matching id
      √ should not return `password` field
    update
      √ should update user with matching id
      √ should not update fields that are not defined
      √ should not return `password` field
    delete
      √ should delete user with matching id
    create
      √ should create user with matching information (72ms)
    authenticate
      √ should authenticate user with correct information (116ms)

  Cards mailer
    sendDueCardsEmail
      √ should send email for valid user
      √ should not send email if user`s notification preference is off
      √ should not send email if number of due cards are less than user`s session size
    sendNewCardsEmail
      √ should send email for valid user
      √ should not send email if user`s notification preference is off
      √ should not send email if number of new cards are less than 3


  49 passing (642ms)

Done in 2.84s.

✨  Test database loaded
  Cards controller
    GET /api/cards
GET /api/cards 200 2005.845 ms - 345
      √ should return array of cards for user (2027ms)
    POST /api/cards
POST /api/cards 200 1992.893 ms - 278
      √ should create single card for user (1997ms)
    DELETE /api/cards/:id
DELETE /api/cards/5b195defb5d63f0834d10423 200 3.603 ms - 14
      √ should delete single card for user

  Decks controller
    GET /api/decks
GET /api/decks 400 0.158 ms - 64
      √ should return 400 if no authentication provided
GET /api/decks 200 8.937 ms - 335
      √ should return decks if token is provided
    POST /api/decks
POST /api/decks 200 3.616 ms - 275
      √ should create single deck for user
    DELETE /api/decks/:id
DELETE /api/decks/5b195defb5d63f0834d10434 200 3.060 ms - 14
      √ should delete single deck for user

  Sessions controller
    GET /api/sessions/:id
GET /api/sessions/5b195defb5d63f0834d1042e 200 7.425 ms - 368
      √ should return a single session for user

  Users controller
    POST /api/users/login
POST /api/users/login 200 61.300 ms - 384
      √ should return user if authentication is valid (63ms)
POST /api/users/login 200 60.517 ms - 384
      √ should return token if authentication is valid (62ms)
    POST /api/users/signup
POST /api/users/signup 200 88.379 ms - 363
      √ should create user if signup is valid (91ms)
    GET /api/users/profile
GET /api/users/profile 200 1.918 ms - 128
      √ should return user for valid token
    PUT /api/user/profile
PUT /api/users/profile 200 5.914 ms - 128
      √ should update single user for valid token

  recallRate
    getRecallRate
      √ should return rate of 50% for current review date
      √ should return recall rate of 100% for current reviewed timestamp
    getCardAverage
      √ should return average recall rate for array of cards

  Server
GET / 302 0.829 ms - 27
    √ GET / redirects to /docs
GET /invalid 404 0.936 ms - 146
    √ response to 404 unsupported routes

  Card model
    get
      √ should return single card for user
    getAll
      √ should return all cards for user
    countAll
      √ should return the length of all cards for a user
    create
      √ should create single card for user
    update
      √ should update single card for user
    delete
      √ should delete single card for user
    deleteAllByDeck
      √ should delete all cards for a deck

  Deck model
    get
      √ should return single deck for user
    all
      √ should return all decks for user
    new
      √ should create single deck for user
    update
      √ should update single deck for user
      √ should not update fields that are not defined

  Review model
    create
      √ should create new review object for user
    get
      √ should return review object by id

  Session model
    get
      √ should return single session object for user
      √ should return populated card objects for session
    create
      √ should create single session object for user

  User model
    get
      √ should return user with matching id
      √ should not return `password` field
    update
      √ should update user with matching id
      √ should not update fields that are not defined
      √ should not return `password` field
    delete
      √ should delete user with matching id
    create
      √ should create user with matching information (57ms)
    authenticate
      √ should authenticate user with correct information (115ms)

  Cards mailer
    sendDueCardsEmail
      √ should send email for valid user
      √ should not send email if user`s notification preference is off
      √ should not send email if number of due cards are less than user`s session size
    sendNewCardsEmail
      √ should send email for valid user
      √ should not send email if user`s notification preference is off
      √ should not send email if number of new cards are less than 3


  49 passing (5s)

Done in 7.12s.

[vkarpov15]

Thanks for reporting, will investigate ASAP

[AbdelrahmanHafez]

I am not sure if it's relevant, but the connection process takes 5 seconds on Windows, I'll try with mongoose v4 and see if it's a v5 thing or that's the normal duration.

[AbdelrahmanHafez]

Running the following code to calculate the connection time:

const mongoose = require('mongoose');


const run = async () => {
  let beforeConnection = Date.now();
  await mongoose.connect('mongodb://localhost/somedb');
  let afterConnection = Date.now();

  console.log(`Time to connect is: ${(afterConnection - beforeConnection) / 1000}s`);
};

run().catch(console.error);

output using mongoose v4.13.14:

Time to connect is: 0.031s

output using mongoose v5.1.5:

Time to connect is: 1.035s

Windows 10 1803 (Build 17134.81)
Node v10.4.0
MongoDB v3.2.7

[vkarpov15]

Just to clarify, are you running mongodb locally or are you connecting to a remote mongodb @AbdelrahmanHafez ?

[AbdelrahmanHafez]

Locally

[AbdelrahmanHafez]

It's not just the connection either, deleting, and creating data are 10x+ slower as well.

Using the following code:

const mongoose = require('mongoose');
const { Schema } = mongoose;
mongoose.Promise = Promise;


const userSchema = new Schema();

const User = mongoose.model('User', userSchema);

const users = [];

for (let i = 0; i < 1000; i++) users.push(new User());

const run = async () => {
  await mongoose.connect('mongodb://localhost/test');

  const before = Date.now();

  await User.remove();
  await User.create(users);

  const after = Date.now();

  console.log(`Duration: ${(after - before) / 1000}s`);
};

run().catch(console.error);

v4.13.14 outputs:

Duration: 0.461s

v5.1.5 outputs:

Duration: 4.621s

[AbdelrahmanHafez]

Perhaps we should remove the needs repro script label from this issue now?
I believe #6566 (comment) is a good start.

[vkarpov15]

Needs repro just means that the mongoose devs haven't been able to confirm this as a bug. In this case, it means we haven't had the time to boot up windows and try it. Perhaps we should split that label into 2 labels, one that says theres no repro script and one that says theres a repro script but the issue is blocked on mongoose devs?

[AbdelrahmanHafez]

a bug? label would be great, needs repro script on an issue that's been abandoned for a while may give the wrong idea to the developers.

[cosminn777]

Speed is greatly reduced for me too. I'm Using MongoDb 4.0, Mongoose 5.2.1, Nodejs 10.5.0 and Windows 10.
Maybe MongoDB 4.0 issue?
SERVER-35657:
https://docs.mongodb.com/manual/release-notes/4.0/#known-issues-in-4-0-0

[AbdelrahmanHafez]

@cosminn777 I don't think so, I am using MongoDB v3.2.7 and I am experiencing the same slowdown.

[cosminn777]

@AbdelrahmanHafez you are right. From my tests I get slowdown on both MongoDB 4.0.0 and MongoDB 3.6.5

[cosminn777]

I am doing many creation/editing operations in DB and I do encounter heavy slowdown.

[cosminn777]

The issue might be from one of the underlying .js libraries that Mongoose is using.

[NewEraCracker]

Are you connecting by name or IP?

On the example you posted, you documented localhost, if you replace that with 127.0.0.1 does it workaround the issue?

Regards,
NewEraCracker

[AbdelrahmanHafez]

@NewEraCracker interesting!

This actually reduced the connection time from 1.04s to 0.04s, and the read/write operation in #6566 (comment) from 4.563s to 0.577s. Which is way better, yet slightly slower than mongoose v4.14.13.

This is a good place to start debugging the issue.

However, I am curious on how you found out that was the problem, was it a happy accident or by debugging it? If so, please elaborate on your debugging process.

[NewEraCracker]

There's a similar issue starting with PHP 5.3 and the native MySQL driver (mysqlnd) that cause same delays. I spotted this back in 2011 I think.

I am guessing something in node or mongoose or a library is now preferring IPv6 but MongoDB is only listening in IPv4.

There are two possible workarounds I am aware of:

• Use 127.0.0.1 instead of localhost in windows for the connection string.
• Set the following entry in the hosts file:
  127.0.0.1 localhost

[AbdelrahmanHafez]

Already switched to 127.0.0.1 in the connection string, and the tests run much faster now.

Thank you!

[vkarpov15]

Yeah I can confirm that switching to 127.0.0.1 from localhost speeds up initial connection from 1000ms to 30ms on windows. Currently digging in to why this is the case.

[vkarpov15]

@NewEraCracker is spot on, good call. The reason for this slowdown is that, starting in mongodb driver 3.0.0, the mongodb driver tries to connect using ipv6 first, and falls back to ipv4 if that fails unless you set the family option or use an ipv4 address like 127.0.0.1. The 1 second delay is because the driver's trying to connect to localhost using ipv6, but presumably either your mongodb server isn't configured to accept ipv6 connections or localhost isn't configured to point to an ipv6 address. Below are the relevant links

mongodb-js/mongodb-core@107bae5
https://jira.mongodb.org/projects/NODE/issues/NODE-1222?filter=allissues
mongodb-js/mongodb-core#260

As a workaround, do this:

const mongoose = require('mongoose');

const run = async () => {
  let beforeConnection = Date.now();
  await mongoose.connect('mongodb://localhost/somedb', { family: 4 });
  let afterConnection = Date.now();

  console.log(`Time to connect is: ${(afterConnection - beforeConnection) / 1000}s`);
};

run().catch(console.error);

We'll add documentation around this option