How to measure Docker build steps duration?

Question

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.

Answer 1

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 

Answer 2

Time whole build

time docker build . 

Time steps of build

docker build . | while read line ; do echo "$(date)| $line"; done; 

Output

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; 

Output

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 *** 

JSON output

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 "]" ) 

Output

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