linuxmint / nemo

File browser for Cinnamon
GNU General Public License v2.0
1.23k stars 299 forks source link

Massive Memory Leak 4.0.6 #2161

Open bitnom opened 5 years ago

bitnom commented 5 years ago

Issue If left running, Nemo will consume RAM in infinitus. When this happens, I have to pkill nemo to get it back. For instance, I just came back to my desktop after about 8 hours to find that Nemo had taken 10GB of RAM. Please relay to me any steps I can perform for debugging.

mtwebster commented 5 years ago

Hi,

If you can get ahold of debug symbols for nemo, glib, gtk3, cairo, you could run nemo inside a debugger (gdb) -

nemo --quit (or killall nemo)
gdb nemo
> r
.... running, taking lots of ram ...
ctrl-c
> thread apply all bt

That may not yield anything useful (depends on the nature of the problem), a couple other things you can try:

If any of these improve the situation, you can individually turn things back on to see if we can home in on the issue.

buck2202 commented 5 years ago

I'm seeing a huge memory leak as well, but it's being eaten up in the nemo-desktop process. Unsure if related, but I didn't see an issue specifically for nemo-desktop.

On Mint Cinnamon 19.1 x64, nemo 4.0.6. nvidia gtx 1060 w/ nvidia-driver-410.104

mtwebster commented 5 years ago

They share about 90% the same code, so it's definitely possible it is the same issue.

I would ask you if possible, to perform the steps I described above. Since you're on Mint, to install the debug symbols, you can go into Software Sources, check the Debug symbols switch under Optional Sources. Then you can do, in a terminal (all one line):

sudo apt-get install libglib2.0-0-dbgsym libgtk-3-0-dbgsym libgdk-pixbuf2.0-0-dbgsym libcairo2-dbgsym nemo-dbg libxapp-dbg

then the debugger will provide more useful info. Just replace any occurrence of 'nemo' in the steps above with 'nemo-desktop'. The other suggestions there also apply.

Thanks a lot

buck2202 commented 5 years ago

In my case, there were no thumbnail issues, and disabling all extensions plus thumbnailing had no effect. No backtrace yet, but I've tracked down the apparent cause of the leak in my scenario.

I'm affected by this bug (https://gitlab.gnome.org/GNOME/glib/issues/1271, https://bugs.launchpad.net/ubuntu/+source/glib2.0/+bug/1691908) which is fixed, but not backported to bionic. The annoying effect is that my bind mounts appear in the nemo "Devices" menu and there is no mechanism to ignore/hide them...but their presence also seems to confuse nemo. Melange shows a flood of messages like info t=2019-06-25T21:22:40Z PlacesManager: Updating devices repeating every few seconds. So, something is preventing nemo from seeing the bind list as static, and there seems to be a memory leak in the refresh. When I unmount all of my binds, nemo-desktop memory after ~18hours has stayed at 10s of MB instead of growing to multiple GB. I've only recently started adding bind mounts to my fstab, so I can't confirm that this is a recent regression.

I can still try to pull a backtrace if you'd like

mtwebster commented 5 years ago

Nah don’t worry about it for now. If I can reproduce it that’ll be all I need. I’m hoping I can do some kind of workaround.

Can you describe your drive setup or share fstab maybe? Anything that might help me duplicate your conditions.

Thanks!

buck2202 commented 5 years ago

My goal was just to aggregate content scattered across a few folders/drives into a single folder for Syncthing, which won't follow symlinks. I hadn't made it very far when I noticed the glib bug. Relevant snip from fstab below

#mount physical drive
UUID=xxx    /media/hda5 ntfs-3g defaults,uid=1000,gid=1000,fmask=077,gmask=077  0   0 

#bind selected subfolders
/media/hda5/classical/downloads         /home/user/music_sync/classical/downloads   none    defaults,bind,x-gvfs-hide   0   0
/media/hda5/classical/downloads_flac/flac   /home/user/music_sync/classical/downloads_flac  none    defaults,bind,x-gvfs-hide   0   0
/media/hda5/classical/rips/flac         /home/user/music_sync/classical/rips        none    defaults,bind,x-gvfs-hide   0   0

