I hope to hear back from you soon, because Monday I will need to use my laptop and I will have to kill the misbehaving dbus-daemon to reclaim memory at that time. In the meantime I will keep my laptop in S3 in order to prevent dbus-daemon from growing to such a size as the kernel's OOM killer kills it. I'm running Stretch on a Thinkpad X220. It was a fresh installation of the KDE task using the netinstaller. Like most laptop users, I suspend or hibernate rather than shutting down, but dbus-daemon has only been running for 7 days. After installing -dbg packages for everything gdb said was missing I was able to capture the attached backtrace...however nothing seems to provide sysdeps/unix/syscall-template.S Here is the only section that jumps out to me: 0x00007f87feb730d3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:84 84 ../sysdeps/unix/syscall-template.S: No such file or directory. #0 0x00007f87feb730d3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:84 I've also attached the relevant output from ps -aux and top.
This will end your KDE login session rather unceremoniously. If
possible, log out from KDE rather than letting the dbus-daemon die
from the OOM killer or a manual kill command. This should make the
dbus-daemon exit automatically, but if it doesn't, log in to a
text console (as your ordinary user or as root) and kill the
`dbus-daemon --session` process (process 958) from there.
Please make sure you don't kill `dbus-daemon --system` by mistake
(only root can do this); if you do, you'll have to reboot to fix it.
Unfortunately this backtrace only indicates "dbus-daemon is idle and
waiting for something interesting to happen". It should normally be in
this state 99% of the time. If it was in a busy-loop that was consuming
all the CPU, a backtrace might be more interesting, but for memory
consumption it's unlikely to help.
The process using all the memory is the standard session bus (dbus-daemon
--session), which has essentially no resource limits (everything on it
is considered equally trusted), so the root cause is probably that some
misbehaving applications or services in your user login session have
used a calling pattern that makes the dbus-daemon use a lot of memory
on their behalf. Sending messages very rapidly to a service that is slow
to process them is one thing that is known to have this effect.
As far as I know, all ways to trigger rapid memory consumption involve
rapid message sending and receiving, so if the dbus-daemon's memory
use is still growing, you can probably see what's happening by running
dbus-monitor, or by looking at top and seeing which other D-Bus-related
processes are actively running. While debugging, you can use "kill -STOP"
and "kill -CONT" to pause and resume the dbus-daemon (which will pause
message processing, so many applications and services will not work
while it is paused, in particular many graphical applications and
dbus-send).
You can correlate bus names (the things that look like :1.23 or
org.gnome.Software) with process IDs by using:
dbus-send --session --dest=org.freedesktop.DBus --type=method_call \
--print-reply /org/freedesktop/DBus \
org.freedesktop.DBus.GetConnectionCredentials "string:$name"
where $name is the bus name.
The dbus-daemon also records some potentially useful statistics for
memory consumption and related things, and this feature is compiled in
to Debian's dbus-daemon. Please try running this:
dbus-send --session --dest=org.freedesktop.DBus --type=method_call \
--print-reply /org/freedesktop/DBus \
org.freedesktop.DBus.Debug.Stats.GetStats
and send the results to this bug report. You could also try retrieving
details of individual connections:
dir="$(mktemp -d)"
echo "Look in $dir for connection details"
dbus-send --session --dest=org.freedesktop.DBus --type=method_call \
--print-reply /org/freedesktop/DBus org.freedesktop.DBus.ListNames | \
perl -ne 'print("$1\n") if /^\s*string "(.*)"$/' | \
while read name; do \
dbus-send --session --dest=org.freedesktop.DBus --type=method_call \
--print-reply /org/freedesktop/DBus \
org.freedesktop.DBus.Debug.Stats.GetConnectionStats "string:$name" \
> "$dir/$name.stats"
done
(It is expected that you get an error message "Error
org.freedesktop.DBus.Error.InvalidArgs: GetConnectionStats is not
meaningful for the message bus "org.freedesktop.DBus" itself",
and it is also OK to get a small number of messages like "Error
org.freedesktop.DBus.Error.NameHasNoOwner: Could not get statistics of
name ':1.92': no such name".)
This will leave a lot of text files in $dir/*.stats (in my GNOME session
there are 127 of them). Then look in $dir/*.stats for a connection or
connections with much larger numbers than the rest. Again, you can use
GetConnectionCredentials to correlate them with process IDs.
Regards,
smcv
Hi Simon,
Thank you for the quick reply!
Yes, I plan to use the log out and only manually kill the dbus-daemon
session if necessary.
Would using memleax help? I'm 90% done packaging it, in case it looks
useful. Packaged because vagrant can't attach to an existing process.
Is it possible for dbus-daemon to signal to the calling application
that a queue is full? If that application would then respond to that
signal (eg: freedesktop notification of popup) then one could start
debugging the problem application.
Done. I've noted these correlations in bus.notes
I tried this just now and dbus-send seems to have errored with exit
status 130:
Must use org.mydomain.Interface.Method notation, no dot in
"/org/freedesktop/DBus"
I feel like it worked earlier today, so I'm attaching
dbus.debug.stats. Plasma's NM frontend wouldn't reconnect to the
network, and I before I realised it I had killed plasmashell ; sleep
3; kstart plasmashell. The dbus-daemon and kded5 daemon seem to be
unaffected, as expected, but maybe this causes problems with dbus?
plasmanetworkmanagement remains broken after restarting plasmashell,
but I was able to connect to my wifi ap with nmtui.
messages (I've attached each of these):
org.kde.StatusNotifierWatcher.stats
:1.33.stats
:1.334.stats
org.kde.plasmashell.stats
org.kde.plasmanetworkmanagement.stats
org.kde.kwrite-17177.stats
org.kde.keyboard.stats
org.kde.kded5.stats
org.kde.kcookiejar5.stats
org.kde.apperd.stats
org.freedesktop.Notifications.stats
And the worst group is:
:1.7.stats: variant uint32 1000000016
:1.7.stats: variant uint32 1000000016
org.kde.apperd.stats: variant uint32 1000000016
org.kde.apperd.stats: variant uint32 1000000016
org.kde.kcookiejar5.stats: variant uint32 1000000016
org.kde.kcookiejar5.stats: variant uint32 1000000016
org.kde.kded5.stats: variant uint32 1000000016
org.kde.kded5.stats: variant uint32 1000000016
org.kde.keyboard.stats: variant uint32 1000000016
org.kde.keyboard.stats: variant uint32 1000000016
org.kde.plasmanetworkmanagement.stats: variant uint32 1000000016
org.kde.plasmanetworkmanagement.stats: variant uint32 1000000016
org.kde.StatusNotifierWatcher.stats: variant uint32 1000000016
org.kde.StatusNotifierWatcher.stats: variant uint32 1000000016
I also filed bug #879901 against kded5, which has grown to consume
over 600MB of memory. IIRC, a couple of days ago kded5 consumed 100%
of one core for quite some time. Maybe that's when it was making all
of these dbus connections? I'm honestly not sure if kded5 is truly at
fault, of if it became overwhelmed when an application spammed [one
of] its dbus interfaces.
Can we keep these two bugs unmerged but associate them somehow?
Thank you!
Nicholas
From the other information you've given I can tell you with reasonable
certainty that (at least a large part of) the "leaked" memory is not
leaked, but is really still in use - the dbus-daemon is genuinely
trying to process millions of messages to kded5. I can't say why,
though.
In principle it might have been if it was defined 10 years ago, but
there is no protocol defined for communicating that fact, and it isn't
clear what an application would do about it anyway. Popping up messages
to annoy the user is generally frowned upon if there is nothing that
most users can do about it...
The dbus 1.11.x development branch (from which a 1.12.0 stable version
will be released soon) does log this information to syslog or the
systemd Journal, but 1.10.x didn't.
The system bus (which has finite limits) responds to excessive messages in
an incoming queue by slowing down reading from that sender, and responds
to excessive messages in an outgoing queue by dropping messages on the
floor. It might be a good idea for the session bus to have a rather smaller
limit on its incoming queues than the 1 GB limit that it has now, perhaps
the 127 MiB that the system bus uses (which tbh could probably also be
reduced) - then floods of messages would get slowed down, but eventually
be processed. Individual messages are allowed to exceed that limit by
up to 1 message, so maximally-sized messages could still be processed
anyway.
That is indeed slightly more than the arbitrary 1 GB limit that the
session bus has. The limit is conceptually only there to stop byte
counts overflowing a signed 32-bit integer, because session bus users
are trusted to not carry out deliberate denial-of-service attacks on each
other; but I think there would probably be value in turning down the
incoming message limit a bit to prevent accidental denial-of-service.
That would throttle reading from very spammy peers, but wouldn't help
when dealing with peers that read messages slower than they should.
Turning down the *outgoing* message limit is dangerous (it results in
messages being discarded unrecoverably) so we have to be very cautious
about reducing it.
You have an extra argument somewhere, possibly a space after one of the
backslashes.
than to those processes and anything that was relying on them), but
if some component has a bug and has responded to the unexpected
disappearance by going into a busy-loop, it's possible that the
busy-loop could result in it sending a flood of messages.
Or the inability to reconnect to the network might itself have been a
symptom of a flood of messages, rather than part of the cause.
However, I will say this: if you have a serious problem (like a key
desktop component getting stuck), and you respond to it by killing
individual components rather than by terminating the whole session
(e.g. logging out and back in), then you are certainly in uncharted
territory. This is the sort of thing that in principle ought to work,
but it is never going to be systematically tested, so it is not at all
surprising if it has or exposes bugs.
Lots of messages rather than lots of connections, I think, but most
likely yes.
It could be either one.
As far as I know there is no machine-readable way to do this. Just
mention each one in a mail to the other.
Looking at the dbus-daemon stats:
The dbus-daemon keeps some memory pools of pre-allocated linked-list links
and messages ready for reuse, in your case 1.6G of them. If your
dbus-daemon is really processing millions of messages then this seems
plausible to be real use rather than a leak: lots of places in dbus-daemon
have to pre-allocate linked-list links in a very pessimistic way so that
they can be used in error-recovery without worrying about whether memory
can be allocated for them, because dbus-daemon has a policy of assuming
that malloc() can legitimately return NULL.
I have often wondered whether these cache is more harmful than helpful
in the general case, but the worst-case answer is clearly: yes it's
more harmful than helpful (because allocated memory doesn't get freed).
I'm not sure whether that peak memory consumption would ever get returned
to the OS after the heap had grown in any case, though. Last time I
experimented with turning off the message cache the answer seemed to be
that it wasn't.
Those look normal.
132 match rules per connection seem a bit on the high side, but I think
QtDBus adds really specific match rules, so this is probably fine.
Looking at connection :1.7:
org.kde.StatusNotifierWatcher, org.kde.plasmanetworkmanagement,
org.kde.keyboard, org.kde.kded5, org.kde.kcookiejar5, org.kde.apperd
are really all the same connection (you can tell by how they all share
UniqueName = :1.7) and they are the worst problem here. Either kded5
has not been reading its dbus messages from its socket for a long time,
or something has sent it far too many messages, or both.
While I recognise the engineering tradeoffs that lead to bundling
several daemons into one process, this might be more robust (or at
least more debuggable) if it was a group of smaller services.
That's a lot. The dbus-daemon *currently* has 13 million messages
totalling 1GB queued to be sent to :1.7, and that's the most there
have ever been at a time. I wonder whether kded has stopped reading
messages (causing them to be stuck in the dbus-daemon until it
disconnects) or whether there is just a massively large backlog that
the dbus-daemon is still working through?
Is there a reason you captured stats for :1.33 (korgac)? It seems to
be a really light D-Bus user - hundreds of bytes, ever, so certainly
non-problematic.
:1.334 is org.kde.kwrite-17177. A peak of 7M waiting to be sent to kwrite
is higher than I would usually expect, but certainly not terrible.
This is org.freedesktop.Notifications aka org.kde.plasmashell aka :1.115.
Again, a peak of 7M waiting to be sent to it is a little high but
certainly not excessive.
smcv
Oh! My apologies for misunderstanding. In that case does it correspond to this upstream bug? https://bugs.freedesktop.org/show_bug.cgi?id=33606#c11 I'm not sure that it does, because I don't understand how 1.6GB becomes 6GB without a leak (see below) Better than a swap storm and eventual mysterious crash, imho. Also if a user could more easily identify which component is precipitating the issue than he/she can file a more useful bug report against the correct package. As it stands, it's extra triaging work for the Debian dbus maintainer[s]. I've had to resort to killing individual components, because KDE5/Plasma Desktop session save/restore is broken. If I logout or reboot I lose my session (more specifically a seemingly random collection of applications sometimes opening old files from old sessions and sometimes opening no file appear on the first virtual desktop). Ksmserver is used for session management and (most? the successful ones?) applications are restarted using kwrapper5...which "tries to make the program look like it was actually really started directly and not via kdeinit" (https://github.com/KDE/kinit/blob/master/docs/wrapper.txt) Shouldn't this have existed since 1.4.10/1.5.2? https://bugs.freedesktop.org/show_bug.cgi?id=35358 That said, grep -i dbus for files in /var/log (as root) org.kde.powerdevil.backlighthelper: QDBusArgument: read from a write-only object # repeats 5 to 15 times each time it occurs org.kde.kuiserver[20319]: QDBusConnection: session D-Bus connection created before QCoreApplication. Application may misbehave. # repeats twice # then more org.kde.powerdevil.backlighthelper repeats org.kde.kcontrol.kcmsddm: QDBusArgument: read from a write-only object # repeats six times That seems very minor compared to millions of messages, but could it be part of the problem? I've seen "QDBusConnection: session D-Bus connection created before QCoreApplication. Application may misbehave." many times over the years, but never memory usage like this. I'm happy to hear there is already rate limiting :-) "you're misbehaving...slow down send or speed up reads" and then finally, if necessary "you seem to be stuck, do an internal reinit but maintain connect"? Do you think dbus-broker ( https://dvdhrm.github.io/rethinking-the-dbus-message-bus/ ) would have avoided this bug? Ah, I was missing '--dest=org.freedesktop.DBus'. I've attached the output to this email. Ok, will do. How does 1.6G of messages become 6GB of memory usage without a memory leak? Do you mean 1.6G of active memory and ~4.4G of cache? I agree. Do you think I should provide full backtraces for all of these as a bug against "plasma-desktop" or individual bugs for individual components? CPU usage is low and dbus-daemon doesn't seem to be very active. IIRC it was part of the problematic grouping, but I might have included it out of unconscious bias against. Thank you, Nicholas
Probably, yes. You'll notice we don't know how to solve that bug without
causing data loss...
dbus-broker is claimed to do better by making use of Linux-specific APIs
and having different concepts of how to assign blame for messages,
fast writing, slow reading etc., but I haven't had time to review it,
and it's possible that it achieves this by (accidentally or deliberately)
not providing invariants/guarantees that dbus-daemon does.
I'm not sure either. Something like memleax might tell you. However,
that 1.6GB is only one of several types of memory allocation in
dbus-daemon (1GB of messages is a separate allocation), so this isn't
a definite leak.
Hmm, yes, the addition in 1.11.x is logging when we hit all the other
arbitrary limits.
I don't expect this should cause any particular issues.
I don't know what form the misbehaviour would take, but I doubt the answer
is millions of messages.
The signal for "slow down sending" is to throttle reading, so that the
messages that are being sent get delayed until the current batch have been
passed through to a recipient. If a sender is sending messages that are
not necessary, then it should not send them ever, regardless of whether
there is memory pressure. If a sender is sending messages that *are*
necessary, then they're necessary, and it can't just not send them...
There is no signal for "speed up reading". It isn't clear to me that
one would be particularly useful: if an app is not reading fast enough,
it's a sign of either pathological performance issues (either a flood of
messages from a sender, or very slow message processing in a recipient),
or a design flaw (blocking the main loop). If there is something useful
for it to do in response to a signal that said "hurry up", it would be
better for it to do that all the time and not pay attention to the signal.
(It also isn't clear to me that sending an extra message is a good way
to deal with a peer that isn't processing its messages fast enough :-)
There is no generic concept of a re-initialization. Higher-level protocols
that are layered over D-Bus generally assume that every message is
delivered and do not cope with messages being discarded, so if there was
any concept of restarting the connection, it would have to be opt-in and
only used by applications whose higher-level D-Bus protocols had been
(re)designed to accommodate it. The only thing we can do with a general
connection is to disconnect it, which is documented to be interpreted as
"end of session, shut down now".
Designing new protocols that require action by library implementations
and/or opt-in by applications is not something that can happen rapidly -
sorry, I only have enough time available for D-Bus work to keep it going
in approximately the same way it does now.
This is 1.6G of linked-list links (overhead of putting things in
lists), not messages. You also have 1G of actual messages queued to
go to kded alone. I could believe there being 3.4G of other stuff
(hash tables? copies of messages? memory fragmentation between/around
messages? etc.).
The way they're designed at the moment, you cannot separate these
components. The most you could do is to provide a backtrace for the
single process that hosts all these services and is identified on D-Bus
as :1.7. I don't know how useful that backtrace would be: it describes
what is happening right now, whereas the information you need here is
probably what happened some time ago when the root cause occurred.
Then my guess would be that a logic error in kded has caused it to
stop reading from the socket that connects it to the dbus-daemon?
(You can see whether messages are still being sent by running
dbus-monitor. If the steady state is more than a few messages a second
then that's probably bad.)
smcv