Docker Desktop on Windows: 'docker context inspect' is very slow

[karolz-ms]

Steps to reproduce the issue:

1. Install Docker Desktop on Windows (tested on Windows 10 Enterpirse version 1909 build 18363.720, Docker Desktop 2.2.0.4)
2. Start Docker Desktop.
3. Open command prompt and do docker context inspect

Describe the results you received:
It consistently takes more than 1 second to run this command, often more than 2 seconds.

Describe the results you expected:
Should take 100 ms or less. The default context, pointing to Docker Desktop engine, is the only context on the machine and it should be really straightforward to "inspect" it.

Additional information you deem important (e.g. issue happens only occasionally):

I took a trace (available upon request) and noticed that the majority of time is spent waiting on results from NetUserGetInfo Windows API. On my machine this API is called for a default Docker Desktop context inspection, which has no user information. Ultimately this accounts for more than 2 seconds of latency (for that run of the command)

May be related to #1739

Output of docker version:

Client: Docker Engine - Community
 Version:           19.03.8
 API version:       1.40
 Go version:        go1.12.17
 Git commit:        afacb8b
 Built:             Wed Mar 11 01:23:10 2020
 OS/Arch:           windows/amd64
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          19.03.8
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.17
  Git commit:       afacb8b
  Built:            Wed Mar 11 01:29:16 2020
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          v1.2.13
  GitCommit:        7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc:
  Version:          1.0.0-rc10
  GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Output of docker info:

Client:
 Debug Mode: false
 Plugins:
  app: Docker Application (Docker Inc., v0.8.0)
  buildx: Build with BuildKit (Docker Inc., v0.3.1-tp-docker)

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 25
 Server Version: 19.03.8
 Storage Driver: overlay2
  Backing Filesystem: <unknown>
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
 init version: fec3683
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 4.19.76-linuxkit
 Operating System: Docker Desktop
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 3.846GiB
 Name: docker-desktop
 ID: KLND:UUTX:OIZ2:IUWS:KHMX:VVTK:SBMI:GHS3:VCM4:WPUY:4TJM:SXMY
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 33
  Goroutines: 49
  System Time: 2020-04-06T15:18:37.131345023Z
  EventsListeners: 3
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: true
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false
 Product License: Community Engine

Additional environment details (AWS, VirtualBox, physical, etc.):

[bwateratmsft]

It may not be limited to just docker context inspect calls. On my system, even doing something as simple as docker help takes 7-8 seconds.

[karolz-ms]

Yep, I have confirmed that docker help also somehow ends up calling NetUserGetInfo... 😕

[bwateratmsft]

For some context, my machine is on VPN, a good 3000 miles away from the corporate network. So, any network calls that cross that gap are gonna end up being pretty slow--I'm sure that my observed 7-8 seconds is well above average.

I looked up the global averages in our telemetry, docker context inspect takes roughly 600 ms on Mac/Linux and roughly 1300ms on Windows. More here: microsoft/vscode-docker#1804 (comment)

[karolz-ms]

@silvin-lubecki @gtardif looks like the issue is still not completely fixed. I have built the binary from the master branch and am observing a lot of variance between the runs. The first run of the context inspect command is almost always is very slow. The following commands were executed from a freshly open Windows command window:

C:\code>\tools\timecmd.bat \scratch\docker-windows-amd64.exe context inspect
[
    {
        "Name": "default",
        "Metadata": {
            "StackOrchestrator": "swarm"
        },
        "Endpoints": {
            "docker": {
                "Host": "npipe:////./pipe/docker_engine",
                "SkipTLSVerify": false
            }
        },
        "TLSMaterial": {},
        "Storage": {
            "MetadataPath": "\u003cIN MEMORY\u003e",
            "TLSPath": "\u003cIN MEMORY\u003e"
        }
    }
]
command took 0:0:2.41 (2.41s total)
C:\code>\tools\timecmd.bat \scratch\docker-windows-amd64.exe context inspect
[
    {
        "Name": "default",
        "Metadata": {
            "StackOrchestrator": "swarm"
        },
        "Endpoints": {
            "docker": {
                "Host": "npipe:////./pipe/docker_engine",
                "SkipTLSVerify": false
            }
        },
        "TLSMaterial": {},
        "Storage": {
            "MetadataPath": "\u003cIN MEMORY\u003e",
            "TLSPath": "\u003cIN MEMORY\u003e"
        }
    }
]
command took 0:0:0.10 (0.10s total)