The bind "devices" are existing subfolders within my mounted /media/hda5 drive, and the mountpoints are just subfolders owned by me. x-gvfs-hide should hide the binds from nemo, but isn't functional due to the gnome issue I linked. The "updating devices" flood and leak occur when any one of the binds are mounted.

For every PlacesManager update, I can see nemo-desktop memory usage increase slightly and I get a momentary, cinnamon-wide UI lag.

Thank you too!

mtwebster commented 5 years ago

That "PlacesManager" warning is actually coming from cinnamon. How is the cinnamon process' memory and cpu use?

I can reproduce the gvfs-hide bug using binds in fstab, but I don't get any sort of memory leak along with it. Is the drive whose folders you're binding to your home a usb-attached drive? Or is it internal (sata or whatever)?

Also, what does 'gmask' do? All I typically see for ntfs is fmask and dmask. I can't find any info on gmask.

buck2202 commented 5 years ago

I don't notice any abnormal use from the cinnamon process. The drive is an NTFS partition on an internal sata drive.

And gmask--now that you point it out, it's a mystery to me too. I've likely been using the same prototype line for mounting NTFS partitions for over a decade, so it could be an option for a long-outdated ntfs driver. Or it could be a typo that I've been pasting all this time. Probably safe to assume that I meant dmask.

With the mount line corrected to dmask (or a bind to an ext4 drive), I get the same behavior. Increasing nemo-desktop memory use, and a lag in cinnamon every time PlacesManager issues a warning.

buck2202 commented 5 years ago

Running nemo-desktop from gdb (pkill nemo-desktop && gdb nemo-desktop) shows a flurry of New Thread/Thread exited activity every time PlacesManager refreshes, but in between those cases, nothing looks that suspicious (in this run, nemo-desktop was stable at ~17.5MiB for 30 minutes with no bind mounts, then grew to ~200MiB after 2 hours). I also notice that the system lag from PlacesManager updates occurs even when nemo-desktop isn't running--which I guess makes sense since you said those warnings come from cinnamon.

Here's the backtrace I happened to catch it in the middle of a new/exit thread cycle

[New Thread 0x7fffdbfff700 (LWP 26810)]
[New Thread 0x7fffc89f3700 (LWP 26811)]
[New Thread 0x7fffd8f7b700 (LWP 26812)]
[New Thread 0x7fffcb1f8700 (LWP 26813)]
[New Thread 0x7fffcb9f9700 (LWP 26814)]
[New Thread 0x7fffca9f7700 (LWP 26815)]
[New Thread 0x7fffca1f6700 (LWP 26816)]
[New Thread 0x7fffc99f5700 (LWP 26817)]
[New Thread 0x7fffc91f4700 (LWP 26818)]
^C
Thread 1 "nemo-desktop" received signal SIGINT, Interrupt.
g_object_set_valist (object=object@entry=0x555556044780, first_property_name=first_property_name@entry=0x7ffff7450b68 "related-action", 
    var_args=var_args@entry=0x7fffffffd8c0) at ../../../../gobject/gobject.c:2308
2308    ../../../../gobject/gobject.c: No such file or directory.
(gdb) thread apply all bt

