44

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.

1
  • 2
    I would expand this question to having timing of each RUN command. Commented Mar 8, 2018 at 0:35

7 Answers 7

63

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
4
  • 3
    This post was so useful, I can't believe you havn't been given more votes up.. thanks for this
    – Cheyne
    Commented Sep 20, 2018 at 1:47
  • As of 14th nov. 2018, there is docker-compose isn't support cf. github.com/moby/buildkit/issues/685 Commented Nov 14, 2018 at 17:10
  • Adding this variable seems to keep me from caching layers (forces me to download an 800-MB Spacy model every time).
    – Noumenon
    Commented Feb 19, 2022 at 16:23
  • What variable? It's been 3.5 years, buildkit is the default in current installs, so no need to set a variable.
    – BMitch
    Commented Feb 19, 2022 at 19:48
62

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

3
  • 2
    this is amazing
    – chaixdev
    Commented Oct 17, 2019 at 22:11
  • 2
    Add --line-buffered to the grep command here, otherwise the output is not buffered and all of the date outputs are the same time Commented Jul 19, 2021 at 14:03
  • docker build . | grep "^Step" | while read line ; do echo "$(date +%s)| $line"; done; In this method, is docker build executed for full file and then output is progrcessed by grep OR line by line, sends output to grep. OR Each line (line by line, i mean) is executed and output of line is processed by grep?
    – Datha
    Commented Dec 12, 2022 at 9:35
22

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
4

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.

1
  • Thanks @tlo, I've been using time as a quick workaround for now, but would love to be able to get more granularity on the individual steps. Especially so we can know when certain steps were skipped because of a cached layer. Commented Sep 13, 2017 at 14:55
2

Many non native solutions here!

Correct docker-native solution

As of November 2021, the correct native solution is to use the buildx. It is not experimental anymore. As per docs

Using buildx as a docker CLI plugin requires using Docker 19.03 or newer. A limited set of functionality works with older versions of Docker when invoking the binary directly.

Install it using the following command. [ref]

docker buildx install

From here on, you should be getting the new buildx cli interface.

If you are using recent version of docker desktop, you might already using buildx, I guess.

Image source: https://frightanic.com/computers/docker-buildx-the-best-thing-since-sliced-bread/

Hope this helped.

1
  • When using gitlab-ci, the timestamps seem to be missing - is there anything specific required to show them in non-interactive shells?
    – Vojtěch
    Commented Dec 20, 2021 at 21:15
1

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.

0

You can use also docker buildx to find time taken for each layers during building a docker image. Buildx builds using the BuildKit engine and does not require DOCKER_BUILDKIT=1 environment variable to start the builds.

docker buildx docker build --tag "ubuntu" -f Dockerfile

Here ubuntu is the tag and -f path to the Dockerfile

Link to the doc docker buildx

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.