Bug 354230 - Blocking calls from PlasmaNM to BlueZ for 30s
Summary: Blocking calls from PlasmaNM to BlueZ for 30s
Status: RESOLVED FIXED
Alias: None
Product: plasma-nm
Classification: Plasma
Component: general (show other bugs)
Version: 5.4.2
Platform: Ubuntu Linux
: NOR normal
Target Milestone: ---
Assignee: Lukáš Tinkl
URL:
Keywords:
: 354249 354304 354396 354474 355327 (view as bug list)
Depends on:
Blocks:
 
Reported: 2015-10-22 21:26 UTC by quesseb
Modified: 2015-12-23 13:13 UTC (History)
22 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments
bootchart svg (860.37 KB, image/svg+xml)
2015-10-23 19:37 UTC, quesseb
Details
bustle output when panel hangs (574.33 KB, application/vnd.tcpdump.pcap)
2015-10-24 18:59 UTC, Amichai Rothman
Details
bustle output (pcap,system) when panel hangs (14.08 KB, application/vnd.tcpdump.pcap)
2015-10-24 20:41 UTC, Amichai Rothman
Details
my-dbus-log (3.61 MB, text/x-log)
2015-10-26 17:01 UTC, quesseb
Details
plasma-nm with Jan's fix built on kubuntu-15.10 (888.42 KB, application/octet-stream)
2015-10-26 17:19 UTC, Alex Sidorenko
Details

Note You need to log in before you can comment on or make changes to this bug.
Description quesseb 2015-10-22 21:26:52 UTC
Hello

i just upgraded an Kubuntu 15.04 to 15.10 today.
After ssdm login, plasma starts launching, I can see wallpaper and desktop icons, but taskbar is empty. Nothing can be done during 30 first seconds with mouse or keyboard in this tty.
During this time, in another tty1 I can see cpu at 3% only...

I reproduce the problem at every startup and at every login with my usual login or with a newly created account.

Bootchart shows a python3 process sleeping a long time and then plasmashell finishes to load..
How to identify this process or to debug it?

Reproducible: Always




I can attach bootchart.svg if necessary
Comment 1 David Edmundson 2015-10-22 21:28:02 UTC
I can attach bootchart.svg if necessary

yes please.
Comment 2 David Edmundson 2015-10-23 16:20:17 UTC
Marking as needsinfo till we get the chart, as till then this doesn't contain anything to go on
Comment 3 quesseb 2015-10-23 19:37:14 UTC
Created attachment 95094 [details]
bootchart svg

python3 from 10th to 60th second on boot
Comment 4 David Edmundson 2015-10-24 14:35:43 UTC
thanks
Comment 5 David Edmundson 2015-10-24 14:36:09 UTC
*** Bug 354304 has been marked as a duplicate of this bug. ***
Comment 6 David Edmundson 2015-10-24 15:00:08 UTC
No idea what that python process is. 

It's not anything from Plasma.

Can you try and find out?

also a time this long with no CPU activity is probably DBus blocking - we'll be waiting for a reply from something that isn't answering. 

Any chance you can add 
"dbus-monitor > ~/my-dbus-log" to your startkde file
Comment 7 Amichai Rothman 2015-10-24 15:06:10 UTC
Same problem here. Just upgraded today, panel takes a minute to be operational. Beore that it's kind of half-drawn, with some task buttons there, some icon frames, and many icons just missing. After a long while it all just works. This happens after reboot, but also saw it at other times (possibly after monitor resumes from power savings mode? not sure). At the moment I have a completely frozen panel, not sure if it's related or not.
Comment 8 Amichai Rothman 2015-10-24 15:17:38 UTC
btw I just found out that it happens consistently every time I 'killall plasmashell && plasmashell'. No need to reboot to recreate.
Comment 9 Amichai Rothman 2015-10-24 15:25:04 UTC
Also, using this technique it takes 53 seconds from running the command plasmashell until it's operational. Maybe the first 3 seconds is regular startup, then 50 second timeout on something?

also, in the terminal (where I run plasmashell) the last thing logged before it hangs is:

unversioned plugin detected, may result in instability
org.kde.plasma.pulseaudio: state callback

and the first thing after it resumes 50 seconds later is:

plasma-nm: Failed to enumerate BT adapters

I hope this helps.
Comment 10 David Edmundson 2015-10-24 15:47:24 UTC
>plasma-nm: Failed to enumerate BT adapters

That seems like it could be it.

can you run 
dbus-monitor (or ideally bustle if you can install that) and launch plasmashell
Comment 11 Amichai Rothman 2015-10-24 16:44:39 UTC
If I understand the output of bustle correctly, there's nothing obviously wrong here.

There's one line at 2928 which is a method return value from PowerManagement.PolicyAgent.ListInhibitions, and the next line after it is at 53016 (that's the 50 seconds later) which is a request for NetworkManagement Introspect.

There don't appear to be any request/response crossing that line, so the time appears to be spent somewhere else, not stuck on a dbus transaction. The method durations statistics pane shows all durations at the millisecond level. Is that the kind of thing you're looking for?
Comment 12 popanz 2015-10-24 17:53:12 UTC
It's definitely a BT-Problem. Putting in a BT-USB-Stick the desktop starts much faster.
Comment 13 David Edmundson 2015-10-24 18:48:07 UTC
Can you see if:
 - any of the lines in bustle were red

if so, the full output of that line.

 - screenshots of the statistics page

Message frequencies and Method Durations
Comment 14 David Edmundson 2015-10-24 18:58:47 UTC
oh bother, of couse you won't see anything

bustle is monitoring the session bus by default.
network manager is on the system bus

I don't think bustle has a UI for it, but 

bustle-pcap --system somefile  

then open it in bustle
Comment 15 Amichai Rothman 2015-10-24 18:59:05 UTC
Created attachment 95108 [details]
bustle output when panel hangs

I attached the bustle output. It starts just before starting plasmashell, and ends when it's all good. Nothing else going on in between. You can see the hang in the entries at the very bottom.
Comment 16 David Edmundson 2015-10-24 19:17:51 UTC
Thanks, in case you missed it I posted a comment 1 minute before you uploaded this realising I need something else.
Comment 17 Amichai Rothman 2015-10-24 20:41:15 UTC
Created attachment 95113 [details]
bustle output (pcap,system) when panel hangs

Thanks, I did miss that comment. Here it is. Quite short.
Comment 18 David Edmundson 2015-10-24 21:05:39 UTC
heh, that wasn't very useful. Has nothing from network manager or bluetooth which is where we think we want to be looking.

The interface must have sniffing turned off.

Does sudo bustle-pcap include anything better?

Altnernate approach is we go from the other side and run "gdb plasma"
then after 10s (where everything else should should be stopped) 
type "control+c" "bt" and we find where plasma is blocked and waiting

If that's a bit much, I'll install Kubuntu 15.10 in a virtual machine which won't have bluetooth - and poke it there.
Comment 19 Amichai Rothman 2015-10-24 21:26:35 UTC
#0  0x00007ffff25d38dd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007fffef11472f in  () at /lib/x86_64-linux-gnu/libdbus-1.so.3
#2  0x00007fffef1133ae in  () at /lib/x86_64-linux-gnu/libdbus-1.so.3
#3  0x00007fffef0fc014 in  () at /lib/x86_64-linux-gnu/libdbus-1.so.3
#4  0x00007fffef0fcacc in  () at /lib/x86_64-linux-gnu/libdbus-1.so.3
#5  0x00007fffef0fcfca in dbus_connection_send_with_reply_and_block () at /lib/x86_64-linux-gnu/libdbus-1.so.3
#6  0x00007ffff7f62ad0 in  () at /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#7  0x00007ffff7f64316 in  () at /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#8  0x00007ffff7f70dcd in  () at /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#9  0x00007ffff7f70f15 in QDBusInterface::QDBusInterface(QString const&, QString const&, QString const&, QDBusConnection const&, QObject*) ()
    at /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#10 0x00007fff36ed46c5 in Handler::isBtEnabled() () at /usr/lib/x86_64-linux-gnu/libplasmanm_internal.so
#11 0x00007fff36ed5cb4 in Handler::Handler(QObject*) () at /usr/lib/x86_64-linux-gnu/libplasmanm_internal.so
#12 0x00007fff3712c780 in  () at /usr/lib/x86_64-linux-gnu/qt5/qml/org/kde/plasma/networkmanagement/libplasmanm_qmlplugins.so
#13 0x00007ffff54816cb in QQmlType::create() const () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#14 0x00007ffff54e58fd in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#15 0x00007ffff54e7a8d in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#16 0x00007ffff54e7e2b in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#17 0x00007ffff54e459d in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#18 0x00007ffff54e4f81 in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#19 0x00007ffff54e60b4 in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#20 0x00007ffff546eec7 in  () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#21 0x00007ffff546f7b4 in QQmlIncubationController::incubateFor(int) () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#22 0x00007ffff61577ac in  () at /usr/lib/x86_64-linux-gnu/libKF5Declarative.so.5
#23 0x00007ffff546f5c9 in QQmlEnginePrivate::incubate(QQmlIncubator&, QQmlContextData*) () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#24 0x00007ffff546ae0c in QQmlComponent::create(QQmlIncubator&, QQmlContext*, QQmlContext*) () at /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#25 0x00007ffff6147845 in KDeclarative::QmlObject::completeInitialization(QHash<QString, QVariant> const&) ()
    at /usr/lib/x86_64-linux-gnu/libKF5Declarative.so.5
#26 0x00007ffff799f658 in PlasmaQuick::AppletQuickItem::init() () at /usr/lib/x86_64-linux-gnu/libKF5PlasmaQuick.so.5
#27 0x00007fffcae665dc in  () at /usr/lib/x86_64-linux-gnu/qt5/plugins/plasma/scriptengines/plasma_appletscript_declarative.so
#28 0x00007fffcae65bc9 in  () at /usr/lib/x86_64-linux-gnu/qt5/plugins/plasma/scriptengines/plasma_appletscript_declarative.so
#29 0x00007ffff2ed7651 in QObject::event(QEvent*) () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#30 0x00007ffff5ef410b in QQuickItem::event(QEvent*) () at /usr/lib/x86_64-linux-gnu/libQt5Quick.so.5
#31 0x00007fffcae66896 in  () at /usr/lib/x86_64-linux-gnu/qt5/plugins/plasma/scriptengines/plasma_appletscript_declarative.so
#32 0x00007ffff3983b8c in QApplicationPrivate::notify_helper(QObject*, QEvent*) () at /usr/lib/x86_64-linux-gnu/libQt5Widgets.so.5
#33 0x00007ffff3989230 in QApplication::notify(QObject*, QEvent*) () at /usr/lib/x86_64-linux-gnu/libQt5Widgets.so.5
#34 0x00007ffff2ea5f1b in QCoreApplication::notifyInternal(QObject*, QEvent*) () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#35 0x00007ffff2ea8057 in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#36 0x00007ffff2efce73 in  () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#37 0x00007fffef380ff7 in g_main_context_dispatch (context=0x7fffdc0016f0) at /build/glib2.0-ajuDY6/glib2.0-2.46.1/./glib/gmain.c:3154
#38 0x00007fffef380ff7 in g_main_context_dispatch (context=context@entry=0x7fffdc0016f0) at /build/glib2.0-ajuDY6/glib2.0-2.46.1/./glib/gmain.c:3769
#39 0x00007fffef381250 in g_main_context_iterate (context=context@entry=0x7fffdc0016f0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at /build/glib2.0-ajuDY6/glib2.0-2.46.1/./glib/gmain.c:3840
#40 0x00007fffef3812fc in g_main_context_iteration (context=0x7fffdc0016f0, may_block=1) at /build/glib2.0-ajuDY6/glib2.0-2.46.1/./glib/gmain.c:3901
#41 0x00007ffff2efd27f in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#42 0x00007ffff2ea375a in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#43 0x00007ffff2eab2cc in QCoreApplication::exec() () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#44 0x00000000004322c3 in main ()
Comment 20 David Edmundson 2015-10-24 21:34:34 UTC
We can see we're making some blocking calls to BlueZ here.

    QDBusInterface managerIface("org.bluez", "/", "org.freedesktop.DBus.ObjectManager", QDBusConnection::systemBus(), this);

is blocking

    QDBusReply<QMap<QDBusObjectPath, NMVariantMapMap> > reply = managerIface.call("GetManagedObjects");

is blocking

                QDBusInterface adapterIface("org.bluez", objPath, "org.bluez.Adapter1", QDBusConnection::systemBus(), this);

is blocking 

and finally

                const bool adapterEnabled = adapterIface.property("Powered").toBool();



Arguably bluez shouldn't be taking so long to respond, but I think we can turn this async. We need to handle an adaptor enabling at runtime regardless so we need to handle it changing in handler.cpp anyway
Comment 21 Jan Grulich 2015-10-25 06:42:07 UTC
*** Bug 354249 has been marked as a duplicate of this bug. ***
Comment 22 Jan Grulich 2015-10-25 16:37:21 UTC
Git commit f3e940d49574b3d464b8d7118cdced136283579b by Jan Grulich.
Committed on 25/10/2015 at 16:37.
Pushed by grulich into branch 'master'.

Make all bluez calls asynchronous

REVIEW:125785

M  +62   -55   libs/handler.cpp
M  +3    -4    libs/handler.h

http://commits.kde.org/plasma-nm/f3e940d49574b3d464b8d7118cdced136283579b
Comment 23 Jan Grulich 2015-10-25 16:38:23 UTC
Git commit 48a45ebad0e1d5ecc023a9e8866a95d47c76790f by Jan Grulich.
Committed on 25/10/2015 at 16:38.
Pushed by grulich into branch 'Plasma/5.4'.

Make all bluez calls asynchronous

REVIEW:125785

M  +62   -55   libs/handler.cpp
M  +3    -4    libs/handler.h

http://commits.kde.org/plasma-nm/48a45ebad0e1d5ecc023a9e8866a95d47c76790f
Comment 24 Jan Grulich 2015-10-25 16:44:58 UTC
Can someone please test the fix? I wasn't able to reproduce this issue even without this fix so we need someone else to confirm that making bluez calls asynchronous helps. Thanks.
Comment 25 Amichai Rothman 2015-10-25 19:51:59 UTC
Is there a simple way to test it without modifying my system?
Comment 26 Jan Grulich 2015-10-26 07:35:13 UTC
Unfortunately no, you would need to compile plasma-nm or if you know how to make deb packages then you need just download the patch and make a new package.
Comment 27 Jan Grulich 2015-10-26 11:29:53 UTC
*** Bug 354396 has been marked as a duplicate of this bug. ***
Comment 28 Alex Sidorenko 2015-10-26 16:03:01 UTC
Hello Jan,

I have build .deb on Kubuntu-15.10 applying your patches to plasma-nm_5.4.2-0ubuntu1 sources.

Everything works fast after that:
  - on login
  - clicking on systray applet
  - starting kde5-nm-connection-editor from shell

Many thanks for a quick fix!

Regards,
Alex
Comment 29 quesseb 2015-10-26 16:59:55 UTC
Hello,

sorry I was away from my computer since 3 days.
Timeout seems not to be related to BT, since I have no BT. I created my-dbus-log as it was asked and attached it.
Have a look at time stamp 1445877558 near line 3074, dbus stops writing until timestamp 1445877595
Comment 30 quesseb 2015-10-26 17:01:18 UTC
Created attachment 95141 [details]
my-dbus-log
Comment 31 Alex Sidorenko 2015-10-26 17:15:40 UTC
Alex(In reply to quesseb from comment #29)

> Timeout seems not to be related to BT, since I have no BT. 

I don't have BT either, but Jan's fix has resolved the problem on my host!

Alex
Comment 32 Jan Grulich 2015-10-26 17:18:53 UTC
Plasma-nm makes bluez calls even when you don't have bluetooth to check whether you have it or don't and because the calls were blocking and bluez was not responding then start of plasma-nm was delayed.
Comment 33 Alex Sidorenko 2015-10-26 17:19:19 UTC
Created attachment 95144 [details]
plasma-nm with Jan's fix built on kubuntu-15.10

I am not an "official" builder of packages but if anybody on Kubuntu-15.10 is interested in testing Jan's fix, this is what I built. It definitely resolves the problem for me - no delays anymore.
Comment 34 quesseb 2015-10-26 18:31:56 UTC
asid, thank you so much for your deb, it works like a charm.
And thank you Jan for your ultra fast fix!!!
Comment 35 kiran 2015-10-27 12:17:25 UTC
Hi All,
          Im a newbie to all this patch fixing world. I can see from Asid's work in ubuntu packages that the latest patch is available for Xenial(Next version of Kubuntu). How do i make sure that that patches will be available for the current kubuntu version (15.10) ?. How do i propose the patch fix for kubuntu 15.10 ?
Comment 36 David Edmundson 2015-10-27 21:59:48 UTC
*** Bug 354474 has been marked as a duplicate of this bug. ***
Comment 37 Serhiy Zahoriya 2015-10-27 23:51:14 UTC
Easier workaround is to purge all bluez packages. Obviously, you should do not only in case you don't need bluetooth support.
Comment 38 Hugo Ortega_H 2015-10-28 04:29:15 UTC
I had the same problem on my desktop computer (without bluetooth) after the upgrade, but using a USB bluetooth adapter solves the problem.
Comment 39 Philip Muškovac 2015-10-28 17:11:53 UTC
@kiran: the patch is pending for 15.10, but due to the procedure it'll take at least another week before you'll find the fix in your regular updates. In the meantime, the fix is in the kubuntu updates ppa (ppa:kubuntu-ppa/ppa)

(and to actually answer your question, the procedure it at https://wiki.ubuntu.com/StableReleaseUpdates#Procedure and in this case, the relevant bug is http://pad.lv/1509334 )
Comment 40 David Edmundson 2015-11-11 22:56:23 UTC
*** Bug 355200 has been marked as a duplicate of this bug. ***
Comment 41 Jan Grulich 2015-11-14 07:38:16 UTC
*** Bug 355327 has been marked as a duplicate of this bug. ***