Thread 7100 (Thread 0x7fffc91f4700 (LWP 26818)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030224)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030224)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc089b70) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffc91f4700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7099 (Thread 0x7fffc99f5700 (LWP 26817)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030245)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030245)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffb80a9370) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffc99f5700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7098 (Thread 0x7fffca1f6700 (LWP 26816)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030234)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030234)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc0ad850) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffca1f6700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7097 (Thread 0x7fffca9f7700 (LWP 26815)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030194)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030194)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc0aeb70) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffca9f7700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7096 (Thread 0x7fffcb9f9700 (LWP 26814)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030177)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030177)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc0ae850) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffcb9f9700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7095 (Thread 0x7fffcb1f8700 (LWP 26813)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030192)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030192)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
---Type <return> to continue, or q <return> to quit---
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc09d050) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffcb1f8700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7094 (Thread 0x7fffd8f7b700 (LWP 26812)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030143)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030143)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc08eb70) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffd8f7b700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7093 (Thread 0x7fffc89f3700 (LWP 26811)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030206)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030206)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc0ae990) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffc89f3700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7092 (Thread 0x7fffdbfff700 (LWP 26810)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030201)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030201)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x55555fd4a320) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffdbfff700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7091 (Thread 0x7fffabfff700 (LWP 26608)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559b6408, mutex=mutex@entry=0x5555559b6400, end_time=end_time@entry=462999030197)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=0x5555559b6400, wait=wait@entry=1, end_time=462999030197)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb68 in g_async_queue_timeout_pop_unlocked (queue=<optimized out>, timeout=timeout@entry=500000) at ../../../../glib/gasyncqueue.c:570
#4  0x00007ffff57318b4 in g_thread_pool_wait_for_new_task (pool=<optimized out>) at ../../../../glib/gthreadpool.c:262
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:296
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc0aab70) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffabfff700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 4 (Thread 0x7fffe880a700 (LWP 17445)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x5555559df260, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=1, fds=0x5555559df260, timeout=<optimized out>, context=0x5555559e0c00)
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=context@entry=0x5555559e0c00, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../../../../glib/gmain.c:3897
#3  0x00007ffff57095dc in g_main_context_iteration (context=0x5555559e0c00, may_block=1) at ../../../../glib/gmain.c:3963
#4  0x00007fffe881236d in ?? () from /usr/lib/x86_64-linux-gnu/gio/modules/libdconfsettings.so
#5  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc010280) at ../../../../glib/gthread.c:784
#6  0x00007ffff3fa66db in start_thread (arg=0x7fffe880a700) at pthread_create.c:463
#7  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 3 (Thread 0x7fffe9218700 (LWP 17444)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x7fffd0008c20, nfds=4, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=4, fds=0x7fffd0008c20, timeout=<optimized out>, context=0x5555559bfba0)
---Type <return> to continue, or q <return> to quit---
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=0x5555559bfba0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../../glib/gmain.c:3897
#3  0x00007ffff5709862 in g_main_loop_run (loop=0x5555559bfce0) at ../../../../glib/gmain.c:4098
#4  0x00007ffff5cf6026 in gdbus_shared_thread_func (user_data=0x5555559bfb70) at ../../../../gio/gdbusprivate.c:275
#5  0x00007ffff5730f15 in g_thread_proxy (data=0x5555559960a0) at ../../../../glib/gthread.c:784
#6  0x00007ffff3fa66db in start_thread (arg=0x7fffe9218700) at pthread_create.c:463
#7  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7fffe9a19700 (LWP 17443)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x5555559b83e0, nfds=2, timeout=3411) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=2, fds=0x5555559b83e0, timeout=<optimized out>, context=0x5555559b8100)
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=context@entry=0x5555559b8100, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../../../../glib/gmain.c:3897
#3  0x00007ffff57095dc in g_main_context_iteration (context=0x5555559b8100, may_block=may_block@entry=1) at ../../../../glib/gmain.c:3963
#4  0x00007ffff5709621 in glib_worker_main (data=<optimized out>) at ../../../../glib/gmain.c:5772
#5  0x00007ffff5730f15 in g_thread_proxy (data=0x555555996000) at ../../../../glib/gthread.c:784
#6  0x00007ffff3fa66db in start_thread (arg=0x7fffe9a19700) at pthread_create.c:463
#7  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7ffff7fab480 (LWP 17440)):
#0  g_object_set_valist (object=object@entry=0x555556044780, first_property_name=first_property_name@entry=0x7ffff7450b68 "related-action", 
    var_args=var_args@entry=0x7fffffffd8c0) at ../../../../gobject/gobject.c:2308
#1  0x00007ffff59eba0c in g_object_set (_object=0x555556044780, first_property_name=first_property_name@entry=0x7ffff7450b68 "related-action")
    at ../../../../gobject/gobject.c:2467
#2  0x00007ffff7130bbc in gtk_activatable_set_related_action (activatable=<optimized out>, action=action@entry=0x55555ff2b630)
    at ../../../../gtk/deprecated/gtkactivatable.c:392
#3  0x00007ffff7162fe0 in update_node (manager=manager@entry=0x555555c93610, node=0x555555fe5290, in_popup=in_popup@entry=1, 
    popup_accels=popup_accels@entry=0) at ../../../../gtk/deprecated/gtkuimanager.c:2928
