9

My Time Machine is in the cleanup state for a long time (several days). The backup is to an external drive and the disk on the mac laptop is less than 500 GB. It usaually takes much less time to clean up.

Is there a way to inspect what the Time Machine actually is doing during the cleanup?

The following log is not helpful.

$ log show --debug --predicate 'subsystem == "com.apple.TimeMachine"' --info --last 4h
Filtering the log data using "subsystem == "com.apple.TimeMachine""
Timestamp                       Thread     Type        Activity             PID    TTL  
2020-02-21 13:36:41.329729-0600 0xb4acfa   Info        0x0                  98     0    backupd-helper: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Not starting scheduled Time Machine backup: Backup already running
2020-02-21 14:36:55.424274-0600 0xb60241   Info        0x0                  98     0    backupd-helper: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Not starting scheduled Time Machine backup: Backup already running
2020-02-21 15:42:20.848345-0600 0xb64cb9   Info        0x0                  98     0    backupd-helper: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Not starting scheduled Time Machine backup: Backup already running
2020-02-21 16:36:27.614466-0600 0xb8060d   Info        0x0                  98     0    backupd-helper: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Not starting scheduled Time Machine backup: Backup already running
--------------------------------------------------------------------------------------------------------------------
Log      - Default:          0, Info:                4, Debug:             0, Error:          0, Fault:          0
Activity - Create:           0, Transition:          0, Actions:           0
user3439894
  • 58,676
user1424739
  • 522
  • You probably updated to latest MacOS, then there is a lot of work to do. – Thorbjørn Ravn Andersen Feb 21 '20 at 23:58
  • I have not updated my MacOS. The only thing is that there might be 100GB data changed since the last backup to the current one. But it doens't make sense to clean up for many days, it takes even more time than the backup stage. – user1424739 Feb 22 '20 at 05:51
  • I would suspect the Time Machine drive is damaged. I used to see this kind of thing a lot on [High] Sierra, a lot less since Mojave. The only thing I've found that can fix it is DiskWarrior You could also try thinning/deleting local snapshots, but I never found that to really fix anything - see https://apple.stackexchange.com/a/362658/85275 – Tetsujin Feb 22 '20 at 08:30
  • Buy another disk and do a fresh backup to that. The cleaning process to remove old images may apparently be quite slow in the latest. My time capsule took forever to catch up – Thorbjørn Ravn Andersen Feb 22 '20 at 10:18
  • Buying another disk could be a solution. But I will lose the history of the backups. Is there a way to see debug what is wrong with the excessively long cleanup stage? – user1424739 Feb 23 '20 at 02:04
  • DiskWarrior is paid software? I am looking for a command line solution. There should be a way to inspect what is wrong with timemachine natively? – user1424739 Feb 23 '20 at 02:09
  • The other disk should be to get A time machine backup up and running so you are not as worried losing this one. To my understanding the "Cleaning up" stage removes old time machine backups from the sparse image to free up space, and apparently this is quite slow for you. I would mount the Time Machine image in Disk Tool without Time Machine actually running and repair it, just to see if any errors have been reported. – Thorbjørn Ravn Andersen Feb 23 '20 at 21:23
  • I think that there may be errors in the current backup disk. But even I can fix it with a disk tool, why there is not a way for me to see where TimeMachnie stuck? Using a different tool to fix the disk still doesn't guarantee that it can fix the problem that gets TimeMachine stuck. I also want to keep the history of the backups, is there a way to migrate the history to the new disk? – user1424739 Feb 23 '20 at 23:12
  • This reproducibly happens on my Mac-Mini m1, running latest MacOS 11.5.2 - Also with almost NO CHANGES induced by my work, and with no software/application updates (To be sure - I kept network disconnected) it chooses to backup at least 600-800 MB every time it starts backing up. Since cleanup takes hours - of course as soon as it ends, TimeMachine starts yet another backup... again this size, and so on - forever. I think the culprit is APFS on a rotational drive. This slows down things so badly - it makes TM almost unusable. – Motti Shneor Aug 28 '21 at 22:50

3 Answers3

4

I noticed that cleaning up old backups can be very slow. In my case, I can hear my external backup drive rattling along, so I know it's doing something.

You can check on progress by opening the latest backup log. Look for the directory with a name ending in .inProgress on your backup drive. Within it, open the log file with the most recent timestamp:

$ sudo less +F "/Volumes/MacBackup/Backups.backupdb/MacBook Pro/2020-08-05-163227.inProgress/.Backup.618330747.626060.log"

Substitute MacBackup, MacBook Pro and the backup/log path. If you're not familiar with less, press Ctrl-C, followed by q to exit.

The log file will tell you how much space needs to be cleared and which of the backups it's (very slowly) deleting. Looking at the amount of free space on your backup disk should give you an idea of how far along it is.

