Time machine is very slow

I will try TimeTracker. But I should mention that when I did a recent Silverkeeper backup (for the first time in a few weeks), its log file showed only 11000 files backed up. So I very much doubt that the 200,000-file number in the log file is correct.

And why are there two entries -- one for 215,000 files and one for 5400 files? Maybe this is normal... but it still comes to my eye.

I will report after trying TimeTracker.

I know of no app I'm running that could be touching such a large number of files.

Thanks... I'll report back when I have TimeTracker info.

-P.

wchlm wrote:
I know of no app I'm running that could be touching such a large number of files.

Thanks... I'll report back when I have TimeTracker info.

TimeTracker from VersionTracker has nothing to do with Time Machine; rather, it's a personal productivity/time-reporting tool. There is a TimeTracker from charlessoft.com that I found a link to on the web; that appears to be what you're thinking of; but charlessoft.com no longer exists.

However, I did find "timedog", a Perl script that does the following (to quote its top-level comment):

# Display the files which time machine backed up in its most recent
# backup (or any of your choosing). Uses the fact that Time Machine
# creates hard links for unchanged files and directories. Reports old
# and new sizes, along with the total file count and backup size.


timedog run on the latest backup reports the following summary, after listing all the files:

==> Total Backup: 1042 changed files, 69.27MB

This latest backup was subsequent to the one I first reported; in the syslog, the latest backup shows the following. There appears to be a huge discrepancy between what Time Machine claims it is backing up and what timedog claims Time Machine is backing up.

--
Jan 11 17:10:56 shenkin /System/Library/CoreServices/backupd[76902]: Starting standard backup
Jan 11 17:10:56 shenkin /System/Library/CoreServices/backupd[76902]: Backing up to: /Volumes/Time Machine Bak/Backups.backupdb
Jan 11 17:16:23 shenkin /System/Library/CoreServices/backupd[76902]: No pre-backup thinning needed: 796.2 MB requested (including padding), 446.50 GB available
Jan 11 17:57:22 shenkin /System/Library/CoreServices/backupd[76902]: Copied 219685 files (62.0 MB) from volume Macintosh HD.
Jan 11 18:03:27 shenkin /System/Library/CoreServices/backupd[76902]: No pre-backup thinning needed: 739.9 MB requested (including padding), 446.43 GB available
Jan 11 18:39:46 shenkin /System/Library/CoreServices/backupd[76902]: Copied 187369 files (17.7 MB) from volume Macintosh HD.
Jan 11 18:52:43 shenkin /System/Library/CoreServices/backupd[76902]: Starting post-backup thinning
Jan 11 19:14:46 shenkin /System/Library/CoreServices/backupd[76902]: Deleted backup /Volumes/Time Machine Bak/Backups.backupdb/shenkin /2009-01-10-120628: 446.39 GB now available
Jan 11 19:14:46 shenkin /System/Library/CoreServices/backupd[76902]: Post-back up thinning complete: 1 expired backups removed
Jan 11 19:14:47 shenkin /System/Library/CoreServices/backupd[76902]: Backup completed successfully.

Pondini wrote:
One other thought: How long have you been on 10.5.6,

Some months.

and how did you install it?

Downloaded software update.

I didn't start using TM till quite a while after the update.

A different, but equally-strange problem in another thread was solved by downloading and installing the Combo update.

Might be worth a try in your case, as well.

What is the Combo update, and where do I get it?

Thanks,
-P.

Pondini wrote:
The "combo" update contains all the changes from the original issue of Leopard in one big package. Thus loading it should fix anything that went wrong in any previous update.

It's possible that some small item was missed or somehow messed-up (pardon the technical term!) on one of your past updates, but never caused a problem because you weren't using TM.

The update and info are at: http://support.apple.com/downloads/MacOS_X_10-5-6_ComboUpdate

It's a big one (668 mb), so allow yourself plenty of time.

Thanks. That's useful. By the way, when I did the upgrade, the "tar" utility disappeared -- others have seen this as well. I had to install it from some other place (I forget where -- the original Leopard disk, maybe).

Since my current system disk is nearly full, I will probably wait about a week before I do this. I want to add a drive.

Pondini wrote:
TimeTracker is back!

Very neat little app, shows what was backed-up (hidden files and all) on each TM backup.

http://www.charlessoft.com/

Thanks. I've downloaded and installed it. TimeTracker shows 31.9 Mb backed up in the most recent backup; system log shows the following; the way I read the system log, it seems to say that 31.7+17.8 = 49.5 Mb were backed up. System log is still claiming 200000+ files backed up; though TimeTracker doesn't give a summary wit the number backed up, going through the folders it displays makes it clear that it's nothing like that; maybe 1000 at the most.

The good news here is that this latest backup took a half hour -- less than earlier ones.

--
Jan 17 21:20:50 shenkin /System/Library/CoreServices/backupd[10924]: Backing up to: /Volumes/Time Machi
ne Bak/Backups.backupdb
Jan 17 21:24:52 shenkin /System/Library/CoreServices/backupd[10924]: No pre-backup thinning needed: 767
.0 MB requested (including padding), 444.38 GB available
Jan 17 21:50:15 shenkin /System/Library/CoreServices/backupd[10924]: Copied 204564 files (31.7 MB) from
volume Macintosh HD.
Jan 17 21:50:22 shenkin /System/Library/CoreServices/backupd[10924]: No pre-backup thinning needed: 750
.2 MB requested (including padding), 444.35 GB available
Jan 17 21:50:42 shenkin /System/Library/CoreServices/backupd[10924]: Copied 763 files (17.8 MB) from vo
lume Macintosh HD.
Jan 17 21:50:47 shenkin /System/Library/CoreServices/backupd[10924]: Starting post-backup thinning
Jan 17 21:50:47 shenkin /System/Library/CoreServices/backupd[10924]: No post-back up thinning needed: n
o expired backups exist
Jan 17 21:50:47 shenkin /System/Library/CoreServices/backupd[10924]: Backup completed successfully.

By the way, for this same backup, timedog's summary shows the following:

==> Total Backup: 189 changed files, 38.37MB

-P.

Pondini wrote:
Glad to hear it's improved, but you've still got something wrong.

...

Since most of the time appears to have been spent copying the first group of files (21:24 to 21:50), it calculates to about 32 mb in 25 minutes! You could fax it faster!

And the huge file counts make no sense either.

...

Are there any other messages in your log for this period?

Do you mean while TM is running? Generally not at all. I get sporadic messages like the following, and occasionally one or two will occur while backups are going on, but I presume this is benign; and besides, even when none of these occurs during the operation of TM, I still see the problem.

Jan 18 09:32:59 shenkin Mail[12651]: * Failed to decode 8-bit data, treating as binary
Jan 18 09:33:03 shenkin mdworker[12647]: * Failed to decode 8-bit data, treating as binary

Are you running File Vault?

No.

Have you watched CPU usage while a backup is in progress (seems unlikely, but something unrelated might be going on).

Yes. Time Machine basically takes up all unused CPU cycles. I usually have Firefox and Mail running in background. I should try it one time with nothing at all running. (I think I've done this and observed no change in behavior, but I should try again to be sure.)

Just to rule it out, you might try doing a simple copy of a file or files totalling perhaps 30 mb to the other partition on that same disk, and time it. Again it seems unlikely, but perhaps there's something strange happening with the drive and/or cable.

"time cp foo /Volumes/Time\ Machine\ Bak" shows 13 sec real time when foo is a 404-Mb file. If I got the full 800 Mbit/sec transfer speed, it would have transferred in 4 sec, but 13 sec isn't so bad. There's nothing wrong with raw file xfer speed.

In a previous posting, you asked how I increased the TM interval to 6 hours from 1 hr. I did this by editing /System/Library/LaunchDaemons/com.apple.backupd-auto.plist, changing the value of StartInterval from 3600 to 216000. This suggestion came from another discussion thread in this forum. However, I doubt this is the culprit, because the whole reason I changed from 1- to 6-hr intervals was because TM was running all the time and the computer was always unusable.