[Interest] Slow graphics effect (due to _dl_resolve_runtime_avx)

[Ch'Gans]

On 27 November 2016 at 07:59, Thiago Macieira <thiago.macieira at intel.com> wrote:
> On domingo, 27 de novembro de 2016 00:08:53 PST Ch'Gans wrote:
>> > That explains why _dl_runtime_resolve_avx was used, as opposed to the
>> > non-AVX version of it.
>> >
>> > Note that I can't find that function in glibc's source code. If it really
>> > is a problem, then your distribution caused it by applying a patch and
>> > you should complain to them. But I don't think that this the problem.
>> > Stop looking at _dl_runtime_resolve_avx, that's a red herring. Your
>> > problem is elsewhere.
>> It's in linux-ld.so. Anyway I gave up about the AVX2, i think you are
>> right, it was just a red herring.
>
> BTW, I've found it in it glibc source code meanwhile. I hate their
> organisation, it was not where I expected (though in hindsight I should have
> expected it). It's in sysdeps/, not elf/, and the assembly code is in the .h,
> not in the .S file...
>
>> But I gave another go at running valgrind, this time i started with
>> event logging off, then started the test app, start zooming until the
>> app slows down, then switched event logging on, zommed in a few times,
>> switched logging off and closed the test app.
>>
>> I think i have now better data to analise.
>>
>> If i sort the data by "Incl. Cost: Ir", then the top one is
>> QEventLoop::exec, called 1.2E9 times, then lot of event processing
>
> "Ir" is not call count, it's "instruction read", or more simply the number of
> instructions executed. That includes "nop" instructions, so it differs from
> the processor's own accounting of retired instructions. And it's not the count
> of cycles, since callgrind does not model how many cycles an instruction
> takes.
>
>> related functions, then the first event handler:
>> QGraphicsView::paintEvent, then scene drawItem, quickly follow by the
>> drop shadow effect draw(), the drop shadow filter draw(),
>> qt_blurImage() followed by expblur<>(), after that the cost drop
>>
>> drastically, so to resume roughly:
>> | Cost              , function
>>
>>   1,212,124,165, QEventLoop::exec()
>
> This line means "the problem happens while your application is executing its
> event loop" or the same as I had said before: "happens inside main".
>
>>   1,169,460,682, QGraphicsView::paintEvent()
>> ...
>>   1,123,576,248, QPixmapDropShadowFilter::draw()
>>   0,907,246,806, qt_blurImage()
>>   0,861,710,958, expblur<>()
>>   0,181,757,861, fillRect_normalized()
>> ...
>
> These are a lot more interesting. As expected, it happens inside the paint
> event, whose time is 96% taken by the drop shadow filter. Note that the
> relative time is not per se a problem: *something* has to take time. But since
> we know it's slow, that is a good target for the culprit.
>
>> What i'm trying to say here, is that almost all the events seem to be
>> targeted at repainting the drop shadow, and I can tell you that the
>> test app ran for only a couple of seconds during which i was
>> wheel-zooming, and the GraphicsView had visually changed only 4 or 5
>> times.
>>
>> So something tells me that, for some reasons, the drop shadow is
>> repainted way too many times, yet the app on the screen is updated
>> only once every second or so.
>
> Your interpretation is incorrect because it's based on the wrong assumption
> that the number is call count. It's not.
>
> The number is more closely related to time spent, so the correct
> interpretation is that most of the application's time is dedicated to
> repainting the drop shadow.
>
> We don't know why that is. The instruction read count is the product of the
> cost of each instruction every time it is called by the number of times it is
> called. So it's still possible we have a call count problem, but your evidence
> doesn't show that or disprove it. It's possible that on your system, the drop
> shadow needs to be painted way more often than on another system.

I have setup a test app, no more manual zoom, here is how it works:
1 QTimer to fire a 10% zoom-in every 500ms (view.scale(1.1, 1.1))
1 QElapsedTimer used to display the elapsed time b/w two calls of the
above QTimer callback
1 QElapsedTimer to display the time elapsed b/w to
QGraphicsView::paintEvent (using event filter from main window)

The results show that:
- Only one paint event is generated per scaling of the view (well only
one paint event is captured by the eventFilter)
- the period of the paint event equals the period of the calls to
scale(), always.
- the period of both timer and paint event *is* 500ms as long as
there's no slow down

But, As the view's scale factor reach 200 (view::transform().m11() >
200), the period of the timer still equal the period of the paint
event, there is still a single paint event per scale() call, but now
the timer/paint period start increasing (kind of) exponentially, as
the scale factor reach 500, the timer period is ca. 3s.

With valgrind data, Thiago's explanations and this timing data, the
conclusion seems to be:
- scaling the view always cause a repaint of the drop shadow effect,
even if the drop shadow doesn't need to be painted (since it is fully
hidden behind the tiny portion of the visible ellipse)
- the time to paint (calculate) the drop shadow grows exponentially
with the level of detail.
- There are no event loop crazyness (1 call to scale() generates a
single paintEvent())
- This happens on a Linux PC with AMD CPU
- This doesn't happen on a Windows PC with Intel CPU (Will run the new
automated test on Tuesday)
- Setting the view's viewport to a QOpenGLWidget doesn't make any difference

Notes, yesterday i made the following changes to my computer:
- Installed support for AMD64 microcode
- Switched my graphics card drivers (NVidida) from OpenSource to the
proprietary ones
- It didn't make any difference

I would like to add one comment about the drop shadow being
systematically repainted/recalculated:
The drop shadow does depends on the view scaling (3D lighting), so
painting the drop shadow means recalculating it, *but* if the drop
shadow doesn't need to be painted (b/c it is hidden), it shouldn't be
repainted.

Chris

>
> --
> Thiago Macieira - thiago.macieira (AT) intel.com
>   Software Architect - Intel Open Source Technology Center
>
> _______________________________________________
> Interest mailing list
> Interest at qt-project.org
> http://lists.qt-project.org/mailman/listinfo/interest