console-conf on beaglebone takes unbearable long

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).

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.

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

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.

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

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

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

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

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

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

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:~$

Mind attaching that strace?

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)

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

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/

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

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.

> 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.

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.

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
>

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