It is enough to wait about 30 seconds between docker context inspect invocations to observe the slow execution again. I bet the Windows user info is still being retrieved over the network, but it is cached for a short while by Windows, that is why quick successful invocations are fast.

The docker.exe binary that comes with Docker Desktop for Windows 2.2.0.5 behaves the same way BTW.

[thaJeztah]

@karolz-ms curious; where do those MetadataPaths (<IN MEMORY>) come from?

FWIW, with #2424 applied, I tried reproducing in a Linux container (I was curious if the difference was between docker context ls, which I tried before, and docker context inspect), on Linux I didn't reproduce the problem though;

docker context create faulty --docker host=tcp://42.42.42.41:4242
docker context create local --docker host=unix:///var/run/docker.sock
docker context use faulty

time docker context ls
NAME                DESCRIPTION                               DOCKER ENDPOINT               KUBERNETES ENDPOINT   ORCHESTRATOR
default             Current DOCKER_HOST based configuration   unix:///var/run/docker.sock                         swarm
faulty *                                                      tcp://42.42.42.41:4242
local                                                         unix:///var/run/docker.sock
real	0m 0.33s
user	0m 0.04s
sys	0m 0.04s


time docker context inspect local
[
    {
        "Name": "local",
        "Metadata": {},
        "Endpoints": {
            "docker": {
                "Host": "unix:///var/run/docker.sock",
                "SkipTLSVerify": false
            }
        },
        "TLSMaterial": {},
        "Storage": {
            "MetadataPath": "/root/.docker/contexts/meta/25bf8e1a2393f1108d37029b3df5593236c755742ec93465bbafa9b290bddcf6",
            "TLSPath": "/root/.docker/contexts/tls/25bf8e1a2393f1108d37029b3df5593236c755742ec93465bbafa9b290bddcf6"
        }
    }
]
real	0m 0.36s
user	0m 0.05s
sys	0m 0.03s

time docker context inspect faulty
[
    {
        "Name": "faulty",
        "Metadata": {},
        "Endpoints": {
            "docker": {
                "Host": "tcp://42.42.42.41:4242",
                "SkipTLSVerify": false
            }
        },
        "TLSMaterial": {},
        "Storage": {
            "MetadataPath": "/root/.docker/contexts/meta/9ec1600e60d2aba399d84db8163ec37fc67cd60096cb32a66f0a52280797ee95",
            "TLSPath": "/root/.docker/contexts/tls/9ec1600e60d2aba399d84db8163ec37fc67cd60096cb32a66f0a52280797ee95"
        }
    }
]
real	0m 0.34s
user	0m 0.03s
sys	0m 0.05s

[thaJeztah]

Oh, never mind; looks like the <IN MEMORY> is a default that's set here;

cli/cli/command/defaultcontextstore.go

Line 212 in 0f337f1

return store.StorageInfo{MetadataPath: "<IN MEMORY>", TLSPath: "<IN MEMORY>"}

Same result when using / inspecting the default

docker context use default
time docker context inspect
[
    {
        "Name": "default",
        "Metadata": {
            "StackOrchestrator": "swarm"
        },
        "Endpoints": {
            "docker": {
                "Host": "unix:///var/run/docker.sock",
                "SkipTLSVerify": false
            }
        },
        "TLSMaterial": {},
        "Storage": {
            "MetadataPath": "\u003cIN MEMORY\u003e",
            "TLSPath": "\u003cIN MEMORY\u003e"
        }
    }
]
real	0m 0.29s
user	0m 0.04s
sys	0m 0.05s

[bwateratmsft]

I can still consistently get long times on Windows with the current build. docker context inspect took an average of 3028 ms over 100 runs; docker info took an average of 7297 ms over 50 runs.

[karolz-ms]

@thaJeztah @gtardif any news on this issue?

You know, we are a Windows shop here ☺️ so let us know if we can help in any way; run some experiments or whatever.

[simonferquel]

The NetGetUserInfo call probably comes for getting the HomeDir of the user... we recently changed the way we get the homedir to the golang base library implementation.
@thaJeztah can we try to revert this PR in some branch to see if it fixes the issue ?