snappy update takes very long (infinite loop?)

[Martin Pitt]

I was looking at bug 1411112 this morning and tried to reproduce it. This involves installing image 211, and updating it to the latest one:

sudo ubuntu-device-flash --revision 211 --verbose core --output=/tmp/snappy211.img --developer-mode --channel=ubuntu-core/devel-proposed
kvm -m 2048 -snapshot -drive file=/tmp/snappy211.img,if=virtio -redir tcp:8022::22
ssh -o UserKnownHostsFile=/dev/null -p 8022 ubuntu@localhost

Then in snappy, do "sudo snappy update". This downloads the 151 image, and then is spinning "Applying [/]". I've waited for 30 minutes, and it's still not done. My /tmp is a tmpfs, so there should be pretty much zero I/O wait, fsync delays or otherwise.

I see three processes

root 937 0.1 0.6 56868 14124 ? S 13:51 0:00 /usr/bin/python3 /usr/bin/ubuntu-core-upgrade /writable/cache/ubuntu_command
root 938 0.0 0.5 56868 11168 ? S 13:51 0:00 /usr/bin/python3 /usr/bin/ubuntu-core-upgrade /writable/cache/ubuntu_command
root 939 95.5 1.8 148088 37428 ? R 13:51 0:45 /usr/bin/python3 /usr/bin/ubuntu-core-upgrade /writable/cache/ubuntu_command

937 just waits on 938, 938 just waits on 939, so these are harmless. 939 is taking 100% CPU all the time (for the full half an hour until I aborted it).

[Martin Pitt (pitti)]

stracing process 939 shows a ton of read()s like

read(6, "\365\261,\303$\177\311P\223i\263\23\214@=Q\304\343\315\22Y{-\344C8\217\357Q\271\327'"..., 8192) = 8192

fd 6 is (/proc/939/fd/6)

lr-x------ 1 root root 64 Jan 23 13:55 6 -> /writable/cache/ubuntu-167a812c3c894b537fa348f36452d288e03bb0670fd358234e261bd41aaa00b3.tar.xz

which is

-rw-r--r-- 1 root root 65179348 Jan 23 13:51 /writable/cache/ubuntu-167a812c3c894b537fa348f36452d288e03bb0670fd358234e261bd41aaa00b3.tar.xz

But it's not only read() calls, after some time I also see stats, chowns etc. of different files in the file system.

I wonder if it's just doing something exceptionally expensive here? Like trying to extract the files from the tarball in non-linear order, so that for each file it has to decompress the whole tarball, seek, and extract a file? But then again I don't see any seeks or close/reopen of fd 6. At this point it's probably better to look at what the upgrader does from a higher level than strace.

[James Hunt (jamesodhunt)]

Hi Martin,

Thanks for reporting. Now that I see you're using an old revision the answer is clear; this is indeed the python tarfile bug (http://bugs.python.org/issue23228).

We worked around this issue in ubuntu-core-upgrader package r52 (aka ubuntu-core-upgrader version 0.6~ppa18). So, if you have to use system-image r211, you'll probably want to rebuild lp:~snappy-dev/+junk/ubuntu-core-upgrader and install that.