[Development] QML instantiation performance

Chris Adams chris.adams at qinetic.com.au
Fri Nov 28 03:20:29 CET 2014 

Hi,

No worries.  Interestingly, when I ran the benchmark against 5.3, I found
that it hangs after performing several tests.

Before each test, the benchmark will clear the QML type registrations to
ensure that the cached compiled type data isn't re-used during the run,
tainting the results.  It appears that if the call to
qmlClearTypeRegistrations() is commented out, the benchmark runs all the
way through (but obviously, with tainted / useless results).  With that
call left in, it hangs, with CPU spinning at 100%, while trying to load a
component:

(gdb) t a a bt

Thread 290 (Thread 0x7fffee1ba700 (LWP 14829)):
#0  0x00007fffec1f7c56 in QQuickValueTypeProvider::create
(this=0x7fffec7b3980 <getValueTypeProvider()::valueTypeProvider>,
type=1037, v=
    @0x7fffee1b9080: 0x0) at util/qquickglobal.cpp:404
#1  0x00007ffff795813f in QQmlValueTypeProvider::createValueType
(this=0x7fffec7b3980 <getValueTypeProvider()::valueTypeProvider>, type=1037)
    at qml/qqmlglobal.cpp:67
#2  0x00007ffff7914d41 in (anonymous
namespace)::QQmlValueTypeFactoryImpl::createValueType (
    this=0x7ffff7dd7340 <(anonymous
namespace)::Q_QGS_factoryImpl::innerFunction()::holder>, t=1037) at
qml/qqmlvaluetype.cpp:121
#3  0x00007ffff7914e21 in (anonymous
namespace)::QQmlValueTypeFactoryImpl::valueType (
    this=0x7ffff7dd7340 <(anonymous
namespace)::Q_QGS_factoryImpl::innerFunction()::holder>, idx=1037) at
qml/qqmlvaluetype.cpp:137
#4  0x00007ffff7915006 in QQmlValueTypeFactory::valueType (idx=1037) at
qml/qqmlvaluetype.cpp:169
#5  0x00007ffff7767d09 in QQmlPropertyValidator::validateObject
(this=0x7fffee1b9580, objectIndex=0, instantiatingBinding=0x0,
    populatingValueTypeGroupProperty=false) at
compiler/qqmltypecompiler.cpp:1912
#6  0x00007ffff7766c6f in QQmlPropertyValidator::validate
(this=0x7fffee1b9580) at compiler/qqmltypecompiler.cpp:1730
#7  0x00007ffff775f676 in QQmlTypeCompiler::compile (this=0x7fffee1b96f0)
at compiler/qqmltypecompiler.cpp:265
#8  0x00007ffff7904370 in QQmlTypeData::compile (this=0x7dc4b0) at
qml/qqmltypeloader.cpp:2341
#9  0x00007ffff7903081 in QQmlTypeData::done (this=0x7dc4b0) at
qml/qqmltypeloader.cpp:2164
#10 0x00007ffff78fc2b0 in QQmlDataBlob::tryDone (this=0x7dc4b0) at
qml/qqmltypeloader.cpp:615
#11 0x00007ffff78fdf56 in QQmlDataLoader::setData (this=0x7d5b48,
blob=0x7dc4b0, d=...) at qml/qqmltypeloader.cpp:1208
#12 0x00007ffff78fde44 in QQmlDataLoader::setData (this=0x7d5b48,
blob=0x7dc4b0, file=0x7fffee1b9910) at qml/qqmltypeloader.cpp:1190
#13 0x00007ffff78fd683 in QQmlDataLoader::loadThread (this=0x7d5b48,
blob=0x7dc4b0) at qml/qqmltypeloader.cpp:1068
#14 0x00007ffff78fcb03 in QQmlDataLoaderThread::loadThread (this=0x751b90,
b=0x7dc4b0) at qml/qqmltypeloader.cpp:816
#15 0x00007ffff7908121 in void
QQmlThread::callMethodInThread<QQmlDataBlob*, QQmlDataBlob*,
QQmlDataLoaderThread>(void (QQmlDataLoaderThread::*)(QQmlDataBlob*),
QQmlDataBlob* const&)::I::call(QQmlThread*) (this=0x7dc7b0, thread=0x751b90)
    at
