gvfs-trashd and gnome-settings-daemon enter infinite loop on /proc/mounts

[Stéphane Graber]

Binary package hint: gvfs

On jaunty (sorry but that's on a production system and quite hard to test on Karmic) with an application server having around 80 users logged in and working on a gnome session for a few hours, gvfsd-trash and gnome-settings-daemon suddenly start taking all the CPU making the load to jump to around 8 (on a dual-quadcore) to over 250 making everything slow as hell.

Doing a strace on one of the buggy process, I get the following trace: http://paste.ubuntu.com/268054/
That trace is from a gvfs-trashd process, the same loop on /proc/mounts happen with gnome-settings-daemon.

The server had 80 users logged in, each with a regular gnome session including gvfs running and a few network shares mounted using cifs, ncpfs and sshfs.

I haven't been able to find a reliable way to reproduce the issue other than waiting for a few hours with over 50 users.
I'm available for any kind of additional data you may need, although as it's a production server, I won't be able to provide certain information and will probably need to anonymise some. I'm also interested on a way to reproduce that on a regular desktop installation.

[Stéphane Graber (stgraber)]

Anonymised mount output (mount | cut -d " " -f2-):
http://pastebin.com/f4becefd3

Who output (who | awk '{print $1" "$2" "$3" "$4}'):
http://pastebin.com/f41363ea2

root@SLXATS2:~# uptime
 13:21:05 up 5 days, 20:47, 53 users, load average: 234.76, 210.85, 114.48

root@SLXATS2:~# free -m
             total used free shared buffers cached
Mem: 24243 6626 17616 0 75 626
-/+ buffers/cache: 5925 18318
Swap: 3898 0 3898

[Chris Coulson (chrisccoulson)]

Thanks, could you please try interrupting the hung process and getting a backtrace?

[Stéphane Graber (stgraber)]

After some more debugging with Chris, here's one more pastebin.
It includes a partial strace, then a backtrace from gdb:
http://paste.ubuntu.com/268099/

[Chris Coulson (chrisccoulson)]

I'll paste the stack trace in line, as I'm not sure how stable pastebin is:

(gdb) bt
#0 0xb7f7e424 in __kernel_vsyscall ()
#1 0xb7687763 in __open_nocancel () from /lib/tls/i686/cmov/libc.so.6
#2 0xb76205cd in _IO_new_file_fopen (fp=0x86e9f90, filename=0xb7a94112 "/proc/mounts", mode=0xbff9b270 "rc", is32not64=1) at fileops.c:228
#3 0xb7613a3d in __fopen_internal (filename=0xb7a94112 "/proc/mounts", mode=0xbff9b270 "rc", is32=1) at iofopen.c:93
#4 0xb7613a9c in _IO_new_fopen (filename=0xb7a94112 "/proc/mounts", mode=0xbff9b270 "rc") at iofopen.c:107
#5 0xb7691ef8 in __setmntent (file=0xb7a94112 "/proc/mounts", mode=0xb7a92e73 "r") at mntent_r.c:47
#6 0xb7a7320a in _g_get_unix_mounts () at /build/buildd/glib2.0-2.20.1/gio/gunixmounts.c:364
#7 0xb7a735fd in IA__g_unix_mounts_get (time_read=0x0) at /build/buildd/glib2.0-2.20.1/gio/gunixmounts.c:1101
#8 0xb7a7363f in IA__g_unix_mount_at (mount_path=0x86a30e8 "/usr/share/fonts/truetype/dustin", time_read=0x0) at /build/buildd/glib2.0-2.20.1/gio/gunixmounts.c:1122
#9 0xb7a76c00 in mounts_changed (mount_monitor=0x8691150, user_data=0x869e2d8) at /build/buildd/glib2.0-2.20.1/gio/glocaldirectorymonitor.c:186
#10 0xb78013a4 in IA__g_cclosure_marshal_VOID__VOID (closure=0x86a32d8, return_value=0x0, n_param_values=1, param_values=0x86ada00, invocation_hint=0xbff9b9dc,
    marshal_data=0xb7a76bd0) at /build/buildd/glib2.0-2.20.1/gobject/gmarshal.c:77
#11 0xb77f3c7b in IA__g_closure_invoke (closure=0x86a32d8, return_value=0x0, n_param_values=1, param_values=0x86ada00, invocation_hint=0xbff9b9dc)
    at /build/buildd/glib2.0-2.20.1/gobject/gclosure.c:767
#12 0xb7809e57 in signal_emit_unlocked_R (node=0x869b038, detail=0, instance=0x8691150, emission_return=0x0, instance_and_params=0x86ada00)
    at /build/buildd/glib2.0-2.20.1/gobject/gsignal.c:3247
#13 0xb780b4b9 in IA__g_signal_emit_valist (instance=0x8691150, signal_id=43, detail=0, var_args=0xbff9bb7c "�_\202��\217���\217������:\023���\025V\b�Sm\b")
    at /build/buildd/glib2.0-2.20.1/gobject/gsignal.c:2980
#14 0xb780b936 in IA__g_signal_emit (instance=0x8691150, signal_id=43, detail=0) at /build/buildd/glib2.0-2.20.1/gobject/gsignal.c:3037
#15 0xb7a7294d in mtab_file_changed (monitor=0x85615d8, file=0x86d53a0, other_file=0x0, event_type=G_FILE_MONITOR_EVENT_CHANGED, user_data=0x8691150)
---Type <return> to continue, or q <return> to quit---
    at /build/buildd/glib2.0-2.20.1/gio/gunixmounts.c:1283
#16 0xb7a8133a in _gio_marshal_VOID__OBJECT_OBJECT_ENUM (closure=0x869b6d0, return_value=0x0, n_param_values=4, param_values=0x86b0f80, invocation_hint=0xbff9bd1c,
    marshal_data=0xb7a72900) at /build/buildd/glib2.0-2.20.1/gio/gio-marshal.c:198
#17 0xb77f3c7b in IA__g_closure_invoke (closure=0x869b6d0, return_value=0x0, n_param_values=4, param_values=0x86b0f80, invocation_hint=0xbff9bd1c)
    at /build/buildd/glib2.0-2.20.1/gobject/gclosure.c:767
#18 0xb7809e57 in signal_emit_unlocked_R (node=0x85a9ef8, detail=0, instance=0x85615d8, emission_return=0x0, instance_and_params=0x86b0f80)
    at /build/buildd/glib2.0-2.20.1/gobject/gsignal.c:3247
#19 0xb780b4b9 in IA__g_signal_emit_valist (instance=0x85615d8, signal_id=42, detail=0, var_args=0xbff9...

[Chris Coulson (chrisccoulson)]

Also, reassigning to glib for now. I've seen this issue reported before with other functions that iterate over /proc/mounts which have lots of entries. I had a quick glance at the glib code, and it doesn't seem to be doing anything really expensive, so this might actually be a glibc issue.

[Chris Coulson (chrisccoulson)]

Bug 315132 is a similar type of issue.

[Jorenko (jorenko)]

I just saw something very like this in 12.04. I have two samba shares mounted via gvfs, but neither has very many users; at most a half dozen simultaneous at peak times. Killing the gnome-settings-daemon process returned CPU usage to normal and the shares are still functional.