Slow Time Machine backup to Time Capsule

Whitehill

Whitehill

Registered
Before I start, yes, I have poked around Pondini for answers.

I have a 3T Time Capsule and back up three machines to it via Time Machine. It is wired via ethernet to a Linksys router.

  1. iMac 10.8.4 wired to switch, switch wired to router
  2. PowerBook G4 10.5.8 via WIFI
  3. iMac 10.6.8 via WIFI
I don't have any problems with #1 and #2. I didn't have problems with #3 until a few weeks ago, when backups began to slow down significantly. No, I can't correlate this to any hardware or software changes.

For any hourly backup, the prepare and backup phases are about as fast as they ever were. But the phases "Finishing backup" and "Cleaning up" take so much time that the next backup starts just a few minutes after previous finally finishes. It's pretty much in constant backup now.

All that said, there may be something else going on here. Over the weekend, I directly connected to system #3 first a USB2 drive, then a Firewire (400) drive, and told Time Machine to use for backup first one then the other. After a while, the progress for each suggested a total time on the order of 100 hours! So I killed them and went back to the Time Capsule.

Below is the log for the currently running backup. It's not that big, although I don't understand why it thinks so many files have changed. Machine #3 is used rather lightly.

OK, any words of wisdom?

------ log -------------

Starting standard backup
Attempting to mount network destination using URL: afp://XXX@YYY-Time-Capsule.local/Data
Mounted network destination using URL: afp://XXX@YYY-Time-Capsule.local/Data
QUICKCHECK ONLY; FILESYSTEM CLEAN
Disk image /Volumes/Data/imac.sparsebundle mounted at: /Volumes/Time Machine Backups
Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
No pre-backup thinning needed: 1.14 GB requested (including padding), 71.98 GB available
Copied 67582 files (159.1 MB) from volume Macintosh HD.
No pre-backup thinning needed: 1.09 GB requested (including padding), 71.98 GB available
 
Looks like the old Data is not deleting correctly so you seem to be running out of space. Check the settings (maybe resetting the Time Machine Preferences) to see if that helps.
 
Satcomer, I'm prepared to believe that, but why do the other disk targets take so long?

I used SuperDuper! to make a clone of my system #3 and it took less than 4 hours for 175gb. I did an incremental a couple hours later and it took 15 minutes!
 
See the console log below. Does this mean the Spotlight database is corrupted? After churning away for 42 minutes, MDS crashed; then again after 30 minutes. Finally it claimed to finish normally an hour after the last crash. I feel sick.

