• State
  • Locked Locked
  • Replies 15 replies
  • Subscribers 98 subscribers
  • Views 3984 views
  • Users 0 members are here
Support feedback
Options
Options
Related

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

Qt5 AM3517 + SGX + eglfs glDrawElements blocking problem

Florian Behrens
Prodigy 130 points
Other Parts Discussed in Thread: AM3517, LM73

Hi,

could anyone help me to understand a problem that appears when I run a small Qt Quick 2 example on a custom AM3517 board running with a patched 3.7.0 kernel and Graphics SDK 4.08.00.01.

My very simple Qt Quick example just displays a rotating green rectangle in the screen center:

import QtQuick 2.0

Rectangle {
    width: 800; height: 480

    Rectangle {
            color: "green"
            width: 400; height: 400
            anchors.centerIn: parent

            NumberAnimation on rotation {
                from: 0.0; to: 360.0
                duration: 5000
                loops: Animation.Infinite
            }
        }
    MouseArea {
        anchors.fill: parent
        onClicked: Qt.quit()
    }
}

When I disable the Qt render thread (QML_BAD_GUI_RENDER_LOOP=1)  this example runs smoothly with ~59 fps. But every ~2 secs there is a short ~100 ms hickup which I can track down to the glDrawElements function used in Qt to render the rectangle. With the render thread enabled it even happens every third frame.

The output of my example looks as follows:

root@bluemode:~ /opt/RotationPerformanceTest/bin/RotationPerformanceTest
evdevtouch: Using device /dev/input/event0
min X: 0 max X: 1791
min Y: 0 max Y: 1023
min pressure: 0 max pressure: 0
device name: EP0700M06
Protocol type B
PVR: Hint: Setting WindowSystem to libpvrPVR2D_FRONTWSEGL.so
PVR:(Error): PVRSRVMetricsTimeNow: using (potentially) low resolution timer [95, /pvr_metrics.c]
PVR:
PVR: Memory Stats
PVR: ------------
PVR:
PVR: High Water Mark = 4144 bytes
PVR:
PVR: 4144 bytes still allocated in 1 allocations
PVR:
PVR: 1   -  4144 bytes at 0x3c6c0 - eurasiacon/imgegl/tls.c:32
PVR:
PVR:(Warning): PVR2DEnumerateDevices: display device name too long, truncating [142, /pvr2dinit.c]
PVR:
PVR: Memory Stats
PVR: ------------
PVR:
PVR: High Water Mark = 4144 bytes
PVR:
PVR: 4144 bytes still allocated in 1 allocations
PVR:
PVR: 1   -  4144 bytes at 0x3c6c0 - eurasiacon/imgegl/tls.c:32
PVR:
PVR:(Warning): Running StartUpMemSpeedTest. High memory watermark will be ruined. Disable using apphint EnableMemorySpeedTest [45, /metrics.c]
PVR: Bytes  :    512    1024    2048    4096    8192   16384   32768   65536  131072
PVR: ---------------|-------|-------|-------|-------|-------|-------|-------|-------|
PVR: H -> VB: 202.23  647.95  684.62  607.64  619.12  646.50  677.43  682.10  709.05
PVR: H ->  H: 434.92  494.15  502.96  369.72  433.07  126.23  391.97  418.94  463.10
glDrawElements took 25.9399 ms
glDrawElements took 95.52 ms
glDrawElements took 101.959 ms
glDrawElements took 102.203 ms
glDrawElements took 94.9707 ms
glDrawElements took 96.0083 ms
glDrawElements took 94.6045 ms
glDrawElements took 101.685 ms
glDrawElements took 94.5435 ms
glDrawElements took 97.0154 ms
glDrawElements took 101.013 ms
glDrawElements took 101.959 ms
glDrawElements took 96.0083 ms
glDrawElements took 96.2219 ms
glDrawElements took 101.746 ms
glDrawElements took 94.635 ms
glDrawElements took 95.2149 ms
glDrawElements took 95.9168 ms
glDrawElements took 94.4824 ms
...

The glDrawElements output comes from a Qt5 patch that outputs the duration of the glDrawElements call in qsgrenderer.cpp if it takes longer than 10 ms. This happens approx. every 2 secs with the render thread disabled.

The gfx_check output is:

WSEGL settings
[default]
WindowSystem=libpvrPVR2D_FRONTWSEGL.so
# for direct writes to FrameBuffer - FRONT mode of operation - directly writes to FrameBuffer without waiting for vsync - fastest mode of operation
#WindowSystem=libpvrPVR2D_FLIPWSEGL.so
# for VSync synchronised writes to Framebuffer - slower, but avoids tearing
#WindowSystem=libpvrPVR2D_BLITWSEGL.so
# for direct writes to back-buffer, which later gets written to FrameBuffer with sync
------
ARM CPU information
Processor    : ARMv7 Processor rev 7 (v7l)
BogoMIPS    : 397.57
Features    : swp half thumb fastmult vfp edsp thumbee neon vfpv3 tls
CPU implementer    : 0x41
CPU architecture: 7
CPU variant    : 0x1
CPU part    : 0xc08
CPU revision    : 7

