console-conf on beaglebone takes unbearable long

[Oliver Grawert]

i did a lot of snappy beaglebone installs today ...

it takes about 5-10 minutes after pressing enter in the serial console until console-conf starts at all.
the network setup is relatively quick then.
setting up the user takes between 12 and 30 minutes then, with the tool sitting at
"Contacting Server..."

note that the slowness of python on single core ARM caused us to switch snappy itself from python to go, it is very likely that the CPU is constantly saturated here, i do not see such behaviour on kvm and also not on multi core arm like the pi2 or pi3 (though it is pretty slow there as well)

[Michael Hudson-Doyle (mwhudson)]

5-10 *minutes*? I timed it on my dragonboard and it was about 5 seconds. I know the beaglebone is slow but it shouldn't be 60x slower than a dragonboard. I'd love to know where the time is going, maybe probing is really slow or something? Is it similarly slow if you run sudo /usr/share/subiquity/console-conf-tui after the board is set up?

I did notice that the create user step was very slow on the dragonboard (about 2 minutes). That's strange because all that console-conf does is run snap create-user, and running that post setup is quite fast (a few seconds).

[Michael Hudson-Doyle (mwhudson)]

Can you pastebin or upload or something the log at /var/log/console-conf/subiquity-debug.log? Might help figuring out which bit is slow at least.

[Oliver Grawert (ogra)]

http://paste.ubuntu.com/23210646/ is /var/log/console-conf/subiquity-debug.log

[Oliver Grawert (ogra)]

running it manually on a completely idling bbb it takes about 30 seconds until i see the UI, watching top at that time the CPU is constantly saturated...
note that there is still a lot processes running in the background during boot up though, where the saturated CPU will be acting a lot slower...

note also that we usually boot with the performance governor and supposedly only switch to ondemand at the end of the boot ... perhaps this step should be blocked by subiquity somehow, so we keep performance up until we are done with thd configuration to make the CPU react a bit snappier.

[Oliver Grawert (ogra)]

also...
(beaglebone)
ogra@bbb:~$ time python3 -v -c "" 2>/dev/null

real 0m1.968s
user 0m1.048s
sys 0m0.368s

vs an x86 machine:
ogra@anubis:~$ time python3 -v -c "" 2>/dev/null

real 0m0.027s
user 0m0.024s
sys 0m0.000s

loading the interpreter alone, without any imports already takes 2sec on the beagle

[Oliver Grawert (ogra)]

here is the output of running:
strace -ff -r -T console-conf --help

http://paste.ubuntu.com/23215333/

[Oliver Grawert (ogra)]

and here is:
sudo strace -ff -r -T /usr/share/subiquity/console-conf-tui

http://paste.ubuntu.com/23215368/

[Martin Pitt (pitti)]

According to that strace, console-conf --help only took 0.02s? Was that really running on the slow beaglebone?

[Oliver Grawert (ogra)]

yes it was ... re-running it with time:

ogra@bbb:~$ time /var/snap/classic/common/classic/usr/bin/strace -ff -r -T console-conf --help >console-conf-help.strace 2>&1

real 0m16.882s
user 0m11.256s
sys 0m5.412s
ogra@bbb:~$

[Martin Pitt (pitti)]

Mind attaching that strace?

[Oliver Grawert (ogra)]

sure, not actually much different from the former though ... http://paste.ubuntu.com/23215975/
( i watched the prompt not coming back for ~20sec in both cases when i ran the command)

[Martin Pitt (pitti)]

oh, sorry, I mis-read the straces -- can you please run with -tt, not with -T, so that we see cumulative/real-time timestamps?

[Oliver Grawert (ogra)]

ogra@bbb:~$ time /var/snap/classic/common/classic/usr/bin/strace -ff -tt console-conf --help >console-conf-help.strace 2>&1

real 0m17.668s
user 0m11.384s
sys 0m6.060s
...
http://paste.ubuntu.com/23216240/

[Oliver Grawert (ogra)]

well, the -T makes it pretyt easy to grep for the bigger time hogs ... see http://paste.ubuntu.com/23216260/ ... gettimeofday seems to consume a lot, as well as loading yaml

[Steve Langasek (vorlon)]

Thanks, the strace shows at least one low-hanging fruit for python startup, which is that all the .pyc files are missing from the image. This needs to be fixed in the ubuntu-core image build process.

[Steve Langasek (vorlon)]

> well, the -T makes it pretyt easy to grep for the bigger time hogs

Except the time at the front is the relative time since the start of the previous syscall. To find syscalls that take a long time, you need to grep on the time shown at the /end/ of the line.

Both are useful, but time /between/ syscalls points to times where the process is doing a lot in userspace.

[Oliver Grawert (ogra)]

with todays daily image (which does not remove the .pyc files anymore) the actual startup time got down to a bearable 10-20 seconds (stopwatched several fresh boots from hitting enter to having the UI appear) ... the time used during account creation is still between 4 and 5 minutes though, so i would say we're half way there already.

[Michael Hudson-Doyle (mwhudson)]

On 23 September 2016 at 22:29, Oliver Grawert <email address hidden> wrote:

> with todays daily image (which does not remove the .pyc files anymore)
> the actual startup time got down to a bearable 10-20 seconds
> (stopwatched several fresh boots from hitting enter to having the UI
> appear) ...

Yay.

> the time used during account creation is still between 4 and
> 5 minutes though, so i would say we're half way there already.

Per https://github.com/snapcore/snapd/pull/1984, can you try this with
SNAPD_DEBUG_HTTP=3 set in snapd's environment and then journalctl -u snapd?
I tried but I'm not seeing any slowness in create-user any more so it's not
showing anything very interesting.

Cheers,
mwh

>
> --
> You received this bug notification because you are subscribed to
> subiquity in Ubuntu.
> https://bugs.launchpad.net/bugs/1625698
>
> Title:
> console-conf on beaglebone takes unbearable long
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/snappy/+bug/1625698/+subscriptions
>

[Víctor R. Ruiz (vrruiz)]

This is also happening with Pi 3. It takes some minutes for console-conf to show up. Also, account creation takes too long.