Why is my Time Machine backup so slow?

Pondini wrote:

<snip> And by all means, report back. If there's a fix, please give us the details, so others may benefit.

I don't have a fix yet, but may have eliminated a possible cause.

Apple rep suggested I uninstall another backup app which I use. CrashPlan.

I've never had any conflict between Time Machine and CrashPlan before, but worth a try, so I have uninstalled, rebooted, and tried to run another Time Machine backup.

Been running for 80 minutes so far, and "stuck" in "Finishing Backup...", so it looks like CrashPlan was not the culprit.

John Kitchen wrote:

. . .

Been running for 80 minutes so far, and "stuck" in "Finishing Backup...", so it looks like CrashPlan was not the culprit.

Hi, John,

Did the backup seem to be ok before it got to "Finishing Backup"?

It may be having trouble deleting old backups. We have seen that a few times, where there was some sort of problem that did eventually get fixed, but apparently the backups made during the problem were difficult or impossible for Time Machine to delete. Repair Disk didn't fix whatever it was. Once the older ones got deleted, backups ran normally again.

See if there are any messages in the log about deletions, especially "found partially deleted backup, trying again."

If so, try deleting that one manually, per #12 in Time Machine - Troubleshooting.

Everything seems OK, just very slow, with a lot of disk activity.

Here is the log, from which you can see how long it took for each phase

I get really suspicious about what is going on because the number of files copied is about the same in EVERY successful backup. You can see four lines of text below. Each time, the number is less than 1,000 different from the previous backup. Usually the amount of data backed up from the SSD and the HDD are identical.

Jul 9 08:32:27 MyMac com.apple.backupd[466]: Starting standard backup

Jul 9 08:32:27 MyMac com.apple.backupd[466]: Backing up to: /Volumes/iMac TM/Backups.backupdb

Jul 9 08:36:38 MyMac com.apple.backupd[466]: No pre-backup thinning needed: 3.94 GB requested (including padding), 885.93 GB available

Jul 9 08:58:37 MyMac com.apple.backupd[466]: Copied 183752 files (2.0 GB) from volume iMacSSD.

Jul 9 09:03:16 MyMac com.apple.backupd[466]: Copied 311395 files (2.0 GB) from volume iMacHDD.

Jul 9 09:09:17 MyMac com.apple.backupd[466]: No pre-backup thinning needed: 1.64 GB requested (including padding), 883.88 GB available

Jul 9 09:32:10 MyMac com.apple.backupd[466]: Copied 131654 files (45.3 MB) from volume iMacSSD.

Jul 9 09:37:41 MyMac com.apple.backupd[466]: Copied 259295 files (71.6 MB) from volume iMacHDD.

Jul 9 10:25:18 MyMac com.apple.backupd[466]: Starting post-backup thinning

Jul 9 10:55:22 MyMac com.apple.backupd[466]: Deleted backup /Volumes/iMac TM/Backups.backupdb/MyMac/2011-07-07-142259: 883.99 GB now available

Jul 9 10:55:22 MyMac com.apple.backupd[466]: Post-back up thinning complete: 1 expired backups removed

Jul 9 10:55:23 MyMac com.apple.backupd[466]: Backup completed successfully.

John Kitchen wrote:

. . .

I get really suspicious about what is going on because the number of files copied is about the same in EVERY successful backup.

I think that's some odd reporting problem; we see it on occasion with multiple drives on otherwise-normal backups. And the number of files is always much higher than makes any sense. I suspect it may be counting every extended attribute, and perhaps every ACL and permission, separately, but yours are still huge.

But you're right: everything is slow:

4 minutes to see how much needs to be backed up (without a deep traversal)

22 minutes to back up 2 GB from the SSD

5 minutes to back up whatever it actually backed-up from the HD

6 minutes to decide how much needs to be backed-up for the second pass

25 minutes to back up 45 MB from the SSD

5 minutes to back up 72 MB from the HD

48 minutes to . . . decide to start post-backup thinning (should be a couple of seconds at most)

30 minutes to delete a backup (a small one, as it only gained 110 MB).

Are there any other messages in the log while this was going on, from other processes, that look suspicious?

ps: here's another thread with similar problems, also with AppleCare involved: https://discussions.apple.com/thread/3163423?tstart=0

This isn't a reporting problem. If you run timedog on your backup (without the -l option) you will see that TimeMachine is incorrectly re-linking tens-of-thousands of files that haven't changed. It does this if it thinks at least one file in the directory has changed, but it hasn't. This is the root of the problem. You might be able to get this to work again by deleting the /.fseventsd directory on your volumes and restarting. This will force a deep traversal because that's where the "what changed since last time" information is stored. I have the exact same problem on my brand new iMac 27" i7 SSD+HD system and have not solved it.

The log shows a lot of Aperture messages (over 2,000), but only for 6 minutes between 10:45:42 and 10:51:25 which overlaps some of the final phases of the backup, but nothing which would explain slowness over the entire period.

Most of the time during this backup, I had pretty much nothing running and very few messages show in system.log

Another interesting data point: I had my old iMac plugged into my new SSD one to transfer files (FireWire target disk mode). Now the old iMac is having exactly the same problem. So there appears to be something about the SSD+HD iMacs that is causing drives to be corrupt in such a way that TimeMachine doesn't work too well. (I deleted .fseventsd on the old iMac but that didn't help.)

david-se wrote:

This isn't a reporting problem.

This particular one may or may not be.

We've seen several threads where the log showed 2 volumes with exactly the same (very large) number of files and GBs backed-up, when that clearly was not the case. Not just SSD + HD, either; some were 2 HDs. Others with ridiculously large numbers of files, but very little data, on reasonably-quick backups.

And you have to be careful with apps like TimeDog, Time Tracker, and Backup Loupe; they compare two backups, and don't always get it right.

The most extreme example is, change the name of a volume that was just backed-up, then run another backup. Very little will be backed-up, but those apps will show a whole new backup of the "new" drive (they must be looking at the names, not the UUIDs).

Just another complication to figuring out what's going on. 😟

I would encourage anyone who is having issues with slow Time Machine in conjunction with it apparently backing up a huge number of files to report this by phone to Apple.

Interesting experiment.....

I tried waiting for a successful completion of a Time Machine backup, followed by an immediate restart and kicked off Time Machine backup again with almost no apps running (except Activity Monitor and Console).

Time Machine found over 800,000 changed files to back up! (but with very little total data)

PS Apple engineers are looking at the logs etc

I filed a bug for this (radar://9749304) and it was closed as a duplicated of radar://6071017, which is marked as closed. I don't have any further visibility, but that means that they are aware of this at the engineering level. Whether this has been prioritized as important is a completely different question, and one which we are unlikely to ever get an answer for.

I can confirm that the slowdown is an issue specific to SSD.

When I excluded the SSD (boot) volume and only backed up the 2TB HDD, incremental backups came down to 11 or 12 minutes.

Aha! Suspicious confirmed.

How much was backed-up in that 11 or 12 minutes, and forgive me, I've forgotten what you're backing-up to?

Pondini wrote:

Aha! Suspicious confirmed.

How much was backed-up in that 11 or 12 minutes, and forgive me, I've forgotten what you're backing-up to?

How much was backed up? According to the system.log it was 756 bytes. But it was 127,677 files! That makes it an average of 0.05 bits per file! But it does it twice every backup cycle.

My backup device is either of two external USB drives. They both behave the same way.

Here is the log for your entertainment

Jul 19 08:38:11 MyiMac com.apple.backupd[6207]: Startingstandard backup

Jul 19 08:38:11 MyiMac com.apple.backupd[6207]: Backing upto: /Volumes/WD Elements/Backups.backupdb

Jul 19 08:38:49 MyiMac com.apple.backupd[6207]: Nopre-backup thinning needed: 100.0 MB requested (including padding), 444.28 GBavailable

Jul 19 08:41:37 MyiMac com.apple.backupd[6207]: Copied127677 files (756 bytes) from volume iMacHDD.

Jul 19 08:42:40 MyiMac com.apple.backupd[6207]: Nopre-backup thinning needed: 100.0 MB requested (including padding), 444.27 GBavailable

Jul 19 08:44:43 MyiMac com.apple.backupd[6207]: Copied127677 files (756 bytes) from volume iMacHDD.

Jul 19 08:49:50 MyiMac com.apple.backupd[6207]: Startingpost-backup thinning

Jul 19 08:49:50 MyiMac com.apple.backupd[6207]: No post-backup thinning needed: no expired backups exist

Jul 19 08:49:51 MyiMac com.apple.backupd[6207]: Backupcompleted successfully.

PS I guess if the average file size is 0.05 bits, there are probably some even smaller files being backed up 👿

Message was edited by: John Kitchen - added PS

I don't think that solved it. A time machine backup with few changes (e.g., choose backup now twice in a row) should take about 30 seconds and should only list 10-20 files that changed. The 11-12 minutes is about 20x longer than it should be taking, so I think you're still having the same problem. There is some reason to believe this will be solved with Lion, but we shouldn't have to update the OS to get the computer to work as advertised.

So the problem is far from solved. 😟 Just the impact is reduced.

It appears to be backing-up the same stuff (whatever it is) on both passes.

Try TimeTracker or BackupLoupe; see if it bears any resemblance to the messages.

Also . . . it looks like many of the spaces have disappeared from the log messages; is that the way they appear, or is it just a problem copying, pasting, or displaying them here?