Why is my Time Machine backup so slow?

TomRadfahrer wrote:

Hi John Kitchen, hi MaBi,

I booted from DVD and repaired the boot volume, but there was nothing to repair. I did a repair of permissions, and there was a single file with permission errors. Disk Utility reported, that it had fixed the problem, but a 2nd repair of permissions showed the same file with the same permission errors.

There is a single file "/private/.../launchd" which cannot be repaired. You both seem to have the same problem. Maybe this is related to the Time Machine problem, or it is a completely independent effect.

I will try to chat with the Apple support.

I have this same problem

Repair permissions on the SSD gives me these messages each time I try it. So it claims to have repaired it, but I guess it gets broken again immediately ;-)

Repairing permissions for “iMacSSD”

ACL found but not expected on "private/var/db/launchd.db/com.apple.launchd".

Repaired "private/var/db/launchd.db/com.apple.launchd".

Permissions repair complete

And the TM session gets very slow on Finishing backup and Cleaning up phases. Takes some hours.

The widget says this about the previous slow backup

Starting standard backup

Backing up to: /Volumes/iMac TM/Backups.backupdb

No pre-backup thinning needed: 1.45 GB requested (including padding), 982.12 GB available

Copied 183667 files (128.9 MB) from volume iMacSSD.

Copied 311601 files (130.0 MB) from volume iMacHDD.

No pre-backup thinning needed: 1.31 GB requested (including padding), 981.61 GB available

Copied 131887 files (12.6 MB) from volume iMacSSD.

Copied 259821 files (12.6 MB) from volume iMacHDD.

Starting post-backup thinning

Deleted backup /Volumes/iMac TM/Backups.backupdb/PossumMagic/2011-06-29-104528: 981.48 GB now available

Post-back up thinning complete: 1 expired backups removed

Backup completed successfully.

And this about the one that is still trying to complete

Starting standard backup

Backing up to: /Volumes/iMac TM/Backups.backupdb

No pre-backup thinning needed: 1.61 GB requested (including padding), 981.49 GB available

Copied 183703 files (36.8 GB) from volume iMacSSD.

Copied 311646 files (38.1 GB) from volume iMacHDD.

No pre-backup thinning needed: 1.31 GB requested (including padding), 943.25 GB available

Copied 131888 files (8.3 MB) from volume iMacSSD.

Copied 259831 files (8.3 MB) from volume iMacHDD.

Hey, this WORKED!

It- frankyl- sounded a bit weird at first, but as I was desperate, I just tried it out and: two scheduled and one manually triggered backup now worked flawlessly and FAST! Wow....

I really think it's due to this deep traversal of the directories on the SSD due to a broken "event store". It would be very useful to be able to check and, if neccessary repair this database with some tool, might help many people out there with their TM problems.

Would be interesting to know, if this problem is really related to or even specific to internal SSDs?!

Anyway: all readers and posters in this thread and related threads: try it out, no matter if it sounds very unprofessional!

Cheers,

Marco

It is probably something related to the iMac with SSD, which I just bought. Backups are taking forever.. :-(

So the exact procedure is to cancel the backup at any point, restart from DVD and repair the SSD and backup disk?

I will try it but I am not getting the expected message "Stopping backupd to allow ejection of backup destination disk!" in my system.log.

NewBartleby wrote:

So the exact procedure is to cancel the backup at any point, restart from DVD and repair the SSD and backup disk?

There's an easier way to trigger a "deep traversal:" Start your Mac up from the Install disc and run Repair Disk on the SSD, then restart normally. If you're not sure how to do that, see the yellow box in #6 of Formatting, Partitioning, Verifying, and Repairing Disks.

Thanks Pondini. I did it (lesson learned: do not use a wireless keyboard), but the backup is stil acting weird (it is still working, but it took 20 minutes to backup less than 3GB, using tons of CPU). Hey now it is "preparing" again - without finishing first, and preparing again more than 100K items... 25 minutes and still goes, now struggling to backup 27 MB. Absurd.

I will try to install 10.6.8 just in case and retry the whole thing.

My iMac i7 + SSD + firewire 800 HD should be running this in no time.

Do I need to find a "deep traversal" event in the system.log, right? I cannot find it now neither there or the kernel.log.

Interesting you should mention moving to 10.6.8

It seemed to me on reflection that my issues started after going to 10.6.8. But could be a coincidence.

Getting help from Apple now who have some diagnostic data from my Mac for later analysis. May take a while, but my situation is not life-threatening 😉 so I have much patience.

NewBartleby wrote:

. . .

Do I need to find a "deep traversal" event in the system.log, right? I cannot find it now neither there or the kernel.log.

The easiest way is to use the widget in #A1 of Time Machine - Troubleshooting.

You can also filter for backupd in your system.log, via Console.

Thanks so much Pondini. I downloaded the widget.

But anyway, I can see the messages in the system.log, and there is nothing with the string "traversal" or "deep" there.

I am running out of options 😟.

I installed 10.6.8 (which may cause a deep traversal), same thing. I rebooted from DVD, repaired the SSD disk, restarted, same thing. Backups are running forever.

I am able to copy files at a high speed (+60 MB/sec) to the D2 Quadra. Firewire 800 cable should be OK.

Any ideas?

John, I had exactly the same problem with 10.6.8.

So you are still having the problem? Repair disk with DVD boot did not help?

Thanks!

NewBartleby wrote:

Thanks so much Pondini. I downloaded the widget.

But anyway, I can see the messages in the system.log, and there is nothing with the string "traversal" or "deep" there.

It's ". . . node requires deep traversal," sent by the backupd process. Why that's not triggered by starting from your SL disc and doing a Repair Disk on your SSD, I have no idea. 😟

You mgiht try cancelling a backup, once it's started copying, then starting another backup.

NewBartleby wrote:

John, I had exactly the same problem with 10.6.8.

So you are still having the problem? Repair disk with DVD boot did not help?

I booted from an external drive with a clone of my system disk so I could repair the SSD resident system partition. Also repaired the HDD internal, and the Time Machine external. None showed any need for repair.

Rebooted again from SSD and manually initiated a Time Machine backup. It took 3 hours, 39 minutes. The quantity of data backed up was trivial. The logs are confusing, I'll paste them below. The Finishing backup phase took 2 hours 10 minutes, followed by a slow Clean up.

Here is the log. I am deeply suspicious of the log, since the amount of data backed up from SSD and HDD is identical. Twice. See the bold numbers below.

Starting standard backup

Backing up to: /Volumes/iMac TM/Backups.backupdb

No pre-backup thinning needed: 2.34 GB requested (including padding), 942.38 GB available

Copied 183761 files (43.0 MB) from volume iMacSSD.

Copied 311704 files (43.0 MB) from volume iMacHDD.

No pre-backup thinning needed: 1.30 GB requested (including padding), 942.25 GB available

Copied 131896 files (42.1 MB) from volume iMacSSD.

Copied 259839 files (42.1 MB) from volume iMacHDD.

Starting post-backup thinning

Deleted backup /Volumes/iMac TM/Backups.backupdb/iMacName/2011-06-29-074504: 942.14 GB now available

Post-back up thinning complete: 1 expired backups removed

Backup completed successfully.

PS I'm also troubled by the line that says a backup was deleted. I can't see why this would happen, since there is nearly a terabyte of free space in the partition.

Message was edited by: John Kitchen - added post script

Sorry John, I meant I had the same problem with 10.6.7 also.

(stupid newbie question: how do you copy a portion of the post you are replying to? I mean, to cite... nothing I tried worked... this is surely not my day!)

John Kitchen wrote:

. . .

Here is the log. I am deeply suspicious of the log, since the amount of data backed up from SSD and HDD is identical. Twice

That does happen sometimes with multiple partitions. It appears to be just some reporting glitch.

Post-back up thinning complete: 1 expired backups removed

Backup completed successfully.

PS I'm also troubled by the line that says a backup was deleted. I can't see why this would happen, since there is nearly a terabyte of free space in the partition.

That's an "expired" backup. Time Machine doesn't keep all backups until space runs out; it "thins" them according to the schedule on the TM Prefs panel. It keeps all for 24 hours, then one per day for a month, then one per week as long as there's room.

The one it deleted was over 24 hours old: 2011-06-29-074504

John Kitchen wrote:

Here is the log. I am deeply suspicious of the log, since the amount of data backed up from SSD and HDD is identical. Twice. See the bold numbers below.

Well at least figured out how to quote :-)

For what is worth, here is my log. As you see the same thing happens in mine.

Nothing similar to ". . . node requires deep traversal," in my whole system.log

Jul 1 20:24:38 raul_imac com.apple.backupd[826]: Starting standard backup

Jul 1 20:24:44 raul_imac com.apple.backupd[826]: Backing up to: /Volumes/Backup New (D2 1TB)/Backups.backupdb

Jul 1 20:25:09 raul_imac com.apple.backupd[826]: Waiting for index to be ready (100)

Jul 1 20:29:21 raul_imac com.apple.backupd[826]: No pre-backup thinning needed: 7.36 GB requested (including padding), 594.05 GB available

Jul 1 20:46:25 raul_imac com.apple.backupd[826]: Copied 481930 files (4.6 GB) from volume Mac SSD.

Jul 1 20:48:16 raul_imac com.apple.backupd[826]: Copied 590896 files (4.6 GB) from volume Mac HD Datos.

Jul 1 20:52:33 raul_imac com.apple.backupd[826]: No pre-backup thinning needed: 2.56 GB requested (including padding), 588.81 GB available

Jul 1 21:07:26 raul_imac com.apple.backupd[826]: Copied 481764 files (2.1 GB) from volume Mac SSD.

Jul 1 21:09:12 raul_imac com.apple.backupd[826]: Copied 590730 files (2.1 GB) from volume Mac HD Datos.

Jul 1 21:23:06 raul_imac com.apple.backupd[826]: Stopping backupd to allow ejection of backup source disk!

Jul 1 21:23:07 raul_imac com.apple.backupd[826]: Backup deletion was canceled by user

Jul 1 21:23:07 raul_imac com.apple.backupd[826]: Starting post-backup thinning

Jul 1 21:23:07 raul_imac com.apple.backupd[826]: Backup completed successfully.

BTW, I never canceled a backup deletion.

It took one hour for something my old Core 2 Duo iMac used to take minutes. And yes, I am suspicious too.

I canceled one backup (again) in the middle of the writing and also I am repairing my HDD (which I have never done). Who knows... I'll try again then...

EDITED: I did cancel the backup since I started repairing the backup disk, so that triggered that message.