Quick tabbing profiling (was Re: Report on `activities switching' profiling)

[Eben Eliason]

Can someone make sense of this for me?  Ben, do you see anything we can
optimize here?  I've noticed while quick-tabbing on my XO that the gray
selection box doesn't usually update as I switch, so I can't tell where I
am.   If I pause long enough to see the selection move, I also get the
redraw of the whole activity, slowing me down and defeating the purpose.
- Eben


On Fri, Jul 18, 2008 at 6:08 AM, riccardo <riccardo.lucchese at gmail.com>
wrote:

> On Thu, 2008-07-17 at 10:31 +0200, riccardo wrote:
> > On Wed, 2008-07-16 at 11:17 -0400, Eben Eliason wrote:
> > >
> > >
> > > On Wed, Jul 16, 2008 at 11:04 AM, riccardo
> > > <riccardo.lucchese at gmail.com> wrote:
> > >         (so that it never ends up in the journal) every 1100. The
> > >         1100ms value
> > >         was chosen after some testing as the minimum value (or very
> > >         near to it)
> > >         at which both activities are able to completely redraw their
> > >         windows on
> > >         switching without artifacts.
> > >
> > >
> > > If you could, it would also be useful to test out the "quick tab"
> > > behavior.  While it's true that after a short delay (I forget the
> > > exact number of ms) the activities redraw their windows, the behavior
> > > is supposed to prevent this redraw as long as the tabbing events
> > > happen quickly enough, so that the redraw doesn't add latency when
> > > attempting to bypass several activities in a row.  I'm not sure if
> > > this is actually working properly on the XOs.
> >
> > Sure, I let you know when I have some results.
> >
>
> Test-case: the test consist of starting few activities and
> `quick-tabbing' between them for a sensible amount of time. Switching
> was automated by patching sugar-shell to call
> tabbinghandler.handle_next_activity() every 100ms; this value should
> trigger the `quick-tabbing' logic. All tests were run on a xo
>
> The following tab. and fig. show cpu time usage of the 8 processes
> taking more cpu time while running the test (pid 2233 and 2254 are two
> activities).
>
> (tot% us+sy) - (partial% us+sy) : cmdline
>       - 39.8 : python /usr/bin/sugar-shell
> 75.0   - 35.1 : python /usr/bin/datastore-service
> 82.7   - 7.6  : picker -t30
> 86.5   - 3.8  : /bin/dbus-daemon --fork --print-pid 5 ...
> 88.9   - 2.3  : python /usr/bin/sugar-presence-service
> 90.8   - 1.8  : python /usr/sbin/rainbow-daemon --daemon (2233)
> 92.7   - 1.8  : python /usr/bin/sugar-activity journalactivity.Jou...
> 94.3   - 1.6  : python /usr/sbin/rainbow-daemon --daemon (2254)
>
>
> http://dev.laptop.org/~rlucchese/ActivitiesSwitching/quick-tabbing/picker.stats.svg
> (
> http://dev.laptop.org/~rlucchese/ActivitiesSwitching/quick-tabbing/picker.stats
> )
>
> They were obtained by running:
> $ picker -t30 -f10
> $ grapher -c8
>
> ! 75% of cpu-time goes to the shell and the datastore.
>
>  next_activity() and previous_activity() in tabbinghandler.py call
>  tabbing_set_activity(self, activity) in homemodel.py that in turn
>  calls SetActive(False, ...) on the current activity and
>  SetActive(True, ...) on the next activity.
>
>
> cProfile statistics (KCacheGrind format) for the shell and the
> datastore:
>
> http://dev.laptop.org/~rlucchese/ActivitiesSwitching/quick-tabbing/cProfile-shell
>
> http://dev.laptop.org/~rlucchese/ActivitiesSwitching/quick-tabbing/cProfile-datastore
>
> Ordering by function's self-time we have for sugar-shell:
> part%     func name
> 26.8 : gtk.main()
> 11.9 : send_message_with_reply_and_block of dbus
> 8.2  : call_async of dbus
> 5.7  : __init__ in sugar/graphics/palette.py 8.2 <cycle 5>
> 5.3  : __init__ in sugar/graphics/icon.py
> 3.3  : gtk.Widget.show() <cycle 5>
> 1.6  : gobject.GObject.connect()
> ----------------------------------------------
> 62%
>
> Where <cycle 5> means there is recursion between those functions.
>
> Ordering by function's self-time we have for the datastore:
> part%     func name
> 41.9 : gobject.MainLoop.run
> 5.8  : flush in secore/indexerconnection.py
> 5.7  : posix.fork
> 3.9  : send_message of dbus
> 3.1  : replace in secore/indexerconnection.py
> 2.8  : cPickle.dumps
> 1.8  : perform in secore/fieldactions.py
> 1.5  : properties in datastore/model.py
> ----------------------------------------------
> 67%
>
>
> I think sysprof statistics aren't extremely interesting in this case:
>
> http://dev.laptop.org/~rlucchese/ActivitiesSwitching/quick-tabbing/sysprof.data
>
>
>
> thanks,
> riccardo
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.laptop.org/pipermail/devel/attachments/20080718/5e8ce367/attachment.html>