Container delta sizes very large despite all large layers using cache.

Product support balenaOS
1

Hi,

Recently I’ve noticed our build is generating very big deltas even when all of the significant steps are cached. For example, in my most recently build I changed something in one service (nautilus) and the container build for a different service (nemo) resulted in a 35 MB delta size.

The nemo build used previously cached data for all of the layers that contain actual content:

...
[nemo]         Step 6/9 : RUN pip install --user -r logunitas/requirements-s3-uploader.txt
[nemo]         Using cache
[nemo]          ---> b44d05c15af6
[nemo]         Step 7/9 : COPY version.txt ./nemo/
[nemo]          ---> ea72cbb480fb
[nemo]         Step 8/9 : WORKDIR /home/point_one/nemo
[nemo]          ---> Running in 9f43b598a148
[nemo]         Removing intermediate container 9f43b598a148
[nemo]          ---> 9ed664c1bbfb
[nemo]         Step 9/9 : CMD ["python3", "-m", "nautilus.nemo", "--nemo-host=0.0.0.0", "balena"]
[nemo]          ---> Running in 1e3a41219532
[nemo]         Removing intermediate container 1e3a41219532
[nemo]          ---> df3e2605c019
[nemo]         Successfully built df3e2605c019
...
[Info]         Release: 191c3b0d45300662c654cb5f545dad01 (id: 1517226)
[Info]         ┌─────────────┬────────────┬────────────┬────────────┐
[Info]         │ Service     │ Image Size │ Delta Size │ Build Time │
[Info]         ├─────────────┼────────────┼────────────┼────────────┤
...
[Info]         │ nemo        │ 261.13 MB  │ 34.72 MB   │ 12 seconds │

Note that updating either service updates a very small version.txt file, which is copied into each container as one of the last steps in the Dockerfile, so it shouldn’t invalidate the previous steps with the actual code.

The only steps that were actually executed for nemo were COPY of single version.txt text file (25 B), WORKDIR, and CMD. I would have expected the delta for this update to nemo to be very small.

Any thoughts?

Cheers,

Adam

4

Hi Adam, that is very strange. I would also expect the delta to be a few KBs if that if you are just changing a txt file. Perhaps the calculation on our servers is somehow off. Let me see if I can reproduce this in a simple test my side.

5

Likely related, I’m also seeing very long “generating image deltas” times. I just made a change to the final CMD step in the nautilus Dockerfile and it correctly used the cache for all but the last step. It’s been generating deltas now for at least 2 or 3 minutes maybe, and it’s printed “still working…” a couple times (not sure what the timeout is on that).

6

The “still working…” log is just a 60 second prompt if the builder is doing something but it hasn’t received any logs from that process. Let me try recreate this my side and get back to you.

7

Ok sounds good. I’ll keep watching my entertaining “still working” print TV show :slight_smile:

8

Hey Adam, I have been trying to reproduce this on my side but haven’t be able to yet. If you look at my build logs below, a simple file copy as the last instruction before the CMD results in only a kb or so of data as expected.

