Time machine is very slow

I have some progress to report.

wchlm wrote:

Pondini wrote:

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

Well, I tried this. I turned off all apps (principally Mail.app and Firefox) and went to sleep. While I was asleep two backups took place. Here's the report from system.log for the first one.

Jan 19 03:20:43 shenkin /System/Library/CoreServices/backupd[15643]: Starting standard backup
Jan 19 03:20:43 shenkin /System/Library/CoreServices/backupd[15643]: Backing up to: /Volumes/Time Machine Bak/Backups.backupdb
Jan 19 03:22:56 shenkin /System/Library/CoreServices/backupd[15643]: No pre-backup thinning needed: 799.2 MB requested (including padding), 444.08 GB available
Jan 19 03:36:23 shenkin /System/Library/CoreServices/backupd[15643]: Copied 199424 files (58.6 MB) from volume Macintosh HD.
Jan 19 03:36:26 shenkin /System/Library/CoreServices/backupd[15643]: No pre-backup thinning needed: 728.9 MB requested (including padding), 444.02 GB available
Jan 19 03:36:34 shenkin /System/Library/CoreServices/backupd[15643]: Copied 512 files (8 KB) from volume Macintosh HD.
Jan 19 03:36:36 shenkin /System/Library/CoreServices/backupd[15643]: Starting post-backup thinning
Jan 19 03:43:57 shenkin /System/Library/CoreServices/backupd[15643]: Deleted backup /Volumes/Time Machine Bak/Backups.backupdb/shenkin /2009-01-17-215042: 444.07 GB now available
Jan 19 03:43:57 shenkin /System/Library/CoreServices/backupd[15643]: Post-back up thinning complete: 1 expired backups removed
Jan 19 03:43:58 shenkin /System/Library/CoreServices/backupd[15643]: Backup completed successfully.

Note in the above that there are still about 200k files being backed up, but the backup is taking place in 23 minutes. This is still long, but shorter than in the past by a factor of ca. 3, and likely just reflects the fact that TM is not competing with other apps for CPU time.

More interesting is the second backup. Recall that no other apps were running during the entire interval between the backup above and the following:

Jan 19 09:20:42 shenkin /System/Library/CoreServices/backupd[16980]: Starting standard backup
Jan 19 09:20:42 shenkin /System/Library/CoreServices/backupd[16980]: Backing up to: /Volumes/Time Machine Bak/Backups.backupdb
Jan 19 09:20:46 shenkin /System/Library/CoreServices/backupd[16980]: No pre-backup thinning needed: 728.9 MB requested (including padding), 444.07 GB available
Jan 19 09:20:57 shenkin /System/Library/CoreServices/backupd[16980]: Copied 460 files (10 KB) from volume Macintosh HD.
Jan 19 09:20:57 shenkin /System/Library/CoreServices/backupd[16980]: Starting post-backup thinning
Jan 19 09:29:45 shenkin /System/Library/CoreServices/backupd[16980]: Deleted backup /Volumes/Time Machine Bak/Backups.backupdb/shenkin /2009-01-17-155613: 444.10 GB now available
Jan 19 09:29:45 shenkin /System/Library/CoreServices/backupd[16980]: Post-back up thinning complete: 1 expired backups removed
Jan 19 09:29:46 shenkin /System/Library/CoreServices/backupd[16980]: Backup completed successfully.

Observations:

1. The second backup took 9 minutes.
2. Nearly all the time was taken in post-backup thinning -- why did this take so long? This is still a problem.
3. There is only a single file-copying operation, presumably because without other apps running, no files changed during the the first file-copying operation.
4. Most interestingly, it now says that it is copying only 460 files (10 KB) in contrast to 200000 files. The actual file-copying operation takes 11 seconds.

My tentative conclusions and caveats are as follows:

A. When TM says it copied 200000 files in an hour, it means that it had to look at 200000 files; most of them (as shown by external utilities, such as timedog and TimeTracker) never get copied. Presumably, it's the need to consider this large number of files that causes TM to take so long.

B. Some app -- mail or Firefox -- is causing TM to need to consider this large number of files. The same large number had to be considered when Mail and Firefox were exited shortly before the (first) backup, but this large number did not have to be considered when no apps were running over the entire backup interval.

C. It still doesn't make sense that TM should have had to consider 200000 files. I know, from having recently done Silverkeeper backups, that there are only about 440000 files on the entire system. But maybe (as Pondini implied), TM counts metadata updates as files, and maybe there are many metadata "bundles" for each file. I don't know enough about the Mac OS file system to know how this works.

D. Though the above new information should facilitate understanding (a little), it still doesn't solve the problem -- yet, anyway. TM is meant to run while one is working. I obviously can't quit all my apps each time TM runs.

E. Since Mac OS works in mysterious ways, I'll watch what happens the next time TM runs (with my apps running), to see whether the symptom has miraculously cured itself. I'll report back.

Pondini wrote:

wchlm wrote:
C. It still doesn't make sense that TM should have had to consider 200000 files. I know, from having recently done Silverkeeper backups, that there are only about 440000 files on the entire system. But maybe (as Pondini implied), TM counts metadata updates as files, and maybe there are many metadata "bundles" for each file. I don't know enough about the Mac OS file system to know how this works.

Neither do I. And I don't know about Silverkeeper (I use CCC), but you almost certainly have far more than 440,000 files. Use Disk Utility to look at your HD (the volume on the second line). Mine says nearly 530,000 (as does my clone) and I have far less data than you.

Well you're right; then again, you're wrong. 🙂

Indeed, Disk Utility says I have just over 1M files. But "sudo ls -a1r / | wc -l" says I have 423636, including directories. This is an overcounting, since the ls output includes blank lines and '.' and '..' entries. So the native Mac tools -- TM and Disk Utility -- are counting some things as files that normal file search tools like ls don't see.

D. Though the above new information should facilitate understanding (a little), it still doesn't solve the problem -- yet, anyway. TM is meant to run while one is working. I obviously can't quit all my apps each time TM runs.

I see I never asked what mail app you're using. If it's not the standard Apple Mail, it may store it's data as one big file, which could be a contributor.

It is the standard Apple Mail. One of my mail accounts is an imap account, and I have it set up to store copies of everything locally. Altogether, including all accounts, I probably have about 40,000 mail messages stored locally.

E. Since Mac OS works in mysterious ways, I'll watch what happens the next time TM runs (with my apps running), to see whether the symptom has miraculously cured itself. I'll report back.

Ever the optimist! Hang in there.

Our Lady of Perpetual Optimism has failed me again. If anything, it's worse now. Look at this: after a round of finding/saving 200k files, TM found and saved another round of 200k +during the same backup+, and took over 2 hours. FWIW, I was doing a lot of work with Google Docs during this time.

Jan 19 21:20:39 shenkin /System/Library/CoreServices/backupd[19042]: Starting standard backup
Jan 19 21:20:40 shenkin /System/Library/CoreServices/backupd[19042]: Backing up to: /Volumes/Time Machine Bak/Backups.backupdb
Jan 19 21:26:10 shenkin /System/Library/CoreServices/backupd[19042]: No pre-backup thinning needed: 822.2 MB requested (including padding), 443.97 GB available
Jan 19 21:28:00 shenkin /System/Library/CoreServices/backupd[19042]: Unable to rebuild path cache for source item. Partial source path:
Jan 19 21:57:25 shenkin /System/Library/CoreServices/backupd[19042]: Unable to rebuild path cache for source item. Partial source path:
Jan 19 22:03:52 shenkin /System/Library/CoreServices/backupd[19042]: Copied 244497 files (77.7 MB) from volume Macintosh HD.
Jan 19 22:06:57 shenkin /System/Library/CoreServices/backupd[19042]: No pre-backup thinning needed: 752.3 MB requested (including padding), 443.87 GB available
Jan 19 22:54:03 shenkin /System/Library/CoreServices/backupd[19042]: Unable to rebuild path cache for source item. Partial source path:
Jan 19 22:54:47 shenkin /System/Library/CoreServices/backupd[19042]: Copied 204113 files (23.9 MB) from volume Macintosh HD.
Jan 19 23:06:32 shenkin /System/Library/CoreServices/backupd[19042]: Starting post-backup thinning
Jan 19 23:29:20 shenkin /System/Library/CoreServices/backupd[19042]: Deleted backup /Volumes/Time Machine Bak/Backups.backupdb/shenkin /2009-01-18-154620: 443.89 GB now available
Jan 19 23:29:20 shenkin /System/Library/CoreServices/backupd[19042]: Post-back up thinning complete: 1 expired backups removed
Jan 19 23:29:22 shenkin /System/Library/CoreServices/backupd[19042]: Backup completed successfully.

Pondini wrote:
Hello again.

Just saw a post that seems to describe a similar problem, that was fixed by uninstalling an app called PeerGuardian. http://discussions.apple.com/thread.jspa?threadID=1864234&tstart=0

If by chance you happen to be running it, this may be worth a look.

Thanks. Actually, that symptom is different. In the case you refer to, the TM backups themselves are huge -- ca. 30 Gb. In my case, the backups are small -- ca. 30 Mb. In any case, I'm not running PeerGuardian....

Pondini wrote:
If you're sure you don't need any old files, update your clone, turn off TM, erase the TM partition (with Disk Utility), and fire it up again from "scratch".

Thanks. I tried it, but still have the same problem after resuming TM backups.

Pondini wrote:
Gadzooks! Makes no sense whatever. Clearly, it's now "Apple Time".

Most likely, I will get a stable nightly sync going with CCC and just turn of TM forever. (Silverkeeper hangs just before quitting.)

Pondini wrote:

Hmmm. If you mentioned a problem with Silverkeeper before, I missed it. I know nothing about it, but wonder if perhaps it's running into the same problem TM is.

That occurred to me as I wrote my last note. I'll see what happens with CCC.

wchlm wrote:

Pondini wrote:
Hmmm. If you mentioned a problem with Silverkeeper before, I missed it. I know nothing about it, but wonder if perhaps it's running into the same problem TM is.

That occurred to me as I wrote my last note. I'll see what happens with CCC.

I've now had CCC running for a few days -- no problems. It takes about 1/2 hour for my daily sync, but this is still less time than it takes TM to back up up 6 hrs worth of updates.

CCC seems to agree with TM that my total number of files is about 1M, and not with the conclusion from "sudo ls -R /" that I have less than half that number. FWIW, a recent CCC summary looks as follows, and I've verified that a recent CCC backup is bootable. Note the 658 files that had to be copied, in contrast to the 200,000 or so that TM claims have to be copied.

06:06:34 Summary statistics:
Data copied: 451.85 MB [Please see http://www.bombich.com/software/docs/CCCHelp/CCCHelp.html?page=debug for a comment about this figure]
Regular files copied: 658
Directories: 167168
Regular files: 973070
Symlinks: 24735
Devices: 0
Special files: 42
Hard links: 81632