Performance analysis

[goldmann]

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

[goldmann]

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

[goldmann]

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.

[goldmann]

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

[goldmann]

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

[goldmann]

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

[goldmann]

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

[goldmann]

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.

[detiber]

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.

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.

[detiber]

Is there any way to get a graph showing iowait time during these periods and whether the iowait is because of network or storage?

[detiber]

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.

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.

[detiber]

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.

[goldmann]

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.

[twaugh]

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.