sugar start-up profiling

[Tomeu Vizoso]

On Tue, Jul 29, 2008 at 3:15 PM, riccardo <riccardo.lucchese at gmail.com> wrote:
> Problem: sugar starts up slowly on the xo
>
> Tests were ran on an xo after a clean joyride-2181 install plus
> sucrose's activities.
>
> A graph of the ending part of the boot process can be found at:
> http://dev.laptop.org/~rlucchese/boot/boot.stats.svg
> (http://dev.laptop.org/~rlucchese/boot/boot.stats)
>
> It was obtained by running:
> $ picker -t 75 -o /tmp/boot.stats &
> $ grapher -i boot.stats -c10
>
> The sampling period begins in `start()' in haldaemon's init script and
> lasts 75 seconds.
>
> The following tab shows cpu usage of the 10 processes that took more cpu
> time during the sampling time:
> $ grapher -i boot.stats -c13 -r cpu
>
>  tot%   ps%     cmdline
>  -----------------------
>        27.7    /bin/sh /usr/bin/sugar
>  44.6   16.8    jffs2_gcd_mtd0
>  51.7   7.1     /usr/bin/env python /usr/bin/sugar-activity journal...
>  56.2   4.5     python /usr/bin/datastore-service
>  60.6   4.4     picker -t75 -o /tmp/boot.stats
>  64.3   3.8     python /usr/sbin/rainbow-daemon --daemon
>  68.0   3.6     xinit /usr/bin/olpc-session -- /usr/bin/X -fp built-ins...
>  71.3   3.3     /bin/sh /usr/bin/olpc-session
>  74.1   2.8     python /usr/bin/sugar-shell-service
>  76.9   2.8     python /usr/bin/sugar-presence-service
>  79.7   2.8     python /usr/sbin/rainbow-daemon --daemon
>  81.2   1.5     hald
>  82.6   1.4     ohmd
>
> Renicing jffs2_gcd_mtd0 to 19 in haldaemon's init script slightly
> speeds-up the last
> part of the boot:
> $ cat /home/olpc/.boot_time.prev  (clean joyride)
> 56.27
>
> $ cat /home/olpc/.boot_time
> 54.14
>
> Note however that when renicing jffs2_gcd_mtd0, boot timings `became
> less deterministic, sometimes being slower than the `clean install'
> case. Stopwatch timings (from boot loader to fully redrawn shell):
> clean install : 1m34.0s
> renice trick  : 1m30.2s +[0. to 4.5 sec]
>
> Would it be possible to make DS, sugar-presence-service and
> sugar-shell-service system services and thus decoupling them from the
> shell's start-up?

Don't think so, as they look to me as quite tied to the user session.
What we should do (for 9.1.0) with the sugar-shell-service and the
journal is to run them inside the shell process, saving memory and
startup time. And we certainly shouldn't block when activating any
services, they should be started asynchronously.

> A script was run that cat'ed all files (5700+) that sugar tries to open
> on boot. (http://dev.laptop.org/~rlucchese/boot/cat_sugar_startup_files)
>
> $ time sh cat_sugar_startup_files
> real 0m16.9s
> user 0m1.0s
> sys  0m12.2s
>
> Timings vary a lot when repeating the test (+-~30%).
> `top' shows that the remaining time goes to io-wait.
>
> Why don't those files get cached when repeating the test ?

Interesting, anybody with kernel knowledge could comment on this?

> cProfile statistics (KCG format) for sugar-shell (start-up only):
> http://dev.laptop.org/~rlucchese/boot/cProfile-shell
>
> Functions ordered by self-time (%):
>  32.2   gtk.main()
>  19.6   send_message_with_reply_and_block of dbus
>  12.8   block of dbus.lowlevel.PendingCall
>  7.3   grab of sugar._sugarext.KeyGrabber
>  3.    _add_weight of sugar/shell/view/home/grid.py
>  2.7  render_cairo of rsvg.Handle
>  1.12 __getitem__ of sugar/shell/view/home/grid.py
> ---------------------------------------------------
>  78.7 %
>
> Perhaps some dbus calls can be made asynchronous; this is taking 30+% of
> start-up time.

Yup. Mostly service activation, see above.

> It's curious that `grab` takes so much time: I don't see anything
> obvious looking at the code.

Yeah, we should look at it, could be quite tasty low hanging fruit (7%).

> Note that the layout for the favorite's view was set to the ring type;
> why is the shell computing weights in this case?

I guess that's for the mesh and friends view?

> High level tasks/functions ordered by total-time:
>  67.3   gtk.main()
>  33.6   __init__ of sugar/view/Shell.py
>  16.8   _start_journal_idle of sugar/view/Shell.py
>  11.6   __init__ shell/view/keyhandler.py
>  7.5   add sugar/shell/view/home/spreadlayout.py
>
> Note that 45% of Shell.__init__ and the 89% of _start_journal_idle
> went to blocking dbus calls.

Just service activation, right?

> The datastore service and the journal will be profiled in separate
> sessions.

Cool, that will be interesting as well.

Nice job, in case startup time becomes a priority, we know now where to look at.

Thanks,

Tomeu