Icon rendering perfs comparison between builds 703 and joyride-2230

Wed Aug 6 08:00:12 EDT 2008

Introductory comments for some of these results can be found at:
http://lists.laptop.org/pipermail/devel/2008-July/016820.html.

Please note that logs were redirected to tmpfs during the tests.

Testcase 1:
Paint 25 svg icons on a GtkWindow, 20000 times using cairo; at every
`frame' icons's source surfaces are sequentially picked-up from a list
of 141 cached surfaces (pre-rendered trough libsrvg from some svg [icon]
files from the standard standard joyride installation).

For the test to work properly one has to copy svg files at
http://dev.laptop.org/~rlucchese/icon_rendering/svg/ to dir /opt/svg on
the XO.

HomeWindow.py was hacked to automate its redraw:
http://dev.laptop.org/~rlucchese/icon_rendering/HomeWindow.py

In build 703 the frame wasn't shown during the test:
http://dev.laptop.org/~rlucchese/icon_rendering/patch_0703_framewindow

 + Macro investigation of cpu usage
--- 2230 ---
A picker graph taken during the test can be found at:
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__cached__.picker.svg
(http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__cached__.picker)

The following tab shows cpu usage of the 3 processes that took more cpu
time during the sampling time:
($ grapher -c3 -n -r cpu -i
2230_icon_rendering__switch__cached__.picker)

 tot%   ps%     cmdline
 -----------------------
        55.2    /usr/bin/X :0 -fp built-ins -wr ...
 93.1   37.9    python /usr/bin/sugar-shell
 99.2   6.2     picker

--- 703 ---
http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__cached__.picker.svg
(http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__cached__.picker)

($ grapher -c3 -n -r cpu -i
0703_icon_rendering__switch__cached__.picker)

 tot%   ps%     cmdline
 -----------------------
        52.9    /usr/bin/X :0 -fp built-ins -wr ...
 91.4   38.4    python /usr/bin/sugar-shell
 100.0  8.6     picker

 + Redraw timings
--- 2230 --
(shell.log snippet at
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__cached__sugar-shell.log)
test duration   : ~598.1s
do_expose_event : avg ~0.027s

--- 703 --
(shell.log snippet at
http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__cached__sugar-shell.log)
test duration   : ~418.2s
do_expose_event : avg ~0.020s

 ! test runs slower on build 2230

 + cProfile statistics (KCG format) for sugar-shell:
Not very interesting for this testcase.

http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__cached__sugar-shell.cProfile
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__cached__sugar-shell.cProfile

 + Sysprof statistics:

--- 2230 ---
(http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__cached__.sysprof)

- 32.5% of time spent in xorg goes to a busy loop in the geode driver:

    void 
    gp_wait_until_idle(void)
    {
        unsigned long temp;

        while (((temp = READ_GP32(GP3_BLT_STATUS)) & GP3_BS_BLT_BUSY) ||
            !(temp & GP3_BS_CB_EMPTY)) {
            ;
        }
    }

- two more functions showing at the top for self time are
dixLookupPrivate and pixman_blt_mmx

--- 703 ---
(http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__cached__.sysprof)

- 53% of time spent in X goes to a busy loop (gp_wait_until_idle) in the
amd driver

- dixLookupPrivate and pixman_blt_mmx aren't present in the results here
  (for dixLookupPrivate see   
   http://lists.freedesktop.org/archives/xorg/2008-July/037233.html)

Time spent in the kernel is almost the same for the two builds.

Looking at the call tree under cairo_paint one can see some bits of
cairo and its xlib backend were refactored since 703, sometimes with
`tiny' (compared to the total) performance loses.