#4  0x00007ffff71622e0 in update_node (manager=manager@entry=0x555555c93610, node=0x555555ee8a10, in_popup=in_popup@entry=1, 
    popup_accels=popup_accels@entry=0) at ../../../../gtk/deprecated/gtkuimanager.c:3075
#5  0x00007ffff71622e0 in update_node (manager=manager@entry=0x555555c93610, node=0x555555ee8890, in_popup=in_popup@entry=1, 
    popup_accels=popup_accels@entry=0) at ../../../../gtk/deprecated/gtkuimanager.c:3075
#6  0x00007ffff71622e0 in update_node (manager=manager@entry=0x555555c93610, node=0x555555ee8800, in_popup=in_popup@entry=1, 
    popup_accels=popup_accels@entry=0) at ../../../../gtk/deprecated/gtkuimanager.c:3075
#7  0x00007ffff71622e0 in update_node (manager=manager@entry=0x555555c93610, node=0x555555ed48d0, in_popup=1, in_popup@entry=0, 
    popup_accels=popup_accels@entry=0) at ../../../../gtk/deprecated/gtkuimanager.c:3075
#8  0x00007ffff71622e0 in update_node (manager=manager@entry=0x555555c93610, node=0x7fffdc02a980, in_popup=in_popup@entry=0, 
    popup_accels=popup_accels@entry=0) at ../../../../gtk/deprecated/gtkuimanager.c:3075
#9  0x00007ffff71633e9 in do_updates (manager=manager@entry=0x555555c93610) at ../../../../gtk/deprecated/gtkuimanager.c:3121
#10 0x00007ffff7165f34 in gtk_ui_manager_ensure_update (manager=manager@entry=0x555555c93610) at ../../../../gtk/deprecated/gtkuimanager.c:3179
#11 0x00007ffff7165f91 in gtk_ui_manager_real_get_widget (manager=0x555555c93610, path=0x555555696738 "/selection/File Clipboard Actions/Duplicate")
    at ../../../../gtk/deprecated/gtkuimanager.c:796
#12 0x00005555555f7c0c in update_complex_popup_items (view=0x555555dabb20) at ../../src/nemo-view.c:9578
#13 real_update_menus (view=<optimized out>) at ../../src/nemo-view.c:10017
#14 0x00005555555ac7f9 in nemo_icon_view_update_menus (view=0x555555dabb20) at ../../src/nemo-icon-view.c:1527
#15 0x000055555559a086 in real_update_menus (view=0x555555dabb20) at ../../src/nemo-desktop-icon-grid-view.c:908
#16 0x00005555555f19b9 in nemo_view_update_menus (view=0x555555dabb20) at ../../src/nemo-view.c:820
#17 0x00005555555f1a62 in update_menus_timeout_callback (data=<error reading variable: value has been optimized out>) at ../../src/nemo-view.c:3861
#18 0x00007ffff5709c03 in g_timeout_dispatch (source=source@entry=0x55555e5c06d0, callback=<optimized out>, user_data=<optimized out>)
    at ../../../../glib/gmain.c:4649
#19 0x00007ffff5709185 in g_main_dispatch (context=0x55555593ac20) at ../../../../glib/gmain.c:3176
#20 g_main_context_dispatch (context=context@entry=0x55555593ac20) at ../../../../glib/gmain.c:3829
#21 0x00007ffff5709550 in g_main_context_iterate (context=context@entry=0x55555593ac20, block=block@entry=1, dispatch=dispatch@entry=1, 
    self=<optimized out>) at ../../../../glib/gmain.c:3902
#22 0x00007ffff57095dc in g_main_context_iteration (context=context@entry=0x55555593ac20, may_block=may_block@entry=1) at ../../../../glib/gmain.c:3963
#23 0x00007ffff5cc9ddd in g_application_run (application=0x5555559351c0, argc=<optimized out>, argv=<optimized out>) at ../../../../gio/gapplication.c:2470
#24 0x000055555558882e in main (argc=1, argv=0x7fffffffe0e8) at ../../src/nemo-desktop-main.c:101

and this is in one of the "quiet" periods

Thread 1 "nemo-desktop" received signal SIGINT, Interrupt.
0x00007ffff3cc2bf9 in __GI___poll (fds=0x55555593cde0, nfds=3, timeout=2000) at ../sysdeps/unix/sysv/linux/poll.c:29
29  in ../sysdeps/unix/sysv/linux/poll.c
(gdb) thread apply all bt

Thread 7129 (Thread 0x7fffc91f4700 (LWP 27807)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007ffff574f5ca in g_cond_wait_until (cond=cond@entry=0x5555559aeb78, mutex=mutex@entry=0x5555559aeb70, end_time=end_time@entry=463215191486)
    at ../../../../glib/gthread-posix.c:1449
#2  0x00007ffff56dc571 in g_async_queue_pop_intern_unlocked (queue=queue@entry=0x5555559aeb70, wait=wait@entry=1, end_time=end_time@entry=463215191486)
    at ../../../../glib/gasyncqueue.c:422
#3  0x00007ffff56dcb2c in g_async_queue_timeout_pop (queue=0x5555559aeb70, timeout=timeout@entry=15000000) at ../../../../glib/gasyncqueue.c:543
#4  0x00007ffff57319be in g_thread_pool_wait_for_new_pool () at ../../../../glib/gthreadpool.c:167
#5  g_thread_pool_thread_proxy (data=<optimized out>) at ../../../../glib/gthreadpool.c:364
#6  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc0afb70) at ../../../../glib/gthread.c:784
#7  0x00007ffff3fa66db in start_thread (arg=0x7fffc91f4700) at pthread_create.c:463
#8  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 4 (Thread 0x7fffe880a700 (LWP 17445)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x5555559df260, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=1, fds=0x5555559df260, timeout=<optimized out>, context=0x5555559e0c00)
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=context@entry=0x5555559e0c00, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../../../../glib/gmain.c:3897
#3  0x00007ffff57095dc in g_main_context_iteration (context=0x5555559e0c00, may_block=1) at ../../../../glib/gmain.c:3963
#4  0x00007fffe881236d in ?? () from /usr/lib/x86_64-linux-gnu/gio/modules/libdconfsettings.so
#5  0x00007ffff5730f15 in g_thread_proxy (data=0x7fffdc010280) at ../../../../glib/gthread.c:784
#6  0x00007ffff3fa66db in start_thread (arg=0x7fffe880a700) at pthread_create.c:463
#7  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 3 (Thread 0x7fffe9218700 (LWP 17444)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x7fffd0008c20, nfds=4, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=4, fds=0x7fffd0008c20, timeout=<optimized out>, context=0x5555559bfba0)
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=0x5555559bfba0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../../glib/gmain.c:3897
#3  0x00007ffff5709862 in g_main_loop_run (loop=0x5555559bfce0) at ../../../../glib/gmain.c:4098
#4  0x00007ffff5cf6026 in gdbus_shared_thread_func (user_data=0x5555559bfb70) at ../../../../gio/gdbusprivate.c:275
#5  0x00007ffff5730f15 in g_thread_proxy (data=0x5555559960a0) at ../../../../glib/gthread.c:784
#6  0x00007ffff3fa66db in start_thread (arg=0x7fffe9218700) at pthread_create.c:463
#7  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7fffe9a19700 (LWP 17443)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x5555559b83e0, nfds=2, timeout=2363) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=2, fds=0x5555559b83e0, timeout=<optimized out>, context=0x5555559b8100)
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=context@entry=0x5555559b8100, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../../../../glib/gmain.c:3897
#3  0x00007ffff57095dc in g_main_context_iteration (context=0x5555559b8100, may_block=may_block@entry=1) at ../../../../glib/gmain.c:3963
#4  0x00007ffff5709621 in glib_worker_main (data=<optimized out>) at ../../../../glib/gmain.c:5772
#5  0x00007ffff5730f15 in g_thread_proxy (data=0x555555996000) at ../../../../glib/gthread.c:784
#6  0x00007ffff3fa66db in start_thread (arg=0x7fffe9a19700) at pthread_create.c:463
#7  0x00007ffff3ccf88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7ffff7fab480 (LWP 17440)):
#0  0x00007ffff3cc2bf9 in __GI___poll (fds=0x55555593cde0, nfds=3, timeout=2000) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007ffff57094c9 in g_main_context_poll (priority=<optimized out>, n_fds=3, fds=0x55555593cde0, timeout=<optimized out>, context=0x55555593ac20)
    at ../../../../glib/gmain.c:4203
#2  g_main_context_iterate (context=context@entry=0x55555593ac20, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../../../../glib/gmain.c:3897
#3  0x00007ffff57095dc in g_main_context_iteration (context=context@entry=0x55555593ac20, may_block=may_block@entry=1) at ../../../../glib/gmain.c:3963
#4  0x00007ffff5cc9ddd in g_application_run (application=0x5555559351c0, argc=<optimized out>, argv=<optimized out>) at ../../../../gio/gapplication.c:2470
#5  0x000055555558882e in main (argc=1, argv=0x7fffffffe0e8) at ../../src/nemo-desktop-main.c:101

I'm not sure how useful valgrind would be since I'm not sure how to exit nemo-desktop "cleanly", but I could give that a shot too if you'd like. Do you have a suppression file? Or want something else?

mtwebster commented 5 years ago

Here I was thinking if I asked you to run valgrind that might be asking too much :)