3:02:13 com.apple.backupd[18828] Attempting to mount network destination using URL: afp://XXX@YYYs-Time-Capsule.local/Data
3:02:26 com.apple.backupd[18828] Mounted network destination using URL: afp://XXX@YYYs-Time-Capsule.local/Data
3:02:27 kernel AFP_VFS afpfs_mount: /Volumes/Data, pid 18829
3:02:29 hdiejectd[18838] running
3:02:30 com.apple.backupd[18828] QUICKCHECK ONLY; FILESYSTEM CLEAN
3:02:33 kernel hfs: Removed 1 orphaned / unlinked files and 0 directories
3:02:33 fseventsd[53] event logs in /Volumes/Time Machine Backups/.fseventsd out of sync with volume. destroying old logs. (2707 1 2707)
3:02:34 com.apple.backupd[18828] Disk image /Volumes/Data/imac.sparsebundle mounted at: /Volumes/Time Machine Backups
3:02:34 com.apple.backupd[18828] Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
3:02:38 fseventsd[53] log dir: /Volumes/Time Machine Backups/.fseventsd getting new uuid: 559F38EC-0482-4C2F-A746-77CF920B0A9B
3:03:26 com.apple.launchd[1] (com.apple.netauth.sysagent[18829]) Exited with exit code: 255
3:12:22 com.apple.backupd[18828] No pre-backup thinning needed: 1.05 GB requested (including padding), 71.66 GB available
3:16:24 kernel CODE SIGNING: cs_invalid_page(0x1000): p=18964[GoogleSoftwareUp] clearing CS_VALID
3:30:15 mDNSResponder[20] PenaltyTimeForServer: PenaltyTime negative -264025, (server penaltyTime -297539688, timenow -297275663) resetting the penalty
3:39:19 com.apple.backupd[18828] Copied 68442 files (82.2 MB) from volume Macintosh HD.
3:44:36 com.apple.ReportCrash.Root[19014] 2013-09-11 03:44:36.766 ReportCrash[19014:2803] Saved crash report for mds[18329] version ??? (???) to /Library/Logs/DiagnosticReports/mds_2013-09-11-034436_localhost.crash
3:45:07 com.apple.launchd[1] (com.apple.metadata.mds[18329]) Job appears to have crashed: Segmentation fault
3:48:28 mDNSResponder[20] PenaltyTimeForServer: PenaltyTime negative -27399, (server penaltyTime -296209316, timenow -296181917) resetting the penalty
3:48:28 mDNSResponder[20] PenaltyTimeForServer: PenaltyTime negative -27400, (server penaltyTime -296209317, timenow -296181917) resetting the penalty
3:52:35 com.apple.backupd[18828] No pre-backup thinning needed: 1.04 GB requested (including padding), 71.66 GB available
4:11:33 com.apple.backupd[18828] Copied 34399 files (72.6 MB) from volume Macintosh HD.
4:15:07 kernel CODE SIGNING: cs_invalid_page(0x1000): p=19078[GoogleSoftwareUp] clearing CS_VALID
4:15:37 com.apple.ReportCrash.Root[19080] 2013-09-11 04:15:37.950 ReportCrash[19080:2803] Saved crash report for mds[19015] version ??? (???) to /Library/Logs/DiagnosticReports/mds_2013-09-11-041537_localhost.crash
4:15:38 com.apple.launchd[1] (com.apple.metadata.mds[19015]) Job appears to have crashed: Segmentation fault
4:18:30 Mail[257] *** Failed to decode 8bi data, treating as binary
4:18:31 mdworker[19083] *** Failed to decode 8bi data, treating as binary
4:39:50 com.apple.backupd[18828] Starting post-backup thinning
5:13:50 kernel CODE SIGNING: cs_invalid_page(0x1000): p=19148[GoogleSoftwareUp] clearing CS_VALID
5:23:11 com.apple.backupd[18828] Deleted backup /Volumes/Time Machine Backups/Backups.backupdb/imac/2013-09-06-051935: 71.66 GB now available
5:23:11 com.apple.backupd[18828] Post-back up thinning complete: 1 expired backups removed
5:23:15 com.apple.backupd[18828] Backup completed successfully.
5:23:20 com.apple.backupd[18828] Ejected Time Machine disk image.
5:23:21 com.apple.backupd[18828] Ejected Time Machine network volume.
 
Yesterday evening, I turned off Time Machine, and followed the directions to reset the SpotLight database. Early this morning I turned Time Machine back on. See console log below.

  1. It took two hours to complete. Four minutes later it started again.
  2. mdworker complains. Looking in earlier logs, I see this a lot.
  3. mds crashed again. Despite what it says, that report is not there.
  4. The Dock software is complaining about something.
  5. The kernel tells me Google is messing around.
What now?


5:08AM | com.apple.backupd[24472] Starting standard backup
5:08AM | com.apple.backupd[24472] Attempting to mount network destination using URL: afp://XXX@YYYs-Time-Capsule.local/Data
5:08AM | com.apple.backupd[24472] Mounted network destination using URL: afp://XXX@YYYs-Time-Capsule.local/Data
5:08AM | com.apple.backupd[24472] QUICKCHECK ONLY; FILESYSTEM CLEAN
5:08AM | com.apple.backupd[24472] Disk image /Volumes/Data/imac.sparsebundle mounted at: /Volumes/Time Machine Backups
5:08AM | com.apple.backupd[24472] Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
5:18AM | com.apple.backupd[24472] No pre-backup thinning needed: 1.14 GB requested (including padding), 71.61 GB available
5:24AM | mdworker32[24542] kCGErrorFailure: Set a breakpoint @ CGErrorBreakpoint() to catch errors as they are logged.
5:41AM | kernel CODE SIGNING: cs_invalid_page(0x1000): p=24579[GoogleSoftwareUp] clearing CS_VALID
5:44AM | mdworker[24507] *** Failed to decode data, treating as binary
5:44AM | mdworker[24507] *** Failed to decode 9bit data, treating as binary
5:44AM | mdworker[24507] *** Failed to decode 7bit ...
5:44AM | mdworker[24507] *** Failed to decode 9bit data, treating as binary
5:56AM | com.apple.backupd[24472] Copied 68897 files (156.3 MB) from volume Macintosh HD.
6:06AM | com.apple.ReportCrash.Root[24611] 2013-09-12 06:06:16.201 ReportCrash[24611:2803]
Saved crash report for mds[21367] version ??? (???) to /Library/Logs/DiagnosticReports/mds_2013-09-12-060616_localhost.crash
6:06AM | com.apple.launchd[1] (com.apple.metadata.mds[21367]) Job appears to have crashed: Segmentation fault
6:11AM | com.apple.backupd[24472] No pre-backup thinning needed: 1.05 GB requested (including padding), 71.61 GB available
6:33AM | com.apple.backupd[24472] Copied 34409 files (75.9 MB) from volume Macintosh HD.
6:40AM | kernel CODE SIGNING: cs_invalid_page(0x1000): p=24685[GoogleSoftwareUp] clearing CS_VALID
6:42AM | Dock[187] kCGErrorIllegalArgument: CGSSetWindowTransformsAtPlacement: Failed
6:42AM | Dock[187] kCGErrorFailure: Set a breakpoint @ CGErrorBreakpoint() to catch errors as they are logged.
6:42AM | Dock[187] kCGErrorIllegalArgument: CGSSetWindowTransformAtPlacement: Failed
6:42AM | com.apple.Dock.agent[187] Thu Sep 12 06:42:01 ZZZ.net
Dock[187] <Error>: kCGErrorIllegalArgument: CGSSetWindowTransformsAtPlacement: Failed
6:42AM | com.apple.Dock.agent[187] Thu Sep 12 06:42:01 ZZZ.net
Dock[187] <Error>: kCGErrorFailure: Set a breakpoint @ CGErrorBreakpoint() to catch errors as they are logged.
...
6:56AM | com.apple.backupd[24472] Starting post-backup thinning
6:56AM | com.apple.backupd[24472] Found partially deleted backup - trying again to delete: 2013-09-07-095905
7:04AM | com.apple.backupd[24472] Deleted backup
/Volumes/Time Machine Backups/Backups.backupdb/imac/2013-09-07-095905: 71.59 GB now available
7:04AM | com.apple.backupd[24472] Post-back up thinning complete: 1 expired backups removed
7:04AM | com.apple.backupd[24472] Backup completed successfully.
7:04AM | com.apple.backupd[24472] Ejected Time Machine disk image.
7:04AM | com.apple.backupd[24472] Ejected Time Machine network volume.
7:08AM | com.apple.backupd[24725] Starting standard backup
 
First, the good news. MDS isn't crashing now.

The bad news. A standard backup still takes 2 hours to handle 150mb. The console shows far fewer weird messages. The following pair is now predominant.

9/13/13 11:22:42 AM | Sep 13, 2013 mDNSResponder[20] ERROR: mDNSPlatformWriteTCP - send Broken pipe
9/13/13 11:22:42 AM | Sep 13, 2013 mDNSResponder[20] mDNSSendDNSMessage: write msg length failed -1/2

OK, my goal for this little exercise is this. This is my wife's machine and she finally agreed to allow me to upgrade it to Mountain Lion. My real fear is I'll just push this issue, and others lurking to spring, into yet another OSX version, likely making them even more difficult to exorcize.

Given my goal, what should I do to attain it?
 
You said the slow backup is only on one Mac?
Does the backup, even though it seems to take a long time, noticeably affect the operation of that Mac?
Or, are you simply concerned about why the backup takes so long, but it is simply a background process that doesn't affect use of the Mac?
 
DeltaMac said:
You said the slow backup is only on one Mac?
Click to expand...
Yes.
Does the backup, even though it seems to take a long time, noticeably affect the operation of that Mac?
Click to expand...
It does not seem to affect it.
Or, are you simply concerned about why the backup takes so long, but it is simply a background process that doesn't affect use of the Mac?
Click to expand...
Yes, but not only that. My concern is that the backups for this mac may be garbage, that an OSX upgrade will be based based on garbage.
 
Whitehill said:
... My concern is that the backups for this mac may be garbage, that an OSX upgrade will be based based on garbage.
Click to expand...

Then can I ask - On what do you base that opinion? (How does "slow" somehow match up to "garbage"?)
You could certainly test that by restoring your system to an external drive, and using your backup as the source for that. If that restore completes successfully, then you have little to be concerned about, I think.

My own direction on that Mac (going with the idea that some part of the system has become corrupted) is to reinstall the system.
It's the 10.6.8 system, correct?
Boot to your Snow Leopard installer (or your restore DVD, whichever you have for reinstalling Snow Leopard), and reinstall OS X.
You won't be erasing the drive, so it simply refreshes the system to whatever 10.6 version that installer has. When you iMac restarts, run Software Update until your system is fully up-to-date.

If you don't feel comfortable with a reinstall just yet, you could reinstall the OS X 10.6.8 combined updater - which might even go far enough to fix you issue. If you don't have that updater, download here: http://support.apple.com/kb/DL1399
The combined updater will often "reset" parts of your system during the install process, and can help with a variety of issues that might appear on your system. It's a good first step, when you can't seem to sort out a problem in software. I might try that first, then proceed to the full reinstall if that updater doesn't help out.

Time Machine may do a first backup (which takes quite a long time, as you know) after a full reinstall, so you would expect that first backup to take a considerable amount of time. You would then watch for the future backups to be at a more normal duration.
 
DeltaMac said:
Then can I ask - On what do you base that opinion? (How does "slow" somehow match up to "garbage"?)
Click to expand...
From my original post ...
I directly connected to system #3 first a USB2 drive, then a Firewire (400) drive, and told Time Machine to use for backup first one then the other. After a while, the progress for each suggested a total time on the order of 100 hours! So I killed them and went back to the Time Capsule.
Click to expand...
The first full backup to the Time Capsule took about 10 hours, as I remember. The total for a full backup is/was 140gb = 140000mb. The current incremental total is around 140mb, or 0.1% of the full. Using that ratio, the incremental should take only a few seconds. But let's be pessimistic and say a few minutes - the time required on my other Macs.

This suggests to me that something on the system disk of this mac is seriously corrupted and the TM backups are capturing that corruption, and any restore or upgrade based on these backups will maintain the corruption.
 
You haven't offered any evidence (other than your guess) that a slow backup means a corrupted backup.

I'm not too sure how you would decide - corrupted files, particularly in the system, would probably cause a failed restore.
I also think that the Time Machine backup process would likely error out, if the files that are backed up are corrupted
My OPINION (for what that's worth) is that the slow processing is caused by some runaway process in your system


As you are getting continual 'hits' on bonjour events (the mDNSResponder is a service used by bonjour), that may be part of the cause (or all of it) and the DNS cache reset suggested by Satcomer could help.
I would follow that up with the reinstalls that I listed - 10.6.8 combined updater, followed by an OS X reinstall, if that still doesn't fix anything.
Dump your current update for that volume, and let the re-done system do a full update.
I suggest that your current time machine backup is likely OK - but you may want to use some other method, such as CCC, to have a full, current backup before you do more major work to the system.
I suggest that the first (full) update may be much faster with a direct connect to the Time Capsule, rather than wifi.
 
DeltaMac said:
I would follow that up with the reinstalls that I listed - 10.6.8 combined updater, followed by an OS X reinstall, if that still doesn't fix anything.
Dump your current update for that volume, and let the re-done system do a full update.
I suggest that your current time machine backup is likely OK - but you may want to use some other method, such as CCC, to have a full, current backup before you do more major work to the system.
I suggest that the first (full) update may be much faster with a direct connect to the Time Capsule, rather than wifi.
Click to expand...

I will apply the combo etc. this Thursday. Regarding CCC ...

Whitehill said:
I used SuperDuper! to make a clone of my system #3 and it took less than 4 hours for 175gb. I did an incremental a couple hours later and it took 15 minutes!
Click to expand...

I take an SD incremental early every morning M-F. Yes, this is directly connected. But before using SD, I tried to use the same disk for a new full TM. After 4 hours, the progress meter showed around 1% complete. The performance disparity is between TM and anything else on this one system. My 10.5.8 mac uses WiFi and its TM performance is very zippy.

I suppose I can temporarily relocate my Time Capsule, but how do I connect it to the Mac? Currently it's wired to a port on my router.
 
Whitehill said:
... relocate my Time Capsule, but how do I connect it to the Mac? Currently it's wired to a port on my router.
Click to expand...

All Time Capsules have a 4-port ethernet hub. So, Mac to Time Capsule, with ethernet. If your ethernet ports are all filled on the Time Capsule, then run ethernet to your router. If all your ethernet ports are in use, then maybe you need more ports :D
That might not solve your problem with the slow backup through Time Machine, but would make your full backup finish much faster.

Did you already try the DNS cache reset?
 
What I do with my first Time Capsule backup was to Ethernet to it for the initial backup. After that I can use wireless for the supplemental backups after that. It worked for like that since the first Time Capsule.

Like Delta said maybe the 10.6.8 Combo 1.1 would be a smart thing to do to see if that helps.
 
You must log in or register to reply here.
Back
Top