Report on `views with many icons' profiling

Tue Jul 22 05:54:02 EDT 2008

Hi, you made some very good points. Comments inline:

On Sun, Jul 20, 2008 at 11:04 PM, riccardo <riccardo.lucchese at gmail.com> wrote:
> On Sat, 2008-07-19 at 11:49 +0200, Tomeu Vizoso wrote:
>
>> I would like to know how much time takes every switch (including the
>> redraw), is that 130ms and 170ms? Looks like it should be more to me.
> for the ring layout:
> favorite's view -> list view : avg 0.15 sec
> list view -> favorite's view : avg 0.15 sec
>
> for the freeform layout:
> favorite's view -> list view : avg 0.16 sec
> list view -> favorite's view : avg 0.85 sec
>
> In fact the 170ms value can be lowered but it makes very difficult to
> see whether both views are always redrawn or if sometimes one of the two
> is jumped (in the case of the freeform layout the screen is gray blank
> most of the time).

I think less than 200ms is already tolerable. At 100ms I think it
wouldn't be noticeable by the user.

>> Also, would like to see as well a top-down analysis, which are the top
>> 3-5 high level operations that take most CPU? Are they executed more
>> often than what would be strictly needed? I see in kcachegrind that
>> _views_switch_...() was called 2481 times, this means that your script
>> switched that many times?
>
> Yes, 2481 is the number of times the views were switched.

Cool.

> I think one can say that there's only one high-level operation: the call
> to _set_view in HomeBox.py; what happens as a consequence(/`parallel
> effect') is the firing of expose events and thus all the time that
> cProfile assigns to cairo and that sysprof shows in geode_drv.so.

Expose is just the rendering of the cairo surface into the window. Do
you know what proportion of the total time is expose?

> One thing I noted particularly is that 77% of the time of _set_view time
> goes to enable_xo_palette in sugar/view/home/favoritesview.py. It seems
> to me this last function is creating a new palette at every call
> (re-doing quite a bit of work scattered on various packages). I guess
> this can be done just once ?

Yeah, _MyIcon.enable_palette() should just set a flag _palette_enabled
to True. Then we should have a create_palette() method that creates
the palette lazily when it is needed. Do you think this is worth doing
in this release?

Example:

http://dev.laptop.org/git?p=sugar;a=commitdiff;h=960d90da474bb090c3905692e672301dab4cd515

> For the ring layout case, all the rest looks ok to me or not worth
> optimizing.
>
>>
>> Can you please try to assess the impact to the user of any slowness we
>> may have in there?
> --ring layout --
> Perhaps we should ask the kids if they notice too much delay. I don't
> think so, this `transition' is much faster than those to other views.
>
> --freeform layout--
> No need to ask ;)

What about the mesh view? Have you seen any slowness there? You may
need to connect to a jabber server in order to see enough icons. The
mesh and group views use the same layout algo than the freeform view.

>>  Which are in your opinion the next steps we should
>> take?
> - see if all the time in enable_xo_palette can be spared

Think so, yeah. Good one.

> - use box2d for the freeform layout; I guess that any naive algorithm
> *handling* collision detection would perform worse than box2d and any
> non naive one (really handling collisions) isn't worth the time.

Interesting, the current layout is a partial implementation of an algo
devised by Eben. Would be good if he explained what the goals are on
this regard and see which changes can be done that improve
performance.

Thanks,

Tomeu

>> On Thu, Jul 17, 2008 at 7:43 PM, riccardo <riccardo.lucchese at gmail.com> wrote:
>> > Hi,
>> >
>> > Problem: slow switching between views with many icons
>> >
>> > Test-case: the test consist of switching between the favorites view and
>> > the list view. Test were ran once with the ring layout in the favorite
>> > view and once with the freeform layout; the xo had 25 activities
>> > installed all checked as `favorite'. The action of switching was
>> > automated with a timer with period 130ms when the ring layout was
>> > selected and 170ms in the case of the freeform layout (as the minimum
>> > values permitting complete redraw of the views).
>> >
>> > Note that there is a noticeable delay when switching to the favorites
>> > views when the selected layout is freeform.
>> >
>> >
>> > --- RING layout ---
>> > The following tab. and fig. show cpu time usage of the processes
>> > taking more cpu time while running the test:
>> >
>> > (tot% us+sy) - (partial% us+sy) : cmdline
>> >             - 63.6             : python /usr/bin/sugar-shell
>> >  91.2        - 27.5             : /usr/bin/X :0 -fp built-ins...
>> >  99.5        - 8.2              : picker -t30
>> >
>> > http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats.svg
>> > (http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats )
>> >
>> > They were obtained by running:
>> > $ picker -t30
>> > $ grapher -c3
>> >
>> > --- FREEFORM layout ---
>> > (tot% us+sy) - (partial% us+sy) : cmdline
>> >             - 82.              : python /usr/bin/sugar-shell
>> >  91.6        - 9.5              : /usr/bin/X :0 -fp built-ins...
>> >  99.4        - 7.7              : picker -t30
>> >
>> > http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats.svg
>> > (http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats )
>> >
>> >  ! sugar-shell is taking 20% more cpu time than in the ring layout case.
>> >
>> >
>> >
>> > cProfile statistics (KCacheGrind format) for sugar-shell:
>> > --- RING layout ---
>> > http://dev.laptop.org/~rlucchese/views/favorites_ring-list/cProfile-shell
>> >
>> > Ordering by function's self-time:
>> >  %      func name
>> > 35.6   : cairo.Context.paint
>> > 3.9    : gtk.Container.add
>> > 2.     : sugar.graphics.palette.do_paint_below_children
>> > 1.9    : __setitem__ sugar.util
>> > ----------------------------------------------
>> > 57%
>> >
>> > Well, this isn't unexpected. But it's interesting when looking at
>> > sysprof results (below).
>> >
>> > --- FREEFORM layout ---
>> > http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/cProfile-shell
>> >
>> > Ordering by function's self-time:
>> >  %      func name
>> > 21.6   : _add_weight in sugar/shell/view/home/grid.py
>> > 21.5   : _remove_weight in sugar/shell/view/home/grid.py
>> > 10.6   : cairo.Context.paint
>> > 8.1    : __setitem__ sugar.util
>> > 5.7    : _compute_weight in sugar/shell/view/home/grid.py
>> > ----------------------------------------------
>> > 57.5%
>> >
>> >  ! Box2D would perform better ;)
>> >
>> >
>> > Sysprof results. Well, in sysprof there are many nested levels, so it is
>> > much more clear to just look at it.
>> >
>> > --- RING layout ---
>> > http://dev.laptop.org/~rlucchese/views/favorites_ring-list/sysprof.data
>> >
>> > - most of self-time is spent in the kernel and in X/X-modules.
>> >
>> > - time spent in the kernel is due to python and X, respectively 60%-40%.
>> >
>> > - time spent `in X' goes mostly to the geode driver, and then, to Xorg
>> > itself and the libexa module.
>> >
>> >
>> > --- FREEFORM layout ---
>> > http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/sysprof.data
>> >
>> > Notes for the ring layout are valid also here.
>> >
>> > There are two (new) entries in this case and they are taking more time
>> > than the X geode module: python's numpy/core/multiarray.so and
>> > numpy/core/umath.so. This is in relation with the algorithm used in the
>> > freeform layout to avoid icons collisions.
>> >
>> >
>> > thanks,
>> > riccardo
>> >
>> > _______________________________________________
>> > Devel mailing list
>> > Devel at lists.laptop.org
>> > http://lists.laptop.org/listinfo/devel
>> >
>
>