Bug 349992 - kwin_wayland and kamd dead locks on startup
Summary: kwin_wayland and kamd dead locks on startup
Status: RESOLVED FIXED
Alias: None
Product: kactivitymanagerd
Classification: Unmaintained
Component: general (other bugs)
Version First Reported In: unspecified
Platform: Other Linux
: NOR grave
Target Milestone: ---
Assignee: Ivan Čukić
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-07-07 09:12 UTC by Martin Flöser
Modified: 2015-11-15 15:18 UTC (History)
2 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Flöser 2015-07-07 09:12:42 UTC
When kwin_wayland starts up, there is a place where it starts kamd and this times out. Backtrace of KWin is:

#0  0x00007fffedde350d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007fffe2766df8 in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#2  0x00007fffe2765ca8 in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#3  0x00007fffe274f074 in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#4  0x00007fffe274fb2c in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#5  0x00007fffe275002a in dbus_connection_send_with_reply_and_block () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#6  0x00007ffff7ea609b in q_dbus_connection_send_with_reply_and_block (connection=0x6797c0, message=0x67b150, timeout_milliseconds=-1, error=0x7fffffffbc60) at qdbus_symbols_p.h:135
#7  0x00007ffff7eb0556 in QDBusConnectionPrivate::sendWithReply (this=0x677e50, message=..., sendMode=1, timeout=-1) at qdbusintegrator.cpp:2046
#8  0x00007ffff7eb363f in QDBusConnectionPrivate::findMetaObject (this=0x677e50, service=..., path=..., interface=..., error=...) at qdbusintegrator.cpp:2527
#9  0x00007ffff7ec6a50 in QDBusInterfacePrivate::QDBusInterfacePrivate (this=0x1a0c740, serv=..., p=..., iface=..., con=...) at qdbusinterface.cpp:150
#10 0x00007ffff7ec6c04 in QDBusInterface::QDBusInterface (this=0x7fffffffc1a0, service=..., path=..., interface=..., connection=..., parent=0x0) at qdbusinterface.cpp:212
#11 0x00007ffff3791aaf in KActivities::Manager::serviceOwnerChanged (this=0x1484f20, serviceName=..., oldOwner=..., newOwner=...) at /home/martin/src/kf5/frameworks/kactivities/src/lib/core/manager_p.cpp:114
#12 0x00007ffff3793b8b in QtPrivate::FunctorCall<QtPrivate::IndexesList<0, 1, 2>, QtPrivate::List<QString const&, QString const&, QString const&>, void, void (KActivities::Manager::*)(QString const&, QString const&, QString const&)>::call (f=(void (KActivities::Manager::*)(KActivities::Manager * const, const QString &, const QString &, const QString &)) 0x7ffff3791964 <KActivities::Manager::serviceOwnerChanged(QString const&, QString const&, QString const&)>, 
    o=0x1484f20, arg=0x7fffffffc550) at /opt/qt5/include/QtCore/qobjectdefs_impl.h:500
#13 0x00007ffff3793719 in QtPrivate::FunctionPointer<void (KActivities::Manager::*)(QString const&, QString const&, QString const&)>::call<QtPrivate::List<QString const&, QString const&, QString const&>, void> (f=
    (void (KActivities::Manager::*)(KActivities::Manager * const, const QString &, const QString &, const QString &)) 0x7ffff3791964 <KActivities::Manager::serviceOwnerChanged(QString const&, QString const&, QString const&)>, 
    o=0x1484f20, arg=0x7fffffffc550) at /opt/qt5/include/QtCore/qobjectdefs_impl.h:519
#14 0x00007ffff3793411 in QtPrivate::QSlotObject<void (KActivities::Manager::*)(QString const&, QString const&, QString const&), QtPrivate::List<QString const&, QString const&, QString const&>, void>::impl (which=1, this_=0x6ab800, 
    r=0x1484f20, a=0x7fffffffc550, ret=0x0) at /opt/qt5/include/QtCore/qobject_impl.h:143
#15 0x00007fffef35262b in QtPrivate::QSlotObjectBase::call (this=0x6ab800, r=0x1484f20, a=0x7fffffffc550) at ../../include/QtCore/../../src/corelib/kernel/qobject_impl.h:124
#16 0x00007fffef34f70c in QMetaObject::activate (sender=0x1484f30, signalOffset=3, local_signal_index=2, argv=0x7fffffffc550) at kernel/qobject.cpp:3702
#17 0x00007fffef34f024 in QMetaObject::activate (sender=0x1484f30, m=0x7ffff7f30f80 <QDBusServiceWatcher::staticMetaObject>, local_signal_index=2, argv=0x7fffffffc550) at kernel/qobject.cpp:3582
#18 0x00007ffff7efb163 in QDBusServiceWatcher::serviceOwnerChanged (this=0x1484f30, _t1=..., _t2=..., _t3=...) at .moc/moc_qdbusservicewatcher.cpp:214
#19 0x00007ffff7efa292 in QDBusServiceWatcherPrivate::_q_serviceOwnerChanged (this=0x14855e0, service=..., oldOwner=..., newOwner=...) at qdbusservicewatcher.cpp:74
#20 0x00007ffff7efad40 in QDBusServiceWatcher::qt_static_metacall (_o=0x1484f30, _c=QMetaObject::InvokeMetaMethod, _id=3, _a=0x7fffffffc6c0) at .moc/moc_qdbusservicewatcher.cpp:98
#21 0x00007ffff7efaf0d in QDBusServiceWatcher::qt_metacall (this=0x1484f30, _c=QMetaObject::InvokeMetaMethod, _id=3, _a=0x7fffffffc6c0) at .moc/moc_qdbusservicewatcher.cpp:151
#22 0x00007ffff7eaa9ef in QDBusConnectionPrivate::deliverCall (this=0x677e50, object=0x1484f30, msg=..., metaTypes=..., slotIdx=8) at qdbusintegrator.cpp:993
#23 0x00007ffff7eb5125 in QDBusCallDeliveryEvent::placeMetaCall (this=0x1a0a330, object=0x1484f30) at qdbusintegrator_p.h:95
#24 0x00007fffef348dd8 in QObject::event (this=0x1484f30, e=0x1a0a330) at kernel/qobject.cpp:1245
#25 0x00007fffefe515ec in QApplicationPrivate::notify_helper (this=0x64cdd0, receiver=0x1484f30, e=0x1a0a330) at kernel/qapplication.cpp:3720
#26 0x00007fffefe4ed68 in QApplication::notify (this=0x7fffffffd600, receiver=0x1484f30, e=0x1a0a330) at kernel/qapplication.cpp:3164
#27 0x00007ffff795381d in KWin::Application::notify (this=0x7fffffffd600, o=0x1484f30, e=0x1a0a330) at /home/martin/src/kf5/kde/workspace/kwin/main.cpp:246
#28 0x0000000000410c7c in KWin::ApplicationWayland::notify (this=0x7fffffffd600, o=0x1484f30, e=0x1a0a330) at /home/martin/src/kf5/kde/workspace/kwin/main_wayland.cpp:270
#29 0x00007fffef30c3bc in QCoreApplication::notifyInternal (this=0x7fffffffd600, receiver=0x1484f30, event=0x1a0a330) at kernel/qcoreapplication.cpp:935
#30 0x00007fffef31001d in QCoreApplication::sendEvent (receiver=0x1484f30, event=0x1a0a330) at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:228
#31 0x00007fffef30d6f5 in QCoreApplicationPrivate::sendPostedEvents (receiver=0x0, event_type=0, data=0x633200) at kernel/qcoreapplication.cpp:1552
#32 0x00007fffef381aff in QEventDispatcherUNIX::processEvents (this=0x63d0d0, flags=...) at kernel/qeventdispatcher_unix.cpp:579
#33 0x00000000004116d5 in KWin::EventDispatcher::processEvents (this=0x63d0d0, flags=...) at /home/martin/src/kf5/kde/workspace/kwin/main_wayland.cpp:371
#34 0x00007fffef309060 in QEventLoop::processEvents (this=0x7fffffffd530, flags=...) at kernel/qeventloop.cpp:128
#35 0x00007fffef309339 in QEventLoop::exec (this=0x7fffffffd530, flags=...) at kernel/qeventloop.cpp:204
#36 0x00007fffef30ca96 in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1188
#37 0x00007fffef70dd36 in QGuiApplication::exec () at kernel/qguiapplication.cpp:1507
---Type <return> to continue, or q <return> to quit---
#38 0x00007fffefe4e595 in QApplication::exec () at kernel/qapplication.cpp:2956
#39 0x0000000000413959 in main (argc=4, argv=0x7fffffffdea8) at /home/martin/src/kf5/kde/workspace/kwin/main_wayland.cpp:639

As we can see it's
QDBusInterface service(KAMD_DBUS_SERVICE,
                    "/ActivityManager",
                    "org.kde.ActivityManager.Application",
                    QDBusConnection::sessionBus(),
                    Q_NULLPTR);

Now the real problem is that kamd is also in a blocking dbus call. The backtrace looks like this:
#0  0x00007ffff4f9450d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007fffe17ebdf8 in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#2  0x00007fffe17eaca8 in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#3  0x00007fffe17d4074 in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#4  0x00007fffe17d4a4d in ?? () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#5  0x00007fffe17d502a in dbus_connection_send_with_reply_and_block () from /lib/x86_64-linux-gnu/libdbus-1.so.3
#6  0x00007ffff7f6909b in q_dbus_connection_send_with_reply_and_block (connection=0x6ff490, message=0x6fe940, timeout_milliseconds=-1, error=0x7fffffffd120) at qdbus_symbols_p.h:135
#7  0x00007ffff7f73556 in QDBusConnectionPrivate::sendWithReply (this=0x6ff230, message=..., sendMode=1, timeout=-1) at qdbusintegrator.cpp:2046
#8  0x00007ffff7f7663f in QDBusConnectionPrivate::findMetaObject (this=0x6ff230, service=..., path=..., interface=..., error=...) at qdbusintegrator.cpp:2527
#9  0x00007ffff7f89a50 in QDBusInterfacePrivate::QDBusInterfacePrivate (this=0x6f1d40, serv=..., p=..., iface=..., con=...) at qdbusinterface.cpp:150
#10 0x00007ffff7f89c04 in QDBusInterface::QDBusInterface (this=0x6f1070, service=..., path=..., interface=..., connection=..., parent=0x0) at qdbusinterface.cpp:212
#11 0x000000000045f04b in KSMServer::Private::serviceOwnerChanged (this=0x6f0d80, service=..., oldOwner=..., newOwner=...) at /home/martin/src/kf5/frameworks/kactivities/src/service/ksmserver/KSMServer.cpp:77
#12 0x000000000045ec6a in KSMServer::Private::Private (this=0x6f0d80, parent=0x6fa040) at /home/martin/src/kf5/frameworks/kactivities/src/service/ksmserver/KSMServer.cpp:55
#13 0x0000000000460386 in kamd::utils::d_ptr<KSMServer::Private>::d_ptr<KSMServer*>(KSMServer*&&) (this=0x6fa050) at /home/martin/src/kf5/frameworks/kactivities/src/utils/d_ptr_implementation.h:37
#14 0x000000000045f20b in KSMServer::KSMServer (this=0x6fa040, parent=0x6f0370) at /home/martin/src/kf5/frameworks/kactivities/src/service/ksmserver/KSMServer.cpp:94
#15 0x000000000044e49c in Activities::Activities (this=0x6f0370, parent=0x0) at /home/martin/src/kf5/frameworks/kactivities/src/service/Activities.cpp:118
#16 0x0000000000447a40 in runInQThread<Activities> () at /home/martin/src/kf5/frameworks/kactivities/src/service/Application.cpp:72
#17 0x0000000000443a04 in Application::init (this=0x7fffffffdbe0) at /home/martin/src/kf5/frameworks/kactivities/src/service/Application.cpp:158
#18 0x0000000000445452 in main (argc=2, argv=0x7fffffffdeb8) at /home/martin/src/kf5/frameworks/kactivities/src/service/Application.cpp:412

which is as one can guess:
new QDBusInterface(KWIN_SERVICE, QStringLiteral("/KWin"), QStringLiteral("org.kde.KWin"))

When this happens we can see the following on KWin's debug output:
kwin(2359)/(default) QDBusBlockingCallWatcher::~QDBusBlockingCallWatcher: QDBusConnection: warning: blocking call took a long time (25161 ms, max for this thread is 200 ms) to service "org.kde.ActivityManager" path "/ActivityManager" interface "org.freedesktop.DBus.Introspectable" member "Introspect"

and
kwin(2359)/(default) KActivities::Manager::serviceOwnerChanged(const QString&, const QString&, const QString&)::<lambda: KActivities: FATAL ERROR: Failed to contact the activity manager daemon

As a freeze of 25 sec in the main thread during startup is not acceptable, we need a good solution for this ASAP. It means one cannot move the cursor, one cannot vt switch and applications which are started in parallel fail due to the Wayland server not being responsive.

Reproducible: Always

Steps to Reproduce:
1. start kwin_wayland

Actual Results:  
DBus dead lock

Expected Results:  
No dbus dead lock

everything on git master, rebuild before reporting this bug.
Comment 1 Martin Flöser 2015-07-07 09:50:32 UTC
Git commit a1a89d3d1efcf863c33a827a5a5d917f839dbb02 by Martin Gräßlin.
Committed on 07/07/2015 at 09:48.
Pushed by graesslin into branch 'master'.

Disable Activities support on Wayland

This is a temporary workaround for bug 349992 which causes freezes
during startup as kwin and kamd dead lock each other on DBus.

To workaround we don't call Activities::create and check in every
usage of Activities::self() whether the pointer is valid.

As a result kwin_wayland now starts pretty fast.

M  +7    -1    client.cpp
M  +6    -0    dbusinterface.cpp
M  +8    -4    effects.cpp
M  +1    -1    manage.cpp
M  +13   -10   scripting/scripting_model.cpp
M  +13   -6    scripting/workspace_wrapper.cpp
M  +3    -1    tabbox/tabbox.cpp
M  +3    -0    toplevel.cpp
M  +9    -0    useractions.cpp
M  +15   -2    workspace.cpp

http://commits.kde.org/kwin/a1a89d3d1efcf863c33a827a5a5d917f839dbb02
Comment 2 Ivan Čukić 2015-08-18 11:27:39 UTC
Can you check whether this happens on clean sessions as well, not only in nested ones? (or do a 'kactivitymanagerd stop' in the main session before starting the nested one)

When testing, wait a bit to make sure that it is dead-locked and not only slow to start.
Comment 3 Martin Flöser 2015-08-18 12:09:36 UTC
yes that clearly affected clean sessions as well.

I always do a
export $(dbus-launch)

before starting kwin_wayland to have an independent session.
Comment 4 Ivan Čukić 2015-08-18 12:14:49 UTC
When I say clean session, I meant a session where kamd is not running at all under the user. Not a clean d-bus session.
Comment 5 Martin Flöser 2015-08-18 12:20:10 UTC
all right, also that used to be the case. During the phone development we always had to wait half a minute during startup for kamd to start.
Comment 6 Martin Flöser 2015-10-02 20:00:43 UTC
It looks like this problem also happens on X11, see https://github.com/lxde/lxqt/issues/836
Comment 7 Ivan Čukić 2015-11-14 21:33:38 UTC
Can you check whether this solves the issue: https://phabricator.kde.org/D544
Comment 8 Ivan Čukić 2015-11-15 15:18:27 UTC
Was an issue in QDBusInterface. Fixed now. At least, it ought to be.