Report on `switching between activities and the journal'

[Tomeu Vizoso]

On Mon, Jul 21, 2008 at 4:20 PM, riccardo <riccardo.lucchese at gmail.com> wrote:
> 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).

Yeah, wonder how we can do this without breaking existing activities.

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

Looks to be updating some palettes, if no palette is visible at that
time, we should make those lazy.

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

Well, we need the find() results in order to redraw. We could move to
a streaming resultset, starting to redraw as we receive the first
results, but I don't think this matters much in this case, as
retrieving 100 elements is almost as expensive as retrieving 1.

> Perhaps icons and palettes could be cached ?

Sorry, the journal in the builds still create the palettes eagerly.
The code has been pushed and I hope to do packages today. This will
improve things in the journal a lot. I'm very sorry but this will
invalidate this report (not that it's not being quite useful already,
though).

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

Yeah, although the one that has real impact is the call to
TakeScreenshot, which needs to be blocking because we want to wait for
the activity to finish taking the screenshot before obscuring it
(switching or showing the frame). This will be removed when we get
composition.

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

As per above, if we don't show any palette, we shouldn't be updating any.

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

Think so, but can we do anything about it?

Thanks,

Tomeu