What is Time Machine doing?
Sometimes OS X tells me that it's "Preparing backup..." for an enormous amount of time. The time it takes seems to have no correlation to the amount of data to be backed up. Same for the "Finishing backup..." stage.
The question: what is OS X doing when it's "Preparing backup..." and "Finishing backup..."?
I know it's figuring out what to backup and then recording the changes, but surely the time this takes should be proportional to the amount of data that changed. There's plenty of space disk space (so I assume it's not deleting old backups). I'm using a TimeCapsule if that makes any difference. Nothing is going wrong with it, I'm just curious.
Here is an answer from another forum (original poster unknown to me):
The "preparing" stage in Time Machine is usually fast, because Time Machine uses a log of file system activities to know where to find changes that need to be backed up.
But there are things you can do to make that log untrustworthy. When Time Machine discovers the log MIGHT not be valid, it does a full scan of your file system to determine what really needs to be backed up. This can take a while. On my Powerbook (and with a firewire external Time Machine drive) it can result in a "preparing" stage that lasts 20 minutes. If you let Time Machine continue, it will eventually figure out what really needs to be added to the backup disk and will continue. This, of course, is better than just gambling the log is correct or just backing up EVERYTHING again even though only a few files might actually have changed (which would take much longer and consume more Time Machine disk space).
In these early days of Leopard installs, one of the most common things you can do that will make the log untrustworthy is booting from the Leopard install DVD. Each time you do that, the next time Time Machine runs it will discover that your hard drive MIGHT have been modified without the changes being reflected in the log. So it does the full scan -- a long "preparing" stage -- to insure it gets things right.
To compliment Commander Keen's answer I recommend reading an in depth look at Time Machine by Earthling Soft. Additionally more information is logged to system.log by backupd (which will say why the preparing status is so long and such)
To easily view the backupd log take a look at the Time Machine Buddy widget. Also note that there's another log on the backup disk itself, in the hidden file .Backup.log which can be found in the folder of each backup. This gives some other information than the backupd logs.
Note that often the logs show figures that do not seem to match:
No pre-backup thinning needed: 821.4 MB requested (including padding) [..] Copied 1630 files (3.8 MB) from volume Macintosh HD.
Above, fewer files are actually copied than first predicted. As Time Machine relies on FSEvents which only reports changed directories, I assume that in the above example these directories held a total of 821.4 MB in files. While actually copying the files, Time Machine then compares the changed directories on the hard disk with the backup, and finds that only 3.8 MB files were actually changed.
To see what has been written to the backup see TimeTracker (GUI) or timedog (command line). Note that, even when running as an admin user, sometimes these programs need to be run as root to see all files. When not doing that, these tools might for example not take the backups of MySQL logs and data into account, owned by _mysql in group wheel:
cd "/Volumes/Backup of XX/Backups.backupdb/XX/Latest" sudo ls -l "Macintosh HD/usr/local/mysql-5.0.51a-osx10.5-x86" [..] drwxr-x---@ 6 _mysql wheel 374 Jul 2 20:05 data
In those cases both tools will (silently) report a lower total backup size and fewer files than the backupd logs in Console. So, if the numbers don't match with the logs, then for TimeTracker:
sudo ~/Downloads/TimeTracker.app/Contents/MacOS/TimeTracker
Likewise, for timedog:
cd "/Volumes/Backup of XX/Backups.backupdb/XX" sudo ~/Downloads/timedog
To easily find large files on your hard disk see Disk Inventory X. This program has nothing to do with Time Machine, but may help investigating problems, like when you wonder why your backup is a lot smaller than the space used on your hard disk. Note that this program will probably always report less total disk space in its window title than in its screen where one can select which disk to investigate (even when running as root and choosing menu View, Show Physical File Size). But if the reported total size is really a lot smaller than the actual totals used on your Mac, then it may help to run as root:
sudo "$HOME/Downloads/Disk Inventory X.app/Contents/MacOS/Disk Inventory X"
To remove files from the backup (like if you happen to discover that Time Machine was actually backing up some huge files, such as a runaway MySQL log file), Apple writes:
Want to delete all instances of a file or folder previously backed up? Easy enough. Launch Time Machine, select the item to be deleted, then choose "Delete from all backups" from the action menu in the Finder toolbar.
Now, if those files that you want to delete are only visible to root, then you should invoke "Enter Time Machine" as root as well. And that requires Finder to be started as root first:
sudo /System/Library/CoreServices/Finder.app/Contents/MacOS/Finder
This looks like a normal Finder, but you'll notice root next to the home folder icon in Finder's sidebar. Now use Shift-Cmd-G (menu Go, Go to Folder) to get to, for example, /usr/local and find the folder from which you want to delete the files from the backup disk. Next, enter Time Machine (and once again validate that root is shown next to the home folder icon) and follow Apple's instructions. When done deleting the files from the backup, hit Ctrl-C in Terminal to stop the root-Finder. (I also needed to log off my Mac as the remote disk would not unmount properly.)
If you are using a sparse bundle (like when using a backup on the network) then any freed space will not be reclaimed automatically (or: not until the space is needed). To enforce this, see How to reclaim all/most free space from a sparsebundle on OS X. This does not only apply to files you removed manually, but also to files removed by Time Machine for expired hourly or daily backups, during post-backup thinning.
Time Machine will actually compact the sparse bundle itself, when disk space runs out. But it seems it might first delete some old backups during pre-backup thinning, so maybe it's wise to manually compact if you ever deleted some huge files, or if expired backups might have included huge files:
Starting pre-backup thinning: 53.57 GB requested (including padding),
9.90 GB available
No expired backups exist - deleting oldest backups to make room
Deleted backup /Volumes/Backup of XX/Backups.backupdb/XX/2007-12-20-172543:
9.90 GB now available
Deleted backup /Volumes/Backup of XX/Backups.backupdb/XX/2007-12-31-005523:
9.90 GB now available
Deleted 2 backups: oldest backup is now 8 Jan 2008
Stopping backup.
Backup canceled.
Ejected Time Machine disk image.
Compacting backup disk image to recover free space
Completed backup disk image compaction
Starting standard backup
[..]
Starting pre-backup thinning: 53.57 GB requested (including padding),
12.75 GB available
Many thanks to Adam Cohen-Rose for testing the above; see his blog for more details!
When stuck in "Preparing" (ThinningPreBackup)
root# tmutil status
Backup session status:
{
BackupPhase = ThinningPreBackup;
ClientID = "com.apple.backupd";
DateOfStateChange = "2018-10-20 12:02:54 +0000";
DestinationID = "XXXXXX0A-1XB7-4X3B-A791-6XXXXX4325D89B";
DestinationMountPoint = "/Volumes/TimeMachineXXX";
Percent = "-1";
Running = 1;
Stopping = 0;
}
Use lsof (be sure to run this as root) to see what files the backups are access - the last file should be changing:
root# ps -ef | grep backupd
0 91 1 0 9:39pm ?? 0:00.15 /System/Library/CoreServices/backupd.bundle/Contents/Resources/backupd-helper -launchd
0 552 1 0 9:59pm ?? 0:49.54 /System/Library/CoreServices/backupd.bundle/Contents/Resources/backupd
0 1244 1156 0 10:30pm ttys003 0:00.01 grep backupd
root# lsof -p 552
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
backupd 552 root cwd DIR 1,4 1292 2 /
backupd 552 root txt REG 1,4 769168 67640888 /System/Library/CoreServices/backupd.bundle/Contents/Resources/backupd
backupd 552 root txt REG 1,4 26771408 67698052 /usr/share/icu/icudt59l.dat
backupd 552 root txt REG 1,4 236208 67730774 /private/var/db/timezone/tz/2018e.1.0/icutz/icutz44l.dat
backupd 552 root txt REG 1,4 841456 67695858 /usr/lib/dyld
backupd 552 root txt REG 1,4 1174183936 69140457 /private/var/db/dyld/dyld_shared_cache_x86_64
backupd 552 root 0r CHR 3,2 0t0 306 /dev/null
backupd 552 root 1u CHR 3,2 0t0 306 /dev/null
backupd 552 root 2u CHR 3,2 0t0 306 /dev/null
backupd 552 root 3w REG 1,9 686 5515544 /Volumes/TimeMachine2/Backups.backupdb/XXXXXXXXXX/2018-10-20-220254.inProgress/.Backup.561729775.162983.log
backupd 552 root 4r DIR 1,4 136 68977542 /Applications/Xcode.app/Contents/Developer/Platforms/AppleTVOS.platform/Developer/Library/CoreSimulator/Profiles/Runtimes/tvOS.simruntime/Contents/Resources/RuntimeRoot/System/Library/Frameworks/CoreLocation.framework/English.lproj
This indicates it is doing something - and to be patient...