Why does docker rm take almost 6 seconds to run?

Question

I have a simple docker image based on ubuntu 15.10 that's just running bash. The image is around 1.2gb. It launches very quickly, but when I try to remove the container after it's exited, it always takes around 6 seconds:

$ time ( echo "exit" | sudo docker run -i media-toolkit )

real    0m0.626s
user    0m0.028s
sys 0m0.004s

$ sudo docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS                      PORTS               NAMES
64d87dfddd60        media-toolkit       "/bin/sh -c bash"   11 seconds ago      Exited (0) 11 seconds ago                       backstabbing_darwin

$ time sudo docker rm 64d87dfddd60
64d87dfddd60

real    0m5.860s
user    0m0.028s
sys 0m0.004s

I can't figure out a combination of command lines that speeds this up. The container is already stopped, and has no networking or socket communication with the host. It has one mount that's not even actually mounted in the example above. I've looked over the source code here but don't see any obvious reason why removing the container should take significant time. What's going on?

Update 1

This is the relevant strace output from the tail end of the docker rm command:

write(3, "DELETE /v1.21/containers/e9c8084"..., 119) = 119
epoll_wait(4, {{EPOLLOUT, {u32=836052264, u64=140506396173608}}}, 128, 0) = 1
epoll_wait(4, {{EPOLLIN|EPOLLOUT, {u32=836052264, u64=140506396173608}}}, 128, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {3747600, 756232919}) = 0
futex(0x1caa060, FUTEX_WAKE, 1)         = 1
read(3, "HTTP/1.1 204 No Content\r\nServer:"..., 4096) = 94
read(3, 0xc208516000, 4096)             = -1 EAGAIN (Resource temporarily unavailable)
write(1, "e9c8084400e2\n", 13e9c8084400e2
)          = 13
exit_group(0)                           = ?
+

++ exited with 0 +++

It's hanging on one of the epoll_wait lines, presumably waiting from the response from the daemon. This is what the daemon is doing after receiving the DELETE command:

