[Plasma 5.27] plasmashell 100% CPU for 5 minutes reading mountinfo

m11k · June 24, 2024, 3:04pm

I’m on Debian 12 with Plasma 5.27. Wayland on Intel graphics (if it matters). I pretty regularly see plasmashell stop responding for several minutes, and top shows it spinning at 100%. This happens maybe every 10 or 15 minutes. I’m unable to interact with the KDE toolbar to open programs or switch windows, however alt-tab still works. When I strace the process, I see it reading from /proc/self/mountinfo, /run/user/*/gvfs, and /run/mount/utab over and over again in what appears to be a tight loop.

This system does happen to have about 350 active mounts, mostly NFS mounts via autofs, but none of them are stuck or hung. The set of mountpoints does change as autofs unmounts them after a period of time, but that’s not very frequent. Plasmashell is just repeatedly opening these mountinfo files and reading the contents. Here’s a sample of the output from strace -tt -p $(pidof plasmashell) |& grep open:

10:28:48.915881 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.917247 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.917520 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.918207 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.921823 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.923190 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.923639 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.924601 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.928172 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.929542 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.929923 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.930791 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.935923 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.937794 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.938120 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.939082 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.946773 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.949207 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.949820 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.951346 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.957602 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.959930 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.960476 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.961682 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.968838 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.971485 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.972187 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.973694 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.981220 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224
10:28:48.983585 openat(AT_FDCWD, "/run/user/8279/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 224
10:28:48.984100 openat(AT_FDCWD, "/run/user/16687/gvfs", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 EACCES (Permission denied)
10:28:48.985085 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 224
10:28:48.990530 openat(AT_FDCWD, "/run/mount/utab", O_RDONLY|O_CLOEXEC) = 224

If I remove the grep from the pipeline, I can see that it is reading the full contents of /proc/self/mountinfo, and /run/mount/utab repeatedly.

I don’t know what part of KDE is causing this behavior. I don’t have file search enabled. I’ve tried disabling the “Locations” plugin and the “Places” plugin in the “Plasma Search” settings. Any other suggestions for debugging tips or components I might be able to disable?

skyfishgoo · June 24, 2024, 3:48pm

i had similar behavior when my SATA controller started to fail… but check your Disks & Devices in the system tray to make sure it has the configuration behavior you want to see at start up.

do you have the show pop up enabled on the Disks & Devices applet in the system tray? is it constantly notifying you of a new device?

do these mounted directories routinely show up in dolphin as unmounted after a reboot?

what is the contents of your fstab?

m11k · June 24, 2024, 3:55pm

I grabbed a core dump and took a look at it in gdb. Here’s what it shows:

(gdb) bt
#0  0x00007f218c8b5124 in _int_free (av=0x7f218c9f1c60 <main_arena>, p=0x55937f5e39e0, have_lock=have_lock@entry=0) at ./malloc/malloc.c:4500
#1  0x00007f218c8b7e8f in __GI___libc_free (mem=<optimized out>) at ./malloc/malloc.c:3385
#2  0x00007f218bdbd520 in mnt_reset_fs () at /lib/x86_64-linux-gnu/libmount.so.1
#3  0x00007f218bdbd5cd in mnt_free_fs () at /lib/x86_64-linux-gnu/libmount.so.1
#4  0x00007f218bdc3f9e in mnt_table_remove_fs () at /lib/x86_64-linux-gnu/libmount.so.1
#5  0x00007f218bdc3ff8 in mnt_reset_table () at /lib/x86_64-linux-gnu/libmount.so.1
#6  0x00007f218bdc4082 in mnt_free_table () at /lib/x86_64-linux-gnu/libmount.so.1
#7  0x00007f218c163881 in KMountPoint::currentMountPoints(QFlags<KMountPoint::DetailsNeededFlag>) (infoNeeded=infoNeeded@entry=...) at ./src/core/kmountpoint.cpp:377
#8  0x00007f2187f9944e in KFilePlacesItem::onAccessibilityChanged(bool) (this=this@entry=0x559381493d20, isAccessible=<optimized out>) at /usr/include/x86_64-linux-gnu/qt5/QtCore/qflags.h:121
#9  0x00007f2187f99de3 in KFilePlacesItem::updateDeviceInfo(QString const&) (this=this@entry=0x559381493d20, udi=...) at ./src/filewidgets/kfileplacesitem.cpp:506
#10 0x00007f2187f9a6b4 in KFilePlacesItem::KFilePlacesItem(KBookmarkManager*, QString const&, QString const&, KFilePlacesModel*) (this=this@entry=0x559381493d20, manager=<optimized out>, address=..., udi=..., parent=parent@entry=0x55937f750980)
    at ./src/filewidgets/kfileplacesitem.cpp:46
#11 0x00007f2187fa29eb in KFilePlacesModelPrivate::loadBookmarkList() (this=this@entry=0x55937fa4bc40) at ./src/filewidgets/kfileplacesmodel.cpp:917
#12 0x00007f2187fa374e in KFilePlacesModelPrivate::reloadBookmarks() (this=this@entry=0x55937fa4bc40) at ./src/filewidgets/kfileplacesmodel.cpp:808
#13 0x00007f2187fa5344 in KFilePlacesModelPrivate::deviceAdded(QString const&) (udi=..., this=0x55937fa4bc40) at ./src/filewidgets/kfileplacesmodel.cpp:783
#14 operator() (device=..., __closure=<optimized out>) at ./src/filewidgets/kfileplacesmodel.cpp:761
#15 QtPrivate::FunctorCall<QtPrivate::IndexesList<0>, QtPrivate::List<const QString&>, void, KFilePlacesModelPrivate::initDeviceList()::<lambda(const QString&)> >::call (arg=<optimized out>, f=<optimized out>) at /usr/include/x86_64-linux-gnu/qt5/QtCore/qobjectdefs_impl.h:146
#16 QtPrivate::Functor<KFilePlacesModelPrivate::initDeviceList()::<lambda(const QString&)>, 1>::call<QtPrivate::List<QString const&>, void> (arg=<optimized out>, f=<optimized out>) at /usr/include/x86_64-linux-gnu/qt5/QtCore/qobjectdefs_impl.h:256
#17 QtPrivate::QFunctorSlotObject<KFilePlacesModelPrivate::initDeviceList()::<lambda(const QString&)>, 1, QtPrivate::List<const QString&>, void>::impl(int, QtPrivate::QSlotObjectBase *, QObject *, void **, bool *)
    (which=<optimized out>, this_=<optimized out>, r=<optimized out>, a=<optimized out>, ret=<optimized out>) at /usr/include/x86_64-linux-gnu/qt5/QtCore/qobjectdefs_impl.h:443
#18 0x00007f218cce8f4f in QtPrivate::QSlotObjectBase::call(QObject*, void**) (a=0x7ffee8a29e40, r=0x55937f750980, this=0x559380b16f40) at ../../include/QtCore/../../src/corelib/kernel/qobjectdefs_impl.h:398
#19 doActivate<false>(QObject*, int, void**) (sender=0x55937fa1f090, signal_index=3, argv=0x7ffee8a29e40) at kernel/qobject.cpp:3923
#20 0x00007f218cce21ef in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) (sender=<optimized out>, m=m@entry=0x7f218f06dd20 <Solid::DeviceNotifier::staticMetaObject>, local_signal_index=local_signal_index@entry=0, argv=argv@entry=0x7ffee8a29e40)
    at kernel/qobject.cpp:3983
#21 0x00007f218efd2492 in Solid::DeviceNotifier::deviceAdded(QString const&) (this=<optimized out>, _t1=<optimized out>) at ./obj-x86_64-linux-gnu/src/solid/KF5Solid_autogen/include/moc_devicenotifier.cpp:144
#22 0x00007f218cce8f7c in doActivate<false>(QObject*, int, void**) (sender=0x55937f7741b0, signal_index=3, argv=0x7ffee8a29f30) at kernel/qobject.cpp:3935
#23 0x00007f218cce21ef in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) (sender=sender@entry=0x55937f7741b0, m=m@entry=0x7f218f06d500 <Solid::Ifaces::DeviceManager::staticMetaObject>, local_signal_index=local_signal_index@entry=0, argv=argv@entry=0x7ffee8a29f30)
    at kernel/qobject.cpp:3983
#24 0x00007f218efbfe52 in Solid::Ifaces::DeviceManager::deviceAdded(QString const&) (this=this@entry=0x55937f7741b0, _t1=...) at ./obj-x86_64-linux-gnu/src/solid/KF5Solid_autogen/3PYKXLVNWF/moc_devicemanager.cpp:144
#25 0x00007f218f025a14 in Solid::Backends::Fstab::FstabManager::_k_updateDeviceList() (this=this@entry=0x55937f7741b0) at ./src/solid/devices/backends/fstab/fstabmanager.cpp:117
#26 0x00007f218f025fa4 in Solid::Backends::Fstab::FstabManager::onMtabChanged() (this=0x55937f7741b0) at ./src/solid/devices/backends/fstab/fstabmanager.cpp:132
#27 0x00007f218cce8f4f in QtPrivate::QSlotObjectBase::call(QObject*, void**) (a=0x7ffee8a2a0c0, r=0x55937f7741b0, this=0x55937fa71700) at ../../include/QtCore/../../src/corelib/kernel/qobjectdefs_impl.h:398
#28 doActivate<false>(QObject*, int, void**) (sender=0x7f218f0702e0 <Solid::Backends::Fstab::(anonymous namespace)::Q_QGS_globalFstabWatcher::innerFunction()::holder>, signal_index=3, argv=0x7ffee8a2a0c0) at kernel/qobject.cpp:3923
#29 0x00007f218cce8f4f in QtPrivate::QSlotObjectBase::call(QObject*, void**) (a=0x7ffee8a2a1e0, r=0x7f218f0702e0 <Solid::Backends::Fstab::(anonymous namespace)::Q_QGS_globalFstabWatcher::innerFunction()::holder>, this=0x55937fad10b0)
    at ../../include/QtCore/../../src/corelib/kernel/qobjectdefs_impl.h:398
#30 doActivate<false>(QObject*, int, void**) (sender=0x55937f7a0d20, signal_index=3, argv=0x7ffee8a2a1e0) at kernel/qobject.cpp:3923
#31 0x00007f218cce21ef in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) (sender=sender@entry=0x55937f7a0d20, m=m@entry=0x7f218cf4c1a0 <QSocketNotifier::staticMetaObject>, local_signal_index=local_signal_index@entry=0, argv=argv@entry=0x7ffee8a2a1e0)
    at kernel/qobject.cpp:3983
#32 0x00007f218ccec28f in QSocketNotifier::activated(QSocketDescriptor, QSocketNotifier::Type, QSocketNotifier::QPrivateSignal) (this=this@entry=0x55937f7a0d20, _t1=..., _t2=<optimized out>, _t3=...) at .moc/moc_qsocketnotifier.cpp:178
#33 0x00007f218cceca95 in QSocketNotifier::event(QEvent*) (this=0x55937f7a0d20, e=<optimized out>) at kernel/qsocketnotifier.cpp:302
#34 0x00007f218db62fae in QApplicationPrivate::notify_helper(QObject*, QEvent*) (this=<optimized out>, receiver=0x55937f7a0d20, e=0x7ffee8a2a2e0) at kernel/qapplication.cpp:3640
#35 0x00007f218ccb16f8 in QCoreApplication::notifyInternal2(QObject*, QEvent*) (receiver=0x55937f7a0d20, event=0x7ffee8a2a2e0) at kernel/qcoreapplication.cpp:1064
#36 0x00007f218ccb18be in QCoreApplication::sendEvent(QObject*, QEvent*) (receiver=<optimized out>, event=<optimized out>) at kernel/qcoreapplication.cpp:1462
#37 0x00007f218cd0a38d in socketNotifierSourceDispatch(GSource*, GSourceFunc, gpointer) (source=0x55937efcc0d0) at kernel/qeventdispatcher_glib.cpp:107
#38 0x00007f218b7aa7a9 in g_main_dispatch (context=0x55937efcd750) at ../../../glib/gmain.c:3454
#39 g_main_context_dispatch (context=context@entry=0x55937efcd750) at ../../../glib/gmain.c:4172
#40 0x00007f218b7aaa38 in g_main_context_iterate (context=context@entry=0x55937efcd750, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../glib/gmain.c:4248
#41 0x00007f218b7aaacc in g_main_context_iteration (context=0x55937efcd750, may_block=1) at ../../../glib/gmain.c:4313
#42 0x00007f218cd09836 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) (this=0x55937efcdfb0, flags=...) at kernel/qeventdispatcher_glib.cpp:423
#43 0x00007f218ccb017b in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) (this=this@entry=0x7ffee8a2a4f0, flags=..., flags@entry=...) at ../../include/QtCore/../../src/corelib/global/qflags.h:69
#44 0x00007f218ccb82d6 in QCoreApplication::exec() () at ../../include/QtCore/../../src/corelib/global/qflags.h:121
#45 0x00007f218d130e8c in QGuiApplication::exec() () at kernel/qguiapplication.cpp:1863
#46 0x00007f218db62f25 in QApplication::exec() () at kernel/qapplication.cpp:2832
#47 0x000055937cf0cdc3 in main(int, char**) (argc=<optimized out>, argv=<optimized out>) at ./shell/main.cpp:235

m11k · June 24, 2024, 4:12pm

I’m not currently getting frequent notifications about new devices, although I was previously getting dozens to hundreds of notifications at about this same frequency (every 10 or 15 minutes). The notifications were about the NFS mount points, and said “Filesystem is not responding. Filesystem mounted at ‘/mnt/nfs/foo’ is not responding”.
The filesystems were still responding and were not slow. I’m not sure why KDE thought these filesystems were unresponsive. At the time I traced the source of the notifications to this code: github dot com /KDE/plasma-workspace/blob/5358c2b52bfe0fcaa9b08df024db6100c4c3ee54/dataengines/soliddevice/soliddeviceengine.cpp#L534 (sorry, discuss won’t let me post links).

The only way I could find to suppress these notifications was ‘Settings’ → ‘Notifications’ → scroll down to bottom → ‘Configure’ → 'Plasma Workspace" → “Configure Events” → “Fatal Error” → turn off “Play a sound” and “Show a message in a popup”.

Now that you pointed me to the Device notifications, I noticed in the stack trace that there is a ‘Solid::DeviceNotifier::deviceAdded’ function call. I tried turning off the “Device Notifier” in the Notifications settings. I think that might have helped. I’m still seeing plasmashell spin up to 100% CPU, and if I catch it in strace I can still see it reading those files, but it now only lasts for a second or two instead of many minutes. It hasn’t been long enough to me to say whether this has resolved the issue, so I’ll keep an eye on it for a while. Thanks!

UPDATE: unfortunately this hasn’t resolved the issue and I’m still seeing the same behavior in plasmashell.

skyfishgoo · June 24, 2024, 5:20pm

i’m suspecting a hardware problem with your controller… but no expert.

is the controller for these drives on a pci card you can pull and reseat?

m11k · June 24, 2024, 7:21pm

Thanks for the suggestions @skyfishgoo. I appreciate the help. I’m pretty sure (100% sure) this isn’t a hardware issue. This only started occurring when my company’s internal distributed testing workloads started running on this machine. Its not a resource problem either, the machine has 32 CPU threads (an i9-13900K) and 128GB of RAM. The machine is otherwise fully responsive.

If changes to /proc/self/mountinfo trigger plasma to take some heavyweight action, that is probably the cause. On some occasions, /proc/self/mountinfo changes several times per second, as new processes start up that trigger new NFS mounts via autofs, and as old mounts expire. This can last for a few minutes. Sometimes however it is 5 or 10 minutes between changes. I wonder if plasma is queueing some callback every time file changes, and it takes a long time to work through the backlog once the file stops changing.

dnpp · July 2, 2024, 8:08pm

I have the same problem, my workstation has about 2200 mounted filesystems, and plasmashell has 100% CPU usage.

I did an strace and have a similar output as m11k. It seems that plasmashell is reading the mounting information of the 2200 NFS.

This is not a hardware issue, please fix this bug.

dnpp · July 3, 2024, 1:47pm

I started dolphin from the terminal, and I have 2000 lines with the following log:

kf.kio.slaves.trash: Root trash dir “/auto/home/XX1/.Trash” exists but didn’t pass the security checks, can’t use it
kf.kio.slaves.trash: Root trash dir “/auto/home/XX2/.Trash” exists but didn’t pass the security checks, can’t use it

plasmashell should have an option to disable the network access

dnpp · July 3, 2024, 5:07pm

I received all hundreds of desktop notification of

“Filesystem mounted at ‘/xxxx’ is not responding”

m11k · July 3, 2024, 6:25pm

Yes, I saw many of the ‘Filesystem mounted at … is not responding’ notifications as well, often dozens of them every 5-10 minutes. I turned them off by disabling notifications for the ‘Fatal Error’ event for the ‘Plasma Workspace’ component in the notification settings.

Unfortunately I’ve stopped using KDE for now because plasmashell was unresponsive most of the time. It is unfortunate because it is the only desktop environment that seems to handle my mixed-DPI displays (one with 1.5x scaling and one with 1x scaling).

I would be interested in trying to debug this further, but trying to build and run a standalone KDE instance on Debian 12 seems pretty daunting.