Valgrind would be nice if you wouldn't mind I usually use:

valgrind --tool=memcheck --leak-check=full --leak-resolution=high --num-callers=20 --log-file=vgdump nemo

A perf report would be great too - if we're stuck in a loop here, this will help tell us where. The trace doesn't help that much (nor was I certain it would), since the break position is pretty random.

This would need a little more setup (you probably ned to install linux-tools-common first)

sudo sh -c "echo 1 >/proc/sys/kernel/perf_event_paranoid"
sudo sh -c " echo 0 > /proc/sys/kernel/kptr_restrict"

then..
perf record -e cycles -F 50 -g --call-graph dwarf -- nemo

If it prompts for missing packages, install the 2 that don't have 'cloud' in the names.

The perf data is binary, so hopefully you have a place to keep it (I'm not sure github has a mechanism)

Anyhow, thanks. Sorry if I'm being too detailed, this is for anyone else encountering it as well (including the OP)

mtwebster commented 5 years ago

This might possibly yield clues also: NEMO_DEBUG=Places,DirectoryView G_MESSAGES_DEBUG=all nemo

buck2202 commented 5 years ago

Just a quick question--nemo-desktop --quit doesn't seem able to trigger a shutdown when the process is running through valgrind. Does ctrl+c/SIGINT trigger a clean exit, or are you just expecting that there will be a lot of not-really-leaks in the report?

mtwebster commented 5 years ago

I don't think I've ever used anything but ctrl-c when using valgrind. There's a bit more info here: https://wiki.gnome.org/Valgrind - it's pretty dated, but still helpful. True leaks for GObject-based programs generally show up as 'definitely lost' - and that has held up to be true when I've worked with valgrind. There are definitely lots of not-really-leaks, in fact most of them in the log.

buck2202 commented 5 years ago

The valgrind listing did turn out to be a bit of a mess. I ran

valgrind --tool=memcheck --leak-check=full --leak-resolution=high --num-callers=20 --log-file=vgdump nemo-desktop

for about 10-15 minutes before ctrl+c, once with bind mounts and once without. For the most part, they show losses from the same places. It looks like it must mostly be catching things that aren't cleaned up at exit?

I'll try to pull a longer run of the "withbind" case to see if I can make anything more obvious--I tried it once before, but valgrind was taking an extremely long to exit after ctrl+c and I had to kill it

vgdump.nobind.txt vgdump.withbind.txt

More to come

mtwebster commented 5 years ago

That actually is showing a couple of real leaks I hadn't seen before (I usually run just nemo when trolling for leaks). Nothing relevant to the issue I think, they're just happening way more often than they should.

From looking at the warning from Cinnamon, it's being called when the volume monitor triggers a change (something added, removed, etc...)

I made this script a long time ago, It might help us figure out what event is triggering the repeated refreshes - https://raw.githubusercontent.com/mtwebster/utils/master/mountmon

You can make it executable or run it with python2 or 3.

You could also try inotifywait -m <path> and watch the parent folder of these binds, or the binds themselves.

buck2202 commented 5 years ago

Ok, so, I ran nemo-desktop in valgrind for about an hour (memory would've grown to about 100MiB), and it's been about 5h with a fully-loaded core since I ctrl+c'd it. No loss listing yet. I'll let it keep going for now.

In the meantime, I ran the mountmon script for the fstab snippet below

UUID=76BB9D6D73827962   /media/hda5     ntfs-3g defaults,uid=1000,gid=1000,fmask=077,dmask=077  0       0
/media/hda5/classical   /media/hda5-bind    none    defaults,bind,x-gvfs-hide       0       0

The first output starts from me running sudo mount /media/hda5-bind and ends with umount a minute or two later. It looks like the bind has the same "name" as the actual volume, and they're fighting with each other over which URI is correct. Dunno if the unique key for volumes is just the printed "name," but whatever the key is, it seems like the bind is conflicting.

$ ./mountmon.py 
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>]
Mount added: hda5-bind, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: hda5-bind, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad5ae840)>]
Mount changed: 268 GB Volume, root: file:///media/hda5
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbd20 (GProxyMount at 0x5577ad591f30)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad5ae840)>]
Mount removed: 268 GB Volume, root: file:///media/hda5-bind
mounts now: 
[<__gi__.GProxyMount object at 0x7fb69d5dbe60 (GProxyMount at 0x5577ad592260)>, <__gi__.GProxyMount object at 0x7fb69d5dbeb0 (GProxyMount at 0x5577ad5921f0)>, <__gi__.GProxyMount object at 0x7fb69d5dbf00 (GProxyMount at 0x5577ad592180)>, <__gi__.GProxyMount object at 0x7fb69d5dbf50 (GProxyMount at 0x5577ad592110)>, <__gi__.GProxyMount object at 0x7fb69d5dbfa0 (GProxyMount at 0x5577ad591f30)>]

