Mutagen constantly resyncing, despite no actual file changes - how do I debug/troubleshoot this?

[keith-chargeover]

Which version of Mutagen are you using (mutagen version)?

❯ mutagen version
0.11.8

Which operating system (platform/version/architecture) are you using?

OS X 10.14.6

What is the issue that you're experiencing?

Mutagen is constantly re-syncing files, despite no files having changed. This causes very high CPU usage.

I see stuff like this if I keep hitting enter - it's just constantly rescanning and syncing changes. No changes are happening on the actual filesystem, and I've verified this with fswatch:

Beta: docker://root@chargeover_php-apache_1/var/www/docker/chargeover/project/chargeover
	DOCKER_HOST=
	DOCKER_TLS_VERIFY=
	DOCKER_CERT_PATH=
	DOCKER_API_VERSION=
Status: Connecting to beta                                                      


Status: Staging files on beta: 0% (0/847)                                       
Status: Staging files on beta: 0% (0/847)                                       
Status: Staging files on beta                                                   
Status: Staging files on beta: 100% (846/847)                                   
Status: Staging files on beta: 100% (846/847)                                   
Status: Scanning files                                                          
Status: [Problems] Scanning files                                               
Status: [Problems] Staging files on beta: 99% (1209/1220)              
Status: [Problems] Staging files on beta: 99% (1209/1220)              
Status: Staging files on beta                                                   
Status: Staging files on beta: 4% (15/385)                                      
Status: Staging files on beta: 4% (15/385)                                      
Status: Staging files on beta: 4% (15/385)                                      
Status: Staging files on beta: 4% (15/385)                                      
Status: Applying changes                                                        
Status: Staging files on beta: 0% (0/382)                                       
Status: Staging files on beta: 0% (0/382)                                       
Status: Scanning files                                                          
Status: Staging files on beta: 1% (5/384)                                       

Status: Staging files on beta: 38% (320/852)                                    
Status: Staging files on beta: 99% (369/371)                                    

Status: Staging files on beta: 98% (363/369)                                    

What are the steps to reproduce the issue?

No idea. It just started happening. Rebooting the computer and restarting Docker does not help.

Config is very simple:

sync:
  defaults:
    mode: "one-way-replica"
    ignore:
      vcs: true
      paths:
        - "node_modules"
        - "vendor"
        - ".DS_Store"
        - "minio"
        - "assets/admin/build"
        - "build/"
        - "doxygen"

What is the expected result of these steps in the absence of the issue?

Don't peg the CPU with constant resyncs.

What is the actual result?

CPU is pegged by constantly resyncing.

Tasks:  24 total,   1 running,  23 sleeping,   0 stopped,   0 zombie
%Cpu(s): 16.3 us, 18.8 sy,  0.0 ni, 64.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   5948.6 total,   4233.2 free,    742.2 used,    973.1 buff/cache
MiB Swap:   2048.0 total,   2048.0 free,      0.0 used.   4659.9 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                                                                                                                    
  589 root      20   0  111100  45564   5976 S  84.3   0.7   5:31.89 mutagen-agent                                                                                                                                                                                                              
  477 root      20   0  110908  41224   5320 S  36.7   0.7   2:30.43 mutagen-agent                                                                                                                                                                                                              
  314 root      20   0  110716  22688   5284 S   2.0   0.4   0:04.65 mutagen-agent                                                                                                                                                                                                              
  258 root      20   0  110204   8276   5280 S   0.3   0.1   0:00.27 mutagen-agent                                                                                                                                                                                                              
    1 root      20   0   88708  28660  22600 S   0.0   0.5   0:00.13 apache2                                                                                                                                                                                                                    
   18 www-data  20   0   88740   7796   1736 S   0.0   0.1   0:00.00 apache2                                                                                                                                                                                                                    
   19 www-data  20   0   88740   7796   1736 S   0.0   0.1   0:00.00 apache2                                                                                                                                                                                                                    
   20 www-data  20   0   88740   7796   1736 S   0.0   0.1   0:00.00 apache2                                                                                                                                                                                                                    
   21 www-data  20   0   88740   7796   1736 S   0.0   0.1   0:00.00 apache2                                                                                                                                                                                                                    
   22 www-data  20   0   88740   7796   1736 S   0.0   0.1   0:00.00 apache2                                                                                                                                                                                                                    
  369 root      20   0  110716  22172   5092 S   0.0   0.4   0:04.10 mutagen-agent                                                                                                                                                                                                              
  396 root      20   0  110716  20948   6028 S   0.0   0.3   3:22.80 mutagen-agent                                                                                                                                                                                                              
  419 root      20   0  110460   9288   5696 S   0.0   0.2   0:00.33 mutagen-agent                                                                                                                                                                                                              
  436 root      20   0  110716  16292   5784 S   0.0   0.3   0:02.39 mutagen-agent                                                                                                                                                                                                              
  458 root      20   0  110204   9068   5036 S   0.0   0.1   0:00.63 mutagen-agent                                                                                                                                                                                                              
  497 root      20   0  110204  10048   4976 S   0.0   0.2   0:00.73 mutagen-agent                                                                                                                                                                                                              
  515 root      20   0  110460  16624   5008 S   0.0   0.3   0:02.91 mutagen-agent                                                                                                                                                                                                              
  534 root      20   0  110716  14348   5288 S   0.0   0.2   0:02.22 mutagen-agent                                                                                                                                                                                                              
  555 root      20   0  110204   9116   5132 S   0.0   0.1   0:00.40 mutagen-agent                                                                                                                                                                                                              
  572 root      20   0  110460  15940   5824 S   0.0   0.3   0:02.45 mutagen-agent                                                                                                                                                                                                              
  609 root      20   0  110716  22736   5256 S   0.0   0.4   3:25.85 mutagen-agent                                                                                                                                                                                                              
  629 root      20   0  110460   8564   4860 S   0.0   0.1   0:00.28 mutagen-agent                                                                                                                                                                                                              
  697 root      20   0    3868   3188   2780 S   0.0   0.1   0:00.06 bash                                                                                                                                                                                                                       
  704 root      20   0    8040   3168   2636 R   0.0   0.1   0:00.00 top        

