Differential D8804

Fix FIRST_ACTIVE regression due to KisRelaxedTimer
ClosedPublic
Actions

Authored by poke1024 on Nov 13 2017, 10:12 PM.

Details

Reviewers

dkazakov

Group Reviewers

Krita

Summary

This concerns https://bugs.kde.org/show_bug.cgi?id=386620.

The bug is a regression caused by using KisRelaxedTimer in KisSignalCompressor. Top of tree repeats with 2 * interval ms when it should repeat with interval ms, thus the lower frame rate. We could fix the problem by reverting KisRelaxedTimer.

Here follows an analysis of what happens and a proposed fix if we use KisRelaxedTimer.

This is what happens in KisCanvas2 (and KisSignalCompressor) during drawing (i.e continuous updates):

(A) updateSignalCompressor gets started: as KisSignalCompressor's timer is inactive: immediate timeout and start timer
(B) during next interval ms: all start requests to updateSignalCompressor get compressed (i.e. m_gotSignals gets set)
(C) after interval ms, timer callback happens, timer stops (as it's configured as single shot)
(D) after a few more ms (e.g. 3 ms), some new update request comes in, updateSignalCompressor gets started from scratch: as KisSignalCompressor's internal timer is inactive, an immediate timeout and and a new start timer happens
(E) and so on...

With QTimer, all this is fine.

But with KisRelaxedTimer, there is one problem: at (D), KisRelaxedTimer is no longer active, since it stopped with the callback in (C), as it's single shot (this is the same behavior as with QTimer). So (D) now restarts the inactive timer. But starting an inactive KisRelaxedTimer will incur an additional delay of up to interval, and this happens after every interval, thus the observed lower frame rate. To illustrate this, here's a typical sequence:

compressor gets started, restarts internal timer
compressor sets m_gotSignals for a few ms
compressor emits signal and stops interval timer
compressor and its timer are inactive for a few ms
compressor gets started, restarts internal timer
compressor sets m_gotSignals for a few ms
compressor emits signal and stops interval timer

The fix here is to make KisSignalCompressor in FIRST_ACTIVE mode be compressing a bit longer and keep its timer running for one more interval. That is, if KisSignalCompressor is compressing, and an compressed event has been sent, it should continue compressing one more interval, before it reverts into neutral mode (i.e. immediate callback mode plus compression).

One could argue, that the current top of tree implementation of KisSignalCompressor in FIRST_ACTIVE mode is not what's intended, as signals actually are emitted more often than once per interval ms due to the effect above.

This patch should guarantee that if events arrive with a rate higher or equal than interval ms, we will output signals with a rate of interval ms. Only if the frequency of the incoming events falls below interval ms, restarts of KisRelaxedTimermight happen, and we might thus drop the event signal output rate to up to 2 * interval ms.

Test Plan

I've reproduced the original problem by using a QElapsedTimer to measure successive call times in KisOpenGLCanvas2::paintGL, i.e.

qInfo() << "elapsed: " << m_elapsed.elapsed();
m_elapsed.start();
// rest of paintGL();

The times were about 80 to 90 ms, when they should have been 50 ms.

With this patch, the callback times now scatter around the expected value (+/- a few ms due to timer inaccuracies).

Diff Detail

Repository

R37 Krita

Lint

Lint Skipped

Unit

Unit Tests Skipped

poke1024 created this revision.Nov 13 2017, 10:12 PM

The patch does seem to make a difference. I previously used (on Windows) an external program to measure the framerate in OpenGL/Direct3D applications, and it always showed a lower value than what was set in Krita. Additionally, the effective drawing framerate in Krita was visibly much lower than that.

After the patch, the externally measured frame rate always remains consistent with the user-set limit, and the painting experience is significantly much smoother. Thus at least one issue appears to be solved.

However, even at 100 fps limit drawing still seems to be less smooth than with Krita 3.3.2.

To be sure that it isn't a frame limit issue I also tried in:

krita/libs/ui/dialogs/kis_dlg_preferences.cc

To increase the upper range here to, say, 200 fps:

sliderFpsLimit->setRange(20, 100);

If then I set it to 132 fps in the program (about the same measured framerate I externally measure with 3.3.2), drawing is still not as smooth as 3.3.2 . Video analysis also shows that at a 60 fps video recording rate brush strokes don't get updated every frame (while the system cursor does). Even setting it to 200 fps doesn't appear to make a difference (although to be fair on my system with the canvas/brush combination the frame rate maxes out at about 145 fps).

It could be some quirk related with Windows' internal triple-buffering/display refresh rate synchronization, but if it was the case, why would brush strokes in Krita 3.3.2 still appear to be smoother in execution?

I also tried this patch on Windows. If I set the fps limit to 40fps, the canvas fps (as painted on the canvas) says 32fps with this patch. Without this patch it says 24fps. It is an improvement, but curiously still a bit off...

What's worth noting is that with the 4.0 pre-alpha 2 I get 27fps with the same config. FWIW 6f3dc831b is not in the 4.0 pre-alpha 2, so the combination of 6f3dc831b and this patch would seem to have improved the fps limiting by a bit. However, the actual fps is still lower than the fps limiter value, so there seems to be another factor somewhere.

If I set the limit to 100fps it does get up to >70fps. (This also shows that it's not actively doing v-sync.)

In D8804#167475, @neviril wrote:

It could be some quirk related with Windows' internal triple-buffering/display refresh rate synchronization, but if it was the case, why would brush strokes in Krita 3.3.2 still appear to be smoother in execution?

IIRC that DWM only does double-buffering and v-sync. If you suspect it might be the cause you can test on Windows 7 with Aero disabled which will in turn disable DWM and bypass said buffering and v-sync.

Anyway, there are a bunch of OpenGL-related optimizations and the multi-threaded brush changes on master which are not present on 3.3.2, so it could really be any one of them.

As far as I can tell, the fix will "break" the following case:

Imagine we have a 50ms FIRST_ACTIVE compressor:

0ms: KisSignalCompressor::start(): signal emitted, timer started
20ms: KisSignalCompressor::start(): not signal emitted, m_gotSignals is scheduled to the next tick
50ms: KisSignalCompressor::slotTimerExpired(): signal emitted, internal timer is still *active*
70ms: KisSignalCompressor::start(): EXPECTED: signal emitted, timer started ACTUAL: the event is scheduled to the 100ms point
100ms: KisSignalCompressor::slotTimerExpired(): the signal is finally emitted

Speaking truly, I cannot say I like the new behavior. We use the compressor in quite a lot of places and it can lead to unexpected behavior. And in some places the delay is >1000ms, so (1 + err) * 1000ms might be a significant difference for the user :( Though, I'm afraid, I cannot propose any better solution. Either to add a special mode FIRST_ACTIVE_IMPRECISE or automatically switch the internal timer to the relaxed version if the timeout is smaller than, say, 100ms.

At the same time, I fully understand that old version of POSTPONE mode with delay < 100ms is highly inefficient, because it creates quite a lot of system timers.

Let's do the following: if you cannot imagine any better solution, just push the patch with the rename I noted inline. And we shall try to fix the regressions as soon as the show up.

libs/global/kis_signal_compressor.cpp
123	Please rename this method into something like `sheduleOnTheNextTick()`. Right now the code relies on a special case inside start() that checks where it is called from, which is highly non-obvious :) It will also let you avoid doing this extra dynamic_cast, because the check will be compile-time. And a short comment in the code about this workaround would be nice.

This revision is now accepted and ready to land.Nov 14 2017, 4:26 PM

Hm, I thought a lot more about this, and now think I understand that this is not a good solution.

In short, this patch does not address several nasty border cases. And as this is a core functionality for Krita and I agree frame updates should not get dropped, I have a another approach: https://phabricator.kde.org/D8868

Details:

First, there are the problems @dkazakov notes: (1) change of current behaviour for FIRST_ACTIVE, (2) added delays, that can't be controlled.

Second, I did more tests related to the observations by @neviril; at high frequencies (e.g. 10 ms intervals), this patch is not really a fix as often an additional signal won't get produced in the 10 ms that this patch now extends the safe phase to.

Third, there is the special case in KisSignalCompressor to emit a signal early if the timer gets swamped by other events; and that stops the timer and thus would produce the additional delays.

Closing this diff; it seems to be obsolete.

Revision Contents
Changeset List

			Path	Packages
M			libs/global/kis_signal_compressor.cpp (8 lines)

Diff 22297

View Options

libs/global/kis_signal_compressor.cpp

Diff	ID	Base	Description	Created	Lint	Unit
Base			Base
Diff 1	22297			Nov 13 2017, 10:05 PM	★	★