[Kde-games-devel] Low framerate in Kdiamond

[Stefan Majewsky]

Warning: A very long post follows, but I highly appreciate any programmer with 
knowledge of the Graphics View framework to read through this.

Am Sonntag 18 Mai 2008 17:44:30 schrieb Eugene Trounev:
> Why is kdiamond so sloooow? (It has always been by the way). If I switch to
> Very Easy and make it full screen the updates are extremely slow... I can
> see every sprite in the disappear animation one by one, and the drop down
> takes seconds. Can it be helped somehow?

I couldn't remember why I gave up on that topic, so I "kDebug"ged a bit to see 
where much time is spent. This is the output produced by a "fill gaps" 
animation (here on a 30x30 board at 1440x900 resolution to raise the time 
differences into msecs areas):

kdiamond(11620) MoveAnimator::setFrame: Calculating  75  animations in frame  
6  of  6  starts at  244  msecs with a scheduled total of  240  msecs

kdiamond(11620) MoveAnimator::setFrame: Calculating  2  animations in frame  2  
of  6  starts at  82  msecs with a scheduled total of  240  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  2  animations in frame  3  
of  6  starts at  126  msecs with a scheduled total of  240  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  2  animations in frame  4  
of  6  starts at  161  msecs with a scheduled total of  240  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  2  animations in frame  5  
of  6  starts at  200  msecs with a scheduled total of  240  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  2  animations in frame  6  
of  6  starts at  250  msecs with a scheduled total of  240  msecs

kdiamond(11620) RemoveAnimator::setFrame: Calculating  6  animations in frame  
3  of  7  starts at  81  msecs with a scheduled total of  200  msecs
kdiamond(11620) RemoveAnimator::setFrame: Calculating  6  animations in frame  
6  of  7  starts at  153  msecs with a scheduled total of  200  msecs
kdiamond(11620) RemoveAnimator::setFrame: Calculating  6  animations in frame  
7  of  7  starts at  201  msecs with a scheduled total of  200  msecs

kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
6  of  18  starts at  285  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
8  of  18  starts at  325  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
10  of  18  starts at  398  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
12  of  18  starts at  440  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
13  of  18  starts at  488  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
15  of  18  starts at  528  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
16  of  18  starts at  572  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
17  of  18  starts at  614  msecs with a scheduled total of  720  msecs
kdiamond(11620) MoveAnimator::setFrame: Calculating  48  animations in frame  
18  of  18  starts at  728  msecs with a scheduled total of  720  msecs

kdiamond(11620) RemoveAnimator::setFrame: Calculating  9  animations in frame  
3  of  7  starts at  81  msecs with a scheduled total of  200  msecs
kdiamond(11620) RemoveAnimator::setFrame: Calculating  9  animations in frame  
4  of  7  starts at  121  msecs with a scheduled total of  200  msecs
kdiamond(11620) RemoveAnimator::setFrame: Calculating  9  animations in frame  
6  of  7  starts at  161  msecs with a scheduled total of  200  msecs
kdiamond(11620) RemoveAnimator::setFrame: Calculating  9  animations in frame  
7  of  7  starts at  201  msecs with a scheduled total of  200  msecs

At first: Yes, the first animation did only consist of one frame.

The first real frame of nearly every animation is played after over a quarter 
of the animation time has already elapsed. This causes the diamonds to jump 
at the beginning of the move animation, and it causes the remove animation to 
be jumpy. Now what is the problem? The timer used here starts with the call 
of (Re)MoveAnimator::start (together with the timeline used by the 
animation), and that is the last function call in my event handler. So 
everything between 0 and ~240 msecs is Qt's CPU load.

Time for a differential diagnosis! These are the symptoms:
* About 80 msecs are spent between starting an animation and drawing the first 
frame. This time increases 240 msecs when new diamonds (i.e. 
QGraphicsPixmapItem instances) are created. Nearly no delay occurs between 
the frames.
* The delay seems to increase in a linear manner when the window resolution or 
the number of animated diamonds increases. (For example, for the move 
animation has a 720 msecs delay for 50x50 diamonds.)

These are the possible causes and why they seem unprobable to me:
* Creating so much diamonds is simply time consuming. That would explain why 
the length of the delay depends on the number of diamonds (because the number 
of created diamonds increases accordingly. However, this cause seems 
unprobable to me because:
  * It does not explain why the impact depends on the resolution.
  * The diamonds are also fully constructed when the animation timeline 
starts; apart from possible initialisations inside of Qt which are deferred 
to a later point of time to speed up my algorithms. I've tried to immediately 
repaint() my QGraphicsView to force such late initialisations to be done 
before my animator starts, but it did not help.
  * The remove animation does also experience a (smaller) delay.
* The repaint operation is very complex. That explains the higher delay for 
more diamonds (just more pixmaps to draw) and a higher resolution (more 
pixmap data to copy). But if the repaint operation is the cause, why does 
this effect not appear between every single step?

Any comments on this topic?

Stefan
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 194 bytes
Desc: This is a digitally signed message part.
Url : http://mail.kde.org/pipermail/kde-games-devel/attachments/20080518/b81ab6f4/attachment.pgp