[regression] Logging in to Unity8 takes 25 seconds (the default DBus timeout)

Bug #1663106 reported by Daniel van Vugt on 2017-02-09
18
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Canonical System Image
High
Zoltan Balogh
content-hub (Ubuntu)
High
Unassigned
qtmir (Ubuntu)
High
Unassigned
ubuntu-app-launch (Ubuntu)
High
Unassigned
ubuntu-ui-toolkit (Ubuntu)
High
Lukáš Tinkl
unity-system-compositor (Ubuntu)
Undecided
Unassigned
unity8 (Ubuntu)
High
Unassigned

Bug Description

[regression] Logging in to Unity8 takes 25 seconds (at least on the first login after a fresh boot) ...

[2017-02-09:11:35:05.263] Empty ualAppId result for "qterminal_drop"
[2017-02-09:11:35:05.263] Failed to get app info for app "qterminal_drop"
[2017-02-09:11:35:05.308] Failed to get all properties for "com.ubuntu.location.providers.here.AccountsService" : "No such interface"
[2017-02-09:11:35:05.310] CursorImageProvider: "" not found (nor its fallbacks, if any). Going for "left_ptr" as a last resort.
[2017-02-09:11:35:05.328] qtmir.applications: applicationManagerSingleton - engine= 0x56395e4119b0 scriptEngine= 0x56395e4119b0
[2017-02-09:11:35:05.330] qtmir.surfaces: MirSurfaceItem::setSurface surface=QObject(0x0)
[2017-02-09:11:35:05.333] ubuntu-app-launch threw an exception getting app info for appId: "address-book-app" : Invalid app ID: address-book-app
[2017-02-09:11:35:05.334] Empty ualAppId result for "com.ubuntu.camera_camera"
[2017-02-09:11:35:05.334] Empty ualAppId result for "com.ubuntu.gallery_gallery"
[2017-02-09:11:35:30.682] qtmir.surfaces: MirSurfaceItem::setSurface surface=QObject(0x0)
[2017-02-09:11:35:30.682] qtmir.surfaces: MirSurfaceItem::setSurface surface=QObject(0x0)
[2017-02-09:11:35:30.687] qtmir.mir.keymap: SET KEYMAP "us"
[2017-02-09:11:35:30.688] qtmir.mir.keymap: Applying keymap "us" "" on 4 "Lite-On Technology Corp. ThinkPad USB Keyboard with TrackPoint"
[2017-02-09:11:35:30.688] qtmir.mir.keymap: Keymap applied

<rebooted and try again>

[2017-02-09:11:38:19.249] qtmir.surfaces: MirSurfaceItem::setSurface surface=QObject(0x0)
[2017-02-09:11:38:19.252] ubuntu-app-launch threw an exception getting app info for appId: "address-book-app" : Invalid app ID: address-book-app
[2017-02-09:11:38:19.253] Empty ualAppId result for "com.ubuntu.camera_camera"
[2017-02-09:11:38:19.253] Empty ualAppId result for "com.ubuntu.gallery_gallery"
[2017-02-09:11:38:44.677] qtmir.surfaces: MirSurfaceItem::setSurface surface=QObject(0x0)
[2017-02-09:11:38:44.677] qtmir.surfaces: MirSurfaceItem::setSurface surface=QObject(0x0)
[2017-02-09:11:38:44.680] qtmir.mir.keymap: SET KEYMAP "us"
[2017-02-09:11:38:44.680] qtmir.mir.keymap: Applying keymap "us" "" on 4 "Lite-On Technology Corp. ThinkPad USB Keyboard with TrackPoint"
[2017-02-09:11:38:44.680] qtmir.mir.keymap: Keymap applied

Related branches

Changed in ubuntu-app-launch (Ubuntu):
importance: Undecided → High
Changed in canonical-devices-system-image:
importance: Undecided → High
Changed in qtmir (Ubuntu):
importance: Undecided → High
Daniel van Vugt (vanvugt) wrote :
Download full text (4.3 KiB)

Two threads look suspicious during the hang:

Thread 1:

#0 pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f34c8fd2b4b in QWaitCondition::wait(QMutex*, unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#2 0x00007f34c965dc7b in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#3 0x00007f34c961a0d5 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#4 0x00007f34c961a8a5 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#5 0x00007f34c962671d in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#6 0x00007f34c9626875 in QDBusInterface::QDBusInterface(QString const&, QString const&, QString const&, QDBusConnection const&, QObject*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#7 0x00007f348291b12b in UCContentHub::UCContentHub(QObject*) ()
   from /usr/lib/x86_64-linux-gnu/libUbuntuToolkit.so.5
