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
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/
(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.
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.
TelepathyMPRIS::detectPlayers() does use async DBus methods (from 0.4 onwards), so I don't think we (KTp) are doing anything wrong?
(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?
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.
(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.
Subscribing Alex Merry as he is a MPRIS specialist.
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*)));
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.
Thanks a lot, I'll try to fix it on the ktp side then.
Reassigning to KDE Telepathy
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.
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
(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.