[Development] QML instantiation performance

[Simon Hausmann]

On Friday 28. November 2014 12.20.29 Chris Adams wrote:
> 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.

Something looks fishy there :)

The backtrace makes sense, but it shouldn't repeatedly end up in there. The 
last line number in question is a return statement for me. What is it in your 
source tree?

Can you try to step and see where the loop header is?

Simon