I inadvertently went afoul of Apple's submission policy by submitting the contents of a bug report to the forums (apparently you can't do that).
I've reposted the full post here (I'm hopeful it might be useful to other with similar issues).
My personal opinion is that much of the "preparing to backup" issues are related to 2 things.
1) Very slow transfer speeds between computers and the TC. Specifically wireless network transfer is very slow. There is something seriously wrong here. It doesn't appear to be universal (in fact I myself had it working fairly well for over a month). I wonder if we can't figure out the combination of factors that lead to poor performance. I tried a number of things (see below), but I wasn't able to get at a root cause. restarting (physically taking power from the TC) seems to help for a while.
2) A backup algorithm that reads enormous amounts of data over the wireless network (from TC to Computer). (for example in one case I read 2.5 gigabytes of data in order to determine we needed to back up 18 megabytes)
Eventually I gave up on wireless, and ran a 1000baseT network cable to my iMac -- Time machine seems to be working just fine now.
The combination of these things leads many users to hours of frustration.
If anyone out there with a bit more network savvy than me can confirm theses findings (and perhaps indicate what the heck time machine is doing while it is preparing to backup), maybe we can file a few more reports for the engineering team to look at.
(While writing this, I noticed my 18 megabyte backup had \"finished\" -- That is, had gotten to 18 out of 18 megabytes, but is still processing. While \"still processing\" it has transferred another 300 megabytes of data from the TC to the computer)
One other interesting fact -- I did all the testing of time machine with spotlight turned off (that is the main hard drive excluded from spotlight). After I got it working directly connected to the mac (not over wireless), I re-enabled spotlight.
While it was re-building it's index, I noticed a rather significant amount of network traffic. I don't believe spotlight indexes network drives (at least you can't exclude them in the privacy pane).
I'm thinking that spotlight and time machine are somehow related. I've seen cases where when time machine is running, spotlight is re-indexing. If this drives significant network traffic then the wireless network performance will introduce long delays into the backup (and likely expose other defects -- I doubt apple engineers thought that backups would end up taking 10's of hours just to do the prepare stage.
Mike
---
I've had increasing difficulties getting the time capsule to work with time machine.
I see failures
1) preparing to backup takes forever.
a) Deep node traversal that never ends
b) Waiting for index that never ends.
2) Very very slow wireless networking speeds. I'm seeing speeds of about 2Mbits per second over wireless. That seems quite slow.
I've done an "archive and install" and wiped my time capsule clean to start over. The initial backup went fine, but subsequent updates got me back into this state.
I've tried disabling spotlight (as well as re-doing the spotlight index) but to no avail.
I've also "fixed" any permissions problems that might exist.
Regarding the wireless bandwidth, I've checked my Signal to Noise ratio (I'm about 30DB, which is in a reasonable range), I've tried G, N and B, 5ghz, as well as 2.4 ghz. Performance was always the same. I've disabled WDS.
I believe that some of the "preparing to backup" problems are related to the amount of data that has to be transferred (or that is being transferred) between the TC and the Mac. For example, I've been "preparing to backup" for about 30 minutes and I'm seeing sustained incoming rates of around 800 KBytes per second (I'm on 1000 base T, no longer wireless), and outgoing rates of about 100KBytes per second.
Note I haven't actually gotten to the part where it copies files to the time machine yet. In the course of "preparing" to back up, it has copied over 1.6 gigabytes of data from the TC.
(brief update, while writing this, I transitioned to backup up data (I have 18.7 MB to back up, and it ultimately transferred 2.5 gigabytes over the network. That's seriously messed up)
I'm not sure what exactly it is doing, but either it is caught in an infinite loop, or it is copying too much data to determine what to back up. (Note: Not an infinite loop, it did finish).
Current logs are:
11/30/08 9:04:11 PM /System/Library/CoreServices/backupd2306 Backup requested by user
11/30/08 9:04:11 PM /System/Library/CoreServices/backupd2306 Starting standard backup
11/30/08 9:04:26 PM kernel AFP_VFS afpfs_mount: /Volumes/mpkirby's Time Capsule, pid 2307
11/30/08 9:04:26 PM /System/Library/CoreServices/backupd2306 Network volume mounted at: /Volumes/mpkirby's Time Capsule
11/30/08 9:04:33 PM hdiejectd2347 running
11/30/08 9:04:34 PM /System/Library/CoreServices/backupd2306 Disk image /Volumes/mpkirby's Time Capsule/mpkirbys Computer_0016cb9a995c.sparsebundle mounted at: /Volumes/Backup of mpkirbys Computer
11/30/08 9:04:34 PM /System/Library/CoreServices/backupd2306 Backing up to: /Volumes/Backup of mpkirbys Computer/Backups.backupdb
11/30/08 9:04:40 PM /System/Library/CoreServices/backupd2306 Event store UUIDs don't match for volume: Macintosh HD
11/30/08 9:04:40 PM /System/Library/CoreServices/backupd2306 Waiting for index to be ready (906 > 0)
11/30/08 9:04:42 PM SyncServer2363 SyncServer: Truth vacuumed. Next vacuum date 2008-12-14 21:04:42 -0500
11/30/08 9:04:45 PM /System/Library/CoreServices/backupd2306 Waiting for index to be ready (906 > 0)
11/30/08 9:05:05 PM /System/Library/CoreServices/backupd2306 Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
11/30/08 9:06:26 PM com.apple.launchd[1] (com.apple.netauth.sysagent2307) Stray process with PGID equal to this dead job: PID 2326 PPID 1 check_afp
11/30/08 9:51:40 PM /System/Library/CoreServices/backupd2306 No pre-backup thinning needed: 100.0 MB requested (including padding), 783.52 GB available
Thanks,
Mike
I've reposted the full post here (I'm hopeful it might be useful to other with similar issues).
My personal opinion is that much of the "preparing to backup" issues are related to 2 things.
1) Very slow transfer speeds between computers and the TC. Specifically wireless network transfer is very slow. There is something seriously wrong here. It doesn't appear to be universal (in fact I myself had it working fairly well for over a month). I wonder if we can't figure out the combination of factors that lead to poor performance. I tried a number of things (see below), but I wasn't able to get at a root cause. restarting (physically taking power from the TC) seems to help for a while.
2) A backup algorithm that reads enormous amounts of data over the wireless network (from TC to Computer). (for example in one case I read 2.5 gigabytes of data in order to determine we needed to back up 18 megabytes)
Eventually I gave up on wireless, and ran a 1000baseT network cable to my iMac -- Time machine seems to be working just fine now.
The combination of these things leads many users to hours of frustration.
If anyone out there with a bit more network savvy than me can confirm theses findings (and perhaps indicate what the heck time machine is doing while it is preparing to backup), maybe we can file a few more reports for the engineering team to look at.
(While writing this, I noticed my 18 megabyte backup had \"finished\" -- That is, had gotten to 18 out of 18 megabytes, but is still processing. While \"still processing\" it has transferred another 300 megabytes of data from the TC to the computer)
One other interesting fact -- I did all the testing of time machine with spotlight turned off (that is the main hard drive excluded from spotlight). After I got it working directly connected to the mac (not over wireless), I re-enabled spotlight.
While it was re-building it's index, I noticed a rather significant amount of network traffic. I don't believe spotlight indexes network drives (at least you can't exclude them in the privacy pane).
I'm thinking that spotlight and time machine are somehow related. I've seen cases where when time machine is running, spotlight is re-indexing. If this drives significant network traffic then the wireless network performance will introduce long delays into the backup (and likely expose other defects -- I doubt apple engineers thought that backups would end up taking 10's of hours just to do the prepare stage.
Mike
---
I've had increasing difficulties getting the time capsule to work with time machine.
I see failures
1) preparing to backup takes forever.
a) Deep node traversal that never ends
b) Waiting for index that never ends.
2) Very very slow wireless networking speeds. I'm seeing speeds of about 2Mbits per second over wireless. That seems quite slow.
I've done an "archive and install" and wiped my time capsule clean to start over. The initial backup went fine, but subsequent updates got me back into this state.
I've tried disabling spotlight (as well as re-doing the spotlight index) but to no avail.
I've also "fixed" any permissions problems that might exist.
Regarding the wireless bandwidth, I've checked my Signal to Noise ratio (I'm about 30DB, which is in a reasonable range), I've tried G, N and B, 5ghz, as well as 2.4 ghz. Performance was always the same. I've disabled WDS.
I believe that some of the "preparing to backup" problems are related to the amount of data that has to be transferred (or that is being transferred) between the TC and the Mac. For example, I've been "preparing to backup" for about 30 minutes and I'm seeing sustained incoming rates of around 800 KBytes per second (I'm on 1000 base T, no longer wireless), and outgoing rates of about 100KBytes per second.
Note I haven't actually gotten to the part where it copies files to the time machine yet. In the course of "preparing" to back up, it has copied over 1.6 gigabytes of data from the TC.
(brief update, while writing this, I transitioned to backup up data (I have 18.7 MB to back up, and it ultimately transferred 2.5 gigabytes over the network. That's seriously messed up)
I'm not sure what exactly it is doing, but either it is caught in an infinite loop, or it is copying too much data to determine what to back up. (Note: Not an infinite loop, it did finish).
Current logs are:
11/30/08 9:04:11 PM /System/Library/CoreServices/backupd2306 Backup requested by user
11/30/08 9:04:11 PM /System/Library/CoreServices/backupd2306 Starting standard backup
11/30/08 9:04:26 PM kernel AFP_VFS afpfs_mount: /Volumes/mpkirby's Time Capsule, pid 2307
11/30/08 9:04:26 PM /System/Library/CoreServices/backupd2306 Network volume mounted at: /Volumes/mpkirby's Time Capsule
11/30/08 9:04:33 PM hdiejectd2347 running
11/30/08 9:04:34 PM /System/Library/CoreServices/backupd2306 Disk image /Volumes/mpkirby's Time Capsule/mpkirbys Computer_0016cb9a995c.sparsebundle mounted at: /Volumes/Backup of mpkirbys Computer
11/30/08 9:04:34 PM /System/Library/CoreServices/backupd2306 Backing up to: /Volumes/Backup of mpkirbys Computer/Backups.backupdb
11/30/08 9:04:40 PM /System/Library/CoreServices/backupd2306 Event store UUIDs don't match for volume: Macintosh HD
11/30/08 9:04:40 PM /System/Library/CoreServices/backupd2306 Waiting for index to be ready (906 > 0)
11/30/08 9:04:42 PM SyncServer2363 SyncServer: Truth vacuumed. Next vacuum date 2008-12-14 21:04:42 -0500
11/30/08 9:04:45 PM /System/Library/CoreServices/backupd2306 Waiting for index to be ready (906 > 0)
11/30/08 9:05:05 PM /System/Library/CoreServices/backupd2306 Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
11/30/08 9:06:26 PM com.apple.launchd[1] (com.apple.netauth.sysagent2307) Stray process with PGID equal to this dead job: PID 2326 PPID 1 check_afp
11/30/08 9:51:40 PM /System/Library/CoreServices/backupd2306 No pre-backup thinning needed: 100.0 MB requested (including padding), 783.52 GB available
Thanks,
Mike