Testcase 2:
Paint 25 svg icons on a GtkWindow 2000 times using cairo; at every
`frame' icons's source surfaces are sequentially picked-up from a list
of 141 svg (icon) files from the standard joyride installation: at every
frame source surfaces are newly rendered from an rsvg handle to the svg
file.

Patches used are those for the previous case with the _TEST_ALWAYSRELOAD
flag set in HomeWindow.py.

 + Macro investigation of cpu usage
--- 2230 ---
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__alwaysreload__.picker.svg
(http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__alwaysreload__.picker)

($ grapher -c3 -n -r cpu -i \
2230_icon_rendering__switch__alwaysreload__.picker)

 tot%	ps%	cmdline
 -----------------------
   	88.1	python /usr/bin/sugar-shell
 94.3	6.2	picker
 99.6	5.2	/usr/bin/X :0 -fp built-ins -wr ...

--- 703 ---
http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__alwaysreload__.picker.svg
(http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__alwaysreload__.picker)

($ grapher -c3 -n -r cpu -i \
0703_icon_rendering__switch__alwaysreload__.picker)

 tot%	ps%	cmdline
 -----------------------
   	88.0	python /usr/bin/sugar-shell
 96.6	8.6	picker
 99.9	3.3	/usr/bin/X :0 -fp built-ins -wr ...

 + Redraw timings
`do_expose_event' timings aren't very interesting here because different
svg files take different times to be rendered to a cairo surface

(log snippet at
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__alwaysreload__sugar-shell.log)
(log snippet at
http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__alwaysreload__sugar-shell.log)
2230 test duration : ~535.14s
 703 test duration : ~537.4s

 + cProfile statistics (KCG format) for sugar-shell:
Not very interesting for this testcase. Just note that
cairo.Context.paint() is slightly slower (takes more time during the
test) on build 2230.

http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__alwaysreload__sugar-shell.cProfile
http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__alwaysreload__sugar-shell.cProfile

 + Sysprof statistics:
Not very interesting for this test case.

(http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__switch__alwaysreload__.sysprof)
(http://dev.laptop.org/~rlucchese/icon_rendering/0703_icon_rendering__switch__alwaysreload__.sysprof)

Testcase 3:
We measure rendering performance when drawing on an hippo.Canvas in
build 2230 (only). This is done by adding 20 `computer-xo' icons to the
friends view and automating the view's redraw.

Patches:
http://dev.laptop.org/~rlucchese/icon_rendering/patch_2230_friendsbox
http://dev.laptop.org/~rlucchese/icon_rendering/patch_2230_friendsbox_test_homewindow

The friends-view was redrawn 10000 times during the test.

 + Macro investigation of cpu usage
--- 2230 ---
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__friendsbox__.picker.svg
(http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__friendsbox__.picker)

($ grapher -c3 -n -r cpu -i \
2230_icon_rendering__friendsbox__.picker.svg)

 tot%	ps%	cmdline
 -----------------------
   	47.9	python /usr/bin/sugar-shell
 92.0	44.2	/usr/bin/X :0 -fp built-ins -wr ...
 99.7	7.6	picker

 + cProfile statistics (KCG format) for sugar-shell:
--- 2230 ---
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__friendsbox__sugar-shell.cProfile

What we are interested in is the time spent in the function
do_paint_below_children of sugar/graphics/icon.py: 77.5% of its time
goes to cairo.Context.paint() while 14.7% of it goes get_surface (in
class Icon).

Where does get_surface spends its time ?
 63.4   __getitem__ of sugar/util.py
  7.4   _get_cache_key of sugar/graphics/icon.py
  6.5   __contains__ sugar/graphics/util.py

 ! The LRU is using a dictionary to store entries

I'm not sure of what the LRU does here:
used for animations? for cpu-cache friendliness?  

 + sysprof statistics:
--- 2230 ---
http://dev.laptop.org/~rlucchese/icon_rendering/2230_icon_rendering__friendsbox__.sysprof

Comments to sysprof results for testcase #1 are `valid' also here.

Also note that of all the time spent in libhippocanvas because of expose
events only its 22.2% goes to cairo_paint(): python overhead is not
negligible for this task.

thanks,

riccardo