`docker run alpine echo hello world` slow; takes >3 seconds

[Mahoney]

• This is a bug report
• This is a feature request
• I searched existing issues before opening this one

Expected behavior

docker run alpine echo hello world completes in <0.5 seconds

Actual behavior

docker run alpine echo hello world completes in >3 seconds

Steps to reproduce the behavior

Run time docker run alpine echo hello world on my desktop

Output of docker version:

Client:
 Version:           18.09.5
 API version:       1.39
 Go version:        go1.10.8
 Git commit:        e8ff056
 Built:             Thu Apr 11 04:43:57 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          18.09.5
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.8
  Git commit:       e8ff056
  Built:            Thu Apr 11 04:10:53 2019
  OS/Arch:          linux/amd64
  Experimental:     false

Output of docker info:

Containers: 2
 Running: 0
 Paused: 0
 Stopped: 2
Images: 171
Server Version: 18.09.5
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host 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: bb71b10fd8f58240ca47fbb579b9d1028eea7c84
runc version: 2b18fe1d885ee5083ef9f0838fee39b62d653e30
init version: fec3683
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.15.0-48-generic
Operating System: Ubuntu 18.04.2 LTS
OSType: linux
Architecture: x86_64
CPUs: 16
Total Memory: 31.35GiB
Name: elliot-linux-desktop-2019
ID: DDOO:ZIOO:3HLM:VMQD:O3US:VC2L:6SGI:27ZW:OCI2:5ZLH:7UVD:EHP6
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false
Product License: Community Engine

WARNING: No swap limit support

Blogs on the net suggest the overhead of docker run should be 0.3-0.4 seconds, and certainly that's been my experience before, but now it seems 3 seconds more than that on what should be a very fast system.

Attached is some sample debug log output:

time="2019-04-27T22:26:53.743606628+01:00" level=debug msg="Calling GET /_ping"
time="2019-04-27T22:26:53.744171043+01:00" level=debug msg="Calling POST /v1.39/containers/create"
time="2019-04-27T22:26:53.744332169+01:00" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":null,\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":[],\"HostConfig\":{\"AutoRemove\":true,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"Devices\":[],\"DiskQuota\":0,\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"hello-world\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}"
time="2019-04-27T22:26:54.439555984+01:00" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/f2db2b2c20745744351d8ec64647d75e08fc5da3a749161767d1a899608174d6/merged 0x55790a0784a0 0x55790a0784a0}"
time="2019-04-27T22:26:55.079021005+01:00" level=debug msg="Calling POST /v1.39/containers/95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549/attach?stderr=1&stdout=1&stream=1"
time="2019-04-27T22:26:55.079323373+01:00" level=debug msg="attach: stderr: begin"
time="2019-04-27T22:26:55.079380134+01:00" level=debug msg="attach: stdout: begin"
time="2019-04-27T22:26:55.080064260+01:00" level=debug msg="Calling POST /v1.39/containers/95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549/wait?condition=removed"
time="2019-04-27T22:26:55.081117695+01:00" level=debug msg="Calling POST /v1.39/containers/95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549/start"
time="2019-04-27T22:26:55.083572541+01:00" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/f2db2b2c20745744351d8ec64647d75e08fc5da3a749161767d1a899608174d6/merged 0x55790a0784a0 0x55790a0784a0}"
time="2019-04-27T22:26:55.084138626+01:00" level=debug msg="Assigning addresses for endpoint stoic_jepsen's interface on network bridge"
time="2019-04-27T22:26:55.084198461+01:00" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
time="2019-04-27T22:26:55.084253234+01:00" level=debug msg="Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3 Serial:false PrefAddress:<nil> "
time="2019-04-27T22:26:55.161155611+01:00" level=debug msg="Assigning addresses for endpoint stoic_jepsen's interface on network bridge"
time="2019-04-27T22:26:55.286263073+01:00" level=debug msg="Programming external connectivity on endpoint stoic_jepsen (43a4296e1feec97378b393e74711cc82b5b6664243a69187d86cd5a308964890)"
time="2019-04-27T22:26:55.336155658+01:00" level=debug msg="EnableService 95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549 START"
time="2019-04-27T22:26:55.336169305+01:00" level=debug msg="EnableService 95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549 DONE"
time="2019-04-27T22:26:55.376436807+01:00" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/f2db2b2c20745744351d8ec64647d75e08fc5da3a749161767d1a899608174d6/merged
time="2019-04-27T22:26:55.677940423+01:00" level=debug msg="sandbox set key processing took 132.643471ms for container 95c0440c5299863eff29900b2f4d0bff3842d04203050092baa16e5f03844549"
time="2019-04-27T22:26:55.813528560+01:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create
time="2019-04-27T22:26:55.831914186+01:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start
time="2019-04-27T22:26:55.926321268+01:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
time="2019-04-27T22:26:55.954343742+01:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
time="2019-04-27T22:26:55.954358842+01:00" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2019-04-27T22:26:55.954359611+01:00" level=debug msg="attach: stdout: end"
time="2019-04-27T22:26:55.954367765+01:00" level=debug msg="attach: stderr: end"
time="2019-04-27T22:26:55.954376498+01:00" level=debug msg="attach done"
time="2019-04-27T22:26:55.954497916+01:00" level=debug msg="Revoking external connectivity on endpoint stoic_jepsen (43a4296e1feec97378b393e74711cc82b5b6664243a69187d86cd5a308964890)"
time="2019-04-27T22:26:55.955574238+01:00" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
time="2019-04-27T22:26:56.253359574+01:00" level=debug msg="Releasing addresses for endpoint stoic_jepsen's interface on network bridge"
time="2019-04-27T22:26:56.253444431+01:00" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
time="2019-04-27T22:26:56.253539732+01:00" level=debug msg="Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"

[Mahoney]

I can't believe this is a general issue, and a bug report is the wrong way to request help with something that surely must be a problem with my machine.

[thaJeztah]

You can narrow-down troubleshooting by setting --network=none, which will skip creating the networking namespace