snappy update takes very long (infinite loop?)

Bug #1414009 reported by Martin Pitt on 2015-01-23
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Snappy
Undecided
Unassigned

Bug Description

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) wrote :

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) wrote :

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.

Changed in snappy-ubuntu:
status: New → Incomplete
status: Incomplete → Fix Released
Michael Terry (mterry) on 2015-05-18
affects: snappy-ubuntu → snappy
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.