<div dir="ltr">I continued profiling Abacus activity to try to see why is slow to start.<div><br></div><div>The first issue I found, was the abacus was redraw many times,</div><div>by different reasons. My patches are here [1]</div>
<div><br></div><div>* In the default case, the abacus was created, and recreated again</div><div>with the same abacus (<a href="https://github.com/godiard/abacus/commit/cd1d44894b317495e23958f508d79d4c3c352a26" class="" title="Do not switch to a abacus already selected
This change avoid one redraw at startup in the default case" style="color:rgb(51,51,51);text-decoration:none;font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px;background-color:rgb(252,252,226)">Do not switch to a abacus already selected</a>)</div>
<div><br></div><div>* The creation/modification of sprites queue the redraw of his own area,</div><div>but when all the sprites are created, that can trigger more than one draw.</div><div>I have added a method to hold the draw until all the sprites are created.</div>
<div>("<a href="https://github.com/godiard/abacus/commit/e3ca53d0bc8b84fcc9d55dd6548a9c881d30e0d1" class="" title="Add a methods to allow delay of draw
Until now, every Sprite request the draw of their own region.
This patch transfer that responsability to the Sprites object,
adding methods to delay the drawing to allow initialize all the sprites
without doing any draw.
Now, the aplication need call the Sprites.init() method,to allow the drawing.
This is needed to optimize the startup time, requesting only one draw.
Signed-off-by: Gonzalo Odiard <godiard@sugarlabs.org>" style="color:rgb(51,51,51);text-decoration:none;font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px;background-color:rgb(252,252,226)">Add a methods to allow delay of draw</a>" and <span style="color:rgb(51,51,51);font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px;background-color:rgb(252,252,226)"> </span><span style="color:rgb(51,51,51);font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px;background-color:rgb(252,252,226)">"</span><a href="https://github.com/godiard/abacus/commit/7f6dc838b91b0953001d06e2e68d6c166f72ff48" class="" title="Draw only one time on activity startup
abacus.py application is also modified" style="color:rgb(51,51,51);text-decoration:none;font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px">Draw only one time on activity startup</a><span style="background-color:rgb(252,252,226);color:rgb(51,51,51);font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px">")</span></div>
<div><br></div><div>Now Abacus starts in 5.4 segs in a XO-4, and in 15/16 segs in a XO-1</div><div>(previously was 22/25 segs in a XO-1)</div><div><br></div><div>* My final test was interesting but disappointing in the results.</div>
<div>The activity create the sprites defining the images as SVGs, rendering them in pixbufs,</div><div>and painting that pixbufs in the screen. I had the theory than that could be slow,</div><div>then added the possibility of use a ImageSurface instead of a Pixbuf in the Sprite,</div>
<div>and generated the images using cairo ("<a href="https://github.com/godiard/abacus/commit/2b85fc2af143ba133044185343385bde28d4549b" class="" title="Draw sprites using cairo surfaces
The objectives is see if the performance can be improved" style="color:rgb(51,51,51);text-decoration:none;font-family:Helvetica,arial,freesans,clean,sans-serif;font-size:14px;line-height:19.600000381469727px;background-color:rgb(252,252,226)">Draw sprites using cairo surfaces</a>") </div>
<div>The patch do all the changes, and the abacus is functional (with some regressions,</div><div>like the labels are not centered), but the performance is almost the same.</div><div><br></div><div>This is the top 20 (on a xo-4) after all these changes:</div>
<div><br></div><div><div><font face="courier new, monospace" size="1">[gonzalo@localhost abacus]$ sort -rn -k2 abacus_cairo_profile.log | head -20</font></div><div><font face="courier new, monospace" size="1"> 1 4.278 4.278 6.741 6.741 activity.py:375(run_main_loop)</font></div>
<div><font face="courier new, monospace" size="1"> 307 1.097 0.004 1.097 0.004 {method 'paint' of 'cairo.Context' objects}</font></div><div><font face="courier new, monospace" size="1">3834/3586 0.302 0.000 0.545 0.000 module.py:252(__getattr__)</font></div>
<div><font face="courier new, monospace" size="1"> 995 0.266 0.000 0.266 0.000 {method 'remove' of 'list' objects}</font></div><div><font face="courier new, monospace" size="1"> 155 0.231 0.001 0.490 0.003 sprites.py:122(remove_from_list)</font></div>
<div><font face="courier new, monospace" size="1"> 1 0.215 0.215 0.463 0.463 activity.py:231(__init__)</font></div><div><font face="courier new, monospace" size="1"> 1 0.202 0.202 2.740 2.740 AbacusActivity.py:72(__init__)</font></div>
<div><font face="courier new, monospace" size="1"> 242 0.137 0.001 0.298 0.001 sprites.py:367(draw_label)</font></div><div><font face="courier new, monospace" size="1"> 67 0.134 0.002 0.134 0.002 {method 'write' of 'file' objects}</font></div>
<div><font face="courier new, monospace" size="1"> 225 0.124 0.001 0.226 0.001 abacus_window.py:237(_image_bead)</font></div><div><font face="courier new, monospace" size="1">9815/9127 0.101 0.000 0.310 0.000 {getattr}</font></div>
<div><font face="courier new, monospace" size="1"> 10596 0.086 0.000 0.086 0.000 {method 'append' of 'list' objects}</font></div><div><font face="courier new, monospace" size="1">19141/18938 0.085 0.000 0.087 0.000 {len}</font></div>
<div><font face="courier new, monospace" size="1"> 10368 0.080 0.000 0.111 0.000 sprites.py:98(get_sprite)</font></div><div><font face="courier new, monospace" size="1"> 207/175 0.079 0.000 0.408 0.002 module.py:110(__getattr__)</font></div>
<div><font face="courier new, monospace" size="1"> 44 0.077 0.002 0.236 0.005 icon.py:133(_get_icon_info)</font></div><div><font face="courier new, monospace" size="1"> 332 0.071 0.000 0.071 0.000 {method 'get_g_type' of 'gi.RegisteredTypeInfo' objects}</font></div>
<div><font face="courier new, monospace" size="1"> 280 0.068 0.000 1.419 0.005 sprites.py:324(draw)</font></div><div><font face="courier new, monospace" size="1"> 31 0.067 0.002 0.067 0.002 {method 'send_message_with_reply_and_block' of '_dbus_bindings.Connection' objects}</font></div>
<div><font face="courier new, monospace" size="1"> 298/25 0.059 0.000 0.102 0.004 types.py:142(find_vfunc_conflict_in_bases)</font></div></div><div><br></div><div><br></div><div>Now, almost all the time, is spent in:</div>
<div><br></div><div><span style="font-family:'courier new',monospace"> 1 4.278 4.278 6.741 6.741 activity.py:375(run_main_loop)</span><br></div><div><br></div><div>What is that?</div><div><a href="https://github.com/sugarlabs/sugar-toolkit-gtk3/blob/master/src/sugar3/activity/activity.py#L375">https://github.com/sugarlabs/sugar-toolkit-gtk3/blob/master/src/sugar3/activity/activity.py#L375</a><br>
</div><div><br></div><div><font face="arial, helvetica, sans-serif"> _initialize_journal_object have a nice FIXME</font><br></div><div><font face="arial, helvetica, sans-serif"><br></font></div><div><div><font face="courier new, monospace" size="1"> # FIXME: We should be able to get an ID synchronously from the DS,</font></div>
<div><font face="courier new, monospace" size="1"> # then call async the actual create.</font></div><div><font face="courier new, monospace" size="1"> # <a href="http://bugs.sugarlabs.org/ticket/2169">http://bugs.sugarlabs.org/ticket/2169</a></font></div>
</div><div><br></div><div><a href="https://github.com/sugarlabs/sugar-toolkit-gtk3/blob/master/src/sugar3/activity/activity.py#L425">https://github.com/sugarlabs/sugar-toolkit-gtk3/blob/master/src/sugar3/activity/activity.py#L425</a><br>
</div><div><br></div><div>points to a bug 4 years old :(</div><div>(there are more information in this bug [2].... 7 years old!</div><div><br></div><div>I will try profile the datastore part. That have the potential of improve the startup time of all the activities.</div>
<div>Of course, If anybody else want help is welcomed.</div><div><br></div><div>Gonzalo </div><div><br></div><div><br><div>[1] <a href="https://github.com/godiard/abacus/commits/master">https://github.com/godiard/abacus/commits/master</a><br>
</div></div><div>[2] <a href="https://dev.laptop.org/ticket/3071">https://dev.laptop.org/ticket/3071</a></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, May 20, 2014 at 10:45 AM, Gonzalo Odiard <span dir="ltr"><<a href="mailto:godiard@sugarlabs.org" target="_blank">godiard@sugarlabs.org</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">One trick is the following (example using the Abacus activity):<div><br></div><div>* In sugar, start one activity</div>
<div>* without close the activity, go tot the terminal, and see the command line used to run it</div>
<div>$ ps ax | grep Abacus<br clear="all"><div>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<br>
</div><div><br></div><div>* close the activity you want profile.</div><div>* in the terminal do:</div><div>$ cd Activities/Abacus.activity</div><div>$ python2 <b>-m cProfile </b>/usr/bin/sugar-activity AbacusActivity.AbacusActivity -b org.sugarlabs.AbacusActivity -a ff8dc731a329b184b7d28c40cc85c47ff2e433cb -o 7ae05000-b61c-4fd8-9b66-e5125f3ba81f <b>> abacus_profile.log</b></div>
<div><br></div><div>Adding -m cProfile to get the profile information, and redirecting to a file</div><div>The activity will start, in this case, some of the icons are not displayed.</div><div>Close the activity and check the generated file, in this case abacus_profile.log</div>
<div><br></div><div>The content of the file is attached, have columns like:</div><div><br></div><div><div> ncalls tottime percall cumtime percall filename:lineno(function)</div><div> 1 0.002 0.002 0.002 0.002 <string>:1(<module>)</div>
<div><br></div><div>Explanation about what means every column is here:</div><div><br></div><div><a href="https://docs.python.org/2/library/profile.html#instant-user-s-manual" target="_blank">https://docs.python.org/2/library/profile.html#instant-user-s-manual</a><br>
</div><div><br></div></div><div>Sorting by the second column (tottime) , and filtering the top 20 we can see:</div><div><br></div><div><div><font face="courier new, monospace">[gonzalo@localhost sugar]$ sort -nr -k2 /run/media/gonzalo/0824-E6BD/abacus_profile.log | head -20</font></div>
<div><font face="courier new, monospace"> 1 2.879 2.879 5.105 5.105 activity.py:375(run_main_loop)</font></div><div><font face="courier new, monospace"> 504 1.177 0.002 1.212 0.002 abacus_window.py:108(_svg_str_to_pixbuf)</font></div>
<div><font face="courier new, monospace"> 30 0.696 0.023 1.392 0.046 abacus_window.py:329(update)</font></div><div><font face="courier new, monospace"> 420 0.559 0.001 1.289 0.003 sprites.py:312(draw)</font></div>
<div><font face="courier new, monospace"> 448 0.433 0.001 0.786 0.002 sprites.py:120(remove_from_list)</font></div><div><font face="courier new, monospace">5642/5394 0.387 0.000 0.666 0.000 module.py:252(__getattr__)</font></div>
<div><font face="courier new, monospace"> 1156 0.359 0.000 0.359 0.000 {method 'remove' of 'list' objects}</font></div><div><font face="courier new, monospace"> 309 0.236 0.001 1.142 0.004 sprites.py:232(set_layer)</font></div>
<div><font face="courier new, monospace"> 1 0.221 0.221 0.512 0.512 activity.py:231(__init__)</font></div><div><font face="courier new, monospace"> 363 0.207 0.001 0.455 0.001 sprites.py:347(draw_label)</font></div>
<div><font face="courier new, monospace"> 20 0.198 0.010 0.198 0.010 {method 'paint' of 'cairo.Context' objects}</font></div><div><font face="courier new, monospace"> 420 0.145 0.000 0.145 0.000 {method 'fill' of 'cairo.Context' objects}</font></div>
<div><font face="courier new, monospace"> 63 0.143 0.002 0.143 0.002 {method 'write' of 'file' objects}</font></div><div><font face="courier new, monospace"> 18935 0.143 0.000 0.202 0.000 sprites.py:96(get_sprite)</font></div>
<div><font face="courier new, monospace">12193/11504 0.127 0.000 0.354 0.000 {getattr}</font></div><div><font face="courier new, monospace">27982/27779 0.117 0.000 0.118 0.000 {len}</font></div><div>
<font face="courier new, monospace"> 1 0.115 0.115 5.313 5.313 AbacusActivity.py:72(__init__)</font></div><div><font face="courier new, monospace"> 31 0.099 0.003 0.099 0.003 {method 'send_message_with_reply_and_block' of '_dbus_bindings.Connection' objects}</font></div>
<div><font face="courier new, monospace"> 10858 0.098 0.000 0.098 0.000 {method 'append' of 'list' objects}</font></div><div><font face="courier new, monospace"> 43 0.088 0.002 0.253 0.006 icon.py:133(_get_icon_info)</font></div>
<span class="HOEnZb"><font color="#888888">
</font></span></div><span class="HOEnZb"><font color="#888888"><div><br></div>-- <br><div dir="ltr">Gonzalo Odiard<br><br><div>SugarLabs - Software for children learning <br></div></div>
</font></span></div></div>
</blockquote></div><br><br clear="all"><div><br></div>-- <br><div dir="ltr">Gonzalo Odiard<br><br><div>SugarLabs - Software for children learning <br></div></div>
</div>