/home/chriadam/Code/qt/qt5/qtbase/include/QtQml/5.3.2/QtQml/private/../../../../../../qtdeclarative/src/qml/qml/ftw/qqmlthread_p.h:160
#16 0x00007ffff7973eee in QQmlThreadPrivate::threadEvent (this=0x729cd0) at
qml/ftw/qqmlthread.cpp:198
#17 0x00007ffff7973c76 in QQmlThreadPrivate::event (this=0x729cd0,
e=0x7dc7e0) at qml/ftw/qqmlthread.cpp:136
#18 0x00007ffff6619936 in QCoreApplicationPrivate::notify_helper
(this=0x60be80, receiver=0x729cd0, event=0x7dc7e0) at
kernel/qcoreapplication.cpp:1052
#19 0x00007ffff6619618 in QCoreApplication::notify (this=0x7fffffffdd10,
receiver=0x729cd0, event=0x7dc7e0) at kernel/qcoreapplication.cpp:997
#20 0x00007ffff6c7a83c in QGuiApplication::notify (this=0x7fffffffdd10,
object=0x729cd0, event=0x7dc7e0) at kernel/qguiapplication.cpp:1477
#21 0x00007ffff6619522 in QCoreApplication::notifyInternal
(this=0x7fffffffdd10, receiver=0x729cd0, event=0x7dc7e0) at
kernel/qcoreapplication.cpp:935
#22 0x00007ffff661d0af in QCoreApplication::sendEvent (receiver=0x729cd0,
event=0x7dc7e0)
    at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:237
#23 0x00007ffff661a7ed in QCoreApplicationPrivate::sendPostedEvents
(receiver=0x0, event_type=0, data=0x6ce920) at
kernel/qcoreapplication.cpp:1539
#24 0x00007ffff668bf85 in QEventDispatcherUNIX::processEvents
(this=0x7fffe0183690, flags=...) at kernel/qeventdispatcher_unix.cpp:587
#25 0x00007ffff66162c2 in QEventLoop::processEvents (this=0x7fffee1b9dd0,
flags=...) at kernel/qeventloop.cpp:136
#26 0x00007ffff6616583 in QEventLoop::exec (this=0x7fffee1b9dd0, flags=...)
at kernel/qeventloop.cpp:212
#27 0x00007ffff63a46ce in QThread::exec (this=0x729cd0) at
thread/qthread.cpp:511
#28 0x00007ffff7973ce7 in QQmlThreadPrivate::run (this=0x729cd0) at
qml/ftw/qqmlthread.cpp:149
#29 0x00007ffff63ab9c9 in QThreadPrivate::start (arg=0x729cd0) at
thread/qthread_unix.cpp:345
---Type <return> to continue, or q <return> to quit---
#30 0x00007ffff54aa182 in start_thread (arg=0x7fffee1ba700) at
pthread_create.c:312
#31 0x00007ffff5b1530d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 2 (Thread 0x7fffef01f700 (LWP 14532)):
#0  0x00007ffff5b07fbd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007ffff16d6b72 in poll (__timeout=-1, __nfds=1,
__fds=0x7fffef01ecc0) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
#2  _xcb_conn_wait (c=c at entry=0x658740, cond=cond at entry=0x658780,
vector=vector at entry=0x0, count=count at entry=0x0) at ../../src/xcb_conn.c:447
#3  0x00007ffff16d864f in xcb_wait_for_event (c=0x658740) at
../../src/xcb_in.c:622
#4  0x00007ffff0cb5a79 in QXcbEventReader::run (this=0x6663a0) at
qxcbconnection.cpp:1043
#5  0x00007ffff63ab9c9 in QThreadPrivate::start (arg=0x6663a0) at
thread/qthread_unix.cpp:345
#6  0x00007ffff54aa182 in start_thread (arg=0x7fffef01f700) at
pthread_create.c:312
#7  0x00007ffff5b1530d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 1 (Thread 0x7ffff7fca7c0 (LWP 14524)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007ffff63ad096 in QWaitConditionPrivate::wait (this=0x6b6d00,
time=18446744073709551615) at thread/qwaitcondition_unix.cpp:136
#2  0x00007ffff63ace69 in QWaitCondition::wait (this=0x729d48,
mutex=0x729d40, time=18446744073709551615) at
thread/qwaitcondition_unix.cpp:208
#3  0x00007ffff79747ba in QQmlThreadPrivate::wait (this=0x729cd0) at
qml/ftw/qqmlthread.cpp:64
#4  0x00007ffff7974409 in QQmlThread::internalCallMethodInThread
(this=0x751b90, message=0x7dc7b0) at qml/ftw/qqmlthread.cpp:319
#5  0x00007ffff790817c in QQmlThread::callMethodInThread<QQmlDataBlob*,
QQmlDataBlob*, QQmlDataLoaderThread> (this=0x751b90, Member=
    (void (QQmlDataLoaderThread::*)(QQmlDataLoaderThread * const,
QQmlDataBlob *)) 0x7ffff78fcadc
<QQmlDataLoaderThread::loadThread(QQmlDataBlob*)>,
    arg=@0x7fffffffce00: 0x7dc4b0)
    at
/home/chriadam/Code/qt/qt5/qtbase/include/QtQml/5.3.2/QtQml/private/../../../../../../qtdeclarative/src/qml/qml/ftw/qqmlthread_p.h:163
#6  0x00007ffff78fc7ab in QQmlDataLoaderThread::load (this=0x751b90,
b=0x7dc4b0) at qml/qqmltypeloader.cpp:761
#7  0x00007ffff78fcebb in QQmlDataLoader::load (this=0x7d5b48,
blob=0x7dc4b0, mode=QQmlDataLoader::PreferSynchronous) at
qml/qqmltypeloader.cpp:936
#8  0x00007ffff78ffe95 in QQmlTypeLoader::getType (this=0x7d5b48, url=...,
mode=QQmlDataLoader::PreferSynchronous) at qml/qqmltypeloader.cpp:1606
#9  0x00007ffff78dedb0 in QQmlComponentPrivate::loadUrl (this=0x7cb9b0,
newUrl=..., mode=QQmlComponent::PreferSynchronous) at
qml/qqmlcomponent.cpp:691
#10 0x00007ffff78deaba in QQmlComponent::loadUrl (this=0x7fffffffd0a0,
url=...) at qml/qqmlcomponent.cpp:648
#11 0x00000000004040e0 in tst_librarymetrics_performance::compilation() ()
#12 0x00007ffff66256c1 in QMetaMethod::invoke (this=0x7fffffffd3b0,
object=0x7fffffffdd20, connectionType=Qt::DirectConnection,
returnValue=...,
    val0=..., val1=..., val2=..., val3=..., val4=..., val5=..., val6=...,
val7=..., val8=..., val9=...) at kernel/qmetaobject.cpp:2169
#13 0x00007ffff6624b99 in QMetaObject::invokeMethod (obj=0x7fffffffdd20,
member=0x7a3ba0 "compilation", type=Qt::DirectConnection, ret=...,
val0=...,
    val1=..., val2=..., val3=..., val4=..., val5=..., val6=..., val7=...,
val8=..., val9=...) at kernel/qmetaobject.cpp:1464
#14 0x00007ffff73d6c21 in QMetaObject::invokeMethod (obj=0x7fffffffdd20,
member=0x7a3ba0 "compilation", type=Qt::DirectConnection, val0=...,
val1=...,
    val2=..., val3=..., val4=..., val5=..., val6=..., val7=..., val8=...,
val9=...) at ../../include/QtCore/../../src/corelib/kernel/qobjectdefs.h:399
#15 0x00007ffff73d26d4 in QTest::qInvokeTestMethodDataEntry (slot=0x7a3ba0
"compilation") at qtestcase.cpp:1890
#16 0x00007ffff73d2f64 in QTest::qInvokeTestMethod (slotName=0x7a4d48
"compilation()", data=0x0) at qtestcase.cpp:2015
#17 0x00007ffff73d3a81 in QTest::qInvokeTestMethods
(testObject=0x7fffffffdd20) at qtestcase.cpp:2242
#18 0x00007ffff73d4047 in QTest::qExec (testObject=0x7fffffffdd20, argc=1,
argv=0x7fffffffde38) at qtestcase.cpp:2475
#19 0x00000000004025c4 in main ()

It appears that the QQuickValueTypeProvider instances are continuously
recreated (spinning at 100% and locking the incubator thread, which the
main thread is waiting on).  Lars or Simon, are you able to guess what
might cause this issue?  The implementation of qmlClearTypeRegistrations
seems fairly straightforward, but my memory of the complexities of value
type providers is hazy.

Juha, are you seeing this issue also, or do I just have a broken build
somehow?

Cheers,
Chris.



www.qinetic.com.au - Qt And QML User Experience Specialists

On Thu, Nov 27, 2014 at 4:37 PM, Juha Vuolle <juvuolle at gmail.com> wrote:

> Hey Chris,
>
> Thanks heaps. I'll have a look and get back with any findings (may
> take a day or two before I get to it).
>
> cheers,
> Juha
>
> 2014-11-27 3:51 GMT+02:00 Chris Adams <chris.adams at qinetic.com.au>:
> > Hi Juha,
> >
> > For some more light on this issue, are you able to run the
> > qtdeclarative/tests/benchmarks/qml/librarymetrics_performance benchmark
> on
> > both 5.1 and 5.3 (you may have to backport to 5.1 as IIRC I made some
> > changes to the way the components were instantiated for 5.2 before the
> > benchmark was integrated, but I may be wrong about that.  It was
> originally
> > written prior to Qt5.0 release so with some minor changes it will
> definitely
> > work against 5.1).
> >
> > The benchmarks are quite granular, and should allow you to see precisely
> > which part of the component instantiation is significantly slower.
> >
> > Kind regards,
> > Chris Adams.
> >
> >
> > www.qinetic.com.au - Qt And QML User Experience Specialists
> >
> > On Wed, Nov 26, 2014 at 6:08 PM, Juha Vuolle <juvuolle at gmail.com> wrote:
> >>
> >> Hello,
> >>
> >> apologies for cross-posting. I find this such a fundamental issue that I
> >> feel
> >> at least having the best possible understanding of it worth it (if any
> >> exists, which is also
> >> a valuable information in itself). I am happy to help if there is
> >> anything I could check.
> >>
> >> thanks,
> >> Juha
> >>
> >> ---
> >>
> >> Hello,
> >>
> >> I’m having trouble going from Qt 5.1 to 5.3 / 5.4 because of a
> >> slowdown in QML (15..35% slower).
> >> This primarily relates to component instantiation and seems quite
> >> consistent across the platforms and
> >> QPAs I’ve used recently.
> >>
> >> If you have any insights, thoughts or something I could check I would
> >> highly appreciate them.
> >>
> >> I’ve tested on dual & quadcore imx6 (both EGLFS and XCB) embedded
> >> platform as well as
> >> few desktop Fedoras. I’ve tested with 5.1.1, 5.3.1 and the latest
> >> 5.4.0. The slowdown varies
> >> but is fairly consistently between 15..35 %. Instantiation CPU loads
> >> do not seem to be particularly high (< 70%).
> >>
> >> Running QML profiler seems to make results less predictable. So I made
> >> a very simple application startup timer
> >> that checks main() -> QQuickWindow::beforeSynchronizing() ->
> >> beforeRendering() -> afterRendering() -> frameSwapped().
> >> Please find my "highly scientific" measurements below. I slowed down
> >> the CPU to make things more clear on the desktop I’m writing
> >> this email from. This behaviour is not specific to only application
> >> startup but later runtime instantiations seem also slower.
> >>
> >> I am grateful for any thoughts or things I could check.
> >>
> >> Thanks,
> >> Juha
> >>
> >> Qt 5.1.1 low CPU qtquickcontrols gallery example startup:
> >> 1. onBeforeSynchronizing() for the FIRST time, time it took from main():
> >> 950
> >> 2. onBeforeRendering() time it took from beforeSynchronizing: 3
> >> 3. onAfterRendering() time it took from beforeRendering: 1572
> >> 4. onFrameSwapped() time it took from afterRendering: 5
> >> = 2530 ms for first frame swapped.
> >>
> >> Qt 5.3.1 low CPU qtquickcontrols gallery example startup:
> >> 1. onBeforeSynchronizing() for the FIRST time, time it took from main():
> >> 1843
> >> 2. onBeforeRendering() time it took from beforeSynchronizing: 364
> >> 3. onAfterRendering() time it took from beforeRendering: 1039
> >> 4. onFrameSwapped() time it took from afterRendering: 83
> >> = 3329 ms for first frame swapped.
> >>
> >> Qt 5.1.1 low CPU my application startup:
> >> 1. onBeforeSynchronizing() for the FIRST time, time it took from main():
> >> 809
> >> 2. onBeforeRendering() time it took from beforeSynchronizing: 3
> >> 3. onAfterRendering() time it took from beforeRendering: 1373
> >> 4. onFrameSwapped() time it took from afterRendering: 88
> >> = 2273 ms for the first frame swapped
> >>
> >> Qt 5.3.1 low CPU my application startup:
> >> 1. onBeforeSynchronizing() for the FIRST time, time it took from main():
> >> 1341
> >> 2. onBeforeRendering() time it took from beforeSynchronizing: 4
> >> 3. onAfterRendering() time it took from beforeRendering: 2184
> >> 4. onFrameSwapped() time it took from afterRendering: 10
> >> = 3539 ms for the first frame swapped
> >> _______________________________________________
> >> Development mailing list
> >> Development at qt-project.org
> >> http://lists.qt-project.org/mailman/listinfo/development
> >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.qt-project.org/pipermail/development/attachments/20141128/a6541f33/attachment.html>

More information about the Development mailing list