Bug 386846

I think at this point it is clear that it is a Qt bug. Why have not you opened a Qt bug instead of creating this one here?

Realistically Qt aren't going to do anything with the amount of info we currently have.

FWIW, I can confirm this bug with 5.10.5

changing my desktop background from slideshow to static image made the CPU load drop from consuming a whole CPU core to not really noticeable.

If anyone can reproduce this with the attached test in #1 and has a self-compiled up-to-date Qt. Please message me.

I compiled Qt 5.9.2 from source to try to debug this a just a few hours ago. So far i see a timer with type Qt::PreciseTimer and a 5ms interval.

By the way, compilation produced 15GiB of build files on my disk, which is a bit too much for me to keep. I have seen that Qt's configure script supports -skip option. If you can tell me what i can skip get a minimal Qt build to test this bug, i will be thankful.

<3 thanks!

200fps sounds problematic. Which timer specifically looking at?

The QSGAnimationDriver reads the screen refresh rate, and then does some timer maths on that; but as I understand it the QSGGuiRenderLoop doesn't use that timer, and uses the animation driver from the main app.


Also can you put a debug line at the end of 
QSGGuiThreadRenderLoop::renderWindow()

Can you print out

qDebug() << "Dave - render window" << window << data.updatePending;

 at the end of the method






----

I have:
skip=qtenginio qtfeedback qtlocation qtpim qtquick1 qtsystems qtwebsockets qtscxml

That 5ms timer might be coming from:

void QQuickWidget::triggerUpdate()
{
    Q_D(QQuickWidget);
    d->updatePending = true;
     if (!d->eventPending) {
        // There's no sense in immediately kicking a render off now, as
        // there may be a number of triggerUpdate calls to come from a multitude
        // of different sources (network, touch/mouse/keyboard, timers,
        // animations, ...), and we want to batch them all into single frames as
        // much as possible for the sake of interactivity and responsiveness.
        //
        // To achieve this, we set a timer and only perform the rendering when
        // this is complete.
        const int exhaustDelay = 5;
        d->updateTimer.start(exhaustDelay, Qt::PreciseTimer, this);
        d->eventPending = true;
    }
}

which doesn't look like the cause for this bug? (I just did a blunt git grep for PreciseTimer, though, there might be places I missed)

Calls made as a result of this timer are always in stack when i pause the debugger once i have triggered the bug. Also this timer leads to a call to the method David is asking about.

@David

Before i trigger the bug it prints "true" while the animation is running, then it prints "false" twice and then it stops. When i trigger the bug it keeps printing "true" forever. The window is always the same.

@Kai AFAIK, we're not in a QQuickWidget?

>When i trigger the bug it keeps printing "true" forever. The window is always the same.

That's exactly what I half expected; we're told to re-render before we've finished our first render.

Our end goal is to see what's setting updatePending=true between 

382:    data.updatePending = false;
and 469

I doubt it's a timer, as we shouldn't be processing events.

I don't suppose you could trigger the bug.

 Break after updatePending = false, and do
"watch data.updatePending" and get a trace


*or*

put breakpoints in  
maybeUpdate
exposureChanged

and get loads of traces.


>Calls made as a result of this timer are always in stack

How do you know which timer it was from a stack trace? It'll just say QEventDispatcher::blahblah ?
Can you paste one.



----

Also thank you *so so much* for putting in the time here.

Created attachment 109003 [details]
A backtrace which is usually seen when pausing when the bug is triggered

This is the full backtrace i always get when pausing when the bug is in effect. Note frame 35 in thread 1. It's QTimerInfoList::activateTimers() . In this backtrace it says currentTimerInfo = 0x0, but if i put a breakpoint a in that function few lines earlier, i can see non-null value of currentTimerInfo and examine it's fields. That is how how i know which timer. Also, currentTimerInfo->obj is a QQmlPrivate::QQmlElement<QQuickWindowQmlImpl> .

I've found our 5 second timer.

It'll be QPlatformWindow::requestUpdate which is called from QWindow::requestUpdate();

Setting QT_QPA_UPDATE_IDLE_TIME=20 should prove that's the case.

Though I think this timer is a red herring. 

We're getting into this timer and rendering because the window is saying "update me now!" and this is throttling it slightly. 
The bug we need to find is why the window is saying "update me now!" instead of syncing to 60fps.

Can I get the backtraces from when maybeUpdate is called please

Created attachment 109012 [details]
A backtrace from call to maybeUpdate when the bug is in effect

QSGGuiThreadRenderLoop::maybeUpdate() seems to be called twice per frame: from QQuickAnimatorController::beforeNodeSync() and then again at the end of QSGGuiThreadRenderLoop::renderWindow() . The attached backtrace is from the first call.

Each double click in the window (a bug.qml window) adds one more element into QQuickAnimatorController::m_animationRoots, and it seems to be never removed.

