Report on `switching between activities and the journal'

[riccardo]

Hi,

Problem: switching between activities and the journal is slow

Test-case: the test consist of starting Write and switching between it
and the journal for a sensible amount of time. All tests were run on a
xo; the journal had 50 entries. Switching was automated by calling
shell.activate_next_activity() every ~730ms (as the minimum value at
which both activities could get completely redrawn).

Real transition timings differ from the timer's period value of 730ms.
The `switch' journal -> write takes an average of 735ms while the
transition write -> journal takes values from 1 to 2 seconds.

During the test, activate_next_activity() in Shell.py was called 695
times.

cpu usage data gathered with Picker (pid 2564 is the Write activity):
tot% ps% cmdline
-----------------------
     34.6 python /usr/bin/sugar-activity journalactivity ...
57.1 22.6 python /usr/sbin/rainbow-daemon --daemon ...   [Write]
77.9 20.8 python /usr/bin/datastore-service
85.0 7.2  python /usr/bin/sugar-shell
91.5 6.5  /usr/bin/X :0 -fp built-ins -wr -auth ...
97.1 5.6  picker

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

They were obtained by running:
$ picker
$ grapher -c6 -r cpu


The 22.6% took by Write is due to the activity saving and loading its
state (taking screnshots, reading/writing files..) regardless it change
or not (http://lists.laptop.org/pipermail/devel/2008-July/016722.html).

The shell is taking the 7% of cpu-time; isn't it too much for this task?



cProfile statistics (KCacheGrind format) for the journal:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-journalactivity

The journal spends 69.4% of it's time in __refresh_idle_cb in
listview.py.

Ordering by function self-time:
29.7 : send_message_with_reply_and_block of dbus
15.7 : gtk.main()
10.9 : __init__ in activities/Journal.activity/palettes.py (2211 calls)
3.7  : cairo.Context.paint()
3.3  : __init__ sugar/graphics/palette.py

Asynchronous dbus calls ? Perhaps icons and palettes could be cached ?



cProfile statistics (KCacheGrind format) for Write:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-write

Similar results were already commented at
http://lists.laptop.org/pipermail/devel/2008-July/016722.html for a
similar task.



cProfile statistics (KCacheGrind format) for the datastore-service
aren't much interesting this time (a separate test case should be
designed for it):
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-datastore



cProfile statistics (KCacheGrind format) for sugar-shell:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-shell

51.3% of time in the shell is going to send_message_with_reply_and_block
of dbus. I guess this is because of the calls to the activities's
services; maybe some of them can be made asynchronous ?

Other functions showing particularly up by self-time are:
20.8 : gtk.main()
4.1  : __init_ in sugar/graphics/icon.py (1509 calls)
2.9  : wnck.Window.activate()
2.1  : __init_ in sugar/graphics/palette.py (859 calls)

Perhaps icons and palettes could be cached ?



sysprof statistics:
http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/sysprof.data

Similar results were already commented at
http://lists.laptop.org/pipermail/devel/2008-July/016722.html for a
similar task.

Only one more thing I note particularly:
1. Python is spending a lot of time in the kernel.
   Too much reading/writing to the nand ?


thanks,
riccardo