1

Ref: https://stackoverflow.com/questions/58856620/mongodb-connection-initialisation-delay-on-certain-windows-10-devices

System info

OS Name: Microsoft Windows 10 Enterprise

OS Version: 10.0.17134 N/A Build 17134

MongoDB Version

MongoDB 4.2.1 x64 Windows.

Overview

When forming a connection to a standalone mongod instances

PS C:\MongoDB> .\mongod.exe --dbpath C:\data

A significant delay, 10-25 seconds, is seen forming the connection between the client and the server.

PS C:\MongoDB> .\mongo.exe 127.0.0.1:27017

We have excluded the theories of the problem being related to the firewall and proxy.

Analysis

Aligning the verbose logs of both the client and server shows a delay when processing the admin command.

(> = server, ~ = client)

~ MongoDB shell version v4.2.1
~ connecting to: mongodb://127.0.0.1:27017/admin?compressors=disabled&gssapiServiceName=mongodb
~ 2019-11-14T02:23:29.803-0800 D1 NETWORK  [js] creating new connection to:127.0.0.1:27017
> 2019-11-14T02:23:29.806-0800 I  NETWORK  [listener] connection accepted from 127.0.0.1:60413 #1 (1 connection now open)
> 2019-11-14T02:23:29.806-0800 D3 EXECUTOR [listener] Starting new executor thread in passthrough mode
~ 2019-11-14T02:23:29.806-0800 D1 NETWORK  [js] connected to server 127.0.0.1:27017
> 2019-11-14T02:23:46.635-0800 D2 COMMAND  [conn1] run command admin.$cmd { isMaster: 1, hostInfo: "REDACTED:27017", client: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.2.1" }, os: { type: "Windows", name: "Microsoft Windows 10", architecture: "x86_64", version: "10.0 (build 17134)" } }, $db: "admin" }
> 2019-11-14T02:23:46.635-0800 I  NETWORK  [conn1] received client metadata from 127.0.0.1:60413 conn1: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.2.1" }, os: { type: "Windows", name: "Microsoft Windows 10", architecture: "x86_64", version: "10.0 (build 17134)" } }
> 2019-11-14T02:23:46.635-0800 D3 NETWORK  [conn1] Starting server-side compression negotiation
> 2019-11-14T02:23:46.635-0800 D3 NETWORK  [conn1] Compression negotiation not requested by client
> 2019-11-14T02:23:46.635-0800 I  COMMAND  [conn1] command admin.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1, hostInfo: "REDACTED:27017", client: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.2.1" }, os: { type: "Windows", name: "Microsoft Windows 10", architecture: "x86_64", version: "10.0 (build 17134)" } }, $db: "admin" } numYields:0 reslen:257 locks:{} protocol:op_query 0ms
~ 2019-11-14T02:23:46.636-0800 D1 NETWORK  [js] connected connection!
~ Implicit session: session { "id" : UUID("a1c87b79-d721-4d57-b3f9-c17aa9db41cd") }
~ MongoDB server version: 4.2.1

Overlaying the network comms captured Wireshark

Time               Source                Destination           Protocol Port        Length Info
02:23:29.805873    127.0.0.1             127.0.0.1             TCP      60413,27017 56     60413 → 27017 [SYN] Seq=0 Win=64240 Len=0 MSS=65495 WS=256 SACK_PERM=1
02:23:29.805954    127.0.0.1             127.0.0.1             TCP      27017,60413 56     27017 → 60413 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=65495 WS=256 SACK_PERM=1
02:23:29.806041    127.0.0.1             127.0.0.1             TCP      60413,27017 44     60413 → 27017 [ACK] Seq=1 Ack=1 Win=525568 Len=0
02:23:29.816470    127.0.0.1             127.0.0.1             SSL      60413,27017 368    Continuation Data
02:23:29.816569    127.0.0.1             127.0.0.1             TCP      27017,60413 44     27017 → 60413 [ACK] Seq=1 Ack=325 Win=525568 Len=0
02:23:46.636463    127.0.0.1             127.0.0.1             SSL      27017,60413 301    Continuation Data
02:23:46.636562    127.0.0.1             127.0.0.1             TCP      60413,27017 44     60413 → 27017 [ACK] Seq=325 Ack=258 Win=525312 Len=0
02:23:46.637297    127.0.0.1             127.0.0.1             SSL      60413,27017 105    Continuation Data
02:23:46.637364    127.0.0.1             127.0.0.1             TCP      27017,60413 44     27017 → 60413 [ACK] Seq=258 Ack=386 Win=525312 Len=0
02:23:46.637991    127.0.0.1             127.0.0.1             SSL      27017,60413 111    Continuation Data
02:23:46.638079    127.0.0.1             127.0.0.1             TCP      60413,27017 44     60413 → 27017 [ACK] Seq=386 Ack=325 Win=525056 Len=0
02:23:46.646216    127.0.0.1             127.0.0.1             SSL      60413,27017 108    Continuation Data
02:23:46.646297    127.0.0.1             127.0.0.1             TCP      27017,60413 44     27017 → 60413 [ACK] Seq=325 Ack=450 Win=525312 Len=0
02:23:46.646984    127.0.0.1             127.0.0.1             SSL      27017,60413 1186   Continuation Data

With particular reference to the following 2 packets

02:23:29.816569    127.0.0.1             127.0.0.1             TCP      27017,60413 44     27017 → 60413 [ACK] Seq=1 Ack=325 Win=525568 Len=0
02:23:46.636463    127.0.0.1             127.0.0.1             SSL      27017,60413 301    Continuation Data

it looks as if mongod has a delay of circa 15 seconds between the initial response and sending the continuation data.

Question

Have you experienced this issue and what can be done to minimise the delay?

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.