Bug 310826

Summary: Amarok startup hangs for 5 seconds in KSystemTimeZonesPrivate::instance() - race condition with Telepathy Integration kded4 Module
Product: [Unmaintained] telepathy Reporter: Matěj Laitl <matej>
Component: kded-moduleAssignee: Telepathy Bugs <kde-telepathy-bugs>
Status: RESOLVED FIXED    
Severity: normal CC: alex.merry, amarok-bugs-dist, cfeck, ddomenichelli, kde-telepathy-bugs, kde, mklapetek
Priority: NOR    
Version: 0.5.1   
Target Milestone: 0.5-next   
Platform: unspecified   
OS: Linux   
Latest Commit: http://commits.kde.org/telepathy-kded-module/b03f8da1eb88d2fbeac5f936cf74a7f72612011d Version Fixed In: 0.5.2
Sentry Crash Report:

Description Matěj Laitl 2012-11-28 15:11:59 UTC 
I've found out that Amarok *sometimes* starts unusually long. Attaching gdb always leads to the same backtrace: KCalendarSystem::formatDate() triggers KSystemTimeZonesPrivate::instance() call which seems to be doing some syncrhonous DBUS stuff that takes at least 5 seconds. I'm Amarok developer and I'd like my app to start as quick as possible.

Note that this doesn't happen everytime for me, but once it happens in a user session, it frequently happens the next time if Amarok is quitted and started again in that session.

Reproducible: Sometimes

Steps to Reproduce:
1. Start Amarok, open Configuration -> Playback -> enable "Resume playback on start"
2. Start playing a song, quit Amarok while it is still playing
3. Start Amarok again.
Actual Results:  
The main window shows, but is gray. This lasts at least 5 seconds, the the window is then filled and Amarok shows its OSD and works normally from this point.

Expected Results:  
Amarok starting in an instant with SSD - as it does when this bug is not triggered.

Possibly the same bug (but no backtrace): bug 227723

Full backtrace follows:
#0  0x00007fa372472bc3 in *__GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
        resultvar = 18446744073709551100
        oldtype = 0
        result = <optimized out>
#1  0x00007fa368e04080 in socket_do_iteration (transport=0x1706610, flags=6, timeout_milliseconds=<optimized out>)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-transport-socket.c:1125
        socket_transport = 0x1706610
        poll_fd = {fd = 5, events = 1, revents = 0}
        poll_res = <optimized out>
        poll_timeout = <optimized out>
#2  0x00007fa368e02f6d in _dbus_transport_do_iteration (transport=0x1706610, flags=<optimized out>, timeout_milliseconds=<optimized out>)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-transport.c:976
No locals.
#3  0x00007fa368df13a5 in _dbus_connection_do_iteration_unlocked (connection=0x1706d00, pending=<optimized out>, flags=6, timeout_milliseconds=25000)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-connection.c:1234
No locals.
#4  0x00007fa368df22a3 in _dbus_connection_block_pending_call (pending=0x26d4140) at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-connection.c:2415
        start_tv_sec = <optimized out>
        start_tv_usec = <optimized out>
        tv_sec = <optimized out>
        tv_usec = <optimized out>
        status = <optimized out>
        connection = 0x1706d00
        client_serial = 176
        timeout = 0x4575060
        timeout_milliseconds = 25000
#5  0x00007fa368df19ed in dbus_connection_send_with_reply_and_block (connection=0x1706d00, message=0x42f9730, timeout_milliseconds=-1, error=0x7fff35f98b50)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-connection.c:3530
        reply = <optimized out>
        pending = 0x26d4140
#6  0x00007fa3707da327 in q_dbus_connection_send_with_reply_and_block (error=0x7fff35f98b50, timeout_milliseconds=-1, message=0x42f9730, connection=<optimized out>)
    at qdbus_symbols_p.h:135
No locals.
#7  QDBusConnectionPrivate::sendWithReply (this=0x17026c0, message=..., sendMode=<optimized out>, timeout=-1) at qdbusintegrator.cpp:1904
        err = {code = QDBusError::NoError, msg = {d = 0x613660}, nm = {d = 0x613660}, unused = 0x7fff35f98be0}
        msg = 0x42f9730
        amsg = {d_ptr = 0x4587cc0}
        error = {error = {name = 0x0, message = 0x0, dummy1 = 1, dummy2 = 0, dummy3 = 0, dummy4 = 0, dummy5 = 1, padding1 = 0x45735a0}}
        reply = <optimized out>
