sugar start-up profiling

[riccardo]

On Thu, 2008-07-31 at 17:27 +0100, Tomeu Vizoso wrote:
> 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.

The DS seems to me a good candidate for being decoupled from the shell's
startup.

> 
> > 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?
Oh, right!
+1 for changing the algorithm.

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

riccardo