Bug 354230

I can attach bootchart.svg if necessary

yes please.

Marking as needsinfo till we get the chart, as till then this doesn't contain anything to go on

Created attachment 95094 [details]
bootchart svg

python3 from 10th to 60th second on boot

thanks

*** Bug 354304 has been marked as a duplicate of this bug. ***

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

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.

btw I just found out that it happens consistently every time I 'killall plasmashell && plasmashell'. No need to reboot to recreate.

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.

>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

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?

It's definitely a BT-Problem. Putting in a BT-USB-Stick the desktop starts much faster.

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

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

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.

Thanks, in case you missed it I posted a comment 1 minute before you uploaded this realising I need something else.

Created attachment 95113 [details]
bustle output (pcap,system) when panel hangs

Thanks, I did miss that comment. Here it is. Quite short.

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.

#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 ()

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

*** Bug 354249 has been marked as a duplicate of this bug. ***

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

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

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.

Is there a simple way to test it without modifying my system?

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.

*** Bug 354396 has been marked as a duplicate of this bug. ***

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

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

Created attachment 95141 [details]
my-dbus-log

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

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.

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.

asid, thank you so much for your deb, it works like a charm.
And thank you Jan for your ultra fast fix!!!

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 ?

*** Bug 354474 has been marked as a duplicate of this bug. ***

Easier workaround is to purge all bluez packages. Obviously, you should do not only in case you don't need bluetooth support.

I had the same problem on my desktop computer (without bluetooth) after the upgrade, but using a USB bluetooth adapter solves the problem.

@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 )

*** Bug 355200 has been marked as a duplicate of this bug. ***

*** Bug 355327 has been marked as a duplicate of this bug. ***