shaunmulligan@Shauns-MacBook-Pro test-bluealsa % balena push release-tester
[Info]     Starting build for release-tester, user shaun_projects
[Info]     Dashboard link: https://dashboard.balena-cloud.com/apps/1715914/devices
[Info]     Building on arm03
[Info]     Pulling previous images for caching purposes...
[Success]  Successfully pulled cache images
[debian]   Step 1/4 : FROM balenalib/raspberrypi3-debian:latest
[debian]    ---> e0f8b96d7af7
[debian]   Step 2/4 : RUN install_packages bluealsa
[debian]   Using cache
[debian]    ---> af5bb531054d
[debian]   Step 3/4 : COPY simple-file.txt simple-file.txt
[debian]    ---> 0fa7ff79cfd3
[debian]   Step 4/4 : CMD [ "balena-idle" ]
[debian]    ---> Running in 7b9f22eda93b
[debian]   Removing intermediate container 7b9f22eda93b
[debian]    ---> e376e688120e
[debian]   Successfully built e376e688120e
[Info]     Generating image deltas from release ad31bf405e8942cf66e8cecd7b32551d (id: 1517347)
[Success]  Successfully generated image deltas
[Info]     Uploading images
[Success]  Successfully uploaded images
[Info]     Built on arm03
[Success]  Release successfully created!
[Info]     Release: 15d87a8cc0771997794037589919e36b (id: 1517350)
[Info]     ┌─────────┬────────────┬────────────┬────────────┐
[Info]     │ Service │ Image Size │ Delta Size │ Build Time │
[Info]     ├─────────┼────────────┼────────────┼────────────┤
[Info]     │ debian  │ 166.74 MB  │ 1.03 KB    │ 4 seconds  │
[Info]     └─────────┴────────────┴────────────┴────────────┘
[Info]     Build finished in 55 seconds
			    \
			     \
			      \\
			       \\
			        >\/7
			    _.-(6'  \
			   (=___._/` \
			        )  \ |
			       /   / |
			      /    > /
			     j    < _\
			 _.-' :      ``.
			 \ r=._\        `.
			<`\\_  \         .`-.
			 \ r-7  `-. ._  ' .  `\
			  \`,      `-.`7  7)   )
			   \/         \|  \'  / `-._
			              ||    .'
			               \\  (
			                >\  >
			            ,.-' >.'
			           <.'_.''
			             <'

There must be something else going on, can you perhaps share more of your dockerfile or perhaps a repo where you can reliably reproduce this?

10

Sure, this is the dockerfile for the nemo container:

FROM pointonenav/atlas-nemo-base:latest

# Install the application.
WORKDIR /home/point_one
COPY nemo_pkg.tar.gz s3_uploader_pkg.tar.gz ./
RUN tar xzf nemo_pkg.tar.gz \
    && tar xzf s3_uploader_pkg.tar.gz \
    && rm -f nemo_pkg.tar.gz s3_uploader_pkg.tar.gz

# Install Python requirements.
#
# Note that the requirements should already be present in the base Docker image.
# We do this simply as a precaution in case the base image is out of date.
RUN pip install --user -r nemo/requirements.txt
RUN pip install --user -r logging/requirements-s3-uploader.txt

# Copy over the version file. We do this last so a change to one container
# doesn't invalidate the build steps of another container.
COPY version.txt ./nemo/

# Run our application on container startup.
WORKDIR /home/point_one/nemo
CMD ["python3", "-m", "nautilus.nemo", "--nemo-host=0.0.0.0", "balena"]

where the 2 tar files have different sets of Python code. The base image is a public image on dockerhub. The docker-compose file looks as follows:

version: '2.1'
networks: {}
volumes:
  resin-data: {}
services:
  nautilus:
    build: ./nautilus
    privileged: true
    # Note: Disabling 'always' restart until Nautilus application handles
    # start/stop behavior internally.
    restart: on-failure
    volumes:
      - 'resin-data:/data'
    ports:
      - "30200:30200"
  nemo:
    build: ./nemo
    privileged: true
    restart: always
    volumes:
      - 'resin-data:/data'
    ports:
      - "8888:8888"
    labels:
      io.balena.features.supervisor-api: '1'
      io.balena.features.balena-api: '1'
  ui-bridge:
    build: ./nautilus
    privileged: true
    restart: always
    ports:
      - "3000:3000"
    command: ["/home/point_one/bootstrap.sh", "--force-start",
              "./bin/ui_websocket_bridge",
              "--ui-multicast-port=30108",
              "--ws-port=3000"]
  ntrip-proxy:
    build: ./nautilus
    privileged: true
    restart: always
    ports:
      - "2101:2101"
    command: ["/home/point_one/bootstrap.sh", "--force-start",
              "./bin/ntrip_proxy",
              "--polaris-api-key=${P1_POLARIS_API_KEY}",
              "--polaris-unique-id=${P1_DEVICE_ID:-${BALENA_DEVICE_NAME_AT_INIT}}-ntrip-proxy",
              "0.0.0.0", "2101", "point_one/applications/ntrip_proxy"]
  eos:
    build: ./eos
    restart: always
    volumes:
      - 'resin-data:/data'
    ports:
      - "80:80"

Note that we have 3 services using the same Dockerfile but with different commands (nautilus uses CMD in the file, ui-bridge and ntrip-proxy use command here). They’re running 3 different binaries out of the same tar file, but otherwise use the exact same stuff so we did that to share the docker layers and disk space. Not sure if that’s confusing things on the build side at all, but it has been working just fine until this delta size issue started happening ~yesterday I think.

My build where I only changed the final CMD in the nautilus service finally finished and as expected, it had similarly large deltas (77 MB for the 3 nautilus-based containers, 35 MB for nemo even though I didn’t change nemo at all).

When I get some free time I can try to put together a more extensive test case to replicate the issue, but in the meantime hopefully this info helps?

11

Thanks for all of that. The last piece about all using the same Dockerfile is an interesting anecdote and perhaps somehow that is causing issues let me add that to my test project and see if it makes things weird :slight_smile:

12

Hey Adam, unfortunately I am a bit stumped here. I used your dockerfile (stubbed in some tar files and commented out the pip installs) and ran this in a compose with 3 other services (all of which use the same dockerfile, a simple debian one) and still could not cause it to produce incorrect delta sizes. There must be something else at play here that we are missing, perhaps if you have time you could put together a minimal project that causes this behaviour. I would love to get to the bottom of it.

14

Huh strange. Ok, I’ll see if I can find a way to replicate it somehow when I get some free time. Definitely want to get to the bottom of it too.

16

@shaunmulligan I haven’t had a chance to build a dummy case yet, but I’ll try to get to that later if I can carve out some time.

In the meantime though, I just ran a test. I did a build on our existing application and it took 40 minutes, 47 seconds. Then I made a brand new application and ran the same build for that. Total time: 6 minutes, 28 seconds.

Could something be messed up in the build caching system for our Atlas application? Is there a way to flush it somewhere on the back end?

One thing I thought of is I updated both of our base images on dockerhub 2 days ago, about the same time that this all started happening. Not sure why that would cause an issue, but maybe that did something?

18

Ever since I ran that test with the other application my builds (on the normal application) are no longer crazy slow. The deltas still seem to be very large for small changes, but at least they’re not taking 40 minutes anymore… I don’t know what building the same containers for another application would have changed?

Still need to track down the delta size issue one way or another.

21

Hi there – thanks for the additional information on the problem you’re having. We’re still digging into this, and hope to have more info to share with you before long. Thanks for your patience as we get to the bottom of this.

[Edit: forgot to add this to my original response] One thing that will help a lot with this is a test case we can use to duplicate this. I see that you were working on that earlier; do you have anything to share with us yet?

All the best,
Hugh

23

Hey Hugh,

I haven’t had time to pull together a test case yet. I’m hoping to do so soon, but in the meantime it seems like it’s mostly back to normal all of the sudden so I’m not sure if I’ll be able to replicate it very easily in the first place unfortunately.

Building for a different application and then going back to the normal application mostly resolved the super long build times. Most builds since then have been around 4-6 minutes, which has been somewhat typical historically, though some as long as maybe 10-12 minutes, which is a bit longer than expected and than we’d like ideally. Still nothing near the 40+ minutes I was seeing earlier.

It seems much of the time is spent in the “generating image deltas” step after the containers have been built. For example:

[Info]         Generating image deltas from release 8e75b83f1ac8300222555928e66a3528 (id: 1519144)
[Info]         Still Working...
[Info]         Still Working...
[Success]      Successfully generated image deltas
[Info]         Uploading images
[Success]      Successfully uploaded images
[Info]         Built on arm03
[Success]      Release successfully created!
[Info]         Release: 807513d16d11c6d529c22ec15f6fb822 (id: 1520140)
[Info]         ┌─────────────┬────────────┬────────────┬───────────────────────┐
[Info]         │ Service     │ Image Size │ Delta Size │ Build Time            │
[Info]         ├─────────────┼────────────┼────────────┼───────────────────────┤
[Info]         │ nautilus    │ 309.82 MB  │ 49.46 MB   │ 2 minutes, 47 seconds │
[Info]         ├─────────────┼────────────┼────────────┼───────────────────────┤
[Info]         │ nemo        │ 261.13 MB  │ 1.53 KB    │ 43 seconds            │
[Info]         ├─────────────┼────────────┼────────────┼───────────────────────┤
[Info]         │ ui-bridge   │ 309.82 MB  │ 49.46 MB   │ 2 minutes, 54 seconds │
[Info]         ├─────────────┼────────────┼────────────┼───────────────────────┤
[Info]         │ ntrip-proxy │ 309.82 MB  │ 49.46 MB   │ 2 minutes, 53 seconds │
[Info]         ├─────────────┼────────────┼────────────┼───────────────────────┤
[Info]         │ eos         │ 44.76 MB   │ 5.58 MB    │ 2 seconds             │
[Info]         └─────────────┴────────────┴────────────┴───────────────────────┘
[Info]         Build finished in 9 minutes, 11 seconds

This isn’t entirely crazy since the deltas are somewhat large (the tar file in the Nautilus container is pretty big), but still a bit surprising to me that it would take 5 or 6 minutes to generate even a 50 MB delta.

It also seems like the small delta sizes are working again today. You can see above that Nemo was only 1 KB instead of 35 MB, and Nautilus was 50 MB instead of the 77 MB it was consistently before. I’m not sure what changed there. I was still seeing large deltas after changing applications away and back, but suddenly it’s back to mostly normal.

When I get a chance I’ll try to put together a test repo if I can replicate the issue at all. Meanwhile, I hope there’s something in some of the server logs somewhere that might be helpful in some way.

Cheers,

Adam

24

One thing I thought of is I updated both of our base images on dockerhub 2 days ago, about the same time that this all started happening. Not sure why that would cause an issue, but maybe that did something?

I think this would bust the cache, and the potential delta here might be quite large. Without knowing the changes to the base layer it’s impossible to predict if this is the cause, but if the issue has resolved now then this is a likely culprit. I would advise that you create tags for your base-layer releases and then you can get more consistent results etc.

26

Ah interesting. The update to the Nemo base image basically just added a few Python packages, which themselves shouldn’t be that big, but the layer containing the pip install had to recompile everything since it was invalidated.

The Nautilus update added an echo to enable core dumps. That echo would have invalidated its pip install layer. It only installs awscli (boto3), but I just checked and shockingly that package is 20 MB. No clue why…

We can version the base images if/when we update them in the future. Hopefully that will help. I assumed, even with the same version number (latest), that Docker images would be hashed in some way and cached based on that, so I’m a little surprised that the update didn’t flush the cache even with the same version number. Does it make sense that building for a different application flushed the cache? Or did it somehow timeout?

A little while back we had a discussion with Jordan on the Balena team about the possibility of building and hosting Docker base images using Balena’s build infrastructure. Hosting the images on dockerhub isn’t an issue for us, but being able to cross-compile them on the native aarch64 machines instead in qemu would be amazing. Right now, the Nemo base image takes around 45 minutes to build locally because of a single Python package: pynacl takes absolutely forever to compile under qemu. Not sure what it would take to leverage the build servers to build a base Docker image rather than a bundled release, but it would sure be nice. What do you think?

27

An interesting idea; I can’t think of any way to do this with the tooling available. I will ask internally to see if this is something we would like to offer, or even if we could.

Does it make sense that building for a different application flushed the cache? Or did it somehow timeout?

Once you changed the base image for the service, the cache would have been invalidated on our builders.

30

Changing the base image was actually when the problems started, which is why I’m surprised if the cache really was invalidated at that point. It would have made sense for maybe the first build after that to be slow, but I did a number of them after that with no speed up.

It seems to have been resolved when I built the same set of containers/docker-compose for a new Balena application, and then built it again for our actual application. Not clear why that would have any effect.

31

Weird behaviour indeed. Please get back to us if you notice something similar.

33

Hey guys,

Just a quick update. I haven’t been able to replicate the large delta size issue since it resolved itself on Thursday, but I have been seeing the long build times intermittently. For example, in the last 2 days most builds took ~2.5-4 minutes or so, but one took almost 30 minutes.

I went back in the release history for application 1623312 and looked at the builds that took a particularly long time. Assuming I didn’t miss any, it looks like all of the slow builds took place on arm03. All of the arm01 builds seem normal speed, and some (most?) of the arm03 builds also seem normal speed. Could something be going on with that machine?

Feel free to have a look if you want.

Cheers,

Adam