Brecht Machiels
  • 354
  • 2
  • 13
  • Apparently "Cleaning up" is possible even without a .inProgress backup and plenty of free space. My current backup has been "Cleaning up" for almost 36 hours and there is no .inProgress dir. The latest backup's Backup.log ends with "Backup complete. Total time elapsed: 14 minutes...". And my backup drive has 5TB free. I'm not sure what to make of the extended cleaning, but I see it frequently. – Jason Campbell Jul 19 '21 at 19:15
  • @JasonCampbell Can't check now, but perhaps the .inProgess directory is hidden in Finder? Did you try looking for it in a terminal (using ls -a)? – Brecht Machiels Jul 20 '21 at 07:59
  • I understood from the pathname in your answer that .inProgress is a suffix on the date-stamped backup directory's name. i.e., it's the trailing part of the name, where the dot would not cause it to be hidden. Is it a standalone .inProgress subdir enclosed in the date-stamped dir instead? Thanks! – Jason Campbell Jul 21 '21 at 09:54
  • @JasonCampbell No, it is a suffix indeed, but I can imagine that Finder still hides this "special" directory (so ls should suffice). Again, I have not verified this guess... – Brecht Machiels Jul 21 '21 at 11:58
  • Just had a chance to check. On Catalina with a long-running "Cleaning Up" in progress there is no .inProgress suffix visible, including with ls -la. The .Backup.log ends with the lines "Backup complete\nTotal elapsed time 36 minutes..." and the "Cleaning Up" has been going on for about 10 hours so far – Jason Campbell Aug 02 '21 at 07:15
  • 1
    Man, this is Macintosh. just open the log file (the Console App should do it) by either navigating and double-clicking the .log file, or in Terminal "open " instead of sudo less. looks better, can be searched better, and feels "native" for Mac users. – Motti Shneor Aug 28 '21 at 22:55
  • @MottiShneor Fair point. Note that you have to make Finder show hidden files (which is not obvious how to do). Also, I get: You do not have permission to open the document “.Backup.666883862.334847.log”. How do you get around that? – Brecht Machiels Feb 18 '22 at 17:16
  • @BrechtMachiels by "sudo open ..." In Terminal, I'd guess, but before that - I'd also scratch my head - where is that log exactly, and why is it hidden, and what permissions you need to read this log file... worth digging a bit. – Motti Shneor Feb 20 '22 at 13:46
  • Also. in newer MacOS versions, logs no longer are written as text files anywhere, but instead are written in a very-compact form into the log database, that only "Console" app and several log utilities in terminal (log show or log collect or log stream commands - man log for the lot) – Motti Shneor Feb 20 '22 at 13:48
4

Good to see you @Jason Campbell! Mine is backing up to a Synology (aptly named "Hades") and there is no "*.inProgress" anywhere in the SMB-mounted Synology folder. But there is one in my local TM snapshot folder. That, however is empty and hasn't been touched in an hour:

tkunze@zork ~ % ls -la /Volumes/Time\ Machine\ Backups/Backups.backupdb/.RecoverySets/
total 0
drwxr-xr-x  4 root  wheel  136 Aug  1 19:29 ./
drwxr-xr-x@ 6 root  wheel  204 Dec 24  2019 ../
drwxr-xr-x  3 root  wheel  102 Oct 15  2020 0/
drwxr-xr-x  2 root  wheel   68 Aug  1 19:29 1.F9D6D42C-90FB-4BFD-A7E6-44E2D39CAB88.inProgress/
tkunze@zork ~ % ls -la /Volumes/Time\ Machine\ Backups/Backups.backupdb/.RecoverySets/1.F9D6D42C-90FB-4BFD-A7E6-44E2D39CAB88.inProgress
total 0
drwxr-xr-x  2 root  wheel   68 Aug  1 19:29 ./
drwxr-xr-x  4 root  wheel  136 Aug  1 19:29 ../

Meanwhile, the TM preference panel still says "Cleaning up…". It seems backupd is still reading and writing to disk, so I upped its IO priority by running

tkunze@zork ~ % sudo sysctl debug.lowpri_throttle_enabled=0
debug.lowpri_throttle_enabled: 1 -> 0

and that made a difference. And now, as I just typed that sentence, the cleanup is done. Don't forget to revert the sudo…

leclercdumombasin
  • 161
0

I would recommend that you do not limit your log show by this predicate, which leaves just one subsystem, but rather - use predicate specifying the Process name (or path) instead. (Don't know which process does the backup - but simple inspection in Activity Monitor will tell you.

Why? because then you see log messages not just by the backup daemon itself, but also from all the Cocoa frameworks and other sub-systems it makes use of.

This is immensely more helpful, and you can quite easily see where things go wrong / slow and if there were retries.

Motti Shneor
  • 622