What is Time Machine doing?

Question

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.

Solution 1

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.

Solution 2

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)

Solution 3

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!

Solution 4

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...

View more solutions

Comments

[Matt Bettiol]

+1 - excellent article!

[Stephen Darlington]

Great article. Wish I could mark two answers as accepted!

[Arjan]

Ars Technica has another good article, but I guess the Earthling Soft link has covered all: arstechnica.com/apple/reviews/2007/10/mac-os-x-10-5.ars/14 And for developers reading this: see a hands-on at developer.apple.com/mac/articles/cocoa/filesystemevents.html

[Arjan]

Actually, the logs are not just used by Time Machine. And it's your Mac that can declare the old logs invalid. You can search Console for fseventsd to see "events log in /Volumes/.. out of sync with volume. destroying old logs." A newly created log will also have a new identifier, which will no longer match the id stored with the backup. This tells Time Machine to compare your harddisk against the last backup. If one uses multiple backup disks, then if fseventsd created a new log, then Time Machine will eventually run into a "Event store UUIDs don’t match" for each backup disk.

[Arjan]

Some software may exclude itself from the Time Machine backup, by setting the extended attribute com.apple.metadata:com_apple_backup_excludeItem on its files. Like pre-1.1.2 versions of VMware Fusion: blogs.vmware.com/teamfusion/2008/04/vmware-fusion-1.html See also 10.5: Show files that Time Machine does not back up at macosxhints.com/article.php?story=20080328025026826 which includes a link to Time Machine Exclusions at shiftedbits.org/2007/10/31/time-machine-exclusions

[Arjan]

See superuser.com/questions/35152/… for more details on running Time Machine as root in Snow Leopard.

[Brant]

Mounting the drive in Windows using a read/write filesystem driver such as MacDrive will also trigger a full file system scan the next time Time Machine backs it up. (Mounting the drive using the read-only filesystem driver in Boot Camp, on the other hand, does not)