[Moved] Timer used to repaint (advance) delayed by event flood processing

dflorin

Ok, thanks. I will try that and get back with the result.

giesbert

But what is done inside this events.

If I countthe events you tell, it is about 110 evnts, that's not much work. But what is done inside Scene::event? Why is bat painted 50 times? that means 50 times a complete viewport repaint? That is overhead.

If Ball::advance initiates an update, which results in a full repaint, that means in your example 63 times a full repaint with all items / elemnts. I'm not sure how fast you processor is (as it's an embedded device I think). On a PC, it wouldn't be problematic.

What do you do in the touch events? Is this time consuming?

All this were just ideas, that came into my mind.

goetz

On one of the last DevDays there was talk about speeding up QGraphicsView. Here are some of the presentations that might help you:

"Graphics View (2007) ":http://qt.nokia.com/developer/learning/online/talks/archive/developerdays2007/graphics-view
"Optimizing Performance in Qt-Based Applications (2009) ":http://qt.nokia.com/developer/learning/online/talks/developerdays2009/tech-talks/optimizing-performance-in-qt-based-applications
"Beautiful and Blazing-Fast Graphics with Qt (2008) ":http://qt.nokia.com/developer/learning/online/talks/archive/developerdays2008/beautiful-and-blazing-fast-graphics-with-qt

I did not review the videos, so it could also be that they fail the topic completely.

I do remember that some issues can be solved by setting the proper caching strategy to avoid complete repaints of the graphics scene.

DenisKormalev

Gerolf is right, full repaint is an overhead. Maybe you can try to make partial repaints (where it is needed)?

dangelog

[quote author="dflorin" date="1293490166"]
When moving the bat as fast as I can using touch events:

Scene::event() called 47 times (this is how fast I move the bat by touching the screen)
Bat::paint() called 50 times (how many times the bat is repainted as a result of setPos() called from the event() method and as a result of paint() done for the ball)
Ball::advance() called 13 times (this is called by the timer and should be 30 calls instead) - this is my problem: the ball has slowed down at less than half speed.
[/quote]

Are these values per second? Can you monitor the CPU usage while moving the bat and/or profile? This doesn't seem to be a flood of events (47+50+13 = 120), rather it seems you're wasting CPU somewhere (for processing events, drawing, etc.) and not returning to the event loop so often like you should; especially, a full viewport update seems to be an overkill. Is there any reason why you chose to do so?

[quote] And one more thing: this is noticeable on a Symbian device. Running it in the simulator on Windows and using mouse events instead of touch events does not slow down the ball. Should the post be moved to Mobile and Embedded?[/quote]

Perhaps the Symbian device hasn't the needed CPU power, or there's a bug somewhere. I'll leave the decision about moving the post to admins :-)

giesbert

As Volker told, there were topics on repainting the QGraphicsView, also on 2010. They showed the difference between Raster painting, open GL etc. I think, it was this:

"Performance: Do Graphics the Right Way ":http://qt.nokia.com/developer/learning/online/talks/developerdays2010/tech-talks/performance-do-graphics-the-right-way

goetz

YESSS! Gerolf, you are a truffle pig :-)

DenisKormalev

[quote author="peppe" date="1293492647"]
Perhaps the Symbian device hasn't the needed CPU power, or there's a bug somewhere. I'll leave the decision about moving the post to admins :-)[/quote]

I'll leave it here for some time. Maybe some Troll can confirm that it is related only to mobile (or even only to symbian).

dflorin

Some more measurements.

This is how it looks before moving the bat:

bq. [Qt Message] "13:29:53.620" Scene::event() ENTER
[Qt Message] "13:29:53.621" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.624" Bat::paint() - paintCount: 63
[Qt Message] "13:29:53.627" Ball::paint() ENTER
[Qt Message] "13:29:53.630" Ball::paint() EXIT
[Qt Message] "13:29:53.647" Ball::advance() - ENTER
[Qt Message] "13:29:53.649" Ball::advance() - advanceCount: 63
[Qt Message] "13:29:53.650" Ball::advance() - EXIT
[Qt Message] "13:29:53.652" Scene::event() ENTER
[Qt Message] "13:29:53.653" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.656" Bat::paint() - paintCount: 64
[Qt Message] "13:29:53.660" Ball::paint() ENTER
[Qt Message] "13:29:53.663" Ball::paint() EXIT
[Qt Message] "13:29:53.678" Ball::advance() - ENTER
[Qt Message] "13:29:53.680" Ball::advance() - advanceCount: 64
[Qt Message] "13:29:53.681" Ball::advance() - EXIT
[Qt Message] "13:29:53.683" Scene::event() ENTER
[Qt Message] "13:29:53.684" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.688" Bat::paint() - paintCount: 65
[Qt Message] "13:29:53.692" Ball::paint() ENTER
[Qt Message] "13:29:53.695" Ball::paint() EXIT
[Qt Message] "13:29:53.711" Ball::advance() - ENTER
[Qt Message] "13:29:53.713" Ball::advance() - advanceCount: 65
[Qt Message] "13:29:53.714" Ball::advance() - EXIT
[Qt Message] "13:29:53.716" Scene::event() ENTER
[Qt Message] "13:29:53.718" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.722" Bat::paint() - paintCount: 66
[Qt Message] "13:29:53.725" Ball::paint() ENTER
[Qt Message] "13:29:53.728" Ball::paint() EXIT

