Is it possible to configure Docker to output timing for the build of a Dockerfile?
We run a medium sized development team and would like to collect statistics on the average build times for our developers' development containers.
Ideally, it should measure the duration of individual steps.
BuildKit, which was experimental in 18.06 and generally available in 18.09, has this functionality built in. To configure the dockerd daemon with experimental mode, you can setup the daemon.json:
$ cat /etc/docker/daemon.json
{
"experimental": true
}
Then you can enable BuildKit from the client side with an environment variable:
$ export DOCKER_BUILDKIT=1
$ docker build -t java-test:latest .
[+] Building 421.6s (13/13) FINISHED
=> local://context (.dockerignore) 1.6s
=> => transferring context: 56B 0.3s
=> local://dockerfile (Dockerfile) 2.0s
=> => transferring dockerfile: 895B 0.4s
=> CACHED docker-image://docker.io/tonistiigi/copy:v0.1.3@sha256:e57a3b4d6240f55bac26b655d2cfb751f8b9412d6f 0.1s
=> docker-image://docker.io/library/openjdk:8-jdk-alpine 1.0s
=> => resolve docker.io/library/openjdk:8-jdk-alpine 0.0s
=> local://context 1.7s
=> => transferring context: 6.20kB 0.4s
=> docker-image://docker.io/library/openjdk:8-jre-alpine 1.3s
=> => resolve docker.io/library/openjdk:8-jre-alpine 0.0s
=> /bin/sh -c apk add --no-cache maven 61.0s
=> copy /src-0/pom.xml java/pom.xml 1.3s
=> /bin/sh -c mvn dependency:go-offline 339.4s
=> copy /src-0 java 0.9s
=> /bin/sh -c mvn package -Dmaven.test.skip=true 10.2s
=> copy /src-0/gs-spring-boot-docker-0.1.0.jar java/app.jar 0.8s
=> exporting to image 1.2s
=> => exporting layers 1.0s
=> => writing image sha256:d57028743ca10bb4d0527a294d5c83dd941aeb1033d4fe08949a135677846179 0.1s
=> => naming to docker.io/library/java-test:latest 0.1s
There's also an option to disable the tty console output which generates output more suitable for scripting with each section having a start, stop, and duration:
$ docker build -t java-test:latest --progress plain .
#1 local://dockerfile (Dockerfile)
#1 digest: sha256:da721b637ea85add6e26070a48520675cefc2bed947c626f392be9890236d11b
#1 name: "local://dockerfile (Dockerfile)"
#1 started: 2018-09-05 19:30:53.899809093 +0000 UTC
#1 completed: 2018-09-05 19:30:53.899903348 +0000 UTC
#1 duration: 94.255µs
#1 started: 2018-09-05 19:30:53.900069076 +0000 UTC
#1 transferring dockerfile: 38B done
#2 ...
#2 local://context (.dockerignore)
#2 digest: sha256:cbf55954659905f4d7bd2fc3e5e52d566055eecd94fd7503565315022d834c21
#2 name: "local://context (.dockerignore)"
#2 started: 2018-09-05 19:30:53.899624016 +0000 UTC
#2 completed: 2018-09-05 19:30:53.899695455 +0000 UTC
#2 duration: 71.439µs
#2 started: 2018-09-05 19:30:53.899839335 +0000 UTC
#2 completed: 2018-09-05 19:30:54.359527504 +0000 UTC
#2 duration: 459.688169ms
#2 transferring context: 34B done
#1 local://dockerfile (Dockerfile)
#1 completed: 2018-09-05 19:30:54.592304408 +0000 UTC
#1 duration: 692.235332ms
#3 docker-image://docker.io/tonistiigi/copy:v0.1.3@sha256:e57a3b4d6240f55ba...
#3 digest: sha256:39386c91e9f27ee70b2eefdee12fc8a029bf5edac621b91eb5f3e6001d41dd4f
#3 name: "docker-image://docker.io/tonistiigi/copy:v0.1.3@sha256:e57a3b4d6240f55bac26b655d2cfb751f8b9412d6f7bb1f787e946391fb4b21b"
#3 started: 2018-09-05 19:30:54.731749377 +0000 UTC
#3 completed: 2018-09-05 19:30:54.732013326 +0000 UTC
#3 duration: 263.949µs
#5 docker-image://docker.io/library/openjdk:8-jdk-alpine
#5 digest: sha256:d680c6a82813d080081fbc3c024d21ddfa7ff995981cc7b4bfafe55edf80a319
#5 name: "docker-image://docker.io/library/openjdk:8-jdk-alpine"
#5 started: 2018-09-05 19:30:54.731483638 +0000 UTC
#5 completed: 2018-09-05 19:30:54.732480345 +0000 UTC
#5 duration: 996.707µs
#4 docker-image://docker.io/library/openjdk:8-jre-alpine
#4 digest: sha256:9ed31df4e6731a1718ea93bfa77354ad1ea2d1625c1cb16e2087d16d0b84bd00
#4 name: "docker-image://docker.io/library/openjdk:8-jre-alpine"
#4 started: 2018-09-05 19:30:54.73176516 +0000 UTC
#4 completed: 2018-09-05 19:30:54.732603067 +0000 UTC
#4 duration: 837.907µs
#7 local://context
#7 digest: sha256:efe765161a29e2bf7a41439cd2e6656fcf6fa6bc97da825ac9b5a0d8adecf1ac
#7 name: "local://context"
#7 started: 2018-09-05 19:30:54.73178732 +0000 UTC
#7 completed: 2018-09-05 19:30:54.731880943 +0000 UTC
#7 duration: 93.623µs
#7 started: 2018-09-05 19:30:54.792740019 +0000 UTC
#7 transferring context: 473B done
#7 completed: 2018-09-05 19:30:55.059008345 +0000 UTC
#7 duration: 266.268326ms
#9 /bin/sh -c mvn dependency:go-offline
#9 digest: sha256:2197672cd7a44d93e0dba40aa00d7ef41f8680226d91f469d1c925646bdc8d6d
#9 name: "/bin/sh -c mvn dependency:go-offline"
#9 started: 2018-09-05 19:30:55.203449147 +0000 UTC
#9 completed: 2018-09-05 19:30:55.203449147 +0000 UTC
#9 duration: 0s
#9 cached: true
#10 copy /src-0 java
#10 digest: sha256:36cf252c34be098731bd8c5fb3f273f9c1437a5f74a65a3555d71150c2092fa7
#10 name: "copy /src-0 java"
#10 started: 2018-09-05 19:30:55.203449147 +0000 UTC
#10 completed: 2018-09-05 19:30:55.203449147 +0000 UTC
#10 duration: 0s
#10 cached: true
#11 /bin/sh -c mvn package -Dmaven.test.skip=true
#11 digest: sha256:390464b1fdc7a4c833b3476033d95b7714e22bcbfd018469e97b04781cb41532
#11 name: "/bin/sh -c mvn package -Dmaven.test.skip=true"
#11 started: 2018-09-05 19:30:55.203449147 +0000 UTC
#11 completed: 2018-09-05 19:30:55.203449147 +0000 UTC
#11 duration: 0s
#11 cached: true
#12 copy /src-0/gs-spring-boot-docker-0.1.0.jar java/app.jar
#12 digest: sha256:a7d60191a720f80de72a77ebe0d4bd1b0fd55d44e623661e80916b7fd1952076
#12 name: "copy /src-0/gs-spring-boot-docker-0.1.0.jar java/app.jar"
#12 started: 2018-09-05 19:30:55.203449147 +0000 UTC
#12 completed: 2018-09-05 19:30:55.203555216 +0000 UTC
#12 duration: 106.069µs
#12 cached: true
#6 /bin/sh -c apk add --no-cache maven
#6 digest: sha256:db505db5e418f195c7bad3a710ad40bec3d91d47ff11a6f464b3ae37af744e7d
#6 name: "/bin/sh -c apk add --no-cache maven"
#6 started: 2018-09-05 19:30:55.203449147 +0000 UTC
#6 completed: 2018-09-05 19:30:55.203449147 +0000 UTC
#6 duration: 0s
#6 cached: true
#8 copy /src-0/pom.xml java/pom.xml
#8 digest: sha256:f032d4ff111c6ab0efef1a4e37d2467fffe43f48a529b8d56291ec81f96296ab
#8 name: "copy /src-0/pom.xml java/pom.xml"
#8 started: 2018-09-05 19:30:55.203449147 +0000 UTC
#8 completed: 2018-09-05 19:30:55.203449147 +0000 UTC
#8 duration: 0s
#8 cached: true
#13 exporting to image
#13 digest: sha256:d536dc2895c30fbde898bb4635581350a87c21f3695913ba21850a73d31422d9
#13 name: "exporting to image"
#13 started: 2018-09-05 19:30:55.203674127 +0000 UTC
#13 exporting layers done
#13 writing image sha256:d57028743ca10bb4d0527a294d5c83dd941aeb1033d4fe08949a135677846179 0.1s done
#13 naming to docker.io/library/java-test:latest
#13 completed: 2018-09-05 19:30:55.341300051 +0000 UTC
#13 duration: 137.625924ms
#13 naming to docker.io/library/java-test:latest 0.0s done
time docker build .
docker build . | while read line ; do echo "$(date)| $line"; done;
Wed 5 Sep 2018 19:12:22 BST| Sending build context to Docker daemon 27.65kB
Wed 5 Sep 2018 19:12:22 BST| Step 1/19 : FROM centos:centos7
Wed 5 Sep 2018 19:12:22 BST| ---> 49f7960eb7e4
...
You can improve the results by only outputting the "Step ?/? :" lines, like so:
docker build . | grep "^Step" | while read line ; do echo "$(date +%s)| $line"; done;
1536171476| Step 1/19 : FROM centos:centos7
1536171476| Step 2/19 : ENV TERM xterm
1536171476| Step 3/19 : RUN *** omitted ***
1536171476| Step 4/19 : RUN *** omitted ***
1536171476| Step 5/19 : COPY *** omitted ***
1536171476| Step 6/19 : RUN *** omitted ***
1536171476| Step 7/19 : COPY *** omitted ***
You can make this into a script if you wanted to run in a CI/CD pipeline, or add to your developer tools.
#!/bin/bash
# script: time-docker-build.sh
#
# All command line arguments are passed to docker build command.
#
# usage: ./time-docker-build.sh
#
DATE_FORMAT="+%s"
(
# Output START line
echo "$(date $DATE_FORMAT) | - 0 - START"
docker build $* . | \
grep "^Step" | \
while read line ;
do
# Output build output prefixed with date
echo "$(date $DATE_FORMAT) | $line";
done;
# Output END line
echo "$(date $DATE_FORMAT) | - -1 - END"
) | (
# Generate JSON array output.
# - START is step: 0
# - END is step: -1
echo "["
FIRST_RUN=true
while read line ;
do
[[ -z "$FIRST_RUN" ]] && echo "," # if not first line, print ','
lineArray=($line)
time="${lineArray[0]}" # step is 0th
step="${lineArray[3]}" # step is 2nd
cmd="${lineArray[@]:5}" # cmd is everything after 5th
stepNum=${step/\/*/}
escapedCmd="${cmd//\"/\\\"}" # escape all double quotes '"'
echo " {"
echo " \"time\": $time,"
echo " \"step\": $stepNum,"
echo " \"cmd\": \"$escapedCmd\""
echo -n " }"
unset FIRST_RUN
done
echo
echo "]"
)
bash-3.2$ ./time-docker-build.sh
[
{
"time": 1536174052,
"step": 0,
"cmd": "START"
},
{
"time": 1536174052,
"step": 1,
"cmd": "FROM centos:centos7"
},
{
"time": 1536174052,
"step": 2,
"cmd": "ENV TERM xterm"
},
Script is available as a gist here:
https://gist.github.com/philpoore/05eca572f3aadf70f529c470ac679147
I had the same issue, there is a command line utility called ts taking care of that issue (part of moreutils):
$ docker build . | ts
Aug 09 09:09:56 Sending build context to Docker daemon 21.2MB
Aug 09 09:09:56 Step 1/22 : FROM node:alpine as apibuild
Aug 09 09:09:56 ---> 5a519d1e3a24
[...]
Aug 09 09:12:56 Successfully built 80bf576659e9
You could use the tool time to measure the build times. E.g.
time docker build .
For individual build steps it's getting more difficult. You could add a RUN date command after each step, but this would add another layer to the image. So it's getting a bit messy.
I was wondering that too. The only solution I came up with for individual steps is to put date +'%F %T' to the end of each step.
RUN set -x && apt-get update && date +'%F %T'
RUN apt-get install -y vim && date +'Time: %F %T'
Output:
Get:1 http://security.debian.org stretch/updates InRelease [63.0 kB]
...
Time: 2018-03-08 00:42:41
In Bash, you could use echo $SECONDS which gives time since the Bash session start; or time ( ... ) (a subshell), but the Docker build environment runs in sh, not bash.
