Time Machine backup very slow in Lion

Philip Raby1 wrote:

Ten days later, it's still stuck on Indexing. Surely it shouldn't take as long as that?

Could you elaborate on that? Does backupd log "waiting for index"?

If you read my posts above, you'll see that my problem was the file system events database, but before you try trashing that (I'm not sure what's the safest way to trash it), you should do the following:

1) Check with disk utility that both your internal disk(s) and the backup disks are OK, and if necessary, repair them.

2) Try to reset spotlight indexing. The easiest way to do that is via the Spotlight System Preferences pane. Simply drag your disks into the lists of exceptions, wait a little while for Spotlight to stop indexing, and then remove your disks from the exceptions again to start indexing anew. It might be wise to turn TM off before you do this, and wait for a while before turning TM on again.

Thanks for your reply. I'm trying what you suggest now.

With regard to the backup log, I'm getting pages of the following, which means little to me:

A437-786B05252E04, auto-retries=2, manual-retries=0

2010-07-21 22:06:51.545 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:0E9F3F73-D355-469C-82D7-273192E1FDFB, auto-retries=2, manual-retries=0

2010-07-21 22:11:06.678 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:E1516EF7-46D1-40D3-91D4-80C2E12325D7, auto-retries=2, manual-retries=0

2010-07-21 22:14:51.796 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:176F01B6-A78C-4BD5-A31B-474F14093600, auto-retries=2, manual-retries=0

2010-07-21 22:19:06.925 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:6BD4ADF2-C3C5-4EF7-9A72-AF19FF081343, auto-retries=2, manual-retries=0

2010-07-21 22:22:52.039 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:34DFF5D0-CD85-41F6-859D-E8963FCE68B0, auto-retries=2, manual-retries=0

2010-07-21 22:26:39.655 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:90C728E6-3D89-44DC-B688-8F0D58876950, auto-retries=2, manual-retries=0

2010-07-21 22:30:24.772 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:16EAFCCB-5951-4314-91B4-E712421CA773, auto-retries=2, manual-retries=0

2010-07-21 22:35:06.912 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:8B556784-9DAC-47FE-8779-39C7962C1149, auto-retries=2, manual-retries=0

2010-07-21 22:38:52.022 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:D7AC05D0-DA69-4563-8140-33A79DBE3EA1, auto-retries=2, manual-retries=0

2010-07-21 22:43:06.649 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:80BED627-001E-4EB1-B067-255D74B820CF, auto-retries=2, manual-retries=0

2010-07-21 22:46:51.763 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:3EC5670D-CE04-4520-8AA7-69025DFECB17, auto-retries=2, manual-retries=0

2010-07-21 22:51:06.891 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:27F244F4-F8AB-44DB-9E9E-0FD7C9FC052C, auto-retries=2, manual-retries=0

2010-07-21 22:54:52.002 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:63DF2875-EEFD-498E-AF9E-15491A2D7EFD, auto-retries=2, manual-retries=0

Philip Raby1 wrote:

Thanks for your reply. I'm trying what you suggest now.

With regard to the backup log, I'm getting pages of the following, which means little to me:

2010-07-21 22:06:51.545 Backup[40950:6213] POST /Info.woa/wa/XMLRPC/accountInfo?username=philraby (FAILED), httpStatusCode:-1, errorType:103 (domain=NSPOSIXErrorDomain, code=60), transactionState:5, txnId:0E9F3F73-D355-469C-82D7-273192E1FDFB, auto-retries=2, manual-retries=0

I'm pretty sure those messages are from the MobileMe Backup program (you seem to be unable to log on ot MobileMe) and NOT from Time Machine, which appears as com.apple.backupd in the system.log.

Ah, my apologies, that makes sense. I've looked in Console and found lots of these type of messages:

Aug 31 11:29:28 Philip-Rabys-Computer-2 com.apple.backupd[573]: Waiting for index to be ready (100)

Aug 31 11:30:21 Philip-Rabys-Computer-2 UserEventAgent[11]: com.apple.backupd-auto launchd job disabled

Aug 31 11:30:21 Philip-Rabys-Computer-2 UserEventAgent[11]: com.apple.backupd-wake launchd job disabled

Aug 31 11:30:21 Philip-Rabys-Computer-2 UserEventAgent[11]: com.apple.backupd-attach launchd job disabled

Aug 31 11:30:22 Philip-Rabys-Computer-2 com.apple.backupd[573]: Copied 0 files (0 bytes) from volume Macintosh HD.

Aug 31 11:30:23 Philip-Rabys-Computer-2 com.apple.backupd[573]: Backup canceled.

Aug 31 11:48:58 Philip-Rabys-Computer-2 UserEventAgent[11]: com.apple.backupd-auto launchd job enabled

Aug 31 11:48:58 Philip-Rabys-Computer-2 UserEventAgent[11]: com.apple.backupd-wake launchd job enabled

Aug 31 11:48:58 Philip-Rabys-Computer-2 UserEventAgent[11]: com.apple.backupd-attach launchd job enabled

Aug 31 11:49:09 Philip-Rabys-Computer-2 com.apple.backupd[664]: Starting standard

I've also downloaded Time Machine Buddy and this shows:

Starting standard backup

