Buildah: COPY command for ~75M takes several minutes

[carlpett]

Description
Building a container with a build context of ~75M and around 3700 files takes several minutes to do a COPY . /target-dir. Colleagues using docker have a build time of seconds.

Checking top or iotop during the build shows very low utilization.

Steps to reproduce the issue:

1. time podman build .

Describe the results you received:
Slow build

Describe the results you expected:
Fast build

Output of rpm -q buildah or apt list buildah:
(Giving podman instead, since I don't have buildah installed itself)

$ rpm -q podman
podman-1.4.4-1.fc30.x86_64

Output of podman version if reporting a podman build issue:

$ podman version
Version:            1.4.5-dev
RemoteAPI Version:  1
Go Version:         go1.12.6
OS/Arch:            linux/amd64

First tested with 1.4.2, updated to see if that helped.
Also note: This is pretty weird packaging? The rpm says 1.4.4, I get something tagged 1.4.5-dev?

Output of cat /etc/*release:

Fedora release 30 (Thirty)
NAME=Fedora
VERSION="30 (Thirty)"
ID=fedora
VERSION_ID=30
VERSION_CODENAME=""
PLATFORM_ID="platform:f30"
PRETTY_NAME="Fedora 30 (Thirty)"
ANSI_COLOR="0;34"
LOGO=fedora-logo-icon
CPE_NAME="cpe:/o:fedoraproject:fedora:30"
HOME_URL="https://fedoraproject.org/"
DOCUMENTATION_URL="https://docs.fedoraproject.org/en-US/fedora/f30/system-administrators-guide/"
SUPPORT_URL="https://fedoraproject.org/wiki/Communicating_and_getting_help"
BUG_REPORT_URL="https://bugzilla.redhat.com/"
REDHAT_BUGZILLA_PRODUCT="Fedora"
REDHAT_BUGZILLA_PRODUCT_VERSION=30
REDHAT_SUPPORT_PRODUCT="Fedora"
REDHAT_SUPPORT_PRODUCT_VERSION=30
PRIVACY_POLICY_URL="https://fedoraproject.org/wiki/Legal:PrivacyPolicy"
Fedora release 30 (Thirty)
Fedora release 30 (Thirty)

Output of uname -a:

Linux - 5.0.16-300.fc30.x86_64 #1 SMP Tue May 14 19:33:09 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Output of cat /etc/containers/storage.conf:

$ cat /etc/containers/storage.conf | grep -Pv '#|^$'
[storage]
driver = "overlay"
runroot = "/var/run/containers/storage"
graphroot = "/var/lib/containers/storage"
[storage.options]
additionalimagestores = [
]
size = ""
override_kernel_check = "true"
mountopt = "nodev"
[storage.options.thinpool]
ostree_repo = ""
skip_mount_home = "false"

[rhatdan]

Any chance you could make the context directory and Dockerfile available to us?

[rhatdan]

Could you see if buildah bud . works any better.

[carlpett]

The directory I was building from contains a bunch of stuff I cannot share, but I just tried from this repo instead, and with a minimal Dockerfile:

FROM scratch
COPY . /tmp

Podman:

$ time podman build -f Dockerfile.perftest .
STEP 1: FROM scratch
STEP 2: COPY . /tmp
STEP 3: COMMIT
2661483544bb5f37ead5636af9aa40cae7619920b885ff4ceb43a96bcce261d8

real    2m35.724s
user    1m31.268s
sys     1m14.133s

Buildah (latest rpm in Fedora 30, version 1.9.0):

$ time buildah bud -f Dockerfile.perftest .
STEP 1: FROM scratch
STEP 2: COPY . /tmp
STEP 3: COMMIT
Getting image source signatures
Copying blob 8abef45192d8 done
Copying config 1f10fc9eea done
Writing manifest to image destination
Storing signatures
1f10fc9eea009bc7381aaa0a101f8824a3e4f5d399d5e75e98d3dfa654512756

real    2m20.140s
user    2m7.612s
sys     0m55.184s

[carlpett]

Full buildah version:

$ buildah version
Version:         1.9.0
Go Version:      go1.12.5
Image Spec:      1.0.0
Runtime Spec:    1.0.0
CNI Spec:        0.4.0
libcni Version:
Git Commit:
Built:           Thu Jan  1 01:00:00 1970
OS/Arch:         linux/amd64

_(Build timestamp seems broken in the rpm package?)_

[rhatdan]

Could you also attach the Docker time.

[carlpett]

$ time docker build -f Dockerfile.perftest .
Sending build context to Docker daemon  72.8 MB
Step 1/2 : FROM scratch
 --->
Step 2/2 : COPY . /tmp
 ---> b9cd51a594f6
Removing intermediate container 96191a5efd1d
Successfully built b9cd51a594f6

real    0m2.211s
user    0m0.190s
sys     0m0.143s

Docker version:

$ docker version
Client:
 Version:         1.13.1
 API version:     1.26
 Package version: docker-1.13.1-67.git1185cfd.fc30.x86_64
 Go version:      go1.12.2
 Git commit:      1185cfd/1.13.1
 Built:           Mon Apr 22 17:46:35 2019
 OS/Arch:         linux/amd64

Server:
 Version:         1.13.1
 API version:     1.26 (minimum version 1.12)
 Package version: docker-1.13.1-67.git1185cfd.fc30.x86_64
 Go version:      go1.12.2
 Git commit:      1185cfd/1.13.1
 Built:           Mon Apr 22 17:46:35 2019
 OS/Arch:         linux/amd64
 Experimental:    false

[rhatdan]

That does not seem to be much difference in Real Time. The reason the User Time is different is that docker daemon is doing the real work. The client is only copying the files.

[carlpett]

It is a differerence of ~2.5 minutes?
Podman: real 2m35.724s
Buildah: real 2m20.140s
Docker: real 0m2.211s

[rhatdan]

Oops I misread.

[carlpett]

No worries :) Anything else I can check? I'm in Europe, so about to shut off for the night soon.

[rhatdan]

Try checking running as root, I think this could be fuse-overlay running slow.
In the libpod github directory on my machine I see:

# time buildah bud -f Dockerfile.perftest .
STEP 1: FROM scratch
STEP 2: COPY . /tmp
STEP 3: COMMIT
Getting image source signatures
Copying blob 97b76cab4843 done
Copying config 58c93701e2 done
Writing manifest to image destination
Storing signatures
--> 58c93701e2aa11ce4634f6407a7810e1e613b86a48d4310cea22368b7487f171

real    0m8.604s
user    0m7.900s
sys 0m2.453s

But podman build is running like crap.
@giuseppe WDYT?

[rhatdan]

@nalind PTAL

[rhatdan]

@QiWang19 PTAL

[michaelgugino]

This started impacting me this afternoon using buildah. Builds were working quickly as normal this morning, then all of a sudden, builds are taking like 10+ minutes. Most time spent on copying.

buildah-1.9.0-1.git00eb895.fc30.x86_64

Dockerfile: https://github.com/openshift/cluster-api-provider-aws/blob/master/Dockerfile.rhel7

I did not upgrade buildah between normal-ness and slowness, it just started happening. I tried rebooting, no improvement.

[rhatdan]

Did you update software? Look at /etc/containers/storage.conf metacopyup line, comment this out and see if it fixes the issue.

[carlpett]

Sorry, still slow as root:

# time buildah bud -f Dockerfile.perftest .
STEP 1: FROM scratch
STEP 2: COPY . /tmp
STEP 3: COMMIT
Getting image source signatures
Copying blob 37c1b822c776 done
Copying config f6e666d9e6 done
Writing manifest to image destination
Storing signatures
f6e666d9e69a17f61ef454dc1ea744def3914ddc4be89078741fdeece5cbbcd8

real    2m14.534s
user    2m7.434s
sys     0m53.182s

From buildah info:

    "store": {
        "ContainerStore": {
            "number": 2
        },
        "GraphDriverName": "overlay",
        "GraphOptions": [
            "overlay.mountopt=nodev"
        ],
        "GraphRoot": "/var/lib/containers/storage",
        "GraphStatus": {
            "Backing Filesystem": "extfs",
            "Native Overlay Diff": "true",
            "Supports d_type": "true",
            "Using metacopy": "false"
        },
        "ImageStore": {
            "number": 1
        },
        "RunRoot": "/var/run/containers/storage"
    }

[michaelgugino]

So, I tried downgrading to buildah-1.7-18.git873f001.fc30.x86_64 and everything works as it did previously (really fast). Tried upgrading back to the version I listed earlier, epic slowness returns. This is strange because I did nothing on my end.

The only thing I can think of is that my build image changed between this morning and this afternoon (I'm a consumer), and there's something about that image the latest version of buildah doesn't like.

[rhatdan]

Weird, I am seeing it slow as podman build, but buildah bud is fairly quick.
Bottom line is we need to figure out why it is slow. It is basically doing a tar/untar, which should be as fast if not faster then Docker.

[michaelgugino]

Did you update software? Look at /etc/containers/storage.conf metacopyup line, comment this out and see if it fixes the issue.

@rhatdan tried this, didn't help.

[rhatdan]

I know there has been a lot of work around making sure we are not being attacked by symlink attacks, I wonder if this is slowing everything down. Basically it is doing a check on symlink on each file. I bet that is the problem.

[rhatdan]

Newer versions of Docker might have similar problems.

[rhatdan]

There is a CVE where a hostile container process could be changing the paths that we are copying to, and so we check before placing any file that their is not a symbolic link outside of the container rootfs. So if you are placing thousands of files, this could cause issues.

[rhatdan]

One potential fix for this would be to not do the check if their is no container running.

[carlpett]

Need to pop away now, I tried generating a perf flamegraph to see if anything was obvious, but I'm too tired... Uploading it here in case it helps anyone (zipped, since Github doesn't allow svgs).
flamegraph.svg.zip

[giuseppe]

patch here: https://github.com/containers/buildah/pull/1715

[michaelgugino]

patch here: #1715

This fixes it for me on fedora.

[carlpett]

@giuseppe @rhatdan Could this have regressed? I noted unexpectedly long build times again today, 5 seconds for COPYing 480 kB. I recently upgraded to podman 1.7.0. Tried with buildah bud too (1.12.0), same timings there.

Unfortunately, I can no longer easily make a 1:1 comparison with Docker since I'm on Fedora 31 (cgroups v2 support still seem to be a future addition to Docker), but I did a (somewhat synthetic) test by starting a F30 live-cd VM and installing podman 1.7.0 and 1.6.1 (from some build cache) and docker 1.13 (which seems to be what was shipped in F30?).
Using the same scratch+copy image as previously, with a directory containing a copy of /usr/include (11M, 1361 files), I get these timings:
time docker build --no-cache . => 0.72s real time
time podman-1.6 build --no-cache . => 1.4s real time
time podman-1.7 build --no-cache . => 1m4s real time

[TomSweeneyRedHat]

I know we'd some speed issues concerning .dockerignore in Podman 1.7/Buildah 1.12.0 that were fixed in Buildah 1.13.0 and 1.13.1. I wonder if this is what you're hitting @carlpett ?

[carlpett]

@TomSweeneyRedHat I do not have a .dockerignore file, if that was the question?
As I recall this issue was originally found to be related to .dockerignore too (since it was marked as fixed by #1715), so that would be a regression if it has crept back, I suppose?

[TomSweeneyRedHat]

@carlpett thanks for the info on the .dockerignore file. It might be the regression I know that @nalind has been working away on a number of performance improvements over the past few releases.

[nforro]

I seem to be hitting this as well on Fedora 30, no .dockerignore, COPYing 41MiB:

podman 1.7.0:

real    3m31.306s
user    3m8.213s
sys     2m2.788s

buildah 1.12.0:

real    2m46.855s
user    2m5.271s
sys     1m30.152s

docker 19.03.6:

real    0m5.681s
user    0m0.162s
sys     0m0.134s

[carlpett]

@TomSweeneyRedHat Ok! Should this issue be reopened, or is there another one I can track?
Relatedly, are there plans for a performance regression test?

[runlevel5]

I think this issue should be re-opened. I could confirm that the issue is not addressed in podman 1.8.0 and buildah 1.14.0

[TomSweeneyRedHat]

Given the above two comments, I'm going to reopen.
@carlpett, nothing in the pipeline at the moment for performance regression tests at this time. Sounds like a great idea and we'd be very open to having someone contribute them.

FYI: @nalind

[xedrac]

I'd just like to chime in and mention this has been a pain point for me too. I have a large directory that I need to COPY in, and it takes about 2 hours in podman. In docker, it takes 5-10 minutes.

[TomSweeneyRedHat]

FYI @nalind

[Madko]

Same here, a couple of hours to build one nodejs image.

$ podman version
Version:            1.8.2
RemoteAPI Version:  1
Go Version:         go1.14
OS/Arch:            linux/amd64
$ buildah version
Version:         1.14.0-dev
Go Version:      go1.14beta1
Image Spec:      1.0.1-dev
Runtime Spec:    1.0.1-dev
CNI Spec:        0.4.0
libcni Version:  
image Version:   5.1.0
Git Commit:      
Built:           Thu Jan  1 01:00:00 1970
OS/Arch:         linux/amd64

ps: This buildah is old ! ;)

[rhatdan]

@nalind continues to work on this, but I am wondering if a hack of something like

buildah bud -v ./:/tmp/context ./
And you add a RUN command that copies your content off of /tmp/context into the container.

Hacky but I think this would work, and should be fast.

[xedrac]

Would this still honor .dockerignore paths?

[rhatdan]

Nope you would have to work around that yourself.

[abitrolly]

Clean test that podman is slow using podman repo itself. podman 1.9.0, Fedora 31.

$ cd /tmp
$ git clone https://github.com/containers/libpod
$ cd libpod
$ time -p podman build -t gate -f contrib/gate/Dockerfile .
...
real 878.05
user 409.52
sys 261.13

Or without -p.

real    11m22.347s
user    6m35.289s
sys 4m9.938s

[abitrolly]

buildah 1.14.8 is a little better, but not significantly better.

$ time buildah bud -t gate -f contrib/gate/Dockerfile .
...
real    9m6.945s
user    5m37.779s
sys 3m22.127s

[abitrolly]

@nalind continues to work on this, but I am wondering if a hack of something like

@rhatdan the hack works. buldah with hack doesn't spend any extra time on replaced COPY operation.

-COPY / $GOSRC
+RUN mkdir -p $GOSRC && cp -r /tmp/context/* $GOSRC

$ time buildah bud -v "$(pwd)":/tmp/context:Z -t gate -f contrib/gate/Dockerfile ./
...
real    7m7.329s
user    3m8.479s
sys 0m45.823s

[frederik-b]

I apparently have the same issue (using podman, not buildah) can I fix this somehow?
I'm just trying to get a project running that some colleagues of mine built around a year ago and
STEP 17: COPY ${THEME_PATH} ./${THEME_PATH}
is taking forever
it does use a .dockerignore file to exclude node_modules and 2 other similar folders

can I somehow get this working in a reasonable time?

[TomSweeneyRedHat]

ping @nalind

[nalind]

At the moment, the key part of any workaround is avoiding having a .dockerignore file present, since the code path that takes its contents into consideration is slower than the code path that doesn't have to pay attention to .dockerignore.

[apenney]

Just another user affected by this (via the latest okd), was very surprised to have a build take multiple minutes to copy in something that takes seconds locally.

[jamescassell]

to make matters worse, COPY --from=build ... doesn't seem to even be cached, so you waste that time over and over with every iteration.

edit: the reason here might is that the scratch image is created on-the-fly and it does not have the same hash every time it's created, hence copying into a scratch image is a cache miss every time. -- swapping out scratch for myscratch (c=$(buildah from scratch) ; buildah commit $c myscratch) cut my build time in half.

[rhatdan]

This is part of the COPY PRs.

[bulanovk]

Hello, is there any progress on fix?

[nalind]

Changes to address this have landed in the 1.16 release. If you've got a build of that (or the master branch) handy, please give it a try. Thanks!

[rocketraman]

@nalind I'm using buildah 1.16.5, and a COPY of a large file into my container still takes a long time.

$  buildah version
Version:         1.16.5
Go Version:      go1.14.9
Image Spec:      1.0.1-dev
Runtime Spec:    1.0.2-dev
CNI Spec:        0.4.0
libcni Version:  
image Version:   5.5.2
Git Commit:      
Built:           Wed Dec 31 19:00:00 1969
OS/Arch:         linux/amd64

I'm using buildah on Fedora 32 from https://bodhi.fedoraproject.org/updates/FEDORA-2020-b9d82abea9.

[rocketraman]

Even if the COPY of large file is cached, buildah 1.16.5 takes several hours only to finally and simply report --> Using cache .... Quite frustrating...

[rhatdan]

@rocketraman Could you build a quick reproducer?

[rhatdan]

Also could you attach buildah info

[rocketraman]

@rhatdan

@rocketraman Could you build a quick reproducer?

It's pretty much exactly the same reproducer as the OP.

mkdir big
dd if=/dev/urandom of=big/Big_1.sav bs=1024 count=75000

Dockerfile:

FROM debian:buster-slim
COPY big ./big/

$ time buildah bud --layers -f Dockerfile -t foo .
STEP 1: FROM debian:buster-slim
STEP 2: COPY big ./big/
STEP 3: COMMIT foo
--> 592e8924d77
592e8924d77fba15cdc7f90593334d5bffc423ffb5ad5c8f039456ffd04e3c85

________________________________________________________
Executed in   17.55 mins   fish           external 
   usr time    5.20 secs    0.00 micros    5.20 secs 
   sys time    2.51 secs  1122.00 micros    2.51 secs

$ time buildah bud --layers -f Dockerfile -t foo .
STEP 1: FROM debian:buster-slim
STEP 2: COPY big ./big/
--> Using cache 592e8924d77fba15cdc7f90593334d5bffc423ffb5ad5c8f039456ffd04e3c85
STEP 3: COMMIT foo
--> 592e8924d77
592e8924d77fba15cdc7f90593334d5bffc423ffb5ad5c8f039456ffd04e3c85

________________________________________________________
Executed in  740.99 secs   fish           external 
   usr time    2.62 secs    0.00 micros    2.62 secs 
   sys time    1.88 secs  1243.00 micros    1.88 secs

(This is with one 75M file, my actual project has about 10 of these, and literally takes several hours to run the COPY command, even if cached).

Also could you attach buildah info

$ buildah info
{
    "host": {
        "CgroupVersion": "v2",
        "Distribution": {
            "distribution": "fedora",
            "version": "32"
        },
        "MemFree": 11369369600,
        "MemTotal": 67350360064,
        "OCIRuntime": "crun",
        "SwapFree": 5501161472,
        "SwapTotal": 21474832384,
        "arch": "amd64",
        "cpus": 32,
        "hostname": "edison",
        "kernel": "5.8.10-200.fc32.x86_64",
        "os": "linux",
        "rootless": true,
        "uptime": "956h 16m 33.03s (Approximately 39.83 days)"
    },
    "store": {
        "ContainerStore": {
            "number": 201
        },
        "GraphDriverName": "overlay",
        "GraphOptions": [
            "overlay.mount_program=/usr/bin/fuse-overlayfs",
            "overlay.mount_program=/usr/bin/fuse-overlayfs"
        ],
        "GraphRoot": "/home/raman/.local/share/containers/storage",
        "GraphStatus": {
            "Backing Filesystem": "extfs",
            "Native Overlay Diff": "false",
            "Supports d_type": "true",
            "Using metacopy": "false"
        },
        "ImageStore": {
            "number": 193
        },
        "RunRoot": "/run/user/1000/containers"
    }
}

$ uname -a
Linux edison 5.8.10-200.fc32.x86_64 #1 SMP Thu Sep 17 16:48:25 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

$ cat /etc/*release
Fedora release 32 (Thirty Two)
NAME=Fedora
VERSION="32 (Thirty Two)"
ID=fedora
VERSION_ID=32
VERSION_CODENAME=""
PLATFORM_ID="platform:f32"
PRETTY_NAME="Fedora 32 (Thirty Two)"
ANSI_COLOR="0;34"
LOGO=fedora-logo-icon
CPE_NAME="cpe:/o:fedoraproject:fedora:32"
HOME_URL="https://fedoraproject.org/"
DOCUMENTATION_URL="https://docs.fedoraproject.org/en-US/fedora/f32/system-administrators-guide/"
SUPPORT_URL="https://fedoraproject.org/wiki/Communicating_and_getting_help"
BUG_REPORT_URL="https://bugzilla.redhat.com/"
REDHAT_BUGZILLA_PRODUCT="Fedora"
REDHAT_BUGZILLA_PRODUCT_VERSION=32
REDHAT_SUPPORT_PRODUCT="Fedora"
REDHAT_SUPPORT_PRODUCT_VERSION=32
PRIVACY_POLICY_URL="https://fedoraproject.org/wiki/Legal:PrivacyPolicy"
Fedora release 32 (Thirty Two)
Fedora release 32 (Thirty Two)

$ rpm -q buildah
buildah-1.16.5-1.fc32.x86_64

$  buildah version
Version:         1.16.5
Go Version:      go1.14.9
Image Spec:      1.0.1-dev
Runtime Spec:    1.0.2-dev
CNI Spec:        0.4.0
libcni Version:  
image Version:   5.5.2
Git Commit:      
Built:           Wed Dec 31 19:00:00 1969
OS/Arch:         linux/amd64

$ cat /etc/containers/storage.conf | grep -Pv '#|^$'
[storage]
driver = "overlay"
runroot = "/var/run/containers/storage"
graphroot = "/var/lib/containers/storage"
[storage.options]
additionalimagestores = [
]
[storage.options.overlay]
mountopt = "nodev,metacopy=on"
[storage.options.thinpool]

Both /home and /var are LVM volumes on a RAID-10 software array, using LVM caching with an NVMe SSD. I do note that buildah info returns a different graphRoot -- not sure if that's relevant.