This is how it looks after I start touching the screen and moving the bat as fast as I can:

bq. Qt Message] "13:29:53.732" Scene::event() ENTER
[Qt Message] "13:29:53.733" Scene::event() - touchCount: 1
[Qt Message] "13:29:53.737" Scene::event() EXIT - touch event processed
[Qt Message] "13:29:53.738" Scene::event() ENTER
[Qt Message] "13:29:53.740" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.742" Scene::event() ENTER
[Qt Message] "13:29:53.744" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.746" Ball::advance() - ENTER
[Qt Message] "13:29:53.748" Ball::advance() - advanceCount: 66
[Qt Message] "13:29:53.751" Ball::advance() - EXIT
[Qt Message] "13:29:53.753" Scene::event() ENTER
[Qt Message] "13:29:53.754" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.757" Bat::paint() - paintCount: 67
[Qt Message] "13:29:53.760" Ball::paint() ENTER
[Qt Message] "13:29:53.763" Ball::paint() EXIT
[Qt Message] "13:29:53.778" Ball::advance() - ENTER
[Qt Message] "13:29:53.780" Ball::advance() - advanceCount: 67
[Qt Message] "13:29:53.783" Ball::advance() - EXIT
[Qt Message] "13:29:53.785" Scene::event() ENTER
[Qt Message] "13:29:53.786" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.789" Bat::paint() - paintCount: 68
[Qt Message] "13:29:53.791" Ball::paint() ENTER
[Qt Message] "13:29:53.794" Ball::paint() EXIT
[Qt Message] "13:29:53.809" Ball::advance() - ENTER
[Qt Message] "13:29:53.812" Ball::advance() - advanceCount: 68
[Qt Message] "13:29:53.815" Ball::advance() - EXIT
[Qt Message] "13:29:53.816" Scene::event() ENTER
[Qt Message] "13:29:53.818" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.821" Bat::paint() - paintCount: 69
[Qt Message] "13:29:53.824" Ball::paint() ENTER
[Qt Message] "13:29:53.827" Ball::paint() EXIT
[Qt Message] "13:29:53.838" Scene::event() ENTER
[Qt Message] "13:29:53.840" Scene::event() - touchCount: 2
[Qt Message] "13:29:53.842" Scene::event() EXIT - touch event processed
[Qt Message] "13:29:53.846" Scene::event() ENTER
[Qt Message] "13:29:53.848" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.851" Scene::event() ENTER
[Qt Message] "13:29:53.852" Scene::event() - touchCount: 3
[Qt Message] "13:29:53.854" Scene::event() EXIT - touch event processed
[Qt Message] "13:29:53.855" Scene::event() ENTER
[Qt Message] "13:29:53.857" Scene::event() EXIT - NO touch event
[Qt Message] "13:29:53.858" Ball::advance() - ENTER
[Qt Message] "13:29:53.860" Ball::advance() - advanceCount: 69
[Qt Message] "13:29:53.862" Ball::advance() - EXIT

As you can see from the traces, when no touch, the interval between 2 consecutive advance() calls is 30ms. After the first touch it raises to 49ms while touch 2 and 3 are processed.

Here is the processing inside the event() method:

@bool MyGraphicsScene::event(QEvent *event)
{
qDebug() << QDateTime::currentDateTime().toString("hh:mm:ss.zzz") << "Scene::event() ENTER";
switch (event->type()) {
case QEvent::TouchBegin:
case QEvent::TouchUpdate:
case QEvent::TouchEnd:
{
QTouchEvent *touchEvent = static_cast<QTouchEvent *>(event);

        if (touchEvent->touchPoints().count() == 1) {
            const QTouchEvent::TouchPoint &touchPoint1 = touchEvent->touchPoints().first();

            QGraphicsItem *bat = items().at(4);
            qreal p = touchPoint1.scenePos().y();
            qreal lp = touchPoint1.lastScenePos().y();
            qreal dY = p - lp;
            bat->setPos(bat->pos().x(), bat->pos().y() + dY/4);
        }

        break;
    }

    default:
        qDebug() << QDateTime::currentDateTime().toString("hh:mm:ss.zzz") << "Scene::event() EXIT - NO touch event";
        return QGraphicsScene::event(event);
}

touchCount++;
qDebug() << QDateTime::currentDateTime().toString("hh:mm:ss.zzz") << "Scene::event() - touchCount: " << touchCount;
qDebug() << QDateTime::currentDateTime().toString("hh:mm:ss.zzz") << "Scene::event() EXIT - touch event processed";

return true;

}@

goetz

I've moved the thread to the Mobile and Embedded forum, as the problem only occurs on the Symbian platform.

dangelog

As I said, profile the CPU usage. Is OpenGL somehow involved?

giesbert

If you look at the time, needed in the events:

bq. [Qt Message] “13:29:53.620” Scene::event() ENTER
[Qt Message] “13:29:53.621” Scene::event() EXIT – NO touch event

bq. Qt Message] “13:29:53.732” Scene::event() ENTER
[Qt Message] “13:29:53.733” Scene::event() – touchCount: 1
[Qt Message] “13:29:53.737” Scene::event() EXIT – touch event processed
[Qt Message] “13:29:53.738” Scene::event() ENTER
[Qt Message] “13:29:53.740” Scene::event() EXIT – NO touch event

So in case of touch, it takes 7 msecs, otherwise 1 msec.
As it seams, there are more events, it would be interesting, which type of evenmts come in.

what I also saw, was:

bq. [Qt Message] “13:29:53.746” Ball::advance() – ENTER
[Qt Message] “13:29:53.778” Ball::advance() – ENTER
[Qt Message] “13:29:53.809” Ball::advance() – ENTER
[Qt Message] “13:29:53.858” Ball::advance() – ENTER

it's only one advance call that is delayed. And if your touch event takes 7 msecs, and you get 2 or three of them, that is 14 to 21 msecs.

So, my next try would be check the event types of the events, that come in at Scene::event() ( as there are more than without touch that are not touch).

Reduce amount of data to redraw.

giesbert

Aditionally, painting the ball takes 4 msecs, painting the bat also takes ??? (I think 2 - 3 msecs, from the trace).

dflorin

I did some adjustments in the code:

I changed the update mode: view.setViewportUpdateMode(QGraphicsView::MinimalViewportUpdate);
the scene was receiving mouse events, so I skip their handling do that they are not forwarded to the Bat object. As a result, now also the Bat is moving with interruptions (paint is not called that often anymore)