Is there any other information that might be helpful?

How can I see what files are being synced?

Then maybe I could troubleshoot what the issue is, or see an error message, or something?

Or is there a way to get logs out of Mutagen? So I can see what it's doing?

[keith-chargeover]

Update: I destroyed my entire Docker machine, changed my Dockerfile around to make it rebuild everything, and brought everything back up... and it's magically fixed.

Really, really wish I could find a way to get Mutagen to show us what it was doing more / push out some debug info.

[d4rky-pl]

The problem is either still here or there's another issue with mutagen causing it to randomly start burning through the CPU, causing entire MacBook to get hot. It's becoming a showstopper for me since it drains my battery and burns my lap on a regular basis.

Is there any way we can help debugging this issue?

[xenoscopic]

To be honest, there's not really a trivial way to debug this at the moment, because Mutagen doesn't have debugging/tracing messages in all the places that it would need to in order to debug the issue. It does have the logging infrastructure to acquire and store that information, even from remote endpoints, but I just haven't managed to get logging statements in everywhere I'd like. If you want to do a custom build of Mutagen (which is actually fairly easy), you could use the existing logging infrastructure to print more granular information to the daemon log about what's triggering synchronization and what's being synchronized. This might end up being necessary anyway since it'll be hard to guess exactly what needs to be traced/logged.

At the moment I'm focused on getting v0.12 out the door ASAP (ideally this week) and punting some of the features that aren't ready to ship into a concurrently released v0.13-beta. As soon as I'm done with that (or maybe even as part of that), I can try to get as much tracing information as possible into the v0.13 beta release.

My best guess is that Mutagen is burning through CPU when rescanning the Linux filesystem. Mutagen can't use accelerated scans on Linux (like it can on macOS/Windows) because there's no recursive watching on Linux (other than fanotify, which I've started prototyping in Mutagen, but is still a little ways off). The only quick solutions are to reduce the number of files you're synchronizing and/or disable watching (via the --watch-mode* flags) on the Linux endpoint, in which case you won't pay the CPU penalty on a regular basis as Mutagen re-polls, only whenever a synchronization cycle is performed due to changes on the macOS side. This latter option will stop the Linux side from triggering synchronization when files are changed, but that might be fine if you're only generating changes on the macOS side.

If you'd like, I can probably spare a few minutes to screen share/video chat about the issue. It'll probably be easier to walk through debugging that way.

[xenoscopic]

More detailed tracing information is now available from the Mutagen daemon in v0.14 and later. To access this, terminate the Mutagen daemon using mutagen daemon stop and then run it in the foreground with:

MUTAGEN_LOG_LEVEL=trace mutagen daemon run

This will print out a lot of information, so you may want to tee it to a log file, but it will record the paths detected by the filesystem watcher that's causing the constant resynchronizaiton. Hopefully that helps.