#8  0x00007fa3707dad7c in QDBusConnectionPrivate::findMetaObject (this=0x17026c0, service=..., path=<optimized out>, interface=..., error=...)
    at qdbusintegrator.cpp:2356
        msg = {d_ptr = 0x45797e0}
        mo = <optimized out>
        xml = {d = 0x4579890}
        reply = {d_ptr = 0x7fff0000000f}
        result = <optimized out>
#9  0x00007fa3707ea173 in QDBusInterfacePrivate::QDBusInterfacePrivate (this=0x4573610, serv=<optimized out>, p=<optimized out>, iface=<optimized out>, 
    con=<optimized out>) at qdbusinterface.cpp:158
No locals.
#10 0x00007fa3707ea2b9 in QDBusInterface::QDBusInterface (this=0x45646f0, service=..., path=..., interface=..., connection=<optimized out>, parent=0x0)
    at qdbusinterface.cpp:220
No locals.
#11 0x00007fa37325de54 in KSystemTimeZonesPrivate::instance () at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/ksystemtimezone.cpp:304
        dbusIface = {d = 0x45853e0}
        ktimezoned = <optimized out>
        reply = {m_error = {code = 3757949436, msg = {d = 0x7fa375b99b22}, nm = {d = 0x0}, unused = 0x0}}
        __PRETTY_FUNCTION__ = "static KSystemTimeZonesPrivate* KSystemTimeZonesPrivate::instance()"
#12 0x00007fa37325e559 in KSystemTimeZones::local () at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/ksystemtimezone.cpp:201
No locals.
#13 0x00007fa373242a98 in KDateTime::Spec::setType (this=0x7fff35f99290, type=<optimized out>, utcOffset=<optimized out>)
    at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/kdatetime.cpp:170
No locals.
#14 0x00007fa37324e9e6 in KDateTimeFormatter::formatDate (this=0x7fff35f99310, fromDate=..., toFormat=..., calendar=0x4585470, locale=0x1779f30, 
    digitSet=KLocale::ArabicDigits, formatStandard=KLocale::KdeFormat)
    at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/kdatetimeformatter.cpp:59
No locals.
#15 0x00007fa37322e494 in KCalendarSystem::formatDate (this=0x4585470, fromDate=..., toFormat=..., digitSet=KLocale::ArabicDigits, formatStandard=KLocale::KdeFormat)
    at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/kcalendarsystem.cpp:2111
        formatter = {_vptr.KDateTimeFormatter = 0x7fa373631730, m_englishLocale = 0x0, m_englishCalendar = 0x0}
#16 0x00007fa37322e4f3 in KCalendarSystem::formatDate (this=0x4585470, fromDate=..., toFormat=..., standard=KLocale::KdeFormat)
    at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/kcalendarsystem.cpp:2099
No locals.
#17 0x00007fa37322ef42 in KCalendarSystem::formatDate (this=0x4585470, date=..., component=<optimized out>, format=KLocale::LongNumber, 
    weekNumberSystem=<optimized out>) at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdecore/date/kcalendarsystem.cpp:2133
        d = 0x26d2160
#18 0x00007fa3752bcd95 in Amarok::verboseTimeSince (datetime=...) at /home/strohel/projekty/amarok/src/core/support/Amarok.cpp:60
        cal = 0x4585470
        date = {jd = 2456169}
        now = {d = {d = 0x454afe0}}
        datediff = <optimized out>
        timediff = <optimized out>
#19 0x00007fa374ca5480 in Amarok::TrayIcon::updateToolTip (this=0x26d7920) at /home/strohel/projekty/amarok/src/TrayIcon.cpp:183
        tooltip = {<QList<QString>> = {{p = {d = 0x42f9300}, d = 0x42f9300}}, <No data fields>}
        volume = {d = 0x42f97f0}
        count = 8
        statistics = {d = 0x7fa338003f98}
        score = <optimized out>
        rating = 0
        lastPlayed = {d = {d = 0x7fa338003580}}
#20 0x00007fa374ca580c in Amarok::TrayIcon::updateToolTipIcon (this=0x26d7920) at /home/strohel/projekty/amarok/src/TrayIcon.cpp:110
No locals.
#21 0x00007fa374ca633d in Amarok::TrayIcon::qt_static_metacall (_o=0x26d7920, _c=<optimized out>, _id=<optimized out>, _a=0x7fff35f99b50)
    at /home/strohel/projekty/amarok/build/src/TrayIcon.moc:68
        _t = 0x26d7920