Hardware    : Technexion TAM3517 Evaluation Board
Revision    : 0020
Serial        : 0000000000000000
------
SGX driver information
Version SGX_DDK_Linux_CustomerTI sgxddk 19 1.9.RC2@2139099 (debug) /home/dev/svn/trunk/ptxdist_workspace/platform-disira/build-target/Graphics_SDK_setuplinux_4_08_00_01/GFX_Linux_KM
System Version String: SGX revision = 1.2.1
------
Framebuffer settings
Frame buffer device information:
    Name        : omapfb
    Address     : 0x8e200000
    Size        : 10485760
    Type        : PACKED PIXELS
    Visual      : TRUECOLOR
    XPanStep    : 1
    YPanStep    : 1
    YWrapStep   : 0
    LineLength  : 1600
    Accelerator : No
mode "UNNAMED" {
    { 800 480 30093 88 40 33 10 128 2 }
    { 16 11:5:0 5:6:0 0:5:0 0:0:0 0 0 }
    virtual 800 480
}
------
Rotation settings
0
------
Kernel Module information
Module                  Size  Used by
omaplfb                11744  0
pvrsrvkm              468251  1 omaplfb
edt_ft5x06              8132  0
pca953x_pnp             4685  0
lm73                    2341  0
rtc_mcp7941x            2403  0
tam3517_buzzer          4852  0
------
Boot settings
mem=256M mpurate=600 console=ttyO0,115200n8 vram=30M omapfb.vram=0:10M,1:10M,2:10M mtdparts=omap2-nand.0:512k(xloader),1024k(uboot),512k(params),6m(kernel),-(rootfs) rootfstype=ubifs ubi.mtd=4 root=ubi0:rootfs
------
Linux Kernel version
Linux bluemode 3.7.0-rc8-71840-g046e293-dirty #53 Wed Feb 6 16:55:51 CET 2013 armv7l GNU/Linux

The init kernel powervr modules output is:

[   12.280090] PVR: PVRCore_Init
[   12.288421] PVR: PVRSRVDriverProbe(pDevice=bf07de98)
[   12.294647] PVR: EnableSystemClocks: Enabling System Clocks
[   12.300750] PVR: Setting GPTIMER11 parent to System Clock
[   12.306518] PVR: GPTIMER11 clock is 13MHz
[   12.310913] PVR: Setting GPTIMER11 mode to posted (currently is non-posted)
[   12.320037] PVR: PVRCore_Init: major device 249
[   12.430786]
[   12.432373] =============================================
[   12.438079] [ INFO: possible recursive locking detected ]
[   12.443786] 3.7.0-rc8-71840-g046e293-dirty #53 Tainted: G           O
[   12.450561] ---------------------------------------------
[   12.456268] pvrsrvctl/1506 is trying to acquire lock:
[   12.461608]  (psPVRSRVMutex){+.+.+.}, at: [<bf046274>] LinuxLockMutex+0x18/0x20 [pvrsrvkm]
[   12.470794]
[   12.470794] but task is already holding lock:
[   12.476959]  (psPVRSRVMutex){+.+.+.}, at: [<bf046274>] LinuxLockMutex+0x18/0x20 [pvrsrvkm]
[   12.485870]
[   12.485870] other info that might help us debug this:
[   12.492767]  Possible unsafe locking scenario:
[   12.492767]
[   12.499023]        CPU0
[   12.501586]        ----
[   12.504150]   lock(psPVRSRVMutex);
[   12.507751]   lock(psPVRSRVMutex);
[   12.511352]
[   12.511352]  *** DEADLOCK ***
[   12.511352]
[   12.517608]  May be due to missing lock nesting notation
[   12.517608]
[   12.524749] 1 lock held by pvrsrvctl/1506:
[   12.529083]  #0:  (psPVRSRVMutex){+.+.+.}, at: [<bf046274>] LinuxLockMutex+0x18/0x20 [pvrsrvkm]
[   12.538452]
[   12.538452] stack backtrace:
[   12.543090] [<c00194d8>] (unwind_backtrace+0x0/0xf0) from [<c007bda4>] (__lock_acquire+0x1338/0x1a14)
[   12.552856] [<c007bda4>] (__lock_acquire+0x1338/0x1a14) from [<c007c9a8>] (lock_acquire+0x98/0x120)
[   12.562408] [<c007c9a8>] (lock_acquire+0x98/0x120) from [<c052fc2c>] (mutex_lock_nested+0x3c/0x294)
[   12.572113] [<c052fc2c>] (mutex_lock_nested+0x3c/0x294) from [<bf046274>] (LinuxLockMutex+0x18/0x20 [pvrsrvkm])
[   12.583068] [<bf046274>] (LinuxLockMutex+0x18/0x20 [pvrsrvkm]) from [<bf042d5c>] (DebugMemAllocRecordAdd+0x20/0x23c [pvrsrvkm])
[   12.595458] [<bf042d5c>] (DebugMemAllocRecordAdd+0x20/0x23c [pvrsrvkm]) from [<bf042cf4>] (_KMallocWrapper+0x7c/0x8c [pvrsrvkm])
[   12.607971] [<bf042cf4>] (_KMallocWrapper+0x7c/0x8c [pvrsrvkm]) from [<bf04ac20>] (OSAllocMem_Impl+0x70/0xa4 [pvrsrvkm])
[   12.619689] [<bf04ac20>] (OSAllocMem_Impl+0x70/0xa4 [pvrsrvkm]) from [<bf026e94>] (PVRSRVPerProcessDataConnect+0x7c/0x324 [pvrsrvkm])
[   12.632568] [<bf026e94>] (PVRSRVPerProcessDataConnect+0x7c/0x324 [pvrsrvkm]) from [<bf035a4c>] (PVRSRVProcessConnect+0x1c/0x2c [pvrsrvkm])
[   12.645965] [<bf035a4c>] (PVRSRVProcessConnect+0x1c/0x2c [pvrsrvkm]) from [<bf048a24>] (PVRSRVOpen+0x34/0xe0 [pvrsrvkm])
[   12.657592] [<bf048a24>] (PVRSRVOpen+0x34/0xe0 [pvrsrvkm]) from [<c00e7c0c>] (chrdev_open+0x90/0x15c)
[   12.667327] [<c00e7c0c>] (chrdev_open+0x90/0x15c) from [<c00e2884>] (do_dentry_open+0x1dc/0x264)
[   12.676635] [<c00e2884>] (do_dentry_open+0x1dc/0x264) from [<c00e2940>] (finish_open+0x34/0x4c)
[   12.685821] [<c00e2940>] (finish_open+0x34/0x4c) from [<c00f06f8>] (do_last.isra.27+0x5a4/0xbb0)
[   12.695098] [<c00f06f8>] (do_last.isra.27+0x5a4/0xbb0) from [<c00f0dac>] (path_openat+0xa8/0x44c)
[   12.704467] [<c00f0dac>] (path_openat+0xa8/0x44c) from [<c00f141c>] (do_filp_open+0x2c/0x80)
[   12.713348] [<c00f141c>] (do_filp_open+0x2c/0x80) from [<c00e3880>] (do_sys_open+0xe4/0x174)
[   12.722290] [<c00e3880>] (do_sys_open+0xe4/0x174) from [<c00131e0>] (ret_fast_syscall+0x0/0x3c)
[   12.772766] PVR: Installing MISR with cookie bf0811a8
[   12.779388] PVR: Installing device LISR SGX ISR on IRQ 21 with cookie ccc05280
[   12.787261] PVR: SysFinalise: Version string: SGX revision = 1.2.1

Can anybody give me a hint where I have to look further into this issue? I was worried about the recursive locking message in dmesg, could that point to the reason?

Thanks in advance,

Florian.

  • 0
    TI__Expert 6580 points

    The lock issue is unrelated (refer to http://processors.wiki.ti.com/index.php/SGXDbg#Lock_related_warnings_seen_on_OMAP35x.2FAM35x.2F37xx_with_2.6.37_kernel)

    On Qt5 - Please update with full commandline, and your environment variable settings.

  • 0 in reply to Prabindh Sundareson
    Prodigy 130 points

    Hi Prabindh,

    thanks for your quick response.

    There are no specific command line arguments:

    root@bluemode:~ /opt/RotationPerformanceTest/bin/RotationPerformanceTest

    I have eglfs as default platform. Same effects with minimalegl. Environment variables related to Qt are:

    QT_QPA_EGLFS_WIDTH=800
    QT_QPA_EGLFS_HEIGHT=480
    QT_QPA_EGLFS_DEPTH=16
    QT_QPA_EGLFS_HIDECURSOR=1
    QML_BAD_GUI_RENDER_LOOP=1

    With QML_BAD_GUI_RENDER_LOOP unset the effect is even worse as described in my inital post.

    Regards,

    Florian.

  • 0 in reply to Florian Behrens
    Prodigy 130 points

    I managed to remove the 100 ms hickups by implementing a custom animation driver triggered by vsync in Qt. Now the rendering is smooth as expected.

    But still I'm not sure why this was necessary. Some thoughts from my side about that issue:

    If there is anything like a render queue within the SGX that is filled by the CPU by OpenGL commands and the CPU fills that queue at a higher rate than the GPU is able to process this queue will eventually flow over? What happens in that case? Probably the queue will block. For how long?

    To my knowledge Qt eglfs platform relies on a blocking render queue. As far as I can see there is no glFinish call or the like in the Scene Graph renderer. The default animation driver seems to fire at a timer-based rate of 60 Hz (1/16 ms to be precise). What happens if the timer is imprecise, e.g., to fast?

    Any insights or doc references about this appreciated,

    Florian.

  • 0 in reply to Florian Behrens
    TI__Expert 6580 points

    Yes, there is a render queue. You can configure one parameter of this by using the step mentioned in below link:

    http://processors.wiki.ti.com/index.php/SGXDbg#ParamBufferSize

    Is there a way you can share a test sample, or the application you are using - so that we can analyse this behaviour ?

  • 0 in reply to Prabindh Sundareson
    TI__Expert 6580 points

    By the way - when I run your application (from first post) in Qt5.0.1, I do not see any hiccups every 2 seconds, and seems to run fine. I tried with qmlscene.

  • 0 in reply to Prabindh Sundareson
    Prodigy 130 points

    Hi Prabindh,

    thanks for your response. Changing the ParamBufferSize parameter has no effect as expected.

    I attached my reference project which shows the above mentioned effect. In case it does behave differently at your site - is there any means to find out why glDrawElements blocks that long?

    Regards,

    Florian.

    3678.RotatingRect.tar.gz

  • 0 in reply to Florian Behrens
    Prodigy 130 points

    Is there any more information on that?

  • 0 in reply to Florian Behrens
    TI__Expert 6580 points

    Florian, sorry for the delay.  Can you please share the instrumented code (complete file or patch) that shows this API taking 100 mSec ?

  • 0 in reply to Prabindh Sundareson
    Prodigy 130 points

    Prabindh, thanks for your time. See attached the patch for Qt-5.0.1.

  • 0 in reply to Florian Behrens
    Prodigy 130 points

    Well,that seems to not have worked. One more try...

    Fullscreen 1234.time-gldrawelements.diff Download 
    --- orig/qtdeclarative/src/quick/scenegraph/coreapi/qsgrenderer.cpp	2013-01-29 20:03:21.000000000 +0100
+++ patched/qtdeclarative/src/quick/scenegraph/coreapi/qsgrenderer.cpp	2013-04-30 12:21:35.642629996 +0200
@@ -629,6 +629,9 @@ static inline GLenum qt_drawTypeForPatte
     \internal
  */
 
+// REMOVE
+#include <QElapsedTimer>
+
 void QSGRenderer::draw(const QSGMaterialShader *shader, const QSGGeometry *g)
 {
     const void *vertexData;
@@ -721,7 +724,15 @@ void QSGRenderer::draw(const QSGMaterial
 
     // draw the stuff...
     if (g->indexCount()) {
+// REMOVE
+static QElapsedTimer elapsedTimer;
+elapsedTimer.start();
         glDrawElements(g->drawingMode(), g->indexCount(), g->indexType(), indexData);
+//REMOVE
+qint64 time = elapsedTimer.nsecsElapsed();
+if (time > 16666666 /* 16.66 ms */) {
+    qDebug() << "glDrawElements took" << time/1000000.0f << "ms";
+}
     } else {
         glDrawArrays(g->drawingMode(), 0, g->vertexCount());
     }

  • 0 in reply to Florian Behrens
    TI__Expert 6580 points

    I am still unable to replicate the issue of jerky animations. I finally applied your patch, and did not get any output (as expected).

    Since this is only a rectangle, and has only 4 vertices to be drawn (I also confirmed this by checking the index count) - how can drawElements lag behind ?

  • 0 in reply to Prabindh Sundareson
    TI__Expert 6580 points

    Have you also confirmed the framerate the demo is running at ? What is it ?

  • 0 in reply to Prabindh Sundareson
    Prodigy 130 points

    Prabindh, thanks for your effort. Disabling the Qt render thread yields ~59 fps on average (see my first post).

    Did you try to reproduce this on a TI EVM3517? We do have a Technexion TAM3517 here. Does this make the difference? What could the reason be?

  • 0 in reply to Florian Behrens
    TI__Expert 6580 points

    I can only suspect the display (fb) driver integration at this time. Did you try it on a Beagleboard, or a 3730 EVM with stock Linux drivers ?

  • 0 in reply to Prabindh Sundareson
    Prodigy 130 points

    Yes, I tried it on a Beagleboard-xM with no problems with Ubuntu for ARM and a modified kernel.