[Sugar-devel] A trick to profile activities startup time

[Gonzalo Odiard]

I continued profiling Abacus activity to try to see why is slow to start.

The first issue I found, was the abacus was redraw many times,
by different reasons. My patches are here [1]

* In the default case, the abacus was created, and recreated again
with the same abacus (Do not switch to a abacus already
selected<https://github.com/godiard/abacus/commit/cd1d44894b317495e23958f508d79d4c3c352a26>
)

* The creation/modification of sprites queue the redraw of his own area,
but when all the sprites are created, that can trigger more than one draw.
I have added a method to hold the draw until all the sprites are created.
("Add a methods to allow delay of
draw<https://github.com/godiard/abacus/commit/e3ca53d0bc8b84fcc9d55dd6548a9c881d30e0d1>"
and  "Draw only one time on activity
startup<https://github.com/godiard/abacus/commit/7f6dc838b91b0953001d06e2e68d6c166f72ff48>
")

Now Abacus starts in 5.4 segs in a XO-4, and in 15/16 segs in a XO-1
(previously was 22/25 segs in a XO-1)

* My final test was interesting but disappointing in the results.
The activity create the sprites defining the images as SVGs, rendering them
in pixbufs,
and painting that pixbufs in the screen. I had the theory than that could
be slow,
then added the possibility of use a ImageSurface instead of a Pixbuf in the
Sprite,
and generated the images using cairo ("Draw sprites using cairo
surfaces<https://github.com/godiard/abacus/commit/2b85fc2af143ba133044185343385bde28d4549b>
")
The patch do all the changes, and the abacus is functional (with some
regressions,
like the labels are not centered), but the performance is almost the same.

This is the top 20 (on a xo-4) after all these changes:

[gonzalo at localhost abacus]$ sort -rn -k2 abacus_cairo_profile.log | head -20
        1    4.278    4.278    6.741    6.741 activity.py:375(run_main_loop)
      307    1.097    0.004    1.097    0.004 {method 'paint' of
'cairo.Context' objects}
3834/3586    0.302    0.000    0.545    0.000 module.py:252(__getattr__)
      995    0.266    0.000    0.266    0.000 {method 'remove' of 'list'
objects}
      155    0.231    0.001    0.490    0.003
sprites.py:122(remove_from_list)
        1    0.215    0.215    0.463    0.463 activity.py:231(__init__)
        1    0.202    0.202    2.740    2.740 AbacusActivity.py:72(__init__)
      242    0.137    0.001    0.298    0.001 sprites.py:367(draw_label)
       67    0.134    0.002    0.134    0.002 {method 'write' of 'file'
objects}
      225    0.124    0.001    0.226    0.001
abacus_window.py:237(_image_bead)
9815/9127    0.101    0.000    0.310    0.000 {getattr}
    10596    0.086    0.000    0.086    0.000 {method 'append' of 'list'
objects}
19141/18938    0.085    0.000    0.087    0.000 {len}
    10368    0.080    0.000    0.111    0.000 sprites.py:98(get_sprite)
  207/175    0.079    0.000    0.408    0.002 module.py:110(__getattr__)
       44    0.077    0.002    0.236    0.005 icon.py:133(_get_icon_info)
      332    0.071    0.000    0.071    0.000 {method 'get_g_type' of
'gi.RegisteredTypeInfo' objects}
      280    0.068    0.000    1.419    0.005 sprites.py:324(draw)
       31    0.067    0.002    0.067    0.002 {method
'send_message_with_reply_and_block' of '_dbus_bindings.Connection' objects}
   298/25    0.059    0.000    0.102    0.004
types.py:142(find_vfunc_conflict_in_bases)


Now, almost all the time, is spent in:

        1    4.278    4.278    6.741    6.741 activity.py:375(run_main_loop)

What is that?
https://github.com/sugarlabs/sugar-toolkit-gtk3/blob/master/src/sugar3/activity/activity.py#L375

 _initialize_journal_object have a nice FIXME

        # FIXME: We should be able to get an ID synchronously from the DS,
        # then call async the actual create.
        # http://bugs.sugarlabs.org/ticket/2169

https://github.com/sugarlabs/sugar-toolkit-gtk3/blob/master/src/sugar3/activity/activity.py#L425

points to a bug 4 years old :(
(there are more information in this bug [2].... 7 years old!

I will try profile the datastore part. That have the potential of improve
the startup time of all the activities.
Of course, If anybody else want help is welcomed.

Gonzalo


[1] https://github.com/godiard/abacus/commits/master
[2] https://dev.laptop.org/ticket/3071


On Tue, May 20, 2014 at 10:45 AM, Gonzalo Odiard <godiard at sugarlabs.org>wrote:

> One trick is the following (example using the Abacus activity):
>
> * In sugar, start one activity
> * without close the activity, go tot the terminal, and see the command
> line used to run it
> $ ps ax | grep Abacus
> 2250  ?             Sl         0:10  python2 /usr/bin/sugar-activity
> AbacusActivity.AbacusActivity -b org.sugarlabs.AbacusActivity -a
> ff8dc731a329b184b7d28c40cc85c47ff2e433cb -o
> 7ae05000-b61c-4fd8-9b66-e5125f3ba81f > abacus_profile.log
>
> * close the activity you want profile.
> * in the terminal do:
> $ cd Activities/Abacus.activity
> $ python2 *-m cProfile */usr/bin/sugar-activity
> AbacusActivity.AbacusActivity -b org.sugarlabs.AbacusActivity -a
> ff8dc731a329b184b7d28c40cc85c47ff2e433cb -o
> 7ae05000-b61c-4fd8-9b66-e5125f3ba81f *> abacus_profile.log*
>
> Adding -m cProfile to get the profile information, and redirecting to a
> file
> The activity will start, in this case, some of the icons are not displayed.
> Close the activity and check the generated file, in this case
> abacus_profile.log
>
> The content of the file is attached, have columns like:
>
>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>         1    0.002    0.002    0.002    0.002 <string>:1(<module>)
>
> Explanation about what means every column is here:
>
> https://docs.python.org/2/library/profile.html#instant-user-s-manual
>
> Sorting by the second column (tottime) , and filtering the top 20 we can
> see:
>
> [gonzalo at localhost sugar]$ sort -nr -k2
> /run/media/gonzalo/0824-E6BD/abacus_profile.log | head -20
>         1    2.879    2.879    5.105    5.105
> activity.py:375(run_main_loop)
>       504    1.177    0.002    1.212    0.002
> abacus_window.py:108(_svg_str_to_pixbuf)
>        30    0.696    0.023    1.392    0.046 abacus_window.py:329(update)
>       420    0.559    0.001    1.289    0.003 sprites.py:312(draw)
>       448    0.433    0.001    0.786    0.002
> sprites.py:120(remove_from_list)
> 5642/5394    0.387    0.000    0.666    0.000 module.py:252(__getattr__)
>      1156    0.359    0.000    0.359    0.000 {method 'remove' of 'list'
> objects}
>       309    0.236    0.001    1.142    0.004 sprites.py:232(set_layer)
>         1    0.221    0.221    0.512    0.512 activity.py:231(__init__)
>       363    0.207    0.001    0.455    0.001 sprites.py:347(draw_label)
>        20    0.198    0.010    0.198    0.010 {method 'paint' of
> 'cairo.Context' objects}
>       420    0.145    0.000    0.145    0.000 {method 'fill' of
> 'cairo.Context' objects}
>        63    0.143    0.002    0.143    0.002 {method 'write' of 'file'
> objects}
>     18935    0.143    0.000    0.202    0.000 sprites.py:96(get_sprite)
> 12193/11504    0.127    0.000    0.354    0.000 {getattr}
> 27982/27779    0.117    0.000    0.118    0.000 {len}
>         1    0.115    0.115    5.313    5.313
> AbacusActivity.py:72(__init__)
>        31    0.099    0.003    0.099    0.003 {method
> 'send_message_with_reply_and_block' of '_dbus_bindings.Connection' objects}
>     10858    0.098    0.000    0.098    0.000 {method 'append' of 'list'
> objects}
>        43    0.088    0.002    0.253    0.006 icon.py:133(_get_icon_info)
>
> --
> Gonzalo Odiard
>
> SugarLabs - Software for children learning
>



-- 
Gonzalo Odiard

SugarLabs - Software for children learning
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sugarlabs.org/archive/sugar-devel/attachments/20140522/4b3a1f0b/attachment-0001.html>