Here is a piece of trace with a lot of events coming and only one paint:
bq. [Qt Message] "02:14:19.789" Ball::advance() - ENTER
[Qt Message] "02:14:19.791" Ball::advance() - advanceCount: 113
[Qt Message] "02:14:19.793" Ball::advance() - EXIT
[Qt Message] "02:14:19.795" Scene::event() ENTER eventType = 43
[Qt Message] "02:14:19.798" Scene::event() - event FORWARDED
[Qt Message] "02:14:19.800" Scene::event() EXIT
[Qt Message] "02:14:19.803" Ball::paint() ENTER
[Qt Message] "02:14:19.805" Ball::paint() EXIT
[Qt Message] "02:14:19.821" Ball::advance() - ENTER
[Qt Message] "02:14:19.823" Ball::advance() - advanceCount: 114
[Qt Message] "02:14:19.825" Ball::advance() - EXIT
[Qt Message] "02:14:19.827" Scene::event() ENTER eventType = 43
[Qt Message] "02:14:19.829" Scene::event() - event FORWARDED
[Qt Message] "02:14:19.830" Scene::event() EXIT
[Qt Message] "02:14:19.833" Ball::paint() ENTER
[Qt Message] "02:14:19.835" Ball::paint() EXIT
[Qt Message] "02:14:19.840" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:19.843" Scene::event() - touchCount: 130
[Qt Message] "02:14:19.845" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:19.846" Scene::event() EXIT
[Qt Message] "02:14:19.849" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:19.851" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:19.853" Scene::event() EXIT
[Qt Message] "02:14:19.854" Scene::event() ENTER eventType = 43
[Qt Message] "02:14:19.856" Scene::event() - event FORWARDED
[Qt Message] "02:14:19.858" Scene::event() EXIT
[Qt Message] "02:14:19.861" Bat::paint() - paintCount: 29
[Qt Message] "02:14:19.865" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:19.868" Scene::event() - touchCount: 131
[Qt Message] "02:14:19.870" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:19.873" Scene::event() EXIT
[Qt Message] "02:14:19.875" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:19.878" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:19.880" Scene::event() EXIT
[Qt Message] "02:14:19.882" Scene::event() ENTER eventType = 43
[Qt Message] "02:14:19.884" Scene::event() - event FORWARDED
[Qt Message] "02:14:19.886" Scene::event() EXIT
[Qt Message] "02:14:19.889" Bat::paint() - paintCount: 30
[Qt Message] "02:14:19.893" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:19.896" Scene::event() - touchCount: 132
[Qt Message] "02:14:19.898" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:19.900" Scene::event() EXIT
[Qt Message] "02:14:19.902" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:19.904" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:19.906" Scene::event() EXIT
[Qt Message] "02:14:19.912" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:19.915" Scene::event() - touchCount: 133
[Qt Message] "02:14:19.917" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:19.919" Scene::event() EXIT
[Qt Message] "02:14:19.923" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:19.925" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:19.927" Scene::event() EXIT
[Qt Message] "02:14:19.932" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:19.934" Scene::event() - touchCount: 134
[Qt Message] "02:14:19.936" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:19.938" Scene::event() EXIT
[Qt Message] "02:14:19.940" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:19.942" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:19.944" Scene::event() EXIT
------------- and many more like these ----------
[Qt Message] "02:14:20.195" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:20.200" Scene::event() - touchCount: 145
[Qt Message] "02:14:20.202" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:20.204" Scene::event() EXIT
[Qt Message] "02:14:20.210" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:20.213" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:20.215" Scene::event() EXIT
[Qt Message] "02:14:20.233" Scene::event() ENTER eventType = 195
[Qt Message] "02:14:20.235" Scene::event() - touchCount: 146
[Qt Message] "02:14:20.237" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:20.238" Scene::event() EXIT
[Qt Message] "02:14:20.240" Scene::event() ENTER eventType = 155
[Qt Message] "02:14:20.241" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:20.243" Scene::event() EXIT
[Qt Message] "02:14:20.250" Scene::event() ENTER eventType = 196
[Qt Message] "02:14:20.252" Scene::event() - touchCount: 147
[Qt Message] "02:14:20.254" Scene::event() TOUCH event PROCESSED
[Qt Message] "02:14:20.255" Scene::event() EXIT
[Qt Message] "02:14:20.257" Scene::event() ENTER eventType = 157
[Qt Message] "02:14:20.259" Scene::event() - MOUSE event SKIPPED
[Qt Message] "02:14:20.261" Scene::event() EXIT
[Qt Message] "02:14:20.262" Scene::event() ENTER eventType = 43
[Qt Message] "02:14:20.264" Scene::event() - event FORWARDED
[Qt Message] "02:14:20.265" Scene::event() EXIT
[Qt Message] "02:14:20.267" Bat::paint() - paintCount: 31
[Qt Message] "02:14:20.271" Ball::advance() - ENTER
[Qt Message] "02:14:20.273" Ball::advance() - advanceCount: 115
[Qt Message] "02:14:20.275" Ball::advance() - EXIT

It seems the CPU is fully doing event processing. Also when running it in the simulator on W Vista, usage suddenly goes up to 70-80% when moving the bat.

You can download the whole project source code here:
https://docs.google.com/leaf?id=0ByKJUz8lbzypNjRmM2JlYTgtZTViYS00YzQyLTk2YzAtNmFjZDJlYjNjMDY5&hl=en&authkey=CKL7rs8G

giesbert

Hi,

I scanned your traces a bit and extended them with the event types:

bq.
[Qt Message] “02:14:19.795” Scene::event() ENTER eventType = 43 [Qt Message] “02:14:19.827” Scene::event() ENTER eventType = 43 [Qt Message] “02:14:19.840” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:19.849” Scene::event() ENTER eventType = 155 [Qt Message] “02:14:19.854” Scene::event() ENTER eventType = 43 [Qt Message] “02:14:19.865” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:19.875” Scene::event() ENTER eventType = 155 [Qt Message] “02:14:19.882” Scene::event() ENTER eventType = 43 [Qt Message] “02:14:19.893” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:19.902” Scene::event() ENTER eventType = 155 [Qt Message] “02:14:19.912” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:19.923” Scene::event() ENTER eventType = 155 [Qt Message] “02:14:19.932” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:19.940” Scene::event() ENTER eventType = 155 ——————- and many more like these—————
[Qt Message] “02:14:20.195” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:20.210” Scene::event() ENTER eventType = 155 [Qt Message] “02:14:20.233” Scene::event() ENTER eventType = 195 [Qt Message] “02:14:20.240” Scene::event() ENTER eventType = 155 [Qt Message] “02:14:20.250” Scene::event() ENTER eventType = 196 [Qt Message] “02:14:20.257” Scene::event() ENTER eventType = 157 [Qt Message] “02:14:20.262” Scene::event() ENTER eventType = 43 --> MetaCall
--> MetaCall
--> TouchUpdate
--> GraphicsSceneMouseMove
--> MetaCall
--> TouchUpdate
--> GraphicsSceneMouseMove
--> MetaCall
--> TouchUpdate
--> GraphicsSceneMouseMove
--> TouchUpdate
--> GraphicsSceneMouseMove
--> TouchUpdate
--> GraphicsSceneMouseMove
--> TouchUpdate
--> GraphicsSceneMouseMove
--> TouchUpdate
--> GraphicsSceneMouseMove
--> TouchEnd
--> GraphicsSceneMouseRelease
--> MetaCall

Then I looked, which event takes which time:

|Event Type|average Time (msecs)|Called|
|MetaCall|4|5|
|TouchUpdate|5|7|
|GraphicsSceneMouseMove|4.5|7|
|TouchEnd|5|1|
|GraphicsSceneMouseRelease|4|1|

MetaCall is in fact an async called slot

dflorin

So is this an issue related to the HW (the Symbian device being too slow to handle all these events in "real time")?

As a bottom line of the debug data during the event flood:

the interval between two consecutive paints of the Bat was about 280ms (02:14:19.889 -> 02:14:20.267). During this period there were 15 touch events, 15 mouse events and some MetaCall events. Why isn't paint() called more often for Bat ? The setPos() for the Bat should trigger paint() roughly after each touch event when the new position of the Bat is set.
the interval between 2 consecutive advance() calls for the Ball (i.e. timer's timeout()) is 450ms (02:14:19.821 -> 02:14:20.271) when it should be 30ms. So the timer does not get CPU time during the event processing.

Is there a way to speed this up? Or is the target HW so poor? (FYI, it is a Nokia C7, where full HD videos play like magic).

What is the right way to handle those events and update the scene?

giesbert

so, if you call repaint, the repaint is done imediately, if you call update, it's posted to the evnt loop. Three calls to update may result in one paint event, as they are compressed and done together. So if the event queue contains 10 events, you post an update, you have 11 events. If you aditionally post 3 events and 3 updates, you will have 14 events in the queue, as the update events are combined.

I'm not sure, why you get so many touch events, but if they appear in the queue, all other events will be after those. A started timer does not guarantee, that you receive the event after 30 seconds, the event is fired after 30 seconds. If the event queue is full, it wil take time to receive them....

dflorin

[quote author="Gerolf" date="1293631695"]so, if you call repaint, the repaint is done imediately, if you call update, it's posted to the evnt loop.[/quote]

I am not calling explicitly repaint() nor update(). The scene is handling it its own way as a result of the setPos() - position change for the Bat.

So this looks like the event queue is so loaded, that the paint and timer events are doomed to wait quite long until the touch events are processed... Is it normal to wait many hundreds of milliseconds on the event queue?

giesbert

That depends (typical computer answer ;-) ).
If there are too many events and the events take too long to process, it's normal.
So you could try to reduce the ammount of things to do in the events.

currently, for each touch event, you are changing the position, this implies a call to update.

That would be a point for optimization.
also, do you need touch begin/end/move or only one of those..?

koshui

Hi, what device you are running this on?
QDateTime::CurrentDateTime() takes quite long to execute and thus skews the results. You should change that to QElapsedTimer http://doc.qt.nokia.com/4.7/qelapsedtimer.html . Also redirect the debug output to custom handler that writes the data at the end of the program.
This way you won't be measuring how long it takes to do debug prints :)

If you are trying to draw on each touch event it will choke. I'd recommend updating only when case QEvent::TouchUpdate and then have some check that if the update was significant enough to move the paddle.

If this doesn't help then you could try to find out if you are getting excessive amount of events because of capacitive screen? see http://doc.qt.nokia.com/4.7/qtouchevent-touchpoint.html .

Edit: can't remember right now if you can increase the timer priority to higher than touch/pointer event priority. it is new years and few beers :D