edit to add: I don't get any output from inotifywait on the bind mountpoint that doesn't correspond with the actual mount/unmount events

buck2202 commented 5 years ago

I think I'm noticing that if nemo-desktop isn't active (or, like now, stuck under valgrind trying to exit), the leaking memory shifts to nemo. Not sure if that makes sense...but just in case, I ran NEMO_DEBUG=Places,DirectoryView G_MESSAGES_DEBUG=all nemo

The debug entry timestamps don't exactly correspond to the melange/placesmanager log entries, but I get this message repeatedly. Nothing else

** (nemo:11623): DEBUG: 20:03:02.728: update_places: ../../src/nemo-places-sidebar.c:719: Updating places sidebar
buck2202 commented 5 years ago

Here is the valgrind listing from the 1hour run with binds mounted...it took a bit over 6 hours after ctrl+c for it to finalize and exit.

vgdump.withbindlong.txt

mtwebster commented 5 years ago

Have you tried a different kernel? I'm trying to think of reasons why I can't reproduce it.

What kernel are you using?

buck2202 commented 5 years ago

I sometimes forget that Mint tries to protect users from bumping into new kernel releases. I think my last fresh install was Mint 19 about a year ago, so I had been using 4.15.0-54. Same behavior now after updating to 5.0.0-20, though.

mtwebster commented 5 years ago

Hi, I haven't forgotten this.. Do you have 'autofs' installed? If so, try removing it. I still haven't had any luck reproducing this. Does this occur if you create a new user and log in there? I'm guessing it does, it's just one more thing to eliminate.

buck2202 commented 5 years ago

autofs is not installed, but I did not see nemo-desktop's memory footprint continually grow with a new account, and melange didn't show the flood of "PlacesManager: Updating devices" messages. Good suggestion!

So, in my normal account, I started killing background applications and services. The melange entries stopped when I exited psensor. Specifically, "udisks2" support for reading hard drive temperatures seems to be what triggers the leak (code here). I can produce the same leak without psensor by opening a "SMART Data & Self-Tests" window in gnome disks and mashing the refresh button while a bind is mounted.

buck2202 commented 5 years ago

Hi, just wanted to check that you were able to reproduce the leak as an effect of refreshing SMART data with binds mounted?