#22 0x00007fa372e038a0 in QMetaObject::activate (sender=0x17e21a0, m=<optimized out>, local_signal_index=<optimized out>, argv=0x7fff35f99b50)
    at kernel/qobject.cpp:3547
        receiverInSameThread = true
        previousSender = 0x0
        callFunction = 0x7fa374ca6270 <Amarok::TrayIcon::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>
        receiver = 0x26d7920
        currentSender = {sender = 0x17e21a0, signal = 7, ref = 1}
        method_relative = 4
        c = 0x275f8b0
        last = 0x42ef710
        methodOffset = <optimized out>
        signal_absolute_index = 7
        empty_argv = {0x0}
        locker = {val = 25557808}
        connectionLists = 0x18f8100
        list = 0x1859e20
        signalOffset = <optimized out>
        signal_index = <optimized out>
        currentThreadId = 140340033202048
#23 0x00007fa37490d805 in EngineController::trackPlaying (this=<optimized out>, _t1=<optimized out>)
    at /home/strohel/projekty/amarok/build/src/moc_EngineController.cpp:282
        _a = {0x0, 0x7fff35f99bc0}
#24 0x00007fa374c79d3d in EngineController::slotNewTrackPlaying (this=0x17e21a0, source=<optimized out>) at /home/strohel/projekty/amarok/src/EngineController.cpp:1130
        uniquelyNamedStackAllocatedStandardBlock = {m_startTime = {t1 = 6, t2 = 23839392}, 
          m_label = 0x7fa374df4ee0 "void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&)", m_color = 0}
        __PRETTY_FUNCTION__ = "void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&)"
#25 0x00007fa374916622 in EngineController::qt_static_metacall (_o=0x17e21a0, _c=<optimized out>, _id=44, _a=0x7fff35f99f40)
    at /home/strohel/projekty/amarok/build/src/moc_EngineController.cpp:199
        _t = 0x17e21a0
#26 0x00007fa372e038a0 in QMetaObject::activate (sender=0x1863ec0, m=<optimized out>, local_signal_index=<optimized out>, argv=0x7fff35f99f40)
    at kernel/qobject.cpp:3547
        receiverInSameThread = true
        previousSender = 0x0
        callFunction = 0x7fa374916190 <EngineController::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>
        receiver = 0x17e21a0
        currentSender = {sender = 0x1863ec0, signal = 11, ref = 1}
        method_relative = 44
        c = 0x172c9a0
        last = 0x172c9a0
        methodOffset = <optimized out>
        signal_absolute_index = 11
        empty_argv = {0x0}
        locker = {val = 30539392}
        connectionLists = 0x171d120
        list = 0x171dd50
        signalOffset = <optimized out>
        signal_index = <optimized out>
        currentThreadId = 140340033202048
#27 0x00007fa36f15b925 in Phonon::MediaObject::currentSourceChanged (this=<optimized out>, _t1=<optimized out>)
    at /var/tmp/portage/media-libs/phonon-4.6.0-r1/work/phonon-4.6.0_build/phonon/moc_mediaobject.cpp:250
        _a = {0x0, 0x2156940}
#28 0x00007fa36f15c406 in Phonon::MediaObjectPrivate::_k_currentSourceChanged (this=<optimized out>, source=...)
    at /var/tmp/portage/media-libs/phonon-4.6.0-r1/work/phonon-4.6.0/phonon/mediaobject.cpp:603
        q = 0x1863ec0
        __PRETTY_FUNCTION__ = "void Phonon::MediaObjectPrivate::_k_currentSourceChanged(const Phonon::MediaSource&)"
#29 0x00007fa372e01aa6 in QObject::event (this=0x1863ec0, e=<optimized out>) at kernel/qobject.cpp:1195
        mce = <optimized out>
        currentSender = {sender = 0x1d0e510, signal = 4, ref = 1}
        previousSender = 0x0
#30 0x00007fa373825634 in QApplicationPrivate::notify_helper (this=0x17192c0, receiver=0x1863ec0, e=0x26c2fc0) at kernel/qapplication.cpp:4557
        consumed = <optimized out>
#31 0x00007fa37382aa03 in QApplication::notify (this=<optimized out>, receiver=0x1863ec0, e=0x26c2fc0) at kernel/qapplication.cpp:4418
        d = 0x17192c0
        res = false
#32 0x00007fa375751da6 in KApplication::notify (this=0x7fff35f9aad0, receiver=0x1863ec0, event=0x26c2fc0)
    at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdeui/kernel/kapplication.cpp:311
No locals.
#33 0x00007fa372deb03c in QCoreApplication::notifyInternal (this=0x7fff35f9aad0, receiver=0x1863ec0, event=0x26c2fc0) at kernel/qcoreapplication.cpp:915
        threadData = 0x15aa1f0
        returnValue = <optimized out>
        result = false
        cbdata = {0x1863ec0, 0x26c2fc0, 0x7fff35f9a6ef}
        d = <optimized out>
