touch-packages team mailing list archive

Thread
Date
[Bug 1403508] [NEW] Dash startup causes unity8 GUI thread to block for 500ms+

To: touch-packages@xxxxxxxxxxxxxxxxxxx
From: Gerry Boland <1403508@xxxxxxxxxxxxxxxxxx>
Date: Wed, 17 Dec 2014 13:32:35 -0000
Reply-to: Bug 1403508 <1403508@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

Dash & Unity8 communicate via DBus, so unity8 can tell Dash to switch to
a scope when needed. This implemented by a DashCommunicator plugin.

DashCommunicator inherits AbstractDBusServiceMonitor, which monitors the
DBus bus for when the Dash service appears, and when it does, creates a
QDBusInterface object for it, which DashCommunicator uses to call
methods on the service. All good.

QDBusInterface, on creation, introspects the Dash's DBus interface, and
this is performed on the GUI thread (see
qtbase/src/dbus/qdbusconnection.cpp, there is a moveToThread(GUI Thread)
call). If the service is busy/blocked, this will hang the Unity8 GUI
thread until unblock/timeout. This is undesirable. We tried to avoid
this by having DashCommunicator in its own thread, but that moveToThread
is unavoidable.

But it's also happening to unity8 on every startup, it's just not noticeable visually as the QML engine is also busy creating objects.
It's easier to see by running in a shell:

stop unity8-dash && start unity8-dash

and watching the spinner. You will see the spinner block for 500ms+
before the Dash appears.


Here is the DBus traffic during this time:

QDBusConnectionPrivate(0xe53c80) got message (signal):
QDBusMessage(type=Signal, service="org.freedesktop.DBus",
path="/org/freedesktop/DBus", interface="org.freedesktop.DBus",
member="NameOwnerChanged", signature="sss",
contents=("com.canonical.UnityDash", "", ":1.124") )

QDBusConnectionPrivate(0xe53c80) sending message (blocking):
QDBusMessage(type=MethodCall, service="org.freedesktop.DBus",
path="/org/freedesktop/DBus", interface="org.freedesktop.DBus",
member="GetNameOwner", signature="",
contents=("com.canonical.UnityDash") )

QDBusConnectionPrivate(0xe53c80) got message reply (blocking):
QDBusMessage(type=MethodReturn, service="org.freedesktop.DBus",
signature="s", contents=(":1.124") )

QDBusConnectionPrivate(0xe53c80) sending message (blocking):
QDBusMessage(type=MethodCall, service="com.canonical.UnityDash",
path="/com/canonical/UnityDash",
interface="org.freedesktop.DBus.Introspectable", member="Introspect",
signature="", contents=() )

<BLOCK>


and here is the backtrace of unity8 during this blockage:


38	../sysdeps/unix/sysv/linux/x86_64/syscall.S: No such file or directory.
(gdb) bt
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f4d03a39470 in _q_futex (op=<optimized out>, val=<optimized out>, timeout=<optimized out>, addr=<optimized out>) at thread/qmutex_linux.cpp:154
#2  lockInternal_helper<false> (timeout=<optimized out>, elapsedTimer=<optimized out>, d_ptr=...) at thread/qmutex_linux.cpp:195
#3  QBasicMutex::lockInternal (this=this@entry=0xe8f9c8) at thread/qmutex_linux.cpp:211
#4  0x00007f4d03a39548 in lock (this=0xe8f9c8) at thread/qmutex.h:67
#5  lock (timeout=-1, this=0xe8f9b0) at thread/qmutex.cpp:628
#6  QMutex::lock (this=this@entry=0xe8fd30) at thread/qmutex.cpp:223
#7  0x00007f4d02000d5e in QDBusMutexLocker (m=0xe8fd30, s=0xe8fcf0, a=RealAddTimeoutAction, this=<synthetic pointer>) at qdbusthreaddebug_p.h:191
#8  QDBusDispatchLocker (s=0xe8fcf0, a=RealAddTimeoutAction, this=<synthetic pointer>) at qdbusthreaddebug_p.h:206
#9  QDBusConnectionPrivate::customEvent (this=0xe8fcf0, e=<optimized out>) at qdbusintegrator.cpp:1149
#10 0x00007f4d03cae9c3 in QObject::event (this=0xe8fcf0, e=<optimized out>) at kernel/qobject.cpp:1263
#11 0x00007f4d03c7e7c5 in QCoreApplication::notify (this=<optimized out>, receiver=<optimized out>, event=<optimized out>) at kernel/qcoreapplication.cpp:997
#12 0x00007f4d03c7e8fb in QCoreApplication::notifyInternal (this=0xa32700, receiver=0xe8fcf0, event=event@entry=0x7f4cac003b90) at kernel/qcoreapplication.cpp:935
#13 0x00007f4d03c808f3 in sendEvent (event=0x7f4cac003b90, receiver=<optimized out>) at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:237
#14 QCoreApplicationPrivate::sendPostedEvents (receiver=receiver@entry=0x0, event_type=event_type@entry=0, data=0xa32840) at kernel/qcoreapplication.cpp:1539
#15 0x00007f4d03c80ef8 in QCoreApplication::sendPostedEvents (receiver=receiver@entry=0x0, event_type=event_type@entry=0) at kernel/qcoreapplication.cpp:1397
#16 0x00007f4d03cd68d3 in postEventSourceDispatch (s=0xa5d600) at kernel/qeventdispatcher_glib.cpp:279
#17 0x00007f4d01388eed in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#18 0x00007f4d013891d0 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#19 0x00007f4d0138927c in g_main_context_iteration () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#20 0x00007f4d03cd6ce7 in QEventDispatcherGlib::processEvents (this=0xa59250, flags=...) at kernel/qeventdispatcher_glib.cpp:426
#21 0x00007f4d03c7c042 in QEventLoop::exec (this=this@entry=0x7fff264c43f0, flags=..., flags@entry=...) at kernel/qeventloop.cpp:212
#22 0x00007f4d03c83c8c in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1188
#23 0x00000000004050a5 in ?? ()
#24 0x00007f4d030daec5 in __libc_start_main (main=0x4045f0, argc=1, argv=0x7fff264c4948, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, 
    stack_end=0x7fff264c4938) at libc-start.c:287