Error loading /Library/Plug-ins/DiskImages/VirtualPCDiskImagePlugin.bundle/Contents/MacOS/Vir tualPCDiskImagePlugin: dlopen(/Library/Plug-ins/DiskImages/VirtualPCDiskImagePlugin.bundle/Contents/Ma cOS/VirtualPCDiskImagePlugin, 262): no suitable image found. Did find:

Cannot find function pointer MacDiskImagePluginFactory for factory 7F1FD83E-6684-11D8-968F-000A957703C0 in CFBundle/CFPlugIn 0x10e02ee30 </Library/Plug-ins/DiskImages/VirtualPCDiskImagePlugin.bundle> (bundle, not loaded)

Backing up to: /Volumes/Time Machine Backups/Backups.backupdb

Backup content size: 203.0 GB excluded items size: 3.8 GB for volume Macintosh HD

Backup content size: 21.8 GB excluded items size: 30.5 MB for volume Phil Raby's removeable drive

267.69 GB required (including padding), 892.84 GB available

Thanks again.

Phil

I think you can ignore the messages about the missing Virtual PC disk image plugin. Otherwise, what you've shown so far just shows that you've turned backup off and on again, and that it has started to back up. Let us know what the logs say after a while!

Edit: I missed the first "waiting for index" line. That's normal when the index is in fact not ready (Spotlight is still indexing), but it shouldn't go on like that for days.

Thanks again. Three hours later and nothing fresh in the log, while TM is saying 'Indexing backup'. How long should this take? I have about 218Gb of data.

Cheers

Phil

I think it sometimes may take some hours. How is it doing now?

Since excluding the back-up drive from Spotlight, there's now a change to 'Waiting to back-up'. Maybe we've made progress?

Phil

Not sure what that means. What has it logged? (try: grep backupd /var/log/system.log)

Philip Raby1 wrote:

Thanks again. Three hours later and nothing fresh in the log, while TM is saying 'Indexing backup'. How long should this take? I have about 218Gb of data.

Cheers

Phil

Took me over 5 hours over WiFi for 90Gb. I've seen reports of it taking over 20 hours over WiFi.

Just be paitent and don't exclude the TM drive from Spotlight.

Tony

My drive is connected via USB, so should be faster, I assume.

Still 'Waiting to Back up' six hours after my last post. Surely this isn't correct?

Phil

Agreed, but look in the Console App, and search for backupd. If you see continous messages of "wating for ....", then I would wait a little longer.

You should also consider running a Disk Repair with Disk Utility on the TM Volume.

Tony

Thanks for the reply.

Oddly, today I can't find anything in Console relating to backupd. There was yesterday but not now...

I've run Disk Repair.

Phil

Looks like my Lion backup on Time Capsule is now smooth as it use to be when I had Snow Leopard installed.

It is taking approx 5 minutes for 250 Mb on WiFi.

What I did was to unflag all the Spotlight categories in System Preference, then I did a backup that took quite some time. After that I restarted the mac and also Time Capsule, I flagged again the categories I am interested in Spotlight (basically all of them except System Preferences and Fonts). Looks like its now working fine and quick since the last 8 backup over a week. As I said 250 Mb in 5 minutes from start to end. Lets see....

🙂

Millone64's method worked for me. I think. Certainly nothing else I've tried, even the terribly time-consuming techniques, did any good.

I turned Time Machine to OFF and then followed Millone64's instructions exactly. I test with manual backups, i.e. choosing BACK UP NOW from Time Machine's menu bar dropdown menu. I did two backups, and both took under 4 minutes. This was amazing at its face, since – no matter how small the backup – I haven't seen Time Machine backups in the 5-minute range for a long time.

I then went back to Spotlight preferences and enabled indexing of System Preferences and Fonts, too. Another manual backup, and it was again just about 4 minutes. Hurrah!

I then did some work and then turned Time Machine to ON. I didn't want to wait an hour to see how much time the next backup would require, so I triggered another manual backup. R'uh-r'oh! It took 20 minutes: 8 minutes PREPARING BACKUP, 10 minutes transferring about 250mb of data over wifi to my Time Capsule, then FINISHING BACKUP and CLEANING UP together about 2 minutes. I watched the progress in Time Machine's preference pane, and the data transfer seemed to "hang" at the 34.1mb mark for over 5 minutes, and took 2 minutes just to get there once BACKING UP started - but the remaining 216mb or so all zipped over in about 3 minutes.

20 minutes is still a long time, and there still seems to be something wrong (maybe I should deselect System Preferences and Fonts and leave them that way...), but even 20 minutes is a nice improvement over what I've been experiencing lately. Things have been so bad that I have had Time Machine OFF since shortly after I upgraded to Lion, doing a manual BACK UP NOW once or twice a day and often having to let it run all day (or all night while I slept) as the dang thing went through INDEXING BACKUP or took 90 minutes to transmit 100mb during BACKING UP. So if my average backup time is going to be 20 minutes, I can live with that.

I have Time Machine ON now, and I plan to leave it that way for at least the rest of tonight as I work to see how the automatic backups do in terms of time. I'll report back to this thread with the results; if things remain positive for me over the next day or two, perhaps other people might try Millone64's method.