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

[riccardo]

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