Uploaded image for project: 'Node.js Driver'
  1. Node.js Driver
  2. NODE-2829

MongoDB Driver 3.6+ Performance issues on AWS Lambda

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 3.6.3
    • Affects Version/s: 3.6.2
    • Component/s: Lambda

      Environment:

      • AWS Lambda with NodeJS 12
      • MongoDB driver 3.6.2
      • MongoDB Atlas Cluster with version 4.4.1 with three nodes in the replica set

      Problem:

      After some idle time between requests any MongoDB request takes more than 10 seconds to complete. During this idle time the same Lambda instance is used.

      The MongoDB connection is "reused" while the Lambda instance is kept warm, following MongoDB Documentation.

      This does not happen if we downgrade to the MongoDB driver version 3.5.11.

      See logs with MongoDB debug enabled, where:

      • The first request took around 1500 ms, including the Lambda setup due to the cold start.
      • The second request, 27 seconds after the first one, took around 500 ms.
      • The third request, 35 seconds after the second one, took around 10000 ms.
      // First Lambda request where the MongoDB connection is established
2020-09-21T07:50:29.258Z 48a2f73a-c6fd-4c8e-a1bc-a8c00ffe035a DEBUG {"message": "Incoming request" }
2020-09-21T07:50:30.653Z 48a2f73a-c6fd-4c8e-a1bc-a8c00ffe035a INFO [DEBUG-Cursor:9] 1600674630653 issue initial query [ { "find": "dataBaseName.collectionName", "limit": 0, "skip": 0, "query": { "primaryKey": "3", "issuedAtDate": { "$gte": "2019-09" } }, "hint": null, "slaveOk": true, "readPreference": { "mode": "primary" } }] with flags [undefined] { type: 'debug', message: 'issue initial query [{"find":"dataBaseName.collectionName","limit":0,"skip":0,"query":{"primaryKey":"3","issuedAtDate":{"$gte":"2019-09"}},"hint":null,"slaveOk":true,"readPreference":{"mode":"primary"}}] with flags [undefined]', className: 'Cursor', pid: 9, date: 1600674630653 }
2020-09-21T07:50:30.692Z 48a2f73a-c6fd-4c8e-a1bc-a8c00ffe035a INFO { "message": "Request Finished" }
REPORT RequestId: 48a2f73a-c6fd-4c8e-a1bc-a8c00ffe035a Duration: 1438.24 ms

// Second request, MongoDB connection already created and being reused without problems
2020-09-21T07:50:57.515Z 2b5e438b-e850-4511-96c6-646f656e00fe DEBUG { "message": "Incoming request" }
2020-09-21T07:50:58.159Z 2b5e438b-e850-4511-96c6-646f656e00fe INFO [DEBUG-Cursor:9] 1600674658159 issue initial query [ { "find": "dataBaseName.collectionName", "limit": 0, "skip": 0, "query": { "primaryKey": "3", "issuedAtDate": { "$gte": "2019-09" } }, "hint": null, "slaveOk": true, "readPreference": { "mode": "primary" } }] with flags [undefined] { type: 'debug', message: 'issue initial query [{"find":"dataBaseName.collectionName","limit":0,"skip":0,"query":{"primaryKey":"3","issuedAtDate":{"$gte":"2019-09"}},"hint":null,"slaveOk":true,"readPreference":{"mode":"primary"}}] with flags [undefined]', className: 'Cursor', pid: 9, date: 1600674658159 }
2020-09-21T07:50:58.174Z 2b5e438b-e850-4511-96c6-646f656e00fe INFO { "message": "Request Finished" }
REPORT RequestId: 2b5e438b-e850-4511-96c6-646f656e00fe Duration: 660.97

// Third request, MongoDB connection already created but the first request to be send to MongoDB takes around 10 seconds
2020-09-21T07:51:33.491Z 662ea707-2859-4339-bfa1-24109ffca3fe DEBUG { "message": "Incoming request" }
2020-09-21T07:51:33.993Z 662ea707-2859-4339-bfa1-24109ffca3fe INFO [DEBUG-Cursor:9] 1600674693992 issue initial query [ { "find": "dataBaseName.collectionName", "limit": 0, "skip": 0, "query": { "primaryKey": "3", "issuedAtDate": { "$gte": "2019-09" } }, "hint": null, "slaveOk": true, "readPreference": { "mode": "primary" } }] with flags [undefined] { type: 'debug', message: 'issue initial query [{"find":"dataBaseName.collectionName","limit":0,"skip":0,"query":{"primaryKey":"3","issuedAtDate":{"$gte":"2019-09"}},"hint":null,"slaveOk":true,"readPreference":{"mode":"primary"}}] with flags [undefined]', className: 'Cursor', pid: 9, date: 1600674693992 }
2020-09-21T07:51:43.673Z 662ea707-2859-4339-bfa1-24109ffca3fe INFO {"message": "Request Finished" }
REPORT RequestId: 662ea707-2859-4339-bfa1-24109ffca3fe Duration: 10183.76

            Assignee:
            matt.broadstone@mongodb.com Matt Broadstone
            Reporter:
            joao.mallmann@my-rio.de Joao Vitor Mallmann
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: