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

Steps to reproduce the issue:

Install Docker Desktop on Windows (tested on Windows 10 Enterpirse version 1909 build 18363.720, Docker Desktop 2.2.0.4)
Start Docker Desktop.
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 https://github.com/docker/cli/issues/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.):

About this issue

Original URL
State: closed
Created 4 years ago
Reactions: 1
Comments: 30 (15 by maintainers)

Commits related to this issue

vendor: update compose-on-kubernetes to remove use of github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kuberne... — committed to thaJeztah/cli by thaJeztah 2 years ago
vendor: update compose-on-kubernetes to remove use of github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kuberne... — committed to thaJeztah/cli by thaJeztah 2 years ago
vendor: update compose-on-kubernetes to remove use of github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kuberne... — committed to thaJeztah/cli by thaJeztah 2 years ago
vendor: update compose-on-kubernetes to remove use of github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kuberne... — committed to thaJeztah/cli by thaJeztah 2 years ago
[20.10] vendor: update compose-on-kubernetes to remove github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kubern... — committed to thaJeztah/cli by thaJeztah 2 years ago
[20.10] vendor: compose-on-kubernetes v0.5.0 to remove github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kubern... — committed to thaJeztah/cli by thaJeztah 2 years ago
vendor: compose-on-kubernetes v0.5.0 to remove use of github.com/golang/glog glog has the same issue as k8s.io/klog, and is calling `user.Current()` inside an `init()`; see https://github.com/kuberne... — committed to thaJeztah/cli by thaJeztah 2 years ago

Most upvoted comments

@thaJeztah @simonferquel I was able to find the issue: it is in the klog logging package that you guys are vendoring. This package calls os/user.Current() upon initialization, which on Windows does all sorts of domain lookups.

These lookups causes problems on some versions of Windows OS, but much more importantly (and this is what this bug is about), this way of obtaining current user information for logging purposes is just too damn slow for a CLI utility, and probably not really necessary either.

Hope this helps! @gtardif FYI

karolz-ms on May 10, 2020

There are definitely substantial improvements in the latest build from master in my testing. I know that my results before were atypically slow so take the % improvements with a grain of salt.

docker context inspect averaged 111 ms over 50 calls (down 96% from 3028 ms before).
docker context ls averaged 102 ms over 50 calls (down 95% from 2210 ms before).
docker -v averaged 124 ms over 50 calls (down 95% from 2255 ms before).
docker info is still a little sluggish at 6525 ms over 50 calls (down 11% from 7297 ms before). However, the VSCode Docker extension only calls this in very rare circumstances, so this isn’t much of a concern for us.

Globally, the average for docker context inspect on Windows looked to be around 1300 ms, so this marks a 91% drop from that. That’s amazing!

Thanks everyone! This is a huge help for us!

bwateratmsft on May 19, 2020

This should be fixed through https://github.com/docker/cli/pull/2516

thaJeztah on May 19, 2020

opened https://github.com/docker/cli/pull/2515 and https://github.com/docker/cli/pull/2516 to (temporarily) vendor tip of release-1.x from k8s.io/klog

thaJeztah on May 10, 2020

How about pulling this fix?

karolz-ms on May 10, 2020

The most reliable way is to call SHGetKnownFolderPath with FOLDERID_Profile. USERPROFILE environment variable should point to the same thing, but might be set to something else by a user looking for trouble.

karolz-ms on May 7, 2020