The animation driver has a bit of code that says at the start of the render "queue render me again!".
It's not great, but you can see how it'd work.  

What I think we want to see is 5ms between frames. Still high, but meh. 
What we're actually doing is 5ms between the start of frames. Which if rendering is taking 5ms, is 100% constantly.

IMHO, the animatotion driver only wants to mark the window dirty, and not request the update

This would match what the threaded render loop is doing:

QSGThreadedRenderLoop::maybeUpdate
    // Call this function from the Gui thread later as startTimer cannot be
        w->updateDuringSync = true;

which is the same as the basic render loop's m_windows[window].updatePending

which then would only start the timer at the end of renderWindow and give us a significant reduction.

Created attachment 109021 [details]
QtDeclarative patch to only update after frame

I've made a patch.
I can confirm that on my system things still render on the gui render loop
ksplashqml is between 0 and 1% CPU usage..but mine wasn't high before either.

Would be great if you can test.

I think we are talking about different bugs now... What you seem to be trying to fix is high CPU usage *during* the animation. What i (and probably most people in the original bug 381000) was talking about is that CPU usage does not drops *after* the animation has finished.

For me the cross-fade animation in Plasma Shell produces around 15% of CPU usage with Animators (4-core CPU). This may be sub-optimal, but not a big deal for me, since wallpapers do not change too often. I remember that you said that some progress indicator is also affected. This may be worse, because it may be meant to be animating much longer then a wallpaper cross-fade. It looks like some people in bug 381000 experience even higher CPU usage, so this may be a problem. However, this is a different problem. The problem i was talking about is that Plasma Shell *always* uses around 7-10% CPU while wallpaper is set to slideshow, even when cross-fade animation is not running. Plasma Shell just keeps redrawing forever.

The .qml file i created earlier (attachment 108642 [details]) manages to reproduce persistent redraws while the animation is *not* running, but it produces much lower CPU usage than Plasma. It's around 2-4% on my system.

That being said, i have tried your patch. I was only able to try it with attachment 108642 [details] (with duration changed from 2000 to 200000) but there was no noticeable difference. Both consumed around 2-4% during animation. Persistent redrawing, triggered by a double click, was not fixed either. I was not able to run Plasma Shell with patched libraries because when i try to run it i get an error:

$ env LD_LIBRARY_PATH=~/myqt/install/lib plasmashell
plasmashell: /home/vovams/myqt/install/lib/libQt5Core.so.5: version `Qt_5.9.2_PRIVATE_API' not found (required by /usr/lib64/libKF5Declarative.so.5)

Actually i think that i might be unable help you with testing CPU usage *during* animation, because replacing Animators with Animations does not reduce CPU usage *during* animation for me. It does fix persistent redraws and thus reduces CPU usage to 0 when animation is *not* running.

Please look again at my comment 13. I believe we have found the reason behind persistent redraws. It looks like QQuickAnimatorController::animationFinished() is never called for canceled animation (i.e. after the second click in bug.qml window).

Oh, I might be getting confused.

I shall review that bit of code you referenced. Thanks.

I have reproduced the issue on my home PC which, i thought, was not affected. I just started qmlscene and plasmashell with QSG_RENDER_LOOP=basic (my home PC uses threaded rendering by default). Both apps demonstrate the same behavior as on my work PC, on which i experienced the issue before. The CPU usage (while not animating), however, is much lower than on my work PC: it's around 1-2% for qmlscene and 2-3% for plasmashell. When plasmashell is started as usual (i.e. with threaded rendering), it's CPU usage is 0-1% here.

I have made a video demonstrating the issue. It is recorded with KWin effect which highlights redraws enabled and with mouse clicks highlighting. The qmlscene window on the left uses threaded rendering, and the one on the right uses basic rendering.

https://drive.google.com/open?id=1U-B70mKQLIwbuT7q9xBqo81gLAi8p8Q6

(I changed colors from red/blue to green/blue for better visibility.)

Also, i noticed that System Settings app is also affected on my home PC even without setting QSG_RENDER_LOOP (see the last paragraph of https://bugs.kde.org/show_bug.cgi?id=381000#c141 ). This may be because of some different issue though.

Both of my systems have updated to Qt 5.10.0 and i can no longer reproduce the issue. Neither with bug.qml nor in Plasma Shell nor in System Settings. Fixed, i think.

One thing i noted, however, is that the highlight-redraws effect starts blinking more often after a second click in the bug.qml window. It returns to normal blinking frequency later, before the new animation finishes. I think that the canceled animation is still not really being canceled, but now it stops at the moment when it should have finished. So there is a chance this bug may come back later.

That might be why I struggled to reproduce (I've been on 5.10 branches for a while).

Thanks again for following up.

6990ae6c1bad32952e371fa72bee65a7af11c313 is probably relevant given everything we've analysed so far.