So far, I've noticed the leak/melange-events as a direct response to SMART polling from psensor, smartmontools, and gnome-disks. Oddly, whatever mechanism GSmartControl uses to refresh the data does not seem to cause the leak in nemo.

mtwebster commented 5 years ago

Hi, sorry, I've been distracted away. Interestingly however, I realized that I've been getting "Updating devices" messages 10 minutes apart, I guess since I'd set up my fstab to emulate your setup.

Going into Drives and hitting refresh on my primary disk's smart page (the usb-attached drive didn't have smart available) will indeed trigger the update. From what I see in mountmon, it's repeatedly juggling the 'parent' and 'child' (is this how you say it?) mounts. I'm not sure how we could do anything about this, or work around it, as it's happening at a level that nemo, or anything in cinnamon, interacts with.

I tried out bindfs and the issue doesn't seem to occur. The fstab is slightly different but the gvfs-hide flag doesn't work.

For example, mine:

UUID=D6E6AD14E6ACF641 /media/Data ntfs-3g defaults,uid=1000,gid=1000,umask=077,noauto 0 0
/media/Data/bin         /media/DataBin          fuse.bindfs     defaults       0       0

This gives me a Data and DataBin drive, and they show up as those names in nemo's sidebar. Refreshing SMART does not cause an update, nor am I getting an update every 10 minutes.

There may very well be some replacement for gvfs-hide available as well, I didn't dig too deep into it yet, I'd like to see if this works (or if you've maybe already tried it).

buck2202 commented 5 years ago

Huh, in my case x-gvfs-hide is functioning properly for bindfs mounts; the gnome bug report makes it sound like it's only an issue for proper binds. Maybe a typo when you tried it?

And just confirming that the "updating devices" messages (and presumably the rapid memory leak) are not present at either 30s intervals (from psensor) or 10m intervals (from wherever...I had thought that was smartd/smartmontools, but the default interval there is 30m). I had avoided bindfs because it (really, fuse) doesn't offer inotify events which are nice to have in syncthing, but if it avoids the leak, it's an option. Thanks for the tip

So do you mean that the leak associated with the parent/child juggling is in a library upstream of nemo? And is it only in this specific instance with binds mounted? Or is it a leak generally when nemo sees volumes added/removed/changed that just normally isn't triggered frequently enough to be an issue?

mtwebster commented 5 years ago

Ok, I apologize again for the delay, I started back on this a few days ago - I was able to more precisely reproduce your behavior, with psensors running and a bind mount in fstab. I can trigger the memory growth/device refreshes with SMART refresh (for my system drive actually, for some reason I haven't investigated I don't get SMART info for my external ones). I can also see it triggered with psensors running, and monitoring my internal drive - again, I don't get any data from my external drives. But this alone gives me updates up to 2 per minute, and I can see the leak in both nemo and nemo-desktop.

With nemo 4.2 I fixed one leak, and it seems to have reduced its severity, but there is at least one more I'm trying to figure out what to do with still. It appears to be coming from an upstream library (fontconfig or pango) but I'm not certain yet.

Cinnamon also leaks from this, though not as seriously I think (I've been mostly paying attention to nemo). A leak there of this kind is a lot more difficult to debug, as the code involved is javascript, and memory management there can be a challenge.

I'll update if I come up with something.

buck2202 commented 5 years ago

Hi, thanks for checking in. Aside from the fuse shortcomings, I've been using bindfs mostly without issue since your last message. It does seem to prevent the leak, so thanks a lot for suggesting that.

Off topic, but on SMART data for external drives, in the past I've had to manually edit /var/lib/smartmontools/drivedb/drivedb.h, which IIRC, still does not fix gnome-disks but does make things work for gsmartcontrol and (I think) smartd. There used to be a utility included in smartmontools that updated the SMART drive database, but debian disabled it upstream for security reasons, and it's been 4 years since they started talking about providing an alternative update mechanism. The packaged database is very old and is missing every large external drive I've ever tried. https://bugs.launchpad.net/ubuntu/+source/smartmontools/+bug/1574894 https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=804299 https://www.smartmontools.org/wiki/Download#Updatethedrivedatabase

Thanks for plugging away on this!