<div dir="ltr"><div>(I'm re-sending this message because the attachment was too large for mesa-dev, and because I want to add wayland-devel CC. The valgrind output can be found here: <a href="http://runeks.dk/files/callgrind.out.11362">http://runeks.dk/files/callgrind.out.11362</a>).</div>
<div><br></div><div>Seems like you are right Pekka.</div><div><br></div><div>I just ran weston through valgrind, and got some interesting results. I ran it like so:</div><div><br></div><div><span class="" style="white-space:pre"> </span>valgrind --tool=callgrind --dump-instr=yes --trace-jump=yes weston</div>
<div><br></div><div>Which allows me to get the time spent on a per-instruction level. Now, this is running inside a virtual machine, so it won't be the same as running it natively, but it agrees with the other benchmarks in the sense that it suggests it is the simple calculations inside screenshooter.c that take up most of the CPU time, not calls to outside functions (like it was before with the slow glReadPixels() path).</div>
<div><br></div><div>The callgrind output can be found at the following URL: <a href="http://runeks.dk/files/callgrind.out.11362">http://runeks.dk/files/callgrind.out.11362</a></div><div>Open it with KCachegrind, select the function weston_recorder_frame_notify(), and go to the "Machine Code" tab in the lower right corner to see the interesting stuff.</div>
<div><br></div><div>According to callgrind, a total of 54.39% CPU time is used in the four lines 251, 252, 253 and 255 in screenshooter.c. That's the function component_delta():</div><div><br></div><div><span class="" style="white-space:pre"> </span>dr = (next >> 16) - (prev >> 16);</div>
<div><span class="" style="white-space:pre"> </span>dg = (next >> 8) - (prev >> 8);</div><div><span class="" style="white-space:pre"> </span>db = (next >> 0) - (prev >> 0);</div><div><br></div>
<div><span class="" style="white-space:pre"> </span>return (dr << 16) | (dg << 8) | (db << 0);</div><div><br></div><div>Additionally, the lines 358, 359, 361, 362, 363 take up 25.9% CPU time. That is the innermost for-loop inside weston_recorder_frame_notify(). It's the following lines with the call to component_delta() not included (line 360) since we've already included the CPU usage of that:</div>
<div><br></div><div><span class="" style="white-space:pre"> </span>for (k = 0; k < width; k++) {</div><div><span class="" style="white-space:pre"> </span>next = *s++;</div><div><span class="" style="white-space:pre"> </span>delta = component_delta(next, *d);</div>
<div><span class="" style="white-space:pre"> </span>*d++ = next;</div><div><span class="" style="white-space:pre"> </span>if (run == 0 || delta == prev) {</div><div><span class="" style="white-space:pre"> </span>run++;</div>
<div><br></div><div>And then finally the call to output_run() on line 365 takes up 10.6% CPU time:</div><div><br></div><div><span class="" style="white-space:pre"> </span>p = output_run(p, prev, run);</div><div><br></div>
<div>Inside output_run(), the lines that take up the most CPU time are: 232, 233, 234, 235, 239, 240. They take up 9.94% CPU time. So it's basically the whole while loop in output_run() except the line with the call to __builtin_clz() (line 238):</div>
<div><br></div><div><span class="" style="white-space:pre"> </span>while (run > 0) {</div><div><span class="" style="white-space:pre"> </span>if (run <= 0xe0) {</div><div><span class="" style="white-space:pre"> </span>*p++ = delta | ((run - 1) << 24);</div>
<div><span class="" style="white-space:pre"> </span>break;</div><div><span class="" style="white-space:pre"> </span>}</div><div><br></div><div><span class="" style="white-space:pre"> </span>i = 24 - __builtin_clz(run);</div>
<div><span class="" style="white-space:pre"> </span>*p++ = delta | ((i + 0xe0) << 24);</div><div><span class="" style="white-space:pre"> </span>run -= 1 << (7 + i);</div><div><span class="" style="white-space:pre"> </span>}</div>
<div><br></div><div>All of that adds up 90.89% CPU time spent inside screenshooter.c.</div><div><br></div><div>/Rune</div><div><br></div><div>On Tue, Mar 26, 2013 at 8:58 AM, Pekka Paalanen <<a href="mailto:ppaalanen@gmail.com">ppaalanen@gmail.com</a>> wrote:</div>
<div>On Tue, 26 Mar 2013 03:30:58 +0100</div><div>Rune Kjær Svendsen <<a href="mailto:runesvend@gmail.com">runesvend@gmail.com</a>> wrote:</div><div><br></div><div>> Marek, do you have an idea on where the currency bottleneck is?</div>
<div>></div><div>> I just did a profiling with sysprof, zooming in on the desktop in Weston</div><div>> and moving the mouse wildly around, so that the buffer is completely</div><div>> changed for every frame. I got around 5 fps, which isn't *that* much, but</div>
<div>> still an order of magnitude better than without your patches.</div><div>></div><div>> sysprof says there is 100% CPU usage, but unlike the previous 0.5-FPS</div><div>> recording, it's not in a single function, but spread out over several</div>
<div>> functions:</div><div>></div><div>> 35% weston_recorder_frame_notify</div><div>> 11% __memcpy_ssse3</div><div>> 4.5% clear_page_c</div><div>> 4.3% output_run</div><div>></div><div>> Although I'm not completely sure I'm reading the sysprof output right.</div>
<div>> weston_recorder_frame_notify, for example, has 35% CPU usage, but none of</div><div>> its child functions has any significant CPU usage. I presume the CPU usage</div><div>> in that function is from calling glReadPixels, although that's not apparent</div>
<div>> from sysprof:</div><div>></div><div>> weston_recorder_frame_notify 39.15%</div><div>> 39.15%</div><div>> - - kernel - - 0.00%</div>
<div>> 0.01%</div><div>> ret_from_intr 0.00%</div><div>> 0.01%</div><div>> __irqentry_text_start 0.00%</div><div>
<br></div><div>Well, if you look at weston_recorder_frame_notify function, it has a</div><div>naive loop over each single pixel it processes. component_delta() may</div><div>get inlined, and output_run() you saw in the profile.</div>
<div><br></div><div>I think it's possible it actually is weston_recorder_frame_notify</div><div>eating the CPU. Can you get more precise profiling, like hits per source</div><div>line or instruction?</div><div><br></div>
<div><br></div><div>Thanks,</div><div>pq</div><div><br></div></div><div class="gmail_extra"><br clear="all"><div><div dir="ltr"><span style="color:rgb(80,0,80)">Med venlig hilsen,</span><br style="color:rgb(80,0,80)"><br style="color:rgb(80,0,80)">
<span style="color:rgb(80,0,80)">Rune Kjær Svendsen</span><br style="color:rgb(80,0,80)"><span style="color:rgb(80,0,80)">Østerbrogade 111, 3. - 302</span><br style="color:rgb(80,0,80)"><span style="color:rgb(80,0,80)">2100 København Ø</span><br style="color:rgb(80,0,80)">
<span style="color:rgb(80,0,80)">Tlf.: 2835 0726</span><br></div></div>
<br><br><div class="gmail_quote">On Tue, Mar 26, 2013 at 8:58 AM, Pekka Paalanen <span dir="ltr"><<a href="mailto:ppaalanen@gmail.com" target="_blank">ppaalanen@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
On Tue, 26 Mar 2013 03:30:58 +0100<br>
<div class="im">Rune Kjær Svendsen <<a href="mailto:runesvend@gmail.com">runesvend@gmail.com</a>> wrote:<br>
<br>
</div><div><div class="h5">> Marek, do you have an idea on where the currency bottleneck is?<br>
><br>
> I just did a profiling with sysprof, zooming in on the desktop in Weston<br>
> and moving the mouse wildly around, so that the buffer is completely<br>
> changed for every frame. I got around 5 fps, which isn't *that* much, but<br>
> still an order of magnitude better than without your patches.<br>
><br>
> sysprof says there is 100% CPU usage, but unlike the previous 0.5-FPS<br>
> recording, it's not in a single function, but spread out over several<br>
> functions:<br>
><br>
> 35% weston_recorder_frame_notify<br>
> 11% __memcpy_ssse3<br>
> 4.5% clear_page_c<br>
> 4.3% output_run<br>
><br>
> Although I'm not completely sure I'm reading the sysprof output right.<br>
> weston_recorder_frame_notify, for example, has 35% CPU usage, but none of<br>
> its child functions has any significant CPU usage. I presume the CPU usage<br>
> in that function is from calling glReadPixels, although that's not apparent<br>
> from sysprof:<br>
><br>
> weston_recorder_frame_notify 39.15%<br>
> 39.15%<br>
> - - kernel - - 0.00%<br>
> 0.01%<br>
> ret_from_intr 0.00%<br>
> 0.01%<br>
> __irqentry_text_start 0.00%<br>
<br>
</div></div>Well, if you look at weston_recorder_frame_notify function, it has a<br>
naive loop over each single pixel it processes. component_delta() may<br>
get inlined, and output_run() you saw in the profile.<br>
<br>
I think it's possible it actually is weston_recorder_frame_notify<br>
eating the CPU. Can you get more precise profiling, like hits per source<br>
line or instruction?<br>
<br>
<br>
Thanks,<br>
pq<br>
</blockquote></div><br></div>