Report on `activities switching' profiling

[riccardo]

Hi,

Problem: switching between activities is noticeably too slow.

Test-case: the test consist of starting Chat and Write and switching
between them for a sensible amount of time. All tests were run on a xo.
Switching was automated by patching sugar-shell to call
shell.activate_next_activity() or shell.activate_previous_activity()
(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.

The following tab. and fig. show cpu time usage of the five processes
taking more cpu time while running the test (the first two processes are
chat and write).

(tot% us+sy) - (partial% us+sy) : cmdline
28.9 - 28.9 : python /usr/sbin/rainbow-daemon --daemon
54.7 - 25.8 : python /usr/sbin/rainbow-daemon --daemon
66.5 - 11.7 : /usr/bin/X :0 -fp built-ins -wr
-auth /home/olpc/.serverauth.1861
76.9 - 10.3 : python /usr/bin/datastore-service
85.3 - 8.4  : python /usr/bin/sugar-shell

http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/stats.picker.p84.svg
(http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/stats.picker)

They were obtained by running:
$ picker -t30 -f10
$ grapher -c5

! 55% of cpu time goes to the activities, to do what?


The two following files are cProfile statistics formatted to be
viewed with KCacheGrind for the chat and write activity:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-chat
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-write

Ordering by function's self-time we have for chat:
part%     func name
17.3 : gtk.gdk.Pixbuf.scale_simple
13.6 : sugar._sugarext.Preview.get_pixbuf
10.4 : gtk.gdk.Pixbuf.save
6.   : sugar._sugarext.Preview.take_screenshot
----------------------------------------------
47.3% 

Values are almost the same for write.

I guess some time can be gained by not doing the conversion Drawable ->
GdkPixbuf (sugar._sugarext.Preview.get_pixbuf) and perform the scaling
and conversion directly on the first buffer. But IMHO the real problem
is:

! Activities save their state and take previews continuously regardless
   of whether their state changed or not


Next, cProfile statistics for the shell:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-shell

Ordering by function self-time we have:
part%     func name
14.5 : set_message_with_reply_and_block of dbus
6.1  : <cycle 6>
2.58 : __init__ of sugar/graphics/palette.py <cycle 6>
1.65 : cairo.context.paint

I don't understand what <cycle 6> refers to (it appears also in the
third entry); maybe Tomeu knows ? ;)

Btw the shell is taking only the 8.4% of the total cpu time.



There also cProfile statistics for the DS and the Journal but they are
not very interesting this time:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-datastore
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-journal



The last tool we used is sysprof:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/stats.sysprof

What it shows is somehow more difficult to comment on; 
I think is much more clear to just look at sysprof.

Much time is spent in __PangoFontset_class_init->__do_global_ctors_aux;
is this libpango or the python-pango bindings being 'reloaded' at every
switch ?

Next, `notable' thing is a memcpy in the xorg libfb module; all the
screenshots ?

libcairo doesn't seem to show up particularly.




Did I miss something interesting in these tests ?

Thanks,
riccardo