Time Machine Bogs Down System

Download the +Time Machine Buddy+ widget. It lists the logs of recent TM backups in a small window. Run a backup, then copy & paste the full log info here (the lines may overflow the window, so try to get them all!).

~Lyssa

Upgrade to 10.5.6 (or change your signature).

Other than the ridiculous amount of time involved, that's a mostly-normal backup. The other odd thing, that we do see sometimes, is the huge number of files it claims to have copied.

Unfortunately, several things can cause what you're seeing:

Exclude your TM disk/partition from any anti-virus scanning.

Also exclude it from Spotlight, at least temporarily, via System Preferences > Spotlight > Privacy.

Is your disk a USB 2.0 version?

Is it plugged-in to one of the ports on the back of your iMac (and not through a USB hub)?

When you first got it, did you erase and format it before using it with TM? If so, has it always been this slow, or is this recent behavior?

Are you running FileVault or any virtualization software?

USB 2.0 is slow compared to Firewire 400. Do some google searches for comparisons if you don't believe me. You say that your CPU bogs down when using TM? That sounds right if you're using USB. USB transactions have to be arbitrated and controlled by the CPU, whereas Firewire does not have that requirement. If your drive has a firewire port use that otherwise upgrade your drive. Costco has 750GB Maxtor FW/USB2.0 drive for $99 right now.

That's all true, but there's still something else wrong here.

48 minutes to copy 1.6 MB is just silly.

I completely disagree that this is "mostly-normal". Note very carefully the enormous number of files compared to the relatively tiny size of the backed up data.

I have a very similar situation causing me no end of headache. To wit:

byakhee-2:log groo$ grep 'backupd.*Backup completed\|Starting standard\|Copied' system.log | sed -e 's/byak.*://' -e 's/from volu.*$//'
Apr 16 00:54:34 Starting standard backup
Apr 16 01:32:04 Copied 58906 files (6.1 MB)
Apr 16 02:00:16 Copied 52969 files (5.7 MB)
Apr 16 02:50:39 Backup completed successfully.
Apr 16 04:54:35 Starting standard backup
Apr 16 05:28:28 Copied 53033 files (6.0 MB)
Apr 16 05:56:17 Copied 52984 files (5.8 MB)
Apr 16 06:42:08 Backup completed successfully.
Apr 16 08:54:35 Starting standard backup
Apr 16 09:29:58 Copied 53053 files (6.0 MB)
Apr 16 09:58:06 Copied 52995 files (5.8 MB)
Apr 16 10:41:02 Backup completed successfully.
Apr 16 12:54:35 Starting standard backup
Apr 16 13:29:54 Copied 63058 files (10.3 MB)
Apr 16 13:59:15 Copied 53026 files (6.9 MB)
Apr 16 14:41:39 Backup completed successfully.
Apr 16 16:54:35 Starting standard backup
Apr 16 17:32:36 Copied 60798 files (10.1 MB)
Apr 16 18:00:04 Copied 53577 files (5.4 MB)
Apr 16 18:46:14 Backup completed successfully.
Apr 16 20:54:36 Starting standard backup
Apr 16 21:30:01 Copied 59726 files (9.7 MB)
Apr 16 22:00:11 Copied 59223 files (6.9 MB)
Apr 16 22:45:34 Backup completed successfully.
Apr 17 08:37:49 Starting standard backup
Apr 17 09:10:25 Copied 66158 files (22.0 MB)
Apr 17 13:23:55 Starting standard backup
Apr 17 14:03:23 Copied 69995 files (19.7 MB)
Apr 17 14:31:57 Copied 58989 files (7.9 MB)
Apr 17 15:34:56 Backup completed successfully.
Apr 17 17:23:56 Starting standard backup
Apr 17 17:54:59 Copied 64839 files (154.8 MB)
Apr 17 18:18:46 Copied 58487 files (4.8 MB)
Apr 17 18:57:33 Backup completed successfully.
Apr 17 21:23:56 Starting standard backup
Apr 17 21:54:13 Copied 59957 files (7.8 MB)
Apr 17 22:17:53 Copied 58498 files (7.1 MB)
Apr 17 22:52:32 Backup completed successfully.


Now, if I examine the delta between the time machine backups with the very handy "tms" utility, I note that only a few HUNDRED files actually comprise the delta. the abbreviated logs above are from my MBP. My Mac Mini correctly reports the number of files in its backupd logs and they match the number of files which appear in the "tms" delta for the backup.

Something is clearly not right.

His backup makes this so much more clear than mine, even. Look at this log message:

---
Copied 89072 files (1.0 MB) from volume Macintosh HD.
---

So he has NINETY-THOUSAND files of size <12 bytes that got changed between backups?

brd1207 wrote:
I am using an Iomega 500GB HDD purchased at a Mac store in December 2007.

It is connected with USB 2.0 directly to the back of my mac. The problem has been noticeable for a long time. I have been paying more attention lately and now want to figure out what is going on.

I am not running firevault or any other virtualization software.

And it's excluded from anti-virus and Spotlight?

Bill Squier wrote:
I completely disagree that this is "mostly-normal". Note very carefully the enormous number of files compared to the relatively tiny size of the backed up data.

Yes, as posted:

Other than the ridiculous amount of time involved, that's a mostly-normal backup. The other odd thing, that we do see sometimes, is the *huge number of files it claims to have copied.*

In other threads where we've seen this, backup times have been relatively normal. Whatever is causing these spurious messages does not appear to be related to the extremely slow backups.

On occasion, a "complete reset" will fix that, and other things as well:

Turn TM off, deselect the drive (select "none"), note any exclusions, quit System Preferences.

Delete the file: /Library/Preferences/com.apple.TimeMachine.plist (this is in the top-level /Library folder, not your home folder).

Eject, disconnect, and power-off the TM drive for a few moments.

Power-up and connect the drive.

Go back into TM Preferences, re-select the drive, re-enter any exclusions, turn TM back on and/or do a +Back Up Now.+

On occasion, doing a +Verify Disk+ (not permissions) on the boot drive (via Disk Utility, in your Applications/Utilities folder) will show errors. If so, you must boot from your Leopard Install disc and use it's copy of DU to do a +Repair Disk+ since you can't repair the disk you're running from.

brd1207 wrote:

Spotlight is now excluded from disk.

Anti-virus, too, I assume?

First backup post reset looks like this: It took 2hours 57 minutes.

Ridiculous. Even worse as it's F/W.

Event store UUIDs don't match for volume: Macintosh HD
Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|

These justify some additional time, in the "preparing" phase, but I'd guess a max of about 90 minutes.

Normally, the UUID message (when it refers to your internal) happens after an improper shutdown, certain hardware repairs, a full restore, or going several days without a completed backup. It means that TM can't trust OSX's "Event Log" of changes to the file system on that disk, so it has to examine every file and folder on your system to figure out what's changed and needs to be saved.

Let's try to see if it's an internal OSX/TM problem, or a problem with or communicating with your drive:

Find a large file on your internal HD, copy it to your TM drive, and time it. Then copy it back (to another location) and time that. This should be faster than TM copying a lot of smaller files, but may give us a sense of where the problem actually is. Post back with the size of the file and both times.