[pid 13026] 14:51:56.377411 <... read resumed> "DELETE /v1.21/containers/d267f0e"..., 4096) = 119
[pid 13026] 14:51:56.378089 write(2, "time=\"2016-01-21T14:51:56.377925"..., 99) = 99
[pid 13026] 14:51:56.378738 access("/var/lib/docker/linkgraph.db-journal", F_OK) = -1 ENOENT (No such file or directory)
[pid 13026] 14:51:56.379913 fcntl(12, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
[pid 13026] 14:51:56.379987 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:56.380846 close(15)   = 0
[pid 13026] 14:51:56.381531 close(15)   = 0
[pid 13026] 14:51:56.382176 access("/var/lib/docker/linkgraph.db-journal", F_OK) = -1 ENOENT (No such file or directory)
[pid 13026] 14:51:56.382241 fstat(9, {st_mode=S_IFREG|0644, st_size=69632, ...}) = 0
[pid 13026] 14:51:56.383715 stat("/var/lib/docker/linkgraph.db", {st_mode=S_IFREG|0644, st_size=69632, ...}) = 0
[pid 13026] 14:51:56.383814 open("/var/lib/docker/linkgraph.db-journal", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 15
[pid 13026] 14:51:56.383933 fstat(15, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid 13026] 14:51:56.384000 geteuid()   = 0
[pid 13026] 14:51:56.384073 fchown(15, 0, 0) = 0
[pid 13026] 14:51:56.384143 fstat(15, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid 13026] 14:51:56.384206 lseek(15, 0, SEEK_SET) = 0
[pid 13026] 14:51:56.384264 write(15, "\0\0\0\0\0\0\0\0\0\0\0\0O\233R\327\0\0\0D\0\0\2\0\0\0\4\0\0\0\0\0"..., 512) = 512
[pid 13026] 14:51:56.384342 lseek(15, 512, SEEK_SET) = 512
[pid 13026] 14:51:56.384414 write(15, "\0\0\0\5", 4) = 4
[pid 13026] 14:51:56.384502 lseek(15, 516, SEEK_SET) = 516
[pid 13026] 14:51:56.384564 write(15, "\n\1\244\0\2\1\227\7\1\227\3\353\3\353\3>\3>\3>\3>\3\351\3\351\3\351\3\351\3\351"..., 1024) = 1024
[pid 13026] 14:51:56.384638 lseek(15, 1540, SEEK_SET) = 1540
[pid 13026] 14:51:56.384717 write(15, "O\233S\331", 4) = 4
[pid 13026] 14:51:56.384786 lseek(15, 1544, SEEK_SET) = 1544
[pid 13026] 14:51:56.384814 write(15, "\0\0\0\4", 4) = 4
[pid 13026] 14:51:56.384893 lseek(15, 1548, SEEK_SET) = 1548
[pid 13026] 14:51:56.384955 write(15, "\r\0\230\0\2\0\220\0\0\220\3\252\3R\2\375\2\250\3\253\3\253\3\253\3\253\3\253\3\253\3\316"..., 1024) = 1024
[pid 13026] 14:51:56.385030 lseek(15, 2572, SEEK_SET) = 2572
[pid 13026] 14:51:56.385058 write(15, "O\233T9", 4) = 4
[pid 13026] 14:51:56.385133 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:56.385713 read(9, "\r\0\177\0\2\0z\0\0z\3\273\3v\0031\2\354\3\273\3\273\3\273\3\273\3\273\3\273\3\273"..., 1024) = 1024
[pid 13026] 14:51:56.385780 lseek(15, 2576, SEEK_SET) = 2576
[pid 13026] 14:51:56.387179 lseek(15, 3612, SEEK_SET) = 3612
[pid 13026] 14:51:56.387252 write(15, "\r\0\177\0\2\0z\0\0z\3\273\3v\0031\2\354\3\273\3\273\3\273\3\273\3\273\3\273\3\273"..., 1024) = 1024
[pid 13026] 14:51:56.387298 lseek(15, 4636, SEEK_SET) = 4636
[pid 13026] 14:51:56.387365 write(15, "O\233S\335", 4) = 4
[pid 13026] 14:51:56.387443 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:56.388054 write(15, "\0\0\0\1", 4) = 4
[pid 13026] 14:51:56.388125 lseek(15, 4644, SEEK_SET) = 4644
[pid 13026] 14:51:56.392231 open("/var/lib/docker", O_RDONLY|O_CLOEXEC) = 17
[pid 13026] 14:51:56.392303 fsync(17)   = 0
[pid 13026] 14:51:56.392332 close(17)   = 0
[pid 13026] 14:51:56.392392 lseek(15, 0, SEEK_SET) = 0
[pid 13026] 14:51:56.392449 write(15, "\331\325\5\371 \241c\327\0\0\0\5", 12) = 12
[pid 13026] 14:51:56.392521 fsync(15)   = 0
[pid 13026] 14:51:56.394289 lseek(9, 0, SEEK_SET) = 0
[pid 13026] 14:51:56.394351 write(9, "SQLite format 3\0\4\0\1\1\0@  \0\0\2\257\0\0\0D"..., 1024) = 1024
[pid 13026] 14:51:56.394423 lseek(9, 1024, SEEK_SET) = 1024
[pid 13026] 14:51:56.394483 write(9, "\r\0\177\0\1\0z\0\0z\3\273\3v\0031\2\354\3\273\3\273\3\273\3\273\3\273\3\273\3\273"..., 1024) = 1024
[pid 13026] 14:51:56.394548 lseek(9, 2048, SEEK_SET) = 2048
[pid 13026] 14:51:56.394606 write(9, "\n\0r\0\1\0m\0\0m\3\272\3\272\3t\3t\3\272\3\272\3\272\3\272\3\272\3\272\3\272"..., 1024) = 1024
[pid 13026] 14:51:56.394673 lseek(9, 3072, SEEK_SET) = 3072
[pid 13026] 14:51:56.394730 write(9, "\r\0\230\0\1\0\220\0\0\220\3\252\3R\2\375\2\250\3\253\3\253\3\253\3\253\3\253\3\253\3\316"..., 1024) = 1024
[pid 13026] 14:51:56.394799 lseek(9, 4096, SEEK_SET) = 4096
[pid 13026] 14:51:56.394857 write(9, "\n\1\244\0\1\1\227\7\1\227\3\353\3\353\3>\3>\3>\3>\3\351\3\351\3\351\3\351\3\351"..., 1024) = 1024
[pid 13026] 14:51:56.394925 fsync(9)    = 0
[pid 13026] 14:51:56.396797 close(15)   = 0
[pid 13026] 14:51:56.396861 unlink("/var/lib/docker/linkgraph.db-journal") = 0
[pid 13026] 14:51:56.396966 fcntl(9, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741826, len=510}) = 0
[pid 13026] 14:51:56.397047 fcntl(9, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=1073741824, len=2}) = 0
[pid 13026] 14:51:56.397081 fcntl(9, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
[pid 13026] 14:51:56.397150 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:56.397821 semget(0xd4deb33, 1, IPC_CREAT|IPC_EXCL|0600) = 147292178
[pid 13026] 14:51:56.397933 semctl(147292178, 0, SETVAL, 0x1) = 0
[pid 13026] 14:51:56.398467 semctl(147292178, 0, GETVAL, 0x7f1d2fb9a3c7) = 2
[pid 13026] 14:51:56.400115 ioctl(5, DM_DEV_SUSPEND, 0x7f1d24042870) = 0
[pid 13026] 14:51:56.405698 semctl(147292178, 0, IPC_RMID, 0) = 0
[pid 13026] 14:51:56.405777 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:56.406024 ioctl(5, DM_DEV_STATUS, 0x7f1d24046880) = 0
[pid 13026] 14:51:56.406094 open("/dev/mapper/docker-202:1-790981-d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d", O_RDWR|O_CLOEXEC) = 15
[pid 13026] 14:51:56.406164 ioctl(15, BLKGETSIZE64, 107374182400) = 0
[pid 13026] 14:51:59.441157 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.451108 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.451240 close(15)   = 0
[pid 13026] 14:51:59.451815 ioctl(5, DM_DEV_STATUS, 0x7f1d2404a890) = 0
[pid 13026] 14:51:59.451938 open("/dev/urandom", O_RDONLY) = 15
[pid 13026] 14:51:59.452049 read(15, "P\227", 2) = 2
[pid 13026] 14:51:59.452149 semget(0xd4d9750, 1, IPC_CREAT|IPC_EXCL|0600) = 147324946
[pid 13026] 14:51:59.452247 semctl(147324946, 0, SETVAL, 0x1) = 0
[pid 13026] 14:51:59.452505 semctl(147324946, 0, GETVAL, 0x7f1d2fb9a42a) = 1
[pid 13026] 14:51:59.452815 semop(147324946, {{0, 1, 0}}, 1) = 0
[pid 13026] 14:51:59.453310 semctl(147324946, 0, GETVAL, 0x7f1d2fb9a3c7) = 2
[pid 13026] 14:51:59.454544 semctl(147324946, 0, GETVAL, 0x800) = 2
[pid 13026] 14:51:59.454609 semop(147324946, {{0, -1, IPC_NOWAIT}}, 1) = 0
[pid 13026] 14:51:59.457329 semctl(147324946, 0, IPC_RMID, 0) = 0
[pid 13026] 14:51:59.457396 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.457710 open("/var/lib/docker/devicemapper/metadata/.tmp717030394", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 15
[pid 13026] 14:51:59.457827 write(15, "{\"open_transaction_id\":1570,\"dev"..., 125) = 125
[pid 13026] 14:51:59.462635 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.462820 rename("/var/lib/docker/devicemapper/metadata/.tmp717030394", "/var/lib/docker/devicemapper/metadata/transaction-metadata") = 0
[pid 13026] 14:51:59.462955 stat("/dev/mapper/docker-202:1-790981-pool", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
[pid 13026] 14:51:59.463032 stat("/dev/mapper/docker-202:1-790981-pool", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
[pid 13026] 14:51:59.468869 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.472111 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.472745 open("/dev/urandom", O_RDONLY) = 15
[pid 13026] 14:51:59.473273 semctl(147357714, 0, GETVAL, 0x7f1d2fb9a42a) = 1
[pid 13026] 14:51:59.473338 close(15)   = 0
[pid 13026] 14:51:59.473400 semop(147357714, {{0, 1, 0}}, 1) = 0
[pid 13026] 14:51:59.474993 ioctl(5, DM_DEV_SUSPEND, 0x7f1d2405e8e0) = 0
[pid 13026] 14:51:59.480219 semctl(147357714, 0, IPC_RMID, 0) = 0
[pid 13026] 14:51:59.480290 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:51:59.480594 ioctl(5, DM_DEV_STATUS, 0x7f1d240628f0) = 0
[pid 13026] 14:51:59.480671 open("/dev/mapper/docker-202:1-790981-d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d-init", O_RDWR|O_CLOEXEC) = 15
[pid 13026] 14:51:59.480752 ioctl(15, BLKGETSIZE64, 107374182400) = 0
[pid 13026] 14:52:02.489043 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:52:02.506827 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:52:02.507470 ioctl(5, DM_DEV_STATUS, 0x7f1d24066900) = 0
[pid 13026] 14:52:02.507567 open("/dev/urandom", O_RDONLY) = 15
[pid 13026] 14:52:02.507704 read(15, "c\236", 2) = 2
[pid 13026] 14:52:02.507775 semget(0xd4d9e63, 1, IPC_CREAT|IPC_EXCL|0600) = 147390482
[pid 13026] 14:52:02.507854 semctl(147390482, 0, SETVAL, 0x1) = 0
[pid 13026] 14:52:02.507919 semctl(147390482, 0, GETVAL, 0x7f1d2fb9a42a) = 1
[pid 13026] 14:52:02.507987 close(15)   = 0
[pid 13026] 14:52:02.508049 semop(147390482, {{0, 1, 0}}, 1) = 0
[pid 13026] 14:52:02.508114 semctl(147390482, 0, GETVAL, 0x7f1d2fb9a3c7) = 2
[pid 13026] 14:52:03.262530 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:52:03.262894 semget(0xd4d9e63, 1, 0) = 147390482
[pid 13026] 14:52:03.262994 semctl(147390482, 0, GETVAL, 0x800) = 1
[pid 13026] 14:52:03.263027 semop(147390482, {{0, -1, IPC_NOWAIT}}, 1) = 0
[pid 13026] 14:52:03.263076 semop(147390482, {{0, 0, 0}}, 1) = 0
[pid 13026] 14:52:03.263107 semctl(147390482, 0, IPC_RMID, 0) = 0
[pid 13026] 14:52:03.263221 stat("/dev/mapper/docker-202:1-790981-d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d-init", 0x7f1d077fcbc0) = -1 ENOENT (No such file or directory)
[pid 13026] 14:52:03.263330 open("/var/lib/docker/devicemapper/metadata/.tmp662028049", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 15
[pid 13026] 14:52:03.263537 write(15, "{\"open_transaction_id\":1571,\"dev"..., 130) = 130
[pid 13026] 14:52:03.266148 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:52:03.266316 rename("/var/lib/docker/devicemapper/metadata/.tmp662028049", "/var/lib/docker/devicemapper/metadata/transaction-metadata") = 0
[pid 13026] 14:52:03.266458 stat("/dev/mapper/docker-202:1-790981-pool", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
[pid 13026] 14:52:03.266533 stat("/dev/mapper/docker-202:1-790981-pool", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
[pid 13026] 14:52:03.273534 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:52:03.273796 stat("/dev/mapper/docker-202:1-790981-pool", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
[pid 13026] 14:52:03.273904 stat("/dev/mapper/docker-202:1-790981-pool", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
[pid 13026] 14:52:03.276718 futex(0x1caa060, FUTEX_WAKE, 1) = 1
[pid 13026] 14:52:03.276979 rmdir("/var/lib/docker/devicemapper/mnt/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d-init") = 0
[pid 13026] 14:52:03.277084 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d") = -1 EISDIR (Is a directory)
[pid 13026] 14:52:03.277170 rmdir("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d") = -1 ENOTEMPTY (Directory not empty)
[pid 13026] 14:52:03.277289 lstat("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
[pid 13026] 14:52:03.277377 open("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d", O_RDONLY|O_CLOEXEC) = 15
[pid 13026] 14:52:03.277473 getdents64(15, /* 11 entries */, 4096) = 408
[pid 13026] 14:52:03.277581 getdents64(15, /* 0 entries */, 4096) = 0
[pid 13026] 14:52:03.277644 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d-json.log") = 0
[pid 13026] 14:52:03.277742 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/mqueue") = -1 EISDIR (Is a directory)
[pid 13026] 14:52:03.277811 rmdir("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/mqueue") = 0
[pid 13026] 14:52:03.277909 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/hostname") = 0
[pid 13026] 14:52:03.278008 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/config.json") = 0
[pid 13026] 14:52:03.278095 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/resolv.conf.hash") = 0
[pid 13026] 14:52:03.278171 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/shm") = -1 EISDIR (Is a directory)
[pid 13026] 14:52:03.278239 rmdir("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/shm") = 0
[pid 13026] 14:52:03.278334 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/hosts") = 0
[pid 13026] 14:52:03.278421 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/hostconfig.json") = 0
[pid 13026] 14:52:03.278503 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d/resolv.conf") = 0
[pid 13026] 14:52:03.278572 getdents64(15, /* 0 entries */, 4096) = 0
[pid 13026] 14:52:03.278665 close(15)   = 0
[pid 13026] 14:52:03.278724 unlink("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d") = -1 EISDIR (Is a directory)
[pid 13026] 14:52:03.278790 rmdir("/var/lib/docker/containers/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d") = 0
[pid 13026] 14:52:03.278867 unlink("/var/run/docker/execdriver/native/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d") = -1 ENOENT (No such file or directory)
[pid 13026] 14:52:03.278935 rmdir("/var/run/docker/execdriver/native/d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d") = -1 ENOENT (No such file or directory)
[pid 13026] 14:52:03.279060 clock_gettime(CLOCK_REALTIME, {1453405923, 279086865}) = 0
[pid 13026] 14:52:03.279190 clock_gettime(CLOCK_REALTIME, {1453405923, 279204411}) = 0

Not that I've removed a bunch of lines like <... x resumed> to fit inside the question body limit. Let me know if those are crucial.

Update 2

Looks like the holdup is in two calls like these, each of which eats about 3 seconds:

[pid 13026] 14:51:56.406094 open("/dev/mapper/docker-202:1-790981-d267f0e99e38c261ca9b35109591e278c99b559d280bd30b6f741e249769f33d", O_RDWR|O_CLOEXEC) = 15
[pid 13026] 14:51:56.406164 ioctl(15, BLKGETSIZE64, 107374182400) = 0
[pid 13026] 14:51:56.406250 ioctl(15, BLKDISCARD, {0, 0} <unfinished ...>
[pid 13026] 14:51:59.440956 <... ioctl resumed> ) = 0

Is there any way I can speed this up or eliminate the operation?

Update 3

I forgot to include my docker version:

$ docker --version
Docker version 1.9.1, build a34a1d5/1.9.1

@Iain strace isn't that helpful on the docker command itself because it's waiting for the daemon to do the actual work. I'll try attaching to the daemon process. — Jesse Crossen, Jan 21 '16 at 19:37
Further notes: the same thing happens removing a container from the `hello-world` image, so it's not config specific. I'm also trying to figure out if this might apply: http://blog.oddbit.com/tag/namespaces/index.html — Jesse Crossen, Jan 21 '16 at 20:40
Please start up a container, then find the /dev/mapper path to the container. Please can you provide the output from the following command: `dmsetup table ` and `dmsetup info ` — Matthew Ife, Jan 21 '16 at 21:40
@MatthewIfe: `$ sudo dmsetup table docker-202:1-790981-4984a6a9a8705116ce88369b7bd54a4b3494f700e5eb9a2db568cae9feb4ce72 0 209715200 thin 253:0 21 $ sudo dmsetup info docker-202:1-790981-4984a6a9a8705116ce88369b7bd54a4b3494f700e5eb9a2db568cae9feb4ce72 Name: docker-202:1-790981-4984a6a9a8705116ce88369b7bd54a4b3494f700e5eb9a2db568cae9feb4ce72 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 1 Number of targets: 1` — Jesse Crossen, Jan 21 '16 at 22:03
Other stuff I've tried is mounting read-only with `sudo docker run --read-only -it hello-world`, which makes no difference, and passing `--storage-opt dm.use_deferred_removal=true --storage-opt dm.use_deferred_deletion=true`, which also makes no difference. My understanding of docker is limited, but it seems like removing a device that couldn't possibly have been written to should be fast. — Jesse Crossen, Jan 21 '16 at 22:15

score 0 · Accepted Answer · answered Jan 25 '16 at 21:00

Okay it turns out the explanation is fairly simple. The slow cleanup time seems to be a side-effect of running the docker device mapper using a loop device on Amazon EBS. In case it might be useful, I had developed a workaround to make the removal not block the process that launched the image. At the end of the bash script that ran the image, I added the following (where $IMAGE is the name of the docker image being used):

nohup ionice -c 3 nice -n 19 \
  docker rm $( docker ps -aq -f "status=exited" -f "ancestor=$IMAGE" ) \
  0</dev/null &>/dev/null &

This will clean up all exited containers from the same image, so even if it fails to run once it will get the ones left behind on the next pass. I think this method would be effective for compensating for cleanup issues caused by the loop device, if any, but it doesn't help much if you're using EBS. The reason is that EBS operations use "hidden" resources that come out of your image's quota but are difficult to see directly. In other words, the hypervisor is doing some work on your behalf and since it's outside the scheduling system of the OS it cannot respect nice or ionice. The net effect is that the process will exit right away and the container will get cleaned up over the next 6 seconds or so, but performance will still be sluggish during that period.

The better solution is to attach an ephemeral storage device and follow the instructions here, assuming you're on Amazon Linux or similar and have a 30GB ephemeral volume at /dev/xvdb:

$ sudo service docker stop
$ sudo rm -rf /var/lib/docker
$ sudo umount /dev/xvdb
$ sudo pvcreate /dev/xvdb
$ sudo vgcreate vg-docker /dev/xvdb
$ sudo lvcreate -L 20G -n data vg-docker
$ sudo lvcreate -L 4G -n metadata vg-docker
$ echo 'DOCKER_STORAGE_OPTIONS="--storage-opt dm.datadev=/dev/vg-docker/data --storage-opt dm.metadatadev=/dev/vg-docker/metadata --storage-opt dm.use_deferred_removal=true --storage-opt dm.use_deferred_deletion=true"' \
    > sudo tee /etc/sysconfig/docker-storage
$ sudo service docker start
$ sudo docker info
Containers: 0
Images: 2
Server Version: 1.9.1
Storage Driver: devicemapper
 Pool Name: docker-202:1-263721-pool
 Pool Blocksize: 65.54 kB
 Base Device Size: 107.4 GB
 Backing Filesystem: 
 Data file: /dev/vg-docker/data
 Metadata file: /dev/vg-docker/metadata
 Data Space Used: 58.39 MB
 Data Space Total: 21.47 GB
 Data Space Available: 21.42 GB
 Metadata Space Used: 426 kB
 Metadata Space Total: 4.295 GB
 Metadata Space Available: 4.295 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: true
 Deferred Deletion Enabled: true
 Deferred Deleted Device Count: 0
 ...

Why does docker rm take almost 6 seconds to run?

Update 1

Update 2

Update 3

1 Answers1