#25 0x0000000000405bef in _start ()

** Affects: unity8 (Ubuntu)
     Importance: Undecided
         Status: New

** Branch linked: lp:~gerboland/unity8/async-dbus-dashcomm

-- 
You received this bug notification because you are a member of Ubuntu
Touch seeded packages, which is subscribed to unity8 in Ubuntu.
https://bugs.launchpad.net/bugs/1403508

Title:
  Dash startup causes unity8 GUI thread to block for 500ms+

Status in unity8 package in Ubuntu:
  New

Bug description:
  Dash & Unity8 communicate via DBus, so unity8 can tell Dash to switch
  to a scope when needed. This implemented by a DashCommunicator plugin.

  DashCommunicator inherits AbstractDBusServiceMonitor, which monitors
  the DBus bus for when the Dash service appears, and when it does,
  creates a QDBusInterface object for it, which DashCommunicator uses to
  call methods on the service. All good.

  QDBusInterface, on creation, introspects the Dash's DBus interface,
  and this is performed on the GUI thread (see
  qtbase/src/dbus/qdbusconnection.cpp, there is a moveToThread(GUI
  Thread) call). If the service is busy/blocked, this will hang the
  Unity8 GUI thread until unblock/timeout. This is undesirable. We tried
  to avoid this by having DashCommunicator in its own thread, but that
  moveToThread is unavoidable.

  But it's also happening to unity8 on every startup, it's just not noticeable visually as the QML engine is also busy creating objects.
  It's easier to see by running in a shell:

  stop unity8-dash && start unity8-dash

  and watching the spinner. You will see the spinner block for 500ms+
  before the Dash appears.

  
  Here is the DBus traffic during this time:

  QDBusConnectionPrivate(0xe53c80) got message (signal):
  QDBusMessage(type=Signal, service="org.freedesktop.DBus",
  path="/org/freedesktop/DBus", interface="org.freedesktop.DBus",
  member="NameOwnerChanged", signature="sss",
  contents=("com.canonical.UnityDash", "", ":1.124") )

  QDBusConnectionPrivate(0xe53c80) sending message (blocking):
  QDBusMessage(type=MethodCall, service="org.freedesktop.DBus",
  path="/org/freedesktop/DBus", interface="org.freedesktop.DBus",
  member="GetNameOwner", signature="",
  contents=("com.canonical.UnityDash") )

  QDBusConnectionPrivate(0xe53c80) got message reply (blocking):
  QDBusMessage(type=MethodReturn, service="org.freedesktop.DBus",
  signature="s", contents=(":1.124") )

  QDBusConnectionPrivate(0xe53c80) sending message (blocking):
  QDBusMessage(type=MethodCall, service="com.canonical.UnityDash",
  path="/com/canonical/UnityDash",
  interface="org.freedesktop.DBus.Introspectable", member="Introspect",
  signature="", contents=() )

  <BLOCK>


  and here is the backtrace of unity8 during this blockage:


  38	../sysdeps/unix/sysv/linux/x86_64/syscall.S: No such file or directory.
  (gdb) bt
  #0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
  #1  0x00007f4d03a39470 in _q_futex (op=<optimized out>, val=<optimized out>, timeout=<optimized out>, addr=<optimized out>) at thread/qmutex_linux.cpp:154
  #2  lockInternal_helper<false> (timeout=<optimized out>, elapsedTimer=<optimized out>, d_ptr=...) at thread/qmutex_linux.cpp:195
  #3  QBasicMutex::lockInternal (this=this@entry=0xe8f9c8) at thread/qmutex_linux.cpp:211
  #4  0x00007f4d03a39548 in lock (this=0xe8f9c8) at thread/qmutex.h:67
  #5  lock (timeout=-1, this=0xe8f9b0) at thread/qmutex.cpp:628
  #6  QMutex::lock (this=this@entry=0xe8fd30) at thread/qmutex.cpp:223
  #7  0x00007f4d02000d5e in QDBusMutexLocker (m=0xe8fd30, s=0xe8fcf0, a=RealAddTimeoutAction, this=<synthetic pointer>) at qdbusthreaddebug_p.h:191
  #8  QDBusDispatchLocker (s=0xe8fcf0, a=RealAddTimeoutAction, this=<synthetic pointer>) at qdbusthreaddebug_p.h:206
  #9  QDBusConnectionPrivate::customEvent (this=0xe8fcf0, e=<optimized out>) at qdbusintegrator.cpp:1149
  #10 0x00007f4d03cae9c3 in QObject::event (this=0xe8fcf0, e=<optimized out>) at kernel/qobject.cpp:1263
  #11 0x00007f4d03c7e7c5 in QCoreApplication::notify (this=<optimized out>, receiver=<optimized out>, event=<optimized out>) at kernel/qcoreapplication.cpp:997
  #12 0x00007f4d03c7e8fb in QCoreApplication::notifyInternal (this=0xa32700, receiver=0xe8fcf0, event=event@entry=0x7f4cac003b90) at kernel/qcoreapplication.cpp:935
  #13 0x00007f4d03c808f3 in sendEvent (event=0x7f4cac003b90, receiver=<optimized out>) at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:237
  #14 QCoreApplicationPrivate::sendPostedEvents (receiver=receiver@entry=0x0, event_type=event_type@entry=0, data=0xa32840) at kernel/qcoreapplication.cpp:1539
  #15 0x00007f4d03c80ef8 in QCoreApplication::sendPostedEvents (receiver=receiver@entry=0x0, event_type=event_type@entry=0) at kernel/qcoreapplication.cpp:1397
  #16 0x00007f4d03cd68d3 in postEventSourceDispatch (s=0xa5d600) at kernel/qeventdispatcher_glib.cpp:279
  #17 0x00007f4d01388eed in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  #18 0x00007f4d013891d0 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  #19 0x00007f4d0138927c in g_main_context_iteration () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  #20 0x00007f4d03cd6ce7 in QEventDispatcherGlib::processEvents (this=0xa59250, flags=...) at kernel/qeventdispatcher_glib.cpp:426
  #21 0x00007f4d03c7c042 in QEventLoop::exec (this=this@entry=0x7fff264c43f0, flags=..., flags@entry=...) at kernel/qeventloop.cpp:212
  #22 0x00007f4d03c83c8c in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1188
  #23 0x00000000004050a5 in ?? ()
  #24 0x00007f4d030daec5 in __libc_start_main (main=0x4045f0, argc=1, argv=0x7fff264c4948, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, 
      stack_end=0x7fff264c4938) at libc-start.c:287
  #25 0x0000000000405bef in _start ()

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/unity8/+bug/1403508/+subscriptions
Follow ups

[Bug 1403508] Re: Dash startup causes unity8 GUI thread to block for 500ms+
From: Launchpad Bug Tracker, 2015-01-14
[Bug 1403508] Re: Dash startup causes unity8 GUI thread to block for 500ms+
From: Michał Sawicz, 2015-01-05
[Bug 1403508] [NEW] Dash startup causes unity8 GUI thread to block for 500ms+
From: Gerry Boland, 2014-12-17
References

[Bug 1403508] [NEW] Dash startup causes unity8 GUI thread to block for 500ms+
From: Gerry Boland, 2014-12-17