#8 0x00007f3482936598 in ?? ()
   from /usr/lib/x86_64-linux-gnu/libUbuntuToolkit.so.5
#9 0x00007f34c9e52ea1 in QQmlType::SingletonInstanceInfo::init(QQmlEngine*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#10 0x00007f34c9eb04c5 in QV4::QmlTypeWrapper::toVariant() const ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#11 0x00007f34c9d886e6 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#12 0x00007f34c9d88844 in QV4::ExecutionEngine::toVariant(QV4::Value const&, int, bool) () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#13 0x00007f34c9ea83ae in QQmlBinding::write(QQmlPropertyData const&, QV4::Value const&, bool, QFlags<QQmlPropertyPrivate::WriteFlag>) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#14 0x00007f34c9ea94e7 in QQmlBinding::update(QFlags<QQmlPropertyPrivate::WriteFlag>) () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#15 0x00007f34c9eb3035 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#16 0x00007f34c9e3d01e in QQmlComponentPrivate::complete(QQmlEnginePrivate*, QQmlComponentPrivate::ConstructionState*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#17 0x00007f34c9e3d0e7 in QQmlComponentPrivate::completeCreate() ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#18 0x00007f34c9e3cf50 in QQmlComponent::create(QQmlContext*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#19 0x00007f34cb97d553 in QQuickView::continueExecute() ()
   from /usr/lib/x86_64-linux-gnu/libQt5Quick.so.5
#20 0x00007f34cb97db1d in QQuickViewPrivate::execute() ()
   from /usr/lib/x86_64-linux-gnu/libQt5Quick.so.5
#21 0x0000556b357e79c5 in ?? ()
#22 0x0000556b357e65b3 in ?? ()
#23 0x0000556b357e26c7 in ?? ()
#24 0x00007f34c85df3f1 in __libc_start_main (main=0x556b357e2600, argc=2,
    argv=0x7ffe95fdf8f8, init=<optimised out>, fini=<optimised out>,
    rtld_fini=<optimised out>, stack_end=0x7ffe95fdf8e8)
    at ../csu/libc-start.c:291
#25 0x0000556b357e2a1a in _start ()

Thread 11:

#0 pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f34c8fd2b4b in QWaitCondition::wait(QMutex*, unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#2 0x00007f34c8fcba23 in QSemaphore::acquire(int) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#3 0x...

Read more...

Changed in ubuntu-ui-toolkit (Ubuntu):
importance: Undecided → High
Daniel van Vugt (vanvugt) wrote :

Yep, 25 seconds is the default QDBus timeout...

http://doc.qt.io/qt-4.8/qdbusabstractinterface.html#setTimeout

summary: - [regression] Logging in to Unity8 takes 25 seconds
+ [regression] Logging in to Unity8 takes 25 seconds (the default DBus
+ timeout)
tags: added: black-screen
Changed in ubuntu-app-launch (Ubuntu):
status: New → Invalid
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in qtmir (Ubuntu):
status: New → Confirmed
Changed in ubuntu-ui-toolkit (Ubuntu):
status: New → Confirmed
Changed in unity8 (Ubuntu):
status: New → Confirmed
Lukáš Tinkl (lukas-kde) wrote :

It started happening 2 days ago, with the new version of unity-system-compositor, namely silo https://bileto.ubuntu.com/#/ticket/2439 and https://code.launchpad.net/~unity-system-compositor-team/unity-system-compositor/0.9/+merge/316460

Alexandros Frantzis (afrantzis) wrote :

unity-system-compositor 0.9.1 (the aforementioned silo) is unlikely to be causing this, since:

1. I had a zesty system I hadn't updated in a week or so, which did not exhibit the bug. After updating only USC to 0.9.1, I still couldn't reproduce the bug. However, after doing a subsequent dist-upgrade the issue appeared, which indicates that one of the dist-upgraded packages is involved. I have uploaded the full dist-upgraded package list at: https://pastebin.canonical.com/178774/.

2. In a fully updated zesty system exhibiting the issue, downgrading USC to 0.9.0 does not fix the problem.

Lukáš Tinkl (lukas-kde) wrote :

Yup, correct alf, verified that downgrading unity-system-compositor on xenial doesn't fix the problem

Lukáš Tinkl (lukas-kde) wrote :

#7 0x00007f348291b12b in UCContentHub::UCContentHub(QObject*) ()

Ok, so looking at the backtrace, it must be this silo that also landed recently:

https://bileto.ubuntu.com/#/ticket/2418

MP: https://code.launchpad.net/~bzoltan/ubuntu-ui-toolkit/landing-2017-01-30/+merge/315882

and the specific code: https://code.launchpad.net/~artmello/ubuntu-ui-toolkit/ubuntu-ui-toolkit-clipboard-dbus/+merge/314072

Changed in canonical-devices-system-image:
status: New → Confirmed
Changed in content-hub (Ubuntu):
importance: Undecided → High
status: New → Confirmed
Changed in unity-system-compositor (Ubuntu):
status: New → Invalid
Daniel van Vugt (vanvugt) wrote :

This appears to be a start-up race between unity8 and content-hub-service.

On a fresh boot content-hub-service is not running. It gets started /during/ the first Unity8 login. But that appears to be slightly too late. Perhaps Unity8 is hanging because it already attempted the the connection to Content Hub slightly before content-hub-service had started.

If you log out then content-hub-service keeps running in the background. So your second and subsequent login is fast.

Changed in ubuntu-ui-toolkit (Ubuntu):
status: Confirmed → In Progress
assignee: nobody → Lukáš Tinkl (lukas-kde)
Changed in qtmir (Ubuntu):
status: Confirmed → Invalid
Changed in content-hub (Ubuntu):
status: Confirmed → Invalid
Changed in unity8 (Ubuntu):
status: Confirmed → Invalid
tags: added: unity8
Changed in ubuntu-ui-toolkit (Ubuntu):
status: In Progress → Fix Committed
Changed in canonical-devices-system-image:
status: Confirmed → Fix Committed
Daniel van Vugt (vanvugt) wrote :

Still eagerly awaiting a release for this :)

Michał Sawicz (saviq) on 2017-03-06
Changed in canonical-devices-system-image:
assignee: nobody → Zoltan Balogh (bzoltan)
kevin gunn (kgunn72) on 2017-03-06
Changed in canonical-devices-system-image:
milestone: none → u8c-1
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package ubuntu-ui-toolkit - 1.3.2184+17.04.20170306

---------------
ubuntu-ui-toolkit (1.3.2184+17.04.20170306) zesty; urgency=medium

  [ Adnane Belmadiaf ]
  * Add support for CheckBox label when set
  * Add more tests for checkbox. Fixes LP: #1333228, LP: #1442851.
  * Make sure we resets partial text input from the input method.
    Fixes LP: #1630872.
  * Fix ListItem title/subtitle alignment & elide in RTL mode.
    Fixes LP: #1665944.
  * Fix PageHeader title alignment & elide in RTL mode. Fixes LP: #1665942.
  * Fix UbuntuListView docs. Fixes LP: #1486940.
  * Add count prop to OptionSelector. Fixes LP: #1341559.
  * Replace the hardcoded color with a theme color. Fixes LP: #1664758.
  * Fix the import statement for Menu, MenuBar and MenuGroup.
    Fixes LP: #1660604.

  [ Albert Astals Cid ]
  * Fix memory leak in UCStyleHints
  * ThinDivider: Anchors can't be null, set to undefined
  * No need to call UCUnits::resolveResource to learn we just need to load it
    normally because the fact that we already loaded it normally means we need
    to load it normally. Fixes LP: #1558663.
  * Fix conditional jump or move depends on uninitialised value(s)

  [ Christian Dywan ]
  * Initialize UCApplication with no side effects. Fixes LP: #1662868.
  * Unit test case insensitive FilterBehavior.pattern. Fixes LP: #1663924.
  * ListItemPopover delegate should (in)visible as per action Bug 1662220:
    [ListItem] Popupmenu shows traces of disabled actions

  [ Olivier Tilloy ]
  * Check that window is not null before accessing its activeFocusItem property.
    Fixes LP: #1664620.

  [ Lukáš Tinkl ]
  * Unbreak the startup race between unity8/qtmir and UITK trying talk to
    content-hub. Fixes LP: #1663106.

 -- Zoltán Balogh <email address hidden> Mon, 06 Mar 2017 16:04:56 +0000

Changed in ubuntu-ui-toolkit (Ubuntu):
status: Fix Committed → Fix Released
Changed in canonical-devices-system-image:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers