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

MongoDB Driver 3.6+ Performance issues on AWS Lambda

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 3.6.2
    • Fix Version/s: 3.6.3
    • Component/s: None
    • Labels:
      None
    • Case:

      Description

      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
      

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved: