Inotify cannot be used, too many open files

ocosta · August 19, 2020, 9:26pm

I tried to run a tail -F and was surprised by this error message:

tail: inotify cannot be used, reverting to polling: Too many open files

I did some quick googling, and realized it is pretty simple to increase the limits. However, I am afraid I might be turning a blind eye for the real issue (are there really too many open files opened?)

So, my questions are:

Is it common to increase these limits (max_user_instances, max_user_watches and max_queued_events)? If so, what are the recommended values?
If I run lsof | wc -l it returns 716852, which seems excessive, but I can’t really say. Is this reasonable? Should I investigate it a little further?

alciregi · August 19, 2020, 9:28pm

Yep. Investigate. Still using lsof, what is the process that open so many files?

ocosta · August 19, 2020, 10:12pm

Here are the top 10 commands (simply grouped by occurrences):

 503852 dbus-daem
 144138 Web\x20Co
  79079 MainThrea
  13560 WebExtens
  12132 Privilege
   9256 gnome-she
   3790 evolution
   2050 core
   2016 gsd-xsett
   1911 Xwayland

Entries 2-5 are all related to Firefox PIDs

Edit: I currently have 17 tabs opened

vgaetera · August 19, 2020, 10:35pm

> lsof | wc -l
206394

> lsof | cut -d " " -f 1 | sort | uniq -c | sort -n -r | head
 164054 chromium-
   5184 evolution
   5112 qemu-syst
   2850 gnome-she
   2772 libvirtd
   2457 Xwayland
   1224 gsd-xsett
   1168 gpaste-da
   1128 transmiss
   1116 goa-daemo

Apps:

GNOME DE @ Wayland
GNOME Boxes, 2 VMs @ KVM/QEMU
GNOME Terminal, ~5 tabs
Gedit, ~5 files
Nautilus, 2 tabs
Chromium, ~15 tabs
Transmission, ~5k files

Try to close apps one by one to find out which one to blame.

ocosta · August 20, 2020, 1:17am

Hi @vgaetera, nice to see you again

As I suspected, closing Firefox does free a lot of resources (but it doesn’t seem much worse than chromium on your system). However, dbus-daemon is still top #1 by far – actually, it has gone worse since last time: now I have 731555 opened files total, and top #2 accounts for only 8520 opened files:

   687190 dbus-daem
   8520 gnome-she
   3790 evolution
   2113 core
   2016 gsd-xsett
   1911 Xwayland
   1593 conky
   1336 gnome-sof
    996 gnome-ter
    903 ibus-x11

ocosta · August 20, 2020, 1:25am

Some additional info:

After a reboot, I have only 48856 opened files
If I then run Firefox with 2 tabs, it goes up to 172264 – again, pretty reasonable considering above outputs

So, something is driving dbus-damon crazy along the way; I wonder what is it…

vgaetera · August 20, 2020, 2:32am

Check the details:

pgrep -a -f dbus | sort -k 2
lsof | grep -e ^dbus | sort -k 9

The dbus-daemon services are disabled for me:

> systemctl status dbus-daemon.service 
● dbus-daemon.service - D-Bus System Message Bus
     Loaded: loaded (/usr/lib/systemd/system/dbus-daemon.service; disabled; vendor preset: disabled)
     Active: inactive (dead)
       Docs: man:dbus-daemon(1)

> systemctl --user status dbus-daemon.service 
● dbus-daemon.service - D-Bus User Message Bus
     Loaded: loaded (/usr/lib/systemd/user/dbus-daemon.service; disabled; vendor preset: disabled)
     Active: inactive (dead)
       Docs: man:dbus-daemon(1)

See also:
https://fedoraproject.org/wiki/Changes/DbusBrokerAsTheDefaultDbusImplementation

ocosta · August 20, 2020, 10:17am

There are 116 different process like this one:

/usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session

pgrep -a -f dbus | sort -k 2 | grep /usr/bin/dbus-daemon | wc -l
116

Funny thing is that I also have dbus-broker installed and active, and dbus-daemon is disabled

systemctl status dbus-broker.service 
● dbus-broker.service - D-Bus System Message Bus
     Loaded: loaded (/usr/lib/systemd/system/dbus-broker.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2020-08-20 06:52:21 -03; 10min ago
TriggeredBy: ● dbus.socket
       Docs: man:dbus-broker-launch(1)
   Main PID: 871 (dbus-broker-lau)
      Tasks: 2 (limit: 19119)
     Memory: 8.4M
        CPU: 513ms
     CGroup: /system.slice/dbus-broker.service
             ├─871 /usr/bin/dbus-broker-launch --scope system --audit
             └─894 dbus-broker --log 4 --controller 9 --machine-id 8df5fde7510f422ebad778666bdbff1d --max-bytes 536870912 --max-fds 4096 --max-matches 131072 --audit

ago 20 06:52:21 localhost.localdomain systemd[1]: Starting D-Bus System Message Bus...
ago 20 06:52:21 localhost.localdomain systemd[1]: Started D-Bus System Message Bus.
ago 20 06:52:21 localhost.localdomain dbus-broker-lau[871]: Ready
ago 20 06:52:25 localhost.localdomain dbus-broker-launch[871]: Activation request for 'org.freedesktop.resolve1' failed: The systemd unit 'dbus-org.freedesktop.resolve1.service' could not be found.
ago 20 06:52:28 localhost.localdomain dbus-broker[894]: A security policy denied :1.30 to send method call /org/freedesktop/PackageKit:org.freedesktop.DBus.Properties.GetAll to :1.37.
ago 20 06:52:28 localhost.localdomain dbus-broker[894]: A security policy denied :1.30 to send method call /org/freedesktop/PackageKit:org.freedesktop.DBus.Properties.GetAll to :1.37.

systemctl status dbus-daemon.service 
● dbus-daemon.service - D-Bus System Message Bus
     Loaded: loaded (/usr/lib/systemd/system/dbus-daemon.service; disabled; vendor preset: disabled)
     Active: inactive (dead)
       Docs: man:dbus-daemon(1)

systemctl --user status dbus-daemon.service 
● dbus-daemon.service - D-Bus User Message Bus
     Loaded: loaded (/usr/lib/systemd/user/dbus-daemon.service; disabled; vendor preset: disabled)
     Active: inactive (dead)
       Docs: man:dbus-daemon(1)

As far as DBus configuration goes, it seems that our systems look the same. What is your output for

pgrep -a -f dbus | sort -k 2 | grep /usr/bin/dbus-daemon | wc -l

?

BTW this was not an upgrade from F31, I installed F32 from scratch (this is how I usually do, I preserve home partition, and reinstall the OS)

So, it seems I have to figure out why there are so many dbus-daemon instances running here. Any clues?

vgaetera · August 20, 2020, 11:50am

I’ve checked again, there’s a single dbus-daemon process per session, a child of systemd --user.

ocosta · August 20, 2020, 12:56pm

I have just realized that 38-40 new instances are being created every minute!

ps -ef | grep dbus-daemon | uniq -f 4 -c | head
      1 earlyoom     835       1  0 06:52 ?        00:00:00 /usr/bin/earlyoom -r 0 -m 4 -M 409600 --prefer ^Web Content$ --avoid ^(dnf|packagekitd|gnome-shell|gnome-session-c|gnome-session-b|lightdm|sddm|sddm-helper|gdm|gdm-wayland-ses|gdm-session-wor|gdm-x-session|Xorg|Xwayland|systemd|systemd-logind|dbus-daemon|dbus-broker|cinnamon|cinnamon-sessio|kwin_x11|kwin_wayland|plasmashell|ksmserver|plasma_session|startplasma-way|xfce4-session|mate-session|marco|lxqt-session|openbox)$
     15 costa       2422       1  0 06:52 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     40 costa       3263       1  0 06:53 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     38 costa       3919       1  0 06:54 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     40 costa       4309       1  0 06:55 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     40 costa       4664       1  0 06:56 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     38 costa       4993       1  0 06:57 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     40 costa       5303       1  0 06:58 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     38 costa       5621       1  0 06:59 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session
     40 costa       5934       1  0 07:00 ?        00:00:00 /usr/bin/dbus-daemon --syslog-only --fork --print-pid 6 --print-address 8 --session

Right now there are 7075 dbus-daemon instances running:

pgrep dbus-daemon | wc -l
7075

Something’s really odd here…

ocosta · August 20, 2020, 1:11pm

@vgaetera may I ask you what is the limit set on /proc/sys/fs/file-max? Not sure if it’s related, but mine shows and unusually large number:

cat /proc/sys/fs/file-max 
9223372036854775807

Is this reasonable?

computersavvy · August 20, 2020, 10:23pm

@ocosta
I don’t know if that number in file-max is reasonable, but my F32 system shows the same as yours.

ocosta · August 20, 2020, 10:42pm

I finally found out the culprit. The crazy spawning of dbus-daemon was being caused by a 3rd-party “security” component installed to enable internet banking

For the investigation, I reinstalled the OS to start off from a clean install. Indeed, at first dbus-daemon seemed completely under control. I then started installing my usual additional packages, and monitoring the number of dbus-daemon instances. At some point, things started going south again. Comparing the timestamp of the first “rogue” instance with the package installations’ timestamps, I got my first clue of a possible culprit. After I uninstalled the infamous warsaw RPM, dbus-daemon instances dropped instantly to zero. I already reported the problem through their support channel, let’s hope they fix it soon enough.

I would like to thank all the ones that participated and helped during the process. Fedora is awesome

system · September 17, 2020, 10:42pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.