#34 0x00007fa372dee6ec in sendEvent (event=0x26c2fc0, receiver=0x1863ec0) at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:231
No locals.
#35 QCoreApplicationPrivate::sendPostedEvents (receiver=0x0, event_type=0, data=0x15aa1f0) at kernel/qcoreapplication.cpp:1539
        pe = @0x2680350
        e = 0x26c2fc0
        r = 0x1863ec0
        locker = {val = 22716984}
        startOffset = 0
        i = @0x15aa22c
#36 0x00007fa372e1d083 in sendPostedEvents () at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:236
No locals.
#37 postEventSourceDispatch (s=<optimized out>) at kernel/qeventdispatcher_glib.cpp:279
        source = 0x1718d90
#38 0x00007fa36b45d653 in g_main_dispatch (context=0x171a340) at gmain.c:2539
        dispatch = 0x7fa372e1d070 <postEventSourceDispatch(GSource*, GSourceFunc, gpointer)>
        was_in_call = 0
        user_data = 0x0
        callback = 0
        cb_funcs = 0x0
        cb_data = 0x0
        current_source_link = {data = 0x1718d90, next = 0x0}
        need_destroy = <optimized out>
        source = 0x1718d90
        current = 0x172cc40
        i = <optimized out>
#39 g_main_context_dispatch (context=0x171a340) at gmain.c:3075
No locals.
#40 0x00007fa36b45d998 in g_main_context_iterate (context=0x171a340, block=1, dispatch=1, self=<optimized out>) at gmain.c:3146
        max_priority = 0
        timeout = 0
        some_ready = 1
        nfds = 13
        allocated_nfds = <optimized out>
        fds = <optimized out>
#41 0x00007fa36b45da54 in g_main_context_iteration (context=0x171a340, may_block=1) at gmain.c:3207
        retval = <optimized out>
#42 0x00007fa372e1d21f in QEventDispatcherGlib::processEvents (this=0x15abad0, flags=<optimized out>) at kernel/qeventdispatcher_glib.cpp:424
        d = 0x1719530
        canWait = true
        result = <optimized out>
#43 0x00007fa3738d799e in QGuiEventDispatcherGlib::processEvents (this=<optimized out>, flags=<optimized out>) at kernel/qguieventdispatcher_glib.cpp:204
        d = 0x1719530
        returnValue = 252
#44 0x00007fa372de94d2 in QEventLoop::processEvents (this=<optimized out>, flags=...) at kernel/qeventloop.cpp:149
        d = 0x27e6160
#45 0x00007fa372de9765 in QEventLoop::exec (this=0x7fff35f9aa30, flags=...) at kernel/qeventloop.cpp:204
        d = 0x27e6160
        locker = {val = 22717192}
        app = 0x7fff35f9a9f0
        eventLoop = 0x7fff35f9aa40
#46 0x00007fa372deeb4b in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1187
        threadData = 0x15aa1f0
        eventLoop = {<QObject> = {_vptr.QObject = 0x7fa373150670, d_ptr = {d = 0x27e6160}}, }
        returnCode = <optimized out>
#47 0x000000000040a1f9 in main (argc=1, argv=0x7fff35f9d068) at /home/strohel/projekty/amarok/src/main.cpp:329
        aboutData = {d = 0x16daa80}
        debugColorsEnabled = <optimized out>
        debugEnabled = false
        app = {<KUniqueApplication> = {<KApplication> = {<QApplication> = {<QCoreApplication> = {<QObject> = {_vptr.QObject = 0x7fa37523b790, d_ptr = {
                      d = 0x17192c0}}, }, }, d = 0x176ffd0}, d = 0x18f8c30}, m_isUniqueInstance = false, m_mainWindow = {d = 0x1a04760, value = 0x1d55cd0}, 
          m_tray = 0x26d7920, m_mediaDeviceManager = 0x7fff35f9aac0}
        args = 0x1701ef0
        startFlag = 0
Comment 1 Christoph Feck 2012-11-28 18:16:50 UTC 
As far as I know, it tries to contact kded4. If that process blocks due to a broken module, you will get the delay. To can confirm this is the case, please try disabling kded4 modules in turn, to find the offending module. For more information, see http://kdepepo.wordpress.com/2011/05/11/troubleshooting-kded4-bugs/
Comment 2 Matěj Laitl 2012-11-29 22:53:31 UTC 
(In reply to comment #1)
> As far as I know, it tries to contact kded4. If that process blocks due to a
> broken module, you will get the delay. To can confirm this is the case,
> please try disabling kded4 modules in turn, to find the offending module.

Okay, let's see. I've attached gdb to kded4 while Amarok was hanging. The hang prolonged to something that feels like 25-second timeout of the DBUS call, so it seems that kded4 is the culprit. The kded4 backtrace was always the same 3 times I've tried starting again:
Thread 3 (Thread 0x7f54e66be700 (LWP 1615)):
#0  0x00007f54ff6cf233 in select () at ../sysdeps/unix/syscall-template.S:82
#1  0x00007f5500deaa8c in QProcessManager::run (this=0x7f5501179440) at io/qprocess_unix.cpp:245
#2  0x00007f5500cfd048 in QThreadPrivate::start (arg=0x7f5501179440) at thread/qthread_unix.cpp:338
#3  0x00007f5500a65da6 in start_thread (arg=0x7f54e66be700) at pthread_create.c:305
#4  0x00007f54ff6d5abd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

Thread 2 (Thread 0x7f54e49ed700 (LWP 1661)):
#0  0x00007f54ff6ccbc3 in *__GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x00007f54fc3aa936 in g_main_context_poll (n_fds=2, fds=0x7f54d80029b0, timeout=-1, context=0x7f54d80009a0, priority=<optimized out>) at gmain.c:3440
#2  g_main_context_iterate (context=0x7f54d80009a0, block=1, dispatch=1, self=<optimized out>) at gmain.c:3141
#3  0x00007f54fc3aaa54 in g_main_context_iteration (context=0x7f54d80009a0, may_block=1) at gmain.c:3207
#4  0x00007f5500e43276 in QEventDispatcherGlib::processEvents (this=0x7f54d80008c0, flags=<optimized out>) at kernel/qeventdispatcher_glib.cpp:426
#5  0x00007f5500e0f4d2 in QEventLoop::processEvents (this=<optimized out>, flags=...) at kernel/qeventloop.cpp:149
#6  0x00007f5500e0f765 in QEventLoop::exec (this=0x7f54e49ecda0, flags=...) at kernel/qeventloop.cpp:204
#7  0x00007f5500cfaa98 in QThread::exec (this=<optimized out>) at thread/qthread.cpp:501
#8  0x00007f5500dec820 in QInotifyFileSystemWatcherEngine::run (this=0x1d12660) at io/qfilesystemwatcher_inotify.cpp:248
#9  0x00007f5500cfd048 in QThreadPrivate::start (arg=0x1d12660) at thread/qthread_unix.cpp:338
#10 0x00007f5500a65da6 in start_thread (arg=0x7f54e49ed700) at pthread_create.c:305
#11 0x00007f54ff6d5abd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

Thread 1 (Thread 0x7f54f92fd780 (LWP 1610)):
#0  0x00007f54ff6ccbc3 in *__GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x00007f54fa58b080 in socket_do_iteration (transport=0x1b23f70, flags=6, timeout_milliseconds=<optimized out>)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-transport-socket.c:1125
#2  0x00007f54fa589f6d in _dbus_transport_do_iteration (transport=0x1b23f70, flags=<optimized out>, timeout_milliseconds=<optimized out>)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-transport.c:976
#3  0x00007f54fa5783a5 in _dbus_connection_do_iteration_unlocked (connection=0x1b24660, pending=<optimized out>, flags=6, timeout_milliseconds=24362)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-connection.c:1234
#4  0x00007f54fa5793a9 in _dbus_connection_block_pending_call (pending=0x2573840) at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-connection.c:2510
#5  0x00007f54fa5789ed in dbus_connection_send_with_reply_and_block (connection=0x1b24660, message=0x270caa0, timeout_milliseconds=-1, error=0x7fff492d6790)
    at /var/tmp/portage/sys-apps/dbus-1.6.8/work/dbus-1.6.8/dbus/dbus-connection.c:3530
#6  0x00007f54fda34327 in q_dbus_connection_send_with_reply_and_block (error=0x7fff492d6790, timeout_milliseconds=-1, message=0x270caa0, connection=<optimized out>)
    at qdbus_symbols_p.h:135
#7  QDBusConnectionPrivate::sendWithReply (this=0x1b20570, message=..., sendMode=<optimized out>, timeout=-1) at qdbusintegrator.cpp:1904
#8  0x00007f54fda34d7c in QDBusConnectionPrivate::findMetaObject (this=0x1b20570, service=..., path=<optimized out>, interface=..., error=...) at qdbusintegrator.cpp:2356
#9  0x00007f54fda44173 in QDBusInterfacePrivate::QDBusInterfacePrivate (this=0x2457cd0, serv=<optimized out>, p=<optimized out>, iface=<optimized out>, con=<optimized out>)
    at qdbusinterface.cpp:158
#10 0x00007f54fda442b9 in QDBusInterface::QDBusInterface (this=0x7fff492d6d90, service=..., path=..., interface=..., connection=<optimized out>, parent=0x0) at qdbusinterface.cpp:220
#11 0x00007f54deefc4c3 in TelepathyMPRIS::detectPlayers (this=0x2079f90) at /var/tmp/portage/net-im/ktp-kded-module-0.5.1/work/ktp-kded-integration-module-0.5.1/telepathy-mpris.cpp:104
#12 0x00007f54deefcc67 in TelepathyMPRIS::serviceOwnerChanged (this=0x2079f90, serviceName=<optimized out>, oldOwner=<optimized out>, newOwner=<optimized out>)
    at /var/tmp/portage/net-im/ktp-kded-module-0.5.1/work/ktp-kded-integration-module-0.5.1/telepathy-mpris.cpp:163
#13 0x00007f5500e298a0 in QMetaObject::activate (sender=0x1b242f0, m=<optimized out>, local_signal_index=<optimized out>, argv=0x7fff492d70d0) at kernel/qobject.cpp:3547
#14 0x00007f54fda70b3f in QDBusConnectionInterface::serviceOwnerChanged (this=<optimized out>, _t1=<optimized out>, _t2=<optimized out>, _t3=<optimized out>)
    at .moc/debug-shared/moc_qdbusconnectioninterface.cpp:224
#15 0x00007f54fda71117 in QDBusConnectionInterface::qt_static_metacall (_o=0x1b242f0, _c=<optimized out>, _id=2, _a=0x7fff492d73b0)
    at .moc/debug-shared/moc_qdbusconnectioninterface.cpp:114
#16 0x00007f5500e298a0 in QMetaObject::activate (sender=0x1b242f0, m=<optimized out>, local_signal_index=<optimized out>, argv=0x7fff492d73b0) at kernel/qobject.cpp:3547
#17 0x00007f54fda70c0f in QDBusConnectionInterface::NameOwnerChanged (this=<optimized out>, _t1=<optimized out>, _t2=<optimized out>, _t3=<optimized out>)
    at .moc/debug-shared/moc_qdbusconnectioninterface.cpp:252
#18 0x00007f54fda70f9f in QDBusConnectionInterface::qt_static_metacall (_o=0x1b242f0, _c=<optimized out>, _id=6, _a=0x7fff492d75e0)
    at .moc/debug-shared/moc_qdbusconnectioninterface.cpp:118
#19 0x00007f54fda7148f in QDBusConnectionInterface::qt_metacall (this=0x1b242f0, _c=QMetaObject::InvokeMetaMethod, _id=6, _a=0x7fff492d75e0)
    at .moc/debug-shared/moc_qdbusconnectioninterface.cpp:177
#20 0x00007f54fda2fe8a in QDBusConnectionPrivate::deliverCall (this=0x1b20570, object=0x1b242f0, msg=..., metaTypes=<optimized out>, slotIdx=11) at qdbusintegrator.cpp:947
#21 0x00007f5500e27aa6 in QObject::event (this=0x1b242f0, e=<optimized out>) at kernel/qobject.cpp:1195
#22 0x00007f54ffe79634 in QApplicationPrivate::notify_helper (this=0x1b30b50, receiver=0x1b242f0, e=0x24b93d0) at kernel/qapplication.cpp:4557
#23 0x00007f54ffe7ea03 in QApplication::notify (this=<optimized out>, receiver=0x1b242f0, e=0x24b93d0) at kernel/qapplication.cpp:4418
#24 0x00007f5501c09da6 in KApplication::notify (this=0x7fff492d82b0, receiver=0x1b242f0, event=0x24b93d0)
    at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kdeui/kernel/kapplication.cpp:311
#25 0x00007f5500e1103c in QCoreApplication::notifyInternal (this=0x7fff492d82b0, receiver=0x1b242f0, event=0x24b93d0) at kernel/qcoreapplication.cpp:915
#26 0x00007f5500e146ec in sendEvent (event=0x24b93d0, receiver=0x1b242f0) at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:231
#27 QCoreApplicationPrivate::sendPostedEvents (receiver=0x0, event_type=0, data=0x1a942b0) at kernel/qcoreapplication.cpp:1539
#28 0x00007f5500e43083 in sendPostedEvents () at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:236
#29 postEventSourceDispatch (s=<optimized out>) at kernel/qeventdispatcher_glib.cpp:279
#30 0x00007f54fc3aa653 in g_main_dispatch (context=0x1b32000) at gmain.c:2539
#31 g_main_context_dispatch (context=0x1b32000) at gmain.c:3075
#32 0x00007f54fc3aa998 in g_main_context_iterate (context=0x1b32000, block=1, dispatch=1, self=<optimized out>) at gmain.c:3146
#33 0x00007f54fc3aaa54 in g_main_context_iteration (context=0x1b32000, may_block=1) at gmain.c:3207
#34 0x00007f5500e4321f in QEventDispatcherGlib::processEvents (this=0x1a967d0, flags=<optimized out>) at kernel/qeventdispatcher_glib.cpp:424
#35 0x00007f54fff2b99e in QGuiEventDispatcherGlib::processEvents (this=<optimized out>, flags=<optimized out>) at kernel/qguieventdispatcher_glib.cpp:204
#36 0x00007f5500e0f4d2 in QEventLoop::processEvents (this=<optimized out>, flags=...) at kernel/qeventloop.cpp:149
#37 0x00007f5500e0f765 in QEventLoop::exec (this=0x7fff492d8200, flags=...) at kernel/qeventloop.cpp:204
#38 0x00007f5500e14b4b in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1187
#39 0x00007f54ec8e5e17 in kdemain (argc=1, argv=0x1b0e490) at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kded/kded.cpp:924
#40 0x000000000040754c in launch (argc=1, _name=0x40b78b "kded4", args=<optimized out>, cwd=0x0, envc=<optimized out>, envs=<optimized out>, reset_env=false, tty=0x0, avoid_loops=false, 
    startup_id_str=0x40b626 "0") at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kinit/kinit.cpp:726
#41 0x0000000000409de6 in main (argc=2, argv=0x7fff492d90a8, envp=0x7fff492d90c0) at /var/tmp/portage/kde-base/kdelibs-4.9.3/work/kdelibs-4.9.3/kinit/kinit.cpp:1841


Wild guess: the TelepathyMPRIS::detectPlayers looks suspicious. MPRIS is a DBUS standard for media players that Amarok implements and advertises over dbus. A race condition comes to my mind:
1. Amarok is started, advertises MPIRS interface over DBUS
2. Amarok calls KCalendarSystem::formatDate() somewhen in the start-up sequence, which launches blocking DBUS call to kded4
2. At the nearly same time, kded4 triggers TelepathyMPRIS::detectPlayers(), which launches blocking DBUS call to amarok
3. -> soft dead-lock.

The question is why that exact timing happens so often. Telepathy Integration Module is a load-on-demand kded4 service, and I cannot trigger it to unload despite turning off KDE telepathy and removing all telepathy-related plasmoids. Will try logging out.
Comment 3 Matěj Laitl 2012-11-29 23:10:11 UTC 
Okay, it's definitely caused by Telepathy Integration kded4 Module, when I start a new session without it running, I'm unable to reproduce the bug. When I add KTP Presence applet to Plasma Desktop, which triggers Telepathy Integration kded4 Modul load, the bug appears on next Amarok startup.

One may wonder what Telepathy could do with MPRIS. I've used "Now Listening to" idle message functionality in KDE Telepathy in past, so that may be the use.

The question is now how to solve this. A simple work-around could be to pospone publishing the MPRIS interface in Amarok a few seconds, but this seems hacky. A "proper" solution IMO would be if both KSystemTimeZonesPrivate::instance() and TelepathyMPRIS::detectPlayers() used *async* DBUS methods, if possible.

Should this bug be reassigned to KDE Telepathy? The KSystemTimeZonesPrivate::instance() situation looks suboptimal to me.
Comment 4 David Edmundson 2012-11-29 23:35:33 UTC 
TelepathyMPRIS::detectPlayers()  does use async DBus methods (from 0.4 onwards), so I don't think we (KTp) are doing anything wrong?
Comment 5 Matěj Laitl 2012-11-29 23:48:46 UTC 
(In reply to comment #4)
> TelepathyMPRIS::detectPlayers()  does use async DBus methods (from 0.4
> onwards), so I don't think we (KTp) are doing anything wrong?

Hmm, I have ktp-kded-module-0.5.1.

From the backtrace
#7 QDBusConnectionPrivate::sendWithReply (this=0x1b20570, message=..., sendMode=<optimized out>, timeout=-1) at qdbusintegrator.cpp:1904
#8 0x00007f54fda34d7c in QDBusConnectionPrivate::findMetaObject (this=0x1b20570, service=..., path=<optimized out>, interface=..., error=...) at qdbusintegrator.cpp:2356
#9 0x00007f54fda44173 in QDBusInterfacePrivate::QDBusInterfacePrivate (this=0x2457cd0, serv=<optimized out>, p=<optimized out>, iface=<optimized out>, con=<optimized out>) at qdbusinterface.cpp:158
#10 0x00007f54fda442b9 in QDBusInterface::QDBusInterface (this=0x7fff492d6d90, service=..., path=..., interface=..., connection=<optimized out>, parent=0x0) at qdbusinterface.cpp:220
#11 0x00007f54deefc4c3 in TelepathyMPRIS::detectPlayers (this=0x2079f90) at /var/tmp/portage/net-im/ktp-kded-module-0.5.1/work/ktp-kded-integration-module-0.5.1/telepathy-mpris.cpp:104

it seem that merely creating a QDBusInterface is synchronous. :-(

But I think my original wild guess doesn't seem to be right. Does the line
QDBusInterface mprisInterface(service, QLatin1String("/org/mpris/MediaPlayer2"), QLatin1String("org.freedesktop.DBus.Properties"));
try to contact Amarok in any way?
Comment 6 David Edmundson 2012-11-29 23:52:43 UTC 
I bet it's QDBusConnectionInterface::registeredServiceNames that's synchronous.  Though there's no async equivalent that I'm aware of.  

That would probably match the line in your code you're showing me.

We call that on load to find the players so we can start our async calls to it to find out if it's playing anything.

Looking at this code, it could be optimised, but we still need to call this method on load, and your potential lock still exists.
Comment 7 Matěj Laitl 2012-11-30 00:31:15 UTC 
(In reply to comment #6)
> I bet it's QDBusConnectionInterface::registeredServiceNames that's
> synchronous.  Though there's no async equivalent that I'm aware of.  
> That would probably match the line in your code you're showing me.

Hmm, it doesn't show up in the backtrace. QDBusConnectionPrivate::findMetaObject() really calls
QDBusMessage reply = sendWithReply(msg, QDBus::Block);
in qdbuintegrator.cpp:2356.
Comment 8 Myriam Schweingruber 2012-11-30 10:08:30 UTC 
Subscribing Alex Merry as he is a MPRIS specialist.
Comment 9 Alex Merry 2012-11-30 10:39:58 UTC 
The way I dealt with registeredBusNames being synchronous in the Plasma mpris2 dataengine was to manually construct a call to it:

    QDBusPendingCall async = QDBusConnection::sessionBus().interface()->asyncCall("ListNames");
    QDBusPendingCallWatcher *callWatcher = new QDBusPendingCallWatcher(async, this);
    connect(callWatcher, SIGNAL(finished(QDBusPendingCallWatcher*)),
            this,        SLOT(serviceNameFetchFinished(QDBusPendingCallWatcher*)));
Comment 10 Alex Merry 2012-11-30 10:43:14 UTC 
Incidentally, it sounds like TelepathyMPRIS is calling registeredServiceNames multiple times in one session, which shouldn't really be happening.  You need to call it once to get a list of the players that are *already running*, but after that you should just be using QDBusServiceWatcher to keep track of which MPRIS-capable players are around.
Comment 11 Martin Klapetek 2012-11-30 13:02:48 UTC 
Thanks a lot, I'll try to fix it on the ktp side then.
Comment 12 Daniele E. Domenichelli 2012-11-30 13:24:04 UTC 
Reassigning to KDE Telepathy
Comment 13 David Edmundson 2012-11-30 14:36:03 UTC 
For future: I'd rather you made a new bug rather than reassigning, then mark the original as blocked.

By reassigning, someone searching for Amarok slow startup time will not be able to find this. 
Also our bug is that we make a synchronous dbus call, we can fix and close that, but it's not our  place to say that the bug in Amarok is fixed.
Comment 14 Martin Klapetek 2012-12-12 01:09:33 UTC 
Git commit b03f8da1eb88d2fbeac5f936cf74a7f72612011d by Martin Klapetek.
Committed on 12/12/2012 at 02:05.
Pushed by mklapetek into branch 'kde-telepathy-0.5'.

Look async'sly for mpris2 dbus interfaces

QDBusConnection::sessionBus().interface()->registeredServiceNames()
is sync dbus call, freezing some things while being called.
This does that call in async way.

REVIEW: 107605

M  +21   -2    telepathy-mpris.cpp
M  +3    -0    telepathy-mpris.h

http://commits.kde.org/telepathy-kded-module/b03f8da1eb88d2fbeac5f936cf74a7f72612011d
Comment 15 Matěj Laitl 2012-12-12 15:53:24 UTC 
(In reply to comment #14)
> Git commit b03f8da1eb88d2fbeac5f936cf74a7f72612011d by Martin Klapetek.
> 
> Look async'sly for mpris2 dbus interfaces

Thanks! Will test when you release 0.5.2 and Gentoo packages it and report back in unlikely occasion that I'm still able to reproduce.