{"action":"created","issue":{"url":"https://api.github.com/repos/docker/docker/issues/29369","repository_url":"https://api.github.com/repos/docker/docker","labels_url":"https://api.github.com/repos/docker/docker/issues/29369/labels{/name}","comments_url":"https://api.github.com/repos/docker/docker/issues/29369/comments","events_url":"https://api.github.com/repos/docker/docker/issues/29369/events","html_url":"https://github.com/docker/docker/issues/29369","id":195377331,"number":29369,"title":"Concurrently starting many containers from same checkpoint leads to error: \"context deadline exceeded\"","user":{"login":"tswift242","id":1853953,"avatar_url":"https://avatars.githubusercontent.com/u/1853953?v=3","gravatar_id":"","url":"https://api.github.com/users/tswift242","html_url":"https://github.com/tswift242","followers_url":"https://api.github.com/users/tswift242/followers","following_url":"https://api.github.com/users/tswift242/following{/other_user}","gists_url":"https://api.github.com/users/tswift242/gists{/gist_id}","starred_url":"https://api.github.com/users/tswift242/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tswift242/subscriptions","organizations_url":"https://api.github.com/users/tswift242/orgs","repos_url":"https://api.github.com/users/tswift242/repos","events_url":"https://api.github.com/users/tswift242/events{/privacy}","received_events_url":"https://api.github.com/users/tswift242/received_events","type":"User","site_admin":false},"labels":[{"id":73616520,"url":"https://api.github.com/repos/docker/docker/labels/area/builder","name":"area/builder","color":"fbca04","default":false},{"id":214964971,"url":"https://api.github.com/repos/docker/docker/labels/kind/experimental","name":"kind/experimental","color":"bfdadc","default":false},{"id":480238176,"url":"https://api.github.com/repos/docker/docker/labels/version/1.13","name":"version/1.13","color":"ededed","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":8,"created_at":"2016-12-13T21:44:39Z","updated_at":"2016-12-20T16:24:21Z","closed_at":null,"body":"<!--\r\nIf you are reporting a new issue, make sure that we do not have any duplicates\r\nalready open. You can ensure this by searching the issue list for this\r\nrepository. If there is a duplicate, please close your issue and add a comment\r\nto the existing issue instead.\r\n\r\nIf you suspect your issue is a bug, please edit your issue description to\r\ninclude the BUG REPORT INFORMATION shown below. If you fail to provide this\r\ninformation within 7 days, we cannot debug your issue and will close it. We\r\nwill, however, reopen it if you later provide the information.\r\n\r\nFor more information about reporting issues, see\r\nhttps://github.com/docker/docker/blob/master/CONTRIBUTING.md#reporting-other-issues\r\n\r\n---------------------------------------------------\r\nGENERAL SUPPORT INFORMATION\r\n---------------------------------------------------\r\n\r\nThe GitHub issue tracker is for bug reports and feature requests.\r\nGeneral support can be found at the following locations:\r\n\r\n- Docker Support Forums - https://forums.docker.com\r\n- IRC - irc.freenode.net #docker channel\r\n- Post a question on StackOverflow, using the Docker tag\r\n\r\n---------------------------------------------------\r\nBUG REPORT INFORMATION\r\n---------------------------------------------------\r\nUse the commands below to provide key information from your environment:\r\nYou do NOT have to include this information if this is a FEATURE REQUEST\r\n-->\r\n\r\n**Description**\r\n\r\nI'm using checkpoint/restore to restore multiple containers from the same checkpoint. Sometimes these restores happen concurrently. In particular, as part of our bootstrap process, we restore 45 containers from the same checkpoint when a new EC2 machine is launched; these restores happen concurrently. What I'm finding is that doing many concurrent restores usually leads to a number of these restores failing. The failure mode is:\r\n\r\n```\r\n\"Error response from daemon: shim error: containerd-shim: opening /var/run/docker/libcontainerd/f7bbb5a85645fb1d34b2ab4966b2893c4507c900d77e0104515451f440181d29/init-stdout failed: context deadline exceeded\"\r\n```\r\nIn the daemon logs, I always see several occurrences of the following error prior to any occurrences of the \"context deadline exceeded\" error:\r\n\r\n```\r\nlevel=error msg=\"stream copy error: reading from a closed fifo\\ngithub.com/docker/docker/vendor/github.com/tonistiigi/fifo.(*fifo).Read\\n\\t/go/src/github.com/docker/docker/vendor/github.com/tonistiigi/fifo/fifo.go:142\\nbufio.(*Reader).fill\\n\\t/usr/local/go/src/bufio/bufio.go:97\\nbufio.(*Reader).WriteTo\\n\\t/usr/local/go/src/bufio/bufio.go:472\\nio.copyBuffer\\n\\t/usr/local/go/src/io/io.go:380\\nio.Copy\\n\\t/usr/local/go/src/io/io.go:360\\ngithub.com/docker/docker/pkg/pools.Copy\\n\\t/go/src/github.com/docker/docker/pkg/pools/pools.go:60\\ngithub.com/docker/docker/container/stream.(*Config).CopyToPipe.func1.1\\n\\t/go/src/github.com/docker/docker/container/stream/streams.go:119\\nruntime.goexit\\n\\t/usr/local/go/src/runtime/asm_amd64.s:2086\"\r\n```\r\n\r\nThe application I'm running in my container has a large memory footprint (~1.1G when idle), and so it's not too surprising that a few dozen concurrent restores of this application leads to some kind of issue. In fact, I've confirmed that adding sleep calls in between the restores in our bootstrap prevents the issue from occuring. So, resource overload/exhaustion is definitely at least one part of this. However, I was curious if there's anything to be done on the Docker/criu side to better support use cases like this.\r\n\r\nI've been looking into how memory and I/O usage play into this. When I tried doing 45+ concurrent restores of a simple Ubuntu container running a bash loop, I was unable to reproduce the issue. I have, however, been able to reproduce the issue when I run a simple C program in a container which just allocates several hundred MB of memory. I've confirmed that the issue doesn't seem to be with exhausting the host's memory. I've measured memory usage on the host during the bootstrap of our actual application, and the \"context deadline exceeded\" error starts happening when there's still 90GB of free memory on the host. Experiments with the toy container have also supported this.\r\n\r\nAs for I/O, this seems more likely to be where the problem is, and we've had issues before with being throttled due to doing too much I/O on our EC2 instance's root device. However, I/O throttling doesn't seem to be the issue here. I've tried setting the exec-root, docker root (\"graph\"), and checkpoint-dir all to locations on an instance's ephemeral storage, which isn't subject to throttling by AWS and which should achieve better performance, and the issue did not go away or improve. I also tried increasing the number of IOPS provisioned for the root device from 100 to 1000, and this also did not seem to really make a difference.\r\n\r\nThe other thing I've noticed is that the number of concurrent restores is a factor, independent of e.g. memory consumption. I've tried playing around with the size of my toy C program and the number of concurrent restores, and I've found that the latter perhaps matters more than the former for reproducting the \"context deadline exceeded\" issue. With a 1.1GB application running in the container, doing 100 concurrent restores will rarely lead to any failures (total of 110GB of memory usage). However, doing 180 concurrent restores of a 550MB application will lead to at least 16 failed restores (total of 99GB of memory usage). Furthermore, doing 250 concurrent restores of a 300MB application will lead to at least 44 failed restores (total of just 75GB of memory usage). It seems like concurrent restores don't quite scale as well as maybe they should.\r\n\r\nAlthough in my experiments I've often done 100-200+ concurrent restores to reproduce the issue, keep in mind that with our actual application, the issue is seen when doing just 45 concurrent restores, which doesn't seem to be an unreasonably high number.\r\n\r\nOne last thing is that while doing these experiments, in addition to the error provided above, I've also occasionally seen the following criu error: \"Error (criu/mount.c:414): mnt: No root found for mountpoint 978 (@./sys/fs/pstore)\". The actual mountpoint flagged varies, but the message is the same.\r\n\r\nI'm attaching the docker daemon logs from the bootstrapping of my actual application, as well as the sample C program, Dockerfile, and shell script I used to reproduce the issue more simply.\r\n[docker_cr_concurrent_restores.zip](https://github.com/docker/docker/files/650222/docker_cr_concurrent_restores.zip)\r\n\r\n\r\n\r\n**Steps to reproduce the issue:**\r\n1. `docker build -t test:latest .`\r\n2. `docker run -d --security-opt=seccomp:unconfined --name cr test`\r\n3. `docker checkpoint create --checkpoint-dir /var/lib/docker/checkpoints cr test_cp`\r\n4. `./stress_cr.sh 250`\r\n5. Vary the number of concurrent restores (argument to `stress_cr.sh`) and the application size in `lots_of_memory.c`\r\n\r\n**Describe the results you received:**\r\nMany restores fail with \"context deadline exceeded\"\r\n\r\n**Describe the results you expected:**\r\nRestores succeed\r\n\r\n**Output of `docker version`:**\r\n\r\n```\r\nClient:\r\n Version:      1.13.0-rc3\r\n API version:  1.25\r\n Go version:   go1.7.3\r\n Git commit:   4d92237\r\n Built:        Tue Dec  6 01:15:44 2016\r\n OS/Arch:      linux/amd64\r\n\r\nServer:\r\n Version:      1.13.0-rc3\r\n API version:  1.25 (minimum version 1.12)\r\n Go version:   go1.7.3\r\n Git commit:   4d92237\r\n Built:        Tue Dec  6 01:15:44 2016\r\n OS/Arch:      linux/amd64\r\n Experimental: true\r\n```\r\n\r\n**Output of `docker info`:**\r\n\r\n```\r\nContainers: 0\r\n Running: 0\r\n Paused: 0\r\n Stopped: 0\r\nImages: 35\r\nServer Version: 1.13.0-rc3\r\nStorage Driver: overlay\r\n Backing Filesystem: extfs\r\n Supports d_type: true\r\nLogging Driver: json-file\r\nCgroup Driver: cgroupfs\r\nPlugins:\r\n Volume: local\r\n Network: bridge host macvlan null overlay\r\nSwarm: inactive\r\nRuntimes: runc\r\nDefault Runtime: runc\r\nInit Binary: docker-init\r\ncontainerd version: 03e5862ec0d8d3b3f750e19fca3ee367e13c090e\r\nrunc version: 51371867a01c467f08af739783b8beafc154c4d7\r\ninit version: 949e6fa\r\nSecurity Options:\r\n apparmor\r\n seccomp\r\n  Profile: default\r\nKernel Version: 4.4.26-040426-generic\r\nOperating System: Ubuntu 14.04.5 LTS\r\nOSType: linux\r\nArchitecture: x86_64\r\nCPUs: 16\r\nTotal Memory: 120.1 GiB\r\nName: ip-10-97-5-247\r\nID: TEID:T5YB:6YAX:E4VG:4QTD:QQQ3:RWRS:6KQU:ALGA:SQTT:TPS6:GZ2I\r\nDocker Root Dir: /var/lib/docker\r\nDebug Mode (client): false\r\nDebug Mode (server): true\r\nRegistry: https://index.docker.io/v1/\r\nExperimental: true\r\nInsecure Registries:\r\n 127.0.0.0/8\r\nLive Restore Enabled: false\r\n```\r\n\r\n**Additional environment details (AWS, VirtualBox, physical, etc.):**\r\nAWS EC2. Using r3.4xlarge instance type. 20GB root device with 100 IOPS. Also tried using 1000 IOPS.\r\n\r\nHave tried using criu version 2.8 and 2.9."},"comment":{"url":"https://api.github.com/repos/docker/docker/issues/comments/268287539","html_url":"https://github.com/docker/docker/issues/29369#issuecomment-268287539","issue_url":"https://api.github.com/repos/docker/docker/issues/29369","id":268287539,"user":{"login":"mlaventure","id":16065150,"avatar_url":"https://avatars.githubusercontent.com/u/16065150?v=3","gravatar_id":"","url":"https://api.github.com/users/mlaventure","html_url":"https://github.com/mlaventure","followers_url":"https://api.github.com/users/mlaventure/followers","following_url":"https://api.github.com/users/mlaventure/following{/other_user}","gists_url":"https://api.github.com/users/mlaventure/gists{/gist_id}","starred_url":"https://api.github.com/users/mlaventure/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mlaventure/subscriptions","organizations_url":"https://api.github.com/users/mlaventure/orgs","repos_url":"https://api.github.com/users/mlaventure/repos","events_url":"https://api.github.com/users/mlaventure/events{/privacy}","received_events_url":"https://api.github.com/users/mlaventure/received_events","type":"User","site_admin":false},"created_at":"2016-12-20T16:24:21Z","updated_at":"2016-12-20T16:24:21Z","body":"The deadline being exceeded is this one: https://github.com/docker/containerd/blob/bb338ce1b949372986f784f491301caa4cc2e5f9/containerd-shim/process_linux.go#L33\r\n\r\nThis is more likely to occur due to lack of CPU time being allocated to that program or the kernel being contended on a lock in the open syscall.\r\n\r\nUnfortunately, as of now your best solution is to prevent too many concurrent restores to be done as to not tax the CPU / filesystem path too much.\r\n\r\nRegarding the `criu` error, it looks like you may be calling restore before all the mountpoints that were present at the time of the checkpoint creation are mounted again."}}
{"actor":{"display_login":"mlaventure"}}