How to measure Docker build steps duration?

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.

Answers


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


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.


Need Your Help

Catching multiple exceptions at once in Scala

exception scala exception-handling pattern-matching try-catch

How to catch multiple exceptions at once in Scala? Is there a better way than in C#: Catch multiple exceptions at once?