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

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

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

Answer 3

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 4

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.

Answer 5

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.