docker-squash
docker-squash copied to clipboard
Published
20 hours ago •
goldmann
goldmann
Performance analysis
In this ticket I want to gather all performance analysis that could make squashing even faster.
All performance related issues in one place: https://github.com/goldmann/docker-scripts/issues?q=is%3Aissue+is%3Aopen+label%3Aperformance
Simple test with using a ramdisk as the temporary directory.
Dockerfile:
FROM fedora:23
RUN dnf -y install java
RUN dnf -y install gimp
RUN dnf -y install maven
RUN dnf clean all
CMD bash
$ mount -t tmpfs -o rw,size=2g tmpfs /mnt/ramdisk
[root@template-rhel test]# time ~/.local/bin/docker-scripts squash -f 7427c9af1454 -t image:squashed image:latest
2016-03-22 16:39:32,044 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-22 16:39:32,044 root INFO Using v1 image format
2016-03-22 16:39:32,174 root INFO Old image has 7 layers
2016-03-22 16:39:32,177 root INFO Checking if squashing is necessary...
2016-03-22 16:39:32,177 root INFO Attempting to squash last 5 layers...
2016-03-22 16:39:32,177 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /tmp/docker-squash-vve9hk/old/image.tar file...
2016-03-22 16:39:42,722 root INFO Image saved!
2016-03-22 16:39:42,725 root INFO Unpacking /tmp/docker-squash-vve9hk/old/image.tar tar file to /tmp/docker-squash-vve9hk/old directory
2016-03-22 16:39:43,881 root INFO Archive unpacked!
2016-03-22 16:39:43,882 root INFO Squashing image 'image:latest'...
2016-03-22 16:39:43,882 root INFO Starting squashing...
2016-03-22 16:39:43,882 root INFO Squashing file '/tmp/docker-squash-vve9hk/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-22 16:39:43,883 root INFO Squashing file '/tmp/docker-squash-vve9hk/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-22 16:39:43,889 root INFO Squashing file '/tmp/docker-squash-vve9hk/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-22 16:39:44,341 root INFO Squashing file '/tmp/docker-squash-vve9hk/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-22 16:39:53,970 root INFO Squashing file '/tmp/docker-squash-vve9hk/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-22 16:39:57,934 root INFO Squashing finished!
2016-03-22 16:39:57,950 root INFO New squashed image ID is None
2016-03-22 16:40:04,041 root INFO Image registered in Docker daemon as image:squashed
2016-03-22 16:40:04,236 root INFO Done
real 0m32.326s
user 0m14.939s
sys 0m4.240s
[root@template-rhel test]# time ~/.local/bin/docker-scripts -v squash --tmp-dir /mnt/ramdisk/docker -f 7427c9af1454 -t image:squashed image:latest^C
[root@template-rhel test]# ^C
[root@template-rhel test]# time ~/.local/bin/docker-scripts squash --tmp-dir /mnt/ramdisk/docker -f 7427c9af1454 -t image:squashed image:latest
2016-03-22 16:41:40,040 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-22 16:41:40,040 root INFO Using v1 image format
2016-03-22 16:41:40,170 root INFO Old image has 7 layers
2016-03-22 16:41:40,173 root INFO Checking if squashing is necessary...
2016-03-22 16:41:40,174 root INFO Attempting to squash last 5 layers...
2016-03-22 16:41:40,174 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /mnt/ramdisk/docker/old/image.tar file...
2016-03-22 16:41:50,386 root INFO Image saved!
2016-03-22 16:41:50,389 root INFO Unpacking /mnt/ramdisk/docker/old/image.tar tar file to /mnt/ramdisk/docker/old directory
2016-03-22 16:41:51,301 root INFO Archive unpacked!
2016-03-22 16:41:51,301 root INFO Squashing image 'image:latest'...
2016-03-22 16:41:51,301 root INFO Starting squashing...
2016-03-22 16:41:51,302 root INFO Squashing file '/mnt/ramdisk/docker/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-22 16:41:51,302 root INFO Squashing file '/mnt/ramdisk/docker/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-22 16:41:51,307 root INFO Squashing file '/mnt/ramdisk/docker/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-22 16:41:51,722 root INFO Squashing file '/mnt/ramdisk/docker/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-22 16:42:01,251 root INFO Squashing file '/mnt/ramdisk/docker/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-22 16:42:05,153 root INFO Squashing finished!
2016-03-22 16:42:05,169 root INFO New squashed image ID is None
2016-03-22 16:42:11,291 root INFO Image registered in Docker daemon as image:squashed
2016-03-22 16:42:11,408 root INFO Done
real 0m31.498s
user 0m14.748s
sys 0m3.670s
Tests with Docker deamon using a ramdisk as it's temporary directory as well as the squash tool indicated that the build slowed down(!!!) by about 1s. Interesting.
Docker daemon disk statistics while doing squashing.
Linux 3.10.0-327.10.1.el7.x86_64 (performance) 03/23/2016 _x86_64_ (4 CPU)
01:52:41 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
01:52:42 PM 0 25122 0.00 0.00 0.00 docker
01:52:43 PM 0 25122 0.00 0.00 0.00 docker
01:52:44 PM 0 25122 0.00 0.00 0.00 docker
01:52:45 PM 0 25122 0.00 0.00 0.00 docker
01:52:46 PM 0 25122 0.00 0.00 0.00 docker
01:52:47 PM 0 25122 134408.00 28.00 0.00 docker
01:52:48 PM 0 25122 157188.00 0.00 0.00 docker
01:52:49 PM 0 25122 93904.00 0.00 0.00 docker
01:52:50 PM 0 25122 115545.00 8.00 0.00 docker
01:52:51 PM 0 25122 184216.00 0.00 0.00 docker
01:52:52 PM 0 25122 126897.00 8.00 0.00 docker
01:52:53 PM 0 25122 108116.00 0.00 0.00 docker
01:52:54 PM 0 25122 63156.00 4.00 0.00 docker
01:52:55 PM 0 25122 585.00 8.00 0.00 docker
01:52:56 PM 0 25122 0.00 0.00 0.00 docker
01:52:57 PM 0 25122 0.00 0.00 0.00 docker
01:52:58 PM 0 25122 0.00 0.00 0.00 docker
01:52:59 PM 0 25122 0.00 0.00 0.00 docker
01:53:00 PM 0 25122 0.00 0.00 0.00 docker
01:53:01 PM 0 25122 0.00 0.00 0.00 docker
01:53:02 PM 0 25122 0.00 0.00 0.00 docker
01:53:03 PM 0 25122 0.00 0.00 0.00 docker
01:53:04 PM 0 25122 0.00 0.00 0.00 docker
01:53:05 PM 0 25122 0.00 0.00 0.00 docker
01:53:06 PM 0 25122 0.00 0.00 0.00 docker
01:53:07 PM 0 25122 0.00 0.00 0.00 docker
01:53:08 PM 0 25122 0.00 0.00 0.00 docker
01:53:09 PM 0 25122 0.00 0.00 0.00 docker
01:53:10 PM 0 25122 0.00 0.00 0.00 docker
01:53:11 PM 0 25122 0.00 0.00 0.00 docker
01:53:12 PM 0 25122 0.00 0.00 0.00 docker
01:53:13 PM 0 25122 0.00 0.00 0.00 docker
01:53:14 PM 0 25122 0.00 0.00 0.00 docker
01:53:15 PM 0 25122 713.00 132.00 0.00 docker
01:53:16 PM 0 25122 0.00 144.00 0.00 docker
01:53:17 PM 0 25122 0.00 244.00 0.00 docker
01:53:18 PM 0 25122 0.00 236.00 0.00 docker
01:53:19 PM 0 25122 1972.00 574008.00 0.00 docker
01:53:20 PM 0 25122 0.00 0.00 0.00 docker
01:53:21 PM 0 25122 0.00 0.00 0.00 docker
01:53:22 PM 0 25122 0.00 0.00 0.00 docker
01:53:23 PM 0 25122 0.00 0.00 0.00 docker
01:53:24 PM 0 25122 0.00 0.00 0.00 docker
^C
Average: 0 25122 22941.18 13364.80 0.00 docker
And the squashing process:
2016-03-23 13:52:46,280 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-23 13:52:46,280 root INFO Using v1 image format
2016-03-23 13:52:46,432 root INFO Old image has 7 layers
2016-03-23 13:52:46,435 root INFO Checking if squashing is necessary...
2016-03-23 13:52:46,436 root INFO Attempting to squash last 5 layers...
2016-03-23 13:52:46,436 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /tmp/docker-squash-Py5npw/old/image.tar file...
2016-03-23 13:52:56,916 root INFO Image saved!
2016-03-23 13:52:56,918 root INFO Unpacking /tmp/docker-squash-Py5npw/old/image.tar tar file to /tmp/docker-squash-Py5npw/old directory
2016-03-23 13:52:58,074 root INFO Archive unpacked!
2016-03-23 13:52:58,074 root INFO Squashing image 'image:latest'...
2016-03-23 13:52:58,075 root INFO Starting squashing...
2016-03-23 13:52:58,075 root INFO Squashing file '/tmp/docker-squash-Py5npw/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-23 13:52:58,075 root INFO Squashing file '/tmp/docker-squash-Py5npw/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-23 13:52:58,082 root INFO Squashing file '/tmp/docker-squash-Py5npw/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-23 13:52:58,541 root INFO Squashing file '/tmp/docker-squash-Py5npw/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-23 13:53:09,089 root INFO Squashing file '/tmp/docker-squash-Py5npw/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-23 13:53:13,077 root INFO Squashing finished!
2016-03-23 13:53:13,093 root INFO New squashed image ID is None
2016-03-23 13:53:19,119 root INFO Image registered in Docker daemon as image:squashed
2016-03-23 13:53:19,327 root INFO Done
Docker daemon CPU statistics while doing squashing
01:54:00 PM UID PID %usr %system %guest %CPU CPU Command
01:54:01 PM 0 25122 0.00 0.00 0.00 0.00 1 docker
01:54:02 PM 0 25122 0.00 0.00 0.00 0.00 1 docker
01:54:03 PM 0 25122 55.00 24.00 0.00 79.00 1 docker
01:54:04 PM 0 25122 74.00 19.00 0.00 93.00 1 docker
01:54:05 PM 0 25122 64.00 20.00 0.00 84.00 1 docker
01:54:06 PM 0 25122 62.00 22.00 0.00 84.00 0 docker
01:54:07 PM 0 25122 74.00 20.00 0.00 94.00 0 docker
01:54:08 PM 0 25122 72.00 17.00 0.00 89.00 0 docker
01:54:09 PM 0 25122 66.00 20.00 0.00 86.00 0 docker
01:54:10 PM 0 25122 55.00 26.00 0.00 81.00 1 docker
01:54:11 PM 0 25122 22.00 43.00 0.00 65.00 2 docker
01:54:12 PM 0 25122 6.00 18.00 0.00 24.00 2 docker
01:54:13 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:14 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:15 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:16 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:17 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:18 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:19 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:20 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:21 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:22 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:23 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:24 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:25 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:26 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:27 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:28 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:29 PM 0 25122 0.00 0.00 0.00 0.00 2 docker
01:54:30 PM 0 25122 13.00 28.00 0.00 41.00 2 docker
01:54:31 PM 0 25122 80.00 11.00 0.00 91.00 2 docker
01:54:32 PM 0 25122 69.00 8.00 0.00 77.00 2 docker
01:54:33 PM 0 25122 80.00 8.00 0.00 88.00 2 docker
01:54:34 PM 0 25122 48.00 5.00 0.00 53.00 2 docker
01:54:35 PM 0 25122 0.00 11.00 0.00 11.00 3 docker
01:54:36 PM 0 25122 0.00 0.00 0.00 0.00 3 docker
01:54:37 PM 0 25122 0.00 0.00 0.00 0.00 3 docker
^C
Average: 0 25122 22.70 8.11 0.00 30.81 - docker
And the squashing process itself:
2016-03-23 13:54:02,933 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-23 13:54:02,933 root INFO Using v1 image format
2016-03-23 13:54:02,977 root INFO Old image has 7 layers
2016-03-23 13:54:02,980 root INFO Checking if squashing is necessary...
2016-03-23 13:54:02,980 root INFO Attempting to squash last 5 layers...
2016-03-23 13:54:02,980 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /tmp/docker-squash-nHI6Sp/old/image.tar file...
2016-03-23 13:54:13,216 root INFO Image saved!
2016-03-23 13:54:13,219 root INFO Unpacking /tmp/docker-squash-nHI6Sp/old/image.tar tar file to /tmp/docker-squash-nHI6Sp/old directory
2016-03-23 13:54:14,345 root INFO Archive unpacked!
2016-03-23 13:54:14,345 root INFO Squashing image 'image:latest'...
2016-03-23 13:54:14,346 root INFO Starting squashing...
2016-03-23 13:54:14,346 root INFO Squashing file '/tmp/docker-squash-nHI6Sp/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-23 13:54:14,346 root INFO Squashing file '/tmp/docker-squash-nHI6Sp/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-23 13:54:14,352 root INFO Squashing file '/tmp/docker-squash-nHI6Sp/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-23 13:54:14,822 root INFO Squashing file '/tmp/docker-squash-nHI6Sp/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-23 13:54:24,608 root INFO Squashing file '/tmp/docker-squash-nHI6Sp/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-23 13:54:28,698 root INFO Squashing finished!
2016-03-23 13:54:28,714 root INFO New squashed image ID is None
2016-03-23 13:54:35,477 root INFO Image registered in Docker daemon as image:squashed
2016-03-23 13:54:35,698 root INFO Done
Now, a bit of CPU stats for the squashing tool itself:
02:16:20 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:21 PM 0 26931 1.00 0.00 0.00 1.00 2 python
02:16:22 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:23 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:24 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:25 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:26 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:27 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:28 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:29 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:30 PM 0 26931 14.00 13.00 0.00 27.00 0 python
02:16:31 PM 0 26931 44.00 49.00 0.00 93.00 0 python
02:16:32 PM 0 26931 17.00 84.00 0.00 101.00 0 python
02:16:33 PM 0 26931 23.00 76.00 0.00 99.00 2 python
02:16:34 PM 0 26931 84.00 17.00 0.00 101.00 0 python
02:16:35 PM 0 26931 83.00 16.00 0.00 99.00 0 python
02:16:36 PM 0 26931 97.00 3.00 0.00 100.00 0 python
02:16:37 PM 0 26931 97.00 3.00 0.00 100.00 0 python
02:16:38 PM 0 26931 98.00 2.00 0.00 100.00 0 python
02:16:39 PM 0 26931 98.00 2.00 0.00 100.00 0 python
02:16:40 PM 0 26931 96.00 4.00 0.00 100.00 0 python
02:16:41 PM 0 26931 98.00 2.00 0.00 100.00 0 python
02:16:42 PM 0 26931 98.00 2.00 0.00 100.00 0 python
02:16:43 PM 0 26931 100.00 0.00 0.00 100.00 0 python
02:16:44 PM 0 26931 99.00 1.00 0.00 100.00 0 python
02:16:45 PM 0 26931 89.00 11.00 0.00 100.00 0 python
02:16:46 PM 0 26931 99.00 1.00 0.00 100.00 0 python
02:16:47 PM 0 26931 100.00 0.00 0.00 100.00 0 python
02:16:48 PM 0 26931 75.00 25.00 0.00 100.00 0 python
02:16:49 PM 0 26931 27.00 73.00 0.00 100.00 2 python
02:16:50 PM 0 26931 0.00 47.00 0.00 47.00 2 python
02:16:51 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:52 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:53 PM 0 26931 0.00 0.00 0.00 0.00 2 python
02:16:54 PM 0 26931 0.00 0.00 0.00 0.00 2 python
Execution:
2016-03-23 14:16:21,517 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-23 14:16:21,518 root INFO Using v1 image format
2016-03-23 14:16:21,584 root INFO Old image has 7 layers
2016-03-23 14:16:21,588 root INFO Checking if squashing is necessary...
2016-03-23 14:16:21,588 root INFO Attempting to squash last 5 layers...
2016-03-23 14:16:21,588 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /tmp/docker-squash-zxOzrj/old/image.tar file...
2016-03-23 14:16:32,923 root INFO Image saved!
2016-03-23 14:16:32,926 root INFO Unpacking /tmp/docker-squash-zxOzrj/old/image.tar tar file to /tmp/docker-squash-zxOzrj/old directory
2016-03-23 14:16:34,079 root INFO Archive unpacked!
2016-03-23 14:16:34,080 root INFO Squashing image 'image:latest'...
2016-03-23 14:16:34,080 root INFO Starting squashing...
2016-03-23 14:16:34,080 root INFO Squashing file '/tmp/docker-squash-zxOzrj/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-23 14:16:34,080 root INFO Squashing file '/tmp/docker-squash-zxOzrj/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-23 14:16:34,087 root INFO Squashing file '/tmp/docker-squash-zxOzrj/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-23 14:16:34,552 root INFO Squashing file '/tmp/docker-squash-zxOzrj/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-23 14:16:44,565 root INFO Squashing file '/tmp/docker-squash-zxOzrj/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-23 14:16:48,726 root INFO Squashing finished!
2016-03-23 14:16:48,743 root INFO New squashed image ID is None
2016-03-23 14:16:55,434 root INFO Image registered in Docker daemon as image:squashed
2016-03-23 14:16:55,753 root INFO Done
And disk usage stats:
02:18:38 PM 0 27021 0.00 4.00 4.00 python
02:18:39 PM 0 27021 0.00 0.00 0.00 python
02:18:40 PM 0 27021 0.00 0.00 0.00 python
02:18:41 PM 0 27021 0.00 0.00 0.00 python
02:18:42 PM 0 27021 0.00 0.00 0.00 python
02:18:43 PM 0 27021 0.00 0.00 0.00 python
02:18:44 PM 0 27021 0.00 0.00 0.00 python
02:18:45 PM 0 27021 0.00 0.00 0.00 python
02:18:46 PM 0 27021 0.00 0.00 0.00 python
02:18:47 PM 0 27021 0.00 0.00 0.00 python
02:18:48 PM 0 27021 0.00 0.00 0.00 python
02:18:49 PM 0 27021 0.00 1157340.00 0.00 python
02:18:50 PM 0 27021 0.00 728700.00 941860.00 python
02:18:51 PM 0 27021 0.00 78656.00 0.00 python
02:18:52 PM 0 27021 0.00 183028.00 0.00 python
02:18:53 PM 0 27021 0.00 17788.00 0.00 python
02:18:54 PM 0 27021 0.00 30016.00 0.00 python
02:18:55 PM 0 27021 0.00 22400.00 0.00 python
02:18:56 PM 0 27021 0.00 20216.00 0.00 python
02:18:57 PM 0 27021 0.00 33664.00 0.00 python
02:18:58 PM 0 27021 0.00 30240.00 0.00 python
02:18:59 PM 0 27021 0.00 672.00 0.00 python
02:19:00 PM 0 27021 0.00 468.00 0.00 python
02:19:01 PM 0 27021 0.00 52512.00 0.00 python
02:19:02 PM 0 27021 0.00 87412.00 0.00 python
02:19:03 PM 0 27021 0.00 4092.00 0.00 python
02:19:04 PM 0 27021 0.00 968.00 0.00 python
02:19:05 PM 0 27021 0.00 92.00 0.00 python
02:19:06 PM 0 27021 0.00 128.00 0.00 python
02:19:07 PM 0 27021 0.00 0.00 0.00 python
02:19:08 PM 0 27021 0.00 0.00 0.00 python
02:19:09 PM 0 27021 0.00 0.00 0.00 python
02:19:10 PM 0 27021 0.00 0.00 0.00 python
02:19:11 PM 0 27021 0.00 0.00 0.00 python
02:19:12 PM 0 27021 0.00 0.00 0.00 python
02:19:13 PM 0 27021 0.00 0.00 0.00 python
02:19:14 PM 0 27021 0.00 0.00 0.00 python
02:19:15 PM 0 27021 0.00 0.00 0.00 python
02:19:16 PM 0 27021 0.00 0.00 0.00 python
Execution:
2016-03-23 14:18:38,457 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-23 14:18:38,457 root INFO Using v1 image format
2016-03-23 14:18:38,464 root INFO Old image has 7 layers
2016-03-23 14:18:38,467 root INFO Checking if squashing is necessary...
2016-03-23 14:18:38,467 root INFO Attempting to squash last 5 layers...
2016-03-23 14:18:38,467 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /tmp/docker-squash-OxMHc1/old/image.tar file...
2016-03-23 14:18:49,683 root INFO Image saved!
2016-03-23 14:18:49,686 root INFO Unpacking /tmp/docker-squash-OxMHc1/old/image.tar tar file to /tmp/docker-squash-OxMHc1/old directory
2016-03-23 14:18:50,880 root INFO Archive unpacked!
2016-03-23 14:18:50,880 root INFO Squashing image 'image:latest'...
2016-03-23 14:18:50,880 root INFO Starting squashing...
2016-03-23 14:18:50,880 root INFO Squashing file '/tmp/docker-squash-OxMHc1/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-23 14:18:50,881 root INFO Squashing file '/tmp/docker-squash-OxMHc1/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-23 14:18:50,888 root INFO Squashing file '/tmp/docker-squash-OxMHc1/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-23 14:18:51,340 root INFO Squashing file '/tmp/docker-squash-OxMHc1/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-23 14:19:01,385 root INFO Squashing file '/tmp/docker-squash-OxMHc1/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-23 14:19:05,648 root INFO Squashing finished!
2016-03-23 14:19:05,669 root INFO New squashed image ID is None
2016-03-23 14:19:17,091 root INFO Image registered in Docker daemon as image:squashed
2016-03-23 14:19:17,307 root INFO Done
A lot of reading in the beginning - Docker prepares the tar archive with the image, so reading all layers. It could be faster (at least twice) than it is, but it seems that there are a lot of things to compute (see next chart). In this case CPU is the bottleneck - we would need to look at the Docker code if the storage plugin could be optimized.
At the end a lot of writing - new squashed image is saved. Lighting fast, so it probably skips already existing layers and only unpacks one tar. Good.
As said above - creating the tar archive uses a lot of CPU. Same at the end.
Squash tool writes the exported tar archive (single file) very fast to the temporary directory.
kB_ccwr/s means:
Number of kilobytes whose writing to disk has been cancelled by the task. This may occur when the task truncates some dirty pagecache. In this case, some IO which another task has been accounted for will not be happening.
This needs investigation if this is what it should be.
Whoah, this is interesting - we keep the CPU busy while squashing. On one hand - good, on the other hand - maybe there is some room for improvement.
This is a combined chart that shows CPU usage for two processes Docker and the squashing tool. These are separate processes so ideally we should see usage of up to 200 % of CPU. This is not the case and most probably never be because we do use these processes heavily at different times.
Combined disk usage for Docker daemon and squashing tool. It seems that disk is not that used.
So, switching to a newer version of Origin 1.2 (or OSE 3.2), Docker 1.9, and enabling parallel pulls should improve this. Currently, all image layers are pulled in serial due to a bug in Docker 1.8.
Is there any way to get a graph showing iowait time during these periods and whether the iowait is because of network or storage?
So, this and the CPU time used by the Docker daemon are most likely the result of computing the tarsums of all the layers involved. I'm not sure there is much that can be done here, other than potentially scaling out to more cores. I'm not sure what the default value of GOMAXPROCS is for the docker daemon you are using. The default generally depends on which version of Go the binary was built with, which in Go 1.4 was limited to single threading because of some concurrency issues.
Some tests would need to be done to see if setting GOMAXPROCS == num logical cpus on the host improves the performance any for the versions used in your environment.
If I'm reading the overlapping of these graphs correctly, then pretty much the entire cpu chart for the represented builds are totally consumed by the docker pull, squash and docker push jobs.
It also looks to me like the docker operations are definitely being limited to a single core as far as the tarsum calculations, and I suspect a similar issue is happening with the squash tool.
Small info: my time will be limited over next days, but I'll update this ticket asap, including new graphs and replies. Please give me a few days.
Am I right that there is no docker pull or docker push shown here, only reading the layers of an image already pulled? If so, I guess the parallel pull performance fix wouldn't help here.
@twaugh is correct - this is local testing that does not involve any push or pull calls. I'm not investigating at all possibilities of parallel builds. This is not part of the testing. What I want to achieve is a clear view where are the places where we can make squashing faster for a single image. This will of course give us hints how we can schedule parallel squashing runs so it will make the best usage of available resources.
So, switching to a newer version of Origin 1.2 (or OSE 3.2), Docker 1.9, and enabling parallel pulls should improve this. Currently, all image layers are pulled in serial due to a bug in Docker 1.8.
No pull calls are executed. What we do see here is the save call executed on a local Docker daemon. There are a few things that could make this faster - including: faster disks, proper storage configuration (storage driver + opts), better CPU.
Switching to Docker 1.9 or even 1.10 will not change anything here since there was no change made to the way the tar is generated (well, besides skipping empty layers in 1.10+ - but this should not affect much the time).
Is there any way to get a graph showing iowait time during these periods and whether the iowait is because of network or storage?
I'll prepare one today.
So, this and the CPU time used by the Docker daemon are most likely the result of computing the tarsums of all the layers involved. I'm not sure there is much that can be done here, other than potentially scaling out to more cores. I'm not sure what the default value of GOMAXPROCS is for the docker daemon you are using. The default generally depends on which version of Go the binary was built with, which in Go 1.4 was limited to single threading because of some concurrency issues.
Some tests would need to be done to see if setting GOMAXPROCS == num logical cpus on the host improves the performance any for the versions used in your environment.
I think that's not the case. If you look at the time when the CPU usage is high - you'll see that this a period where the Docker daemon is not involved at all with the image loading/exporting. High CPU usage in this case is due:
- Unpacking the exported tar to disk, this method - only 2 seconds - mostly %system.
- A lot of files moving around and adding it to tar by the squashing tool itself, this method - 15 seconds - mostly %usr.
In this specific image we copy a lot of files to the new squashed layer (in-memory tar archive). This is a probable place where we could improve a bit performance. This will be very hard though. I was looking at making this parallel in #64. Feel free to take a look at this issue.
Here is some report that shows iowait too:
$ sar 1
Linux 3.10.0-327.10.1.el7.x86_64 (performance) 03/29/2016 _x86_64_ (4 CPU)
10:35:38 AM all 0.00 0.00 0.25 0.00 0.00 99.75
10:35:39 AM all 0.00 0.00 0.00 0.00 0.00 100.00
10:35:40 AM all 0.25 0.00 0.00 0.00 0.00 99.75
10:35:41 AM all 0.00 0.00 0.00 0.00 0.00 100.00
10:35:42 AM all 0.00 0.00 0.00 0.00 0.00 100.00
10:35:43 AM all 0.00 0.00 0.00 0.00 0.00 100.00
10:35:44 AM all 0.00 0.00 0.25 0.00 0.00 99.75
10:35:45 AM all 0.00 0.00 0.00 0.00 0.00 100.00
10:35:46 AM all 0.00 0.00 0.00 0.00 0.00 100.00
10:35:47 AM all 0.75 0.00 0.25 0.25 0.00 98.74
10:35:48 AM all 15.19 0.00 8.61 2.28 0.00 73.92
10:35:49 AM all 17.88 0.00 8.06 2.02 0.00 72.04
10:35:50 AM all 15.70 0.00 8.61 3.80 0.00 71.90
10:35:51 AM all 16.62 0.00 8.82 2.02 0.00 72.54
10:35:52 AM all 19.14 0.00 7.81 1.26 0.00 71.79
10:35:53 AM all 16.67 0.00 8.33 2.53 0.00 72.47
10:35:54 AM all 16.46 0.00 7.59 3.80 0.00 72.15
10:35:55 AM all 14.68 0.00 14.18 2.28 0.00 68.86
10:35:56 AM all 16.16 0.00 24.24 0.00 0.00 59.60
10:35:57 AM all 4.25 0.00 20.75 0.00 0.00 75.00
10:35:58 AM all 5.76 0.00 19.30 0.00 0.00 74.94
10:35:59 AM all 17.79 0.00 7.02 0.00 0.00 75.19
10:36:00 AM all 23.31 0.00 1.75 0.00 0.00 74.94
10:36:01 AM all 21.75 0.00 3.25 0.00 0.00 75.00
10:36:02 AM all 24.25 0.00 0.75 0.00 0.00 75.00
10:36:03 AM all 24.31 0.00 2.51 1.25 0.00 71.93
10:36:04 AM all 24.25 0.00 0.75 0.00 0.00 75.00
10:36:05 AM all 24.31 0.00 0.75 0.00 0.00 74.94
10:36:06 AM all 24.00 0.00 1.00 0.00 0.00 75.00
10:36:07 AM all 24.50 0.00 0.50 0.00 0.00 75.00
10:36:08 AM all 24.81 0.00 4.01 3.51 0.00 67.67
10:36:09 AM all 25.00 0.00 0.00 0.00 0.00 75.00
10:36:10 AM all 22.06 0.00 2.76 0.00 0.00 75.19
10:36:11 AM all 24.81 0.00 0.25 0.00 0.00 74.94
10:36:12 AM all 24.94 0.00 0.25 0.00 0.00 74.81
10:36:13 AM all 24.25 0.00 0.75 0.00 0.00 75.00
10:36:14 AM all 7.77 0.00 17.29 0.00 0.00 74.94
10:36:15 AM all 5.51 0.00 24.81 0.25 0.00 69.42
10:36:16 AM all 21.74 0.00 13.30 0.26 0.00 64.71
10:36:17 AM all 21.97 0.00 10.61 0.00 0.00 67.42
10:36:18 AM all 22.73 0.00 11.36 0.00 0.00 65.91
10:36:19 AM all 10.33 0.00 27.20 7.56 0.00 54.91
10:36:20 AM all 0.25 0.00 9.34 4.55 0.00 85.86
10:36:21 AM all 0.00 0.00 0.25 0.00 0.00 99.75
And the run:
2016-03-29 10:35:47,587 root INFO docker-scripts version 1.0.0rc1, Docker a01dc02/1.8.2, API 1.20...
2016-03-29 10:35:47,588 root INFO Using v1 image format
2016-03-29 10:35:47,718 root INFO Old image has 7 layers
2016-03-29 10:35:47,722 root INFO Checking if squashing is necessary...
2016-03-29 10:35:47,722 root INFO Attempting to squash last 5 layers...
2016-03-29 10:35:47,722 root INFO Saving image 48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43 to /tmp/docker-squash-a589tp/old/image.tar file...
2016-03-29 10:35:57,764 root INFO Image saved!
2016-03-29 10:35:57,767 root INFO Unpacking /tmp/docker-squash-a589tp/old/image.tar tar file to /tmp/docker-squash-a589tp/old directory
2016-03-29 10:35:58,956 root INFO Archive unpacked!
2016-03-29 10:35:58,956 root INFO Squashing image 'image:latest'...
2016-03-29 10:35:58,956 root INFO Starting squashing...
2016-03-29 10:35:58,956 root INFO Squashing file '/tmp/docker-squash-a589tp/old/48f9ecdfebc8516d4d41ca54d9e965078c47cc698360d3ece8a3fd7e44d63b43/layer.tar'...
2016-03-29 10:35:58,957 root INFO Squashing file '/tmp/docker-squash-a589tp/old/b3b76e207a7d4687d8468dcd7d3319d995f1f34bffff3ba9f7a2b057aa0d56dc/layer.tar'...
2016-03-29 10:35:58,964 root INFO Squashing file '/tmp/docker-squash-a589tp/old/ebe43cd57ca40c9bd3684ca607eca00489182a36b335551ec1d4c67738ab947a/layer.tar'...
2016-03-29 10:35:59,642 root INFO Squashing file '/tmp/docker-squash-a589tp/old/e103ca0c45f26572595d6a7adc14b1b84c24d6a8542cb9191386b0f7fb835d79/layer.tar'...
2016-03-29 10:36:09,689 root INFO Squashing file '/tmp/docker-squash-a589tp/old/20ea09835daf64a672f5b84a09a33dccf5bce157cd8c0ff6d2b303e7f132c9a5/layer.tar'...
2016-03-29 10:36:13,795 root INFO Squashing finished!
2016-03-29 10:36:13,812 root INFO New squashed image ID is None
2016-03-29 10:36:20,021 root INFO Image registered in Docker daemon as image:squashed
2016-03-29 10:36:20,219 root INFO Done
A few words on the environment I test on:
- This is a VM (KVM) with 20GB of RAM, 4vCPU (Intel(R) Xeon(R) CPU E5-2698 v3 @ 2.30GHz)
- One virtio disk configured as separate LVM volume on the host, raw storage format, io native.
- Docker:
$ docker info
Containers: 1
Images: 68
Storage Driver: devicemapper
Pool Name: docker-253:0-101827-pool
Pool Blocksize: 65.54 kB
Backing Filesystem: xfs
Data file: /dev/loop0
Metadata file: /dev/loop1
Data Space Used: 24.76 GB
Data Space Total: 107.4 GB
Data Space Available: 21.43 GB
Metadata Space Used: 16.16 MB
Metadata Space Total: 2.147 GB
Metadata Space Available: 2.131 GB
Udev Sync Supported: true
Deferred Removal Enabled: false
Data loop file: /var/lib/docker/devicemapper/devicemapper/data
Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata
Library Version: 1.02.107-RHEL7 (2015-12-01)
Execution Driver: native-0.2
Logging Driver: json-file
Kernel Version: 3.10.0-327.10.1.el7.x86_64
Operating System: Employee SKU
CPUs: 4
Total Memory: 19.45 GiB
Name: performance
ID: LU7V:DRBA:MEPX:UTMJ:H7FT:VP46:7JER:NEZL:K4VX:XGVQ:IIEE:IFG4
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled
$ docker version
Client:
Version: 1.8.2-el7
API version: 1.20
Package Version: docker-1.8.2-10.el7.x86_64
Go version: go1.4.2
Git commit: a01dc02/1.8.2
Built:
OS/Arch: linux/amd64
Server:
Version: 1.8.2-el7
API version: 1.20
Package Version:
Go version: go1.4.2
Git commit: a01dc02/1.8.2
Built:
OS/Arch: linux/amd64
Now looking from the Docker storage driver used:
xfs
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m33.035s
user 0m15.463s
sys 0m4.497s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m33.887s
user 0m16.258s
sys 0m4.599s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m33.908s
user 0m16.147s
sys 0m4.541s
ext4
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m33.999s
user 0m16.649s
sys 0m4.446s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m31.697s
user 0m14.834s
sys 0m4.430s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m32.552s
user 0m15.433s
sys 0m4.409s
btrfs
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m30.451s
user 0m15.258s
sys 0m4.260s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m29.230s
user 0m14.333s
sys 0m4.079s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m29.875s
user 0m14.919s
sys 0m4.141s
direct-lvm
DOCKER_STORAGE_OPTIONS=--storage-driver devicemapper --storage-opt dm.fs=xfs --storage-opt dm.thinpooldev=/dev/mapper/rhel_template--rhel-docker--pool --storage-opt dm.use_deferred_removal=true
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m38.082s
user 0m15.209s
sys 0m4.187s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m39.596s
user 0m15.174s
sys 0m4.213s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m38.768s
user 0m14.952s
sys 0m4.125s
overlay
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m30.809s
user 0m15.228s
sys 0m4.106s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m30.464s
user 0m15.485s
sys 0m4.185s
[root@performance docker-scripts]# time python docker_scripts/cli.py squash -f 7427c9af1454 -t image:squashed image:latest 2> /dev/null
real 0m30.503s
user 0m15.576s
sys 0m4.154s
It seems that brtfs and overlay perfrorm the best in this case.
It seems that PR #68 can increase performance by up to 40%, depending on the case. This is huge and already available in master.
Comparison of squashing the same image before and after merging #68 and #69.
Before:
After:
Please note that the 2nd run took only 22 seconds compared to the 34 long run in the first run.
EDIT: Updated to reflect tests on the same storage plugin.
Here is an annotated version of the CPU usage graph that shows what's going on. Orange blocks are CPU cycles used by Docker daemon which is very hard to improve directly in the code.
First orange field is saving the tar archive from Docker daemon to local disk. Over this time Docker prepares the tar archive on the fly, it's sent to the squashing tool and saved to the disk. This operation takes about 8 seconds. Hard to improve.
Dark blue field is unpacking tar archive. It takes a bit over 1 second. Hard to improve. Removing tar archive takes about 100ms.
Brown part is what we can focus on. This is the actual squashing of layers. This task is extrated into #64.
Loading image - last orange field is about generating the final tar archive (600ms) and uploading it to Docker daemon (1.5s). Again - hard to improve.
Last light blue field is cleanup of the temporary directory (100ms).
Saving image
This focuses on the "saving image" process highlighted in above's graph (first orange field).
Logs
This is log from Docker daemon. It shows what happens when you execute the /get call.
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.827006167+02:00" level=debug msg="Calling GET /v1.21/images/jboss/wildfly:latest/json"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.827065628+02:00" level=debug msg="GET /v1.21/images/jboss%2Fwildfly%3Alatest/json"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.834694323+02:00" level=debug msg="Calling GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/history"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.834813260+02:00" level=debug msg="GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/history"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.835522422+02:00" level=debug msg="{Action=history, Username=goldmann, LoginUID=1000, PID=27487}"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.835577127+02:00" level=info msg="{Action=history, Username=goldmann, LoginUID=1000, PID=27487}"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841144181+02:00" level=debug msg="Calling GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/get"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841172092+02:00" level=debug msg="GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/get"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841367521+02:00" level=info msg="{Action=get, Username=goldmann, LoginUID=1000, PID=27487}"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841520362+02:00" level=debug msg="Serializing 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.842522449+02:00" level=debug msg="[graph] TarLayer with reassembly: 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.842596854+02:00" level=debug msg="[graph] 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730 is at \"/var/lib/docker/btrfs/subvolumes/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730\""
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.842783416+02:00" level=debug msg="rendered layer for 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730 of [1024] size"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.843440134+02:00" level=debug msg="[graph] TarLayer with reassembly: 5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.843517698+02:00" level=debug msg="[graph] 5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895 is at \"/var/lib/docker/btrfs/subvolumes/5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895\""
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.843693588+02:00" level=debug msg="rendered layer for 5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895 of [1024] size"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.844241878+02:00" level=debug msg="[graph] TarLayer with reassembly: dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.844322277+02:00" level=debug msg="[graph] dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004 is at \"/var/lib/docker/btrfs/subvolumes/dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004\""
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.844485978+02:00" level=debug msg="rendered layer for dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004 of [1024] size"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.845072181+02:00" level=debug msg="[graph] TarLayer with reassembly: d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.845154787+02:00" level=debug msg="[graph] d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528 is at \"/var/lib/docker/btrfs/subvolumes/d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.654952775+02:00" level=debug msg="rendered layer for d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528 of [162209280] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655381201+02:00" level=debug msg="[graph] TarLayer with reassembly: b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655430748+02:00" level=debug msg="[graph] b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655 is at \"/var/lib/docker/btrfs/subvolumes/b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655539994+02:00" level=debug msg="rendered layer for b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655873270+02:00" level=debug msg="[graph] TarLayer with reassembly: 38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655910340+02:00" level=debug msg="[graph] 38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b is at \"/var/lib/docker/btrfs/subvolumes/38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655992422+02:00" level=debug msg="rendered layer for 38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656266752+02:00" level=debug msg="[graph] TarLayer with reassembly: ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656302141+02:00" level=debug msg="[graph] ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3 is at \"/var/lib/docker/btrfs/subvolumes/ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656385468+02:00" level=debug msg="rendered layer for ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656647763+02:00" level=debug msg="[graph] TarLayer with reassembly: 2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656684246+02:00" level=debug msg="[graph] 2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074 is at \"/var/lib/docker/btrfs/subvolumes/2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656769362+02:00" level=debug msg="rendered layer for 2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.657263981+02:00" level=debug msg="[graph] TarLayer with reassembly: 118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.657338545+02:00" level=debug msg="[graph] 118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9 is at \"/var/lib/docker/btrfs/subvolumes/118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.657492401+02:00" level=debug msg="rendered layer for 118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.658030763+02:00" level=debug msg="[graph] TarLayer with reassembly: 5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.658090338+02:00" level=debug msg="[graph] 5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23 is at \"/var/lib/docker/btrfs/subvolumes/5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649353134+02:00" level=debug msg="rendered layer for 5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23 of [199169536] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649795740+02:00" level=debug msg="[graph] TarLayer with reassembly: 3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649850894+02:00" level=debug msg="[graph] 3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73 is at \"/var/lib/docker/btrfs/subvolumes/3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649946242+02:00" level=debug msg="rendered layer for 3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73 of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.650351410+02:00" level=debug msg="[graph] TarLayer with reassembly: f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.650418649+02:00" level=debug msg="[graph] f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe is at \"/var/lib/docker/btrfs/subvolumes/f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.650568351+02:00" level=debug msg="rendered layer for f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651040240+02:00" level=debug msg="[graph] TarLayer with reassembly: 4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651081478+02:00" level=debug msg="[graph] 4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c is at \"/var/lib/docker/btrfs/subvolumes/4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651220027+02:00" level=debug msg="rendered layer for 4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651637971+02:00" level=debug msg="[graph] TarLayer with reassembly: 5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651680670+02:00" level=debug msg="[graph] 5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22 is at \"/var/lib/docker/btrfs/subvolumes/5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651815307+02:00" level=debug msg="rendered layer for 5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22 of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.652292497+02:00" level=debug msg="[graph] TarLayer with reassembly: 7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.652335151+02:00" level=debug msg="[graph] 7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1 is at \"/var/lib/docker/btrfs/subvolumes/7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.653379679+02:00" level=debug msg="rendered layer for 7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1 of [15872] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.653868371+02:00" level=debug msg="[graph] TarLayer with reassembly: bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.653926863+02:00" level=debug msg="[graph] bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564 is at \"/var/lib/docker/btrfs/subvolumes/bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840265182+02:00" level=debug msg="rendered layer for bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564 of [26285056] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840783969+02:00" level=debug msg="[graph] TarLayer with reassembly: b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840851061+02:00" level=debug msg="[graph] b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c is at \"/var/lib/docker/btrfs/subvolumes/b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840958469+02:00" level=debug msg="rendered layer for b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.841418911+02:00" level=debug msg="[graph] TarLayer with reassembly: 4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.841476404+02:00" level=debug msg="[graph] 4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a is at \"/var/lib/docker/btrfs/subvolumes/4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.841623385+02:00" level=debug msg="rendered layer for 4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842090213+02:00" level=debug msg="[graph] TarLayer with reassembly: 6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842156420+02:00" level=debug msg="[graph] 6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc is at \"/var/lib/docker/btrfs/subvolumes/6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842272336+02:00" level=debug msg="rendered layer for 6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842656897+02:00" level=debug msg="[graph] TarLayer with reassembly: 474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842711210+02:00" level=debug msg="[graph] 474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2 is at \"/var/lib/docker/btrfs/subvolumes/474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2\""
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.767523473+02:00" level=debug msg="rendered layer for 474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2 of [204176896] size"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768210747+02:00" level=debug msg="[graph] TarLayer with reassembly: 1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768275188+02:00" level=debug msg="[graph] 1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e is at \"/var/lib/docker/btrfs/subvolumes/1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e\""
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768451418+02:00" level=debug msg="rendered layer for 1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e of [1024] size"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768490431+02:00" level=debug msg="End Serializing 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768501029+02:00" level=debug msg="There were no repositories to write"
Mar 30 11:57:39 mistress docker[1175]: time="2016-03-30T11:57:39.391523999+02:00" level=debug msg="End export image"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.827006167+02:00" level=debug msg="Calling GET /v1.21/images/jboss/wildfly:latest/json"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.827065628+02:00" level=debug msg="GET /v1.21/images/jboss%2Fwildfly%3Alatest/json"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.834694323+02:00" level=debug msg="Calling GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/history"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.834813260+02:00" level=debug msg="GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/history"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.835522422+02:00" level=debug msg="{Action=history, Username=goldmann, LoginUID=1000, PID=27487}"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.835577127+02:00" level=info msg="{Action=history, Username=goldmann, LoginUID=1000, PID=27487}"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841144181+02:00" level=debug msg="Calling GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/get"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841172092+02:00" level=debug msg="GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/get"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841367521+02:00" level=info msg="{Action=get, Username=goldmann, LoginUID=1000, PID=27487}"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.841520362+02:00" level=debug msg="Serializing 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.842522449+02:00" level=debug msg="[graph] TarLayer with reassembly: 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.842596854+02:00" level=debug msg="[graph] 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730 is at \"/var/lib/docker/btrfs/subvolumes/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730\""
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.842783416+02:00" level=debug msg="rendered layer for 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730 of [1024] size"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.843440134+02:00" level=debug msg="[graph] TarLayer with reassembly: 5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.843517698+02:00" level=debug msg="[graph] 5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895 is at \"/var/lib/docker/btrfs/subvolumes/5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895\""
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.843693588+02:00" level=debug msg="rendered layer for 5ae69cb454a5a542f63e148ce40fb9e01de5bb01805b4ded238841bc2ce8e895 of [1024] size"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.844241878+02:00" level=debug msg="[graph] TarLayer with reassembly: dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.844322277+02:00" level=debug msg="[graph] dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004 is at \"/var/lib/docker/btrfs/subvolumes/dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004\""
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.844485978+02:00" level=debug msg="rendered layer for dc24712f35c40e958be8aca2731e7bf8353b9b18baa6a94ad84c6952cbc77004 of [1024] size"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.845072181+02:00" level=debug msg="[graph] TarLayer with reassembly: d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528"
Mar 30 11:57:34 mistress docker[1175]: time="2016-03-30T11:57:34.845154787+02:00" level=debug msg="[graph] d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528 is at \"/var/lib/docker/btrfs/subvolumes/d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.654952775+02:00" level=debug msg="rendered layer for d929129d4c8e61ea3661eb42c30d01f4c152418689178afc7dc8185a37814528 of [162209280] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655381201+02:00" level=debug msg="[graph] TarLayer with reassembly: b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655430748+02:00" level=debug msg="[graph] b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655 is at \"/var/lib/docker/btrfs/subvolumes/b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655539994+02:00" level=debug msg="rendered layer for b8fa3caf7d6dc228bf2499a3af86e5073ad0c17304c3900fa341e9d2fe4e5655 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655873270+02:00" level=debug msg="[graph] TarLayer with reassembly: 38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655910340+02:00" level=debug msg="[graph] 38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b is at \"/var/lib/docker/btrfs/subvolumes/38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.655992422+02:00" level=debug msg="rendered layer for 38b8f85e74bfa773a0ad69da2205dc0148945e6f5a7ceb04fa4e8619e1de425b of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656266752+02:00" level=debug msg="[graph] TarLayer with reassembly: ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656302141+02:00" level=debug msg="[graph] ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3 is at \"/var/lib/docker/btrfs/subvolumes/ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656385468+02:00" level=debug msg="rendered layer for ae79b646b9a9a287c5f6a01871cc9d9ee596dafee2db942714ca3dea0c06eef3 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656647763+02:00" level=debug msg="[graph] TarLayer with reassembly: 2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656684246+02:00" level=debug msg="[graph] 2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074 is at \"/var/lib/docker/btrfs/subvolumes/2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.656769362+02:00" level=debug msg="rendered layer for 2b4606dc9dc773aa220a65351fe8d54f03534c58fea230960e95915222366074 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.657263981+02:00" level=debug msg="[graph] TarLayer with reassembly: 118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.657338545+02:00" level=debug msg="[graph] 118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9 is at \"/var/lib/docker/btrfs/subvolumes/118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9\""
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.657492401+02:00" level=debug msg="rendered layer for 118fa9e33576ecc625ebbbfdf2809c1527e716cb4fd5cb40548eb6d3503a75a9 of [1024] size"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.658030763+02:00" level=debug msg="[graph] TarLayer with reassembly: 5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23"
Mar 30 11:57:35 mistress docker[1175]: time="2016-03-30T11:57:35.658090338+02:00" level=debug msg="[graph] 5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23 is at \"/var/lib/docker/btrfs/subvolumes/5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649353134+02:00" level=debug msg="rendered layer for 5f7e8f36c3bb20c9db7470a22f828710b4d28aede64966c425add48a1b14fe23 of [199169536] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649795740+02:00" level=debug msg="[graph] TarLayer with reassembly: 3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649850894+02:00" level=debug msg="[graph] 3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73 is at \"/var/lib/docker/btrfs/subvolumes/3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.649946242+02:00" level=debug msg="rendered layer for 3d4d0228f161b67eb46fdb425ad148c31d9944dcb822f67eac3e2ac2effefc73 of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.650351410+02:00" level=debug msg="[graph] TarLayer with reassembly: f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.650418649+02:00" level=debug msg="[graph] f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe is at \"/var/lib/docker/btrfs/subvolumes/f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.650568351+02:00" level=debug msg="rendered layer for f7ab4ea197084ab7483a2ca5409bdcf5473141bfb61b8687b1329943359cc3fe of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651040240+02:00" level=debug msg="[graph] TarLayer with reassembly: 4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651081478+02:00" level=debug msg="[graph] 4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c is at \"/var/lib/docker/btrfs/subvolumes/4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651220027+02:00" level=debug msg="rendered layer for 4bb15f3b69771b7eefad7a6bca598954c83f2e1ddf97a0afb43f6b279f08db4c of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651637971+02:00" level=debug msg="[graph] TarLayer with reassembly: 5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651680670+02:00" level=debug msg="[graph] 5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22 is at \"/var/lib/docker/btrfs/subvolumes/5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.651815307+02:00" level=debug msg="rendered layer for 5dc1e49f436139e722b787b85106aa657fe97011c5be03364ba041c63037ab22 of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.652292497+02:00" level=debug msg="[graph] TarLayer with reassembly: 7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.652335151+02:00" level=debug msg="[graph] 7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1 is at \"/var/lib/docker/btrfs/subvolumes/7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.653379679+02:00" level=debug msg="rendered layer for 7f0f9eb311744d3b262ceb327c3c839bce7d603266625f0cbbe9158707bc4ed1 of [15872] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.653868371+02:00" level=debug msg="[graph] TarLayer with reassembly: bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.653926863+02:00" level=debug msg="[graph] bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564 is at \"/var/lib/docker/btrfs/subvolumes/bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840265182+02:00" level=debug msg="rendered layer for bd515f044af75b179b18a1c110d445946f4e1bffb84f7e4c010f6563eb193564 of [26285056] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840783969+02:00" level=debug msg="[graph] TarLayer with reassembly: b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840851061+02:00" level=debug msg="[graph] b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c is at \"/var/lib/docker/btrfs/subvolumes/b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.840958469+02:00" level=debug msg="rendered layer for b78336099045fb8f9c4cf2fab492089fb36a1bb067cbf6ca7ba70be9e10e2f4c of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.841418911+02:00" level=debug msg="[graph] TarLayer with reassembly: 4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.841476404+02:00" level=debug msg="[graph] 4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a is at \"/var/lib/docker/btrfs/subvolumes/4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.841623385+02:00" level=debug msg="rendered layer for 4816a298548c167ddba4e740c42d657a40a6b5757890066a66f98adad983a52a of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842090213+02:00" level=debug msg="[graph] TarLayer with reassembly: 6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842156420+02:00" level=debug msg="[graph] 6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc is at \"/var/lib/docker/btrfs/subvolumes/6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc\""
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842272336+02:00" level=debug msg="rendered layer for 6ee235cf4473c4a8902a975c7f2d6ba70c2f79214ce1759542666dd6f55f40fc of [1024] size"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842656897+02:00" level=debug msg="[graph] TarLayer with reassembly: 474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2"
Mar 30 11:57:36 mistress docker[1175]: time="2016-03-30T11:57:36.842711210+02:00" level=debug msg="[graph] 474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2 is at \"/var/lib/docker/btrfs/subvolumes/474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2\""
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.767523473+02:00" level=debug msg="rendered layer for 474c2ee77fa39d403e777fecb066572ec2cf3c7f4bfdfa9ad8de531fa5b7eba2 of [204176896] size"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768210747+02:00" level=debug msg="[graph] TarLayer with reassembly: 1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768275188+02:00" level=debug msg="[graph] 1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e is at \"/var/lib/docker/btrfs/subvolumes/1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e\""
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768451418+02:00" level=debug msg="rendered layer for 1544084fad81e27c28a8c12c08b2439451fd1e745e38c1dcecd862d240c4235e of [1024] size"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768490431+02:00" level=debug msg="End Serializing 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730"
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768501029+02:00" level=debug msg="There were no repositories to write"
Mar 30 11:57:39 mistress docker[1175]: time="2016-03-30T11:57:39.391523999+02:00" level=debug msg="End export image"
And here is the log from the squashing tool:
2016-03-30 11:57:34,840 root INFO Saving image 25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730 to /tmp/docker-squash-JHbbLi/old/image.tar file...
2016-03-30 11:57:34,840 root DEBUG Try #1...
2016-03-30 11:57:38,769 requests.packages.urllib3.connectionpool DEBUG "GET /v1.21/images/25954e6d230006235eecb7f0cc560264d73146985c2d2e663bac953d660b8730/get HTTP/1.1" 200 None
2016-03-30 11:57:39,824 root INFO Image saved!
Investigation
Very important is the debug log from requests module. It shows us that the call returned at 11:57:38,769, which corresponds to the following Docker daemon line:
Mar 30 11:57:38 mistress docker[1175]: time="2016-03-30T11:57:38.768501029+02:00" level=debug msg="There were no repositories to write"
This means that preparing the tar archive is a blocking call. The tar archive is not streamed to the client, but instead whole archive is prepared and afterwards send to the client. Over that time client is just idling. Preparing the tar archive on the daemon side took almost exactly 4 seconds in this case.
Later in the same log we see:
Mar 30 11:57:39 mistress docker[1175]: time="2016-03-30T11:57:39.391523999+02:00" level=debug msg="End export image"
This means that transferring the tar archive to the client took about 650ms.
Conclusion
It's not possible to make this part performing better because most of the time is taken by Docker daemon preparing the tar archive. We do not have any control over it. I tried multiple ways of fetching the image (using API) but it did not make any significant difference.
Recommendation
To make this part faster you need to use faster CPU and disks. Focus on CPU.
Comment: the issue is that this call is single threaded and layers are prepared serially. It doesn't make sense since that data is read-only and could use multi threading easily. I estimate that this simple change could cut the tar preparation time by 50%. Which would make the squashing shorter by at least 2 seconds. If the daemon would additionally stream the tar archive on the fly we could make it even shorter.
Unpacking tar archive
Investigation of the dark blue part of the graph.
Logs
2016-03-30 13:34:54,399 root INFO Unpacking /tmp/docker-squash-E0Up8C/old/image.tar tar file to /tmp/docker-squash-E0Up8C/old directory
2016-03-30 13:34:54,786 root DEBUG Removing exported tar (/tmp/docker-squash-E0Up8C/old/image.tar)...
2016-03-30 13:34:54,832 root INFO Archive unpacked!
Investigation
In this case unpacking took about 500ms. This is not much considering that the unpacked image size is 565MB.
The code looks clean and I do not see any room for improvement here.
$ python -m cProfile -o foo.cprof docker-squash ...
$ pyprof2calltree -k -i foo.cprof
is an easy way to get some hard data. Eg. I found out that 18% of runtime is spent in the _file_should_be_skipped method, because in my case it was called 615k times and issued stunning 535M .startswith() calls which took my PC 70 seconds to execute. So that's one piece of hot code right there.
@rindeal I'll take a closer look on this at some point. I cannot really promise any dates though. Performance is an important thing for this tool. I think it does it's job pretty well even now. The tool itself was undergoing many rounds of performance improvements already, I'm happy to do another one :)
I love this project @goldmann however I agree with @rindeal's analysis. Thats a good bit of low hanging fruit. I hope you can find time to do another round as you put it.
I've noted between 10 and 20% utilization in _file_should_be_skipped particularly in images with large numbers of files. Node projects suffer particularly badly.
I'd suggest changing file_paths[layer] to be a more optimal structure. Does python have a prefixing tree structure?
It would be simpler if that directory lookup part wasnt there, and to be honest I'm not entirely sure why it is needed.
The other bit of low hangining fruit I suspect is within a layer doing parallel comparisons when looking for changed files. Each layer must still be handled independantly of course (to do otherwise would be complex).
