Time Machine preparing WAY too many items

I just wanted to post a sample system.log from my iMac:

Feb 8 16:22:37 david-horowitzs-computer-3 com.apple.backupd[48194]: Starting standard backup

Feb 8 16:22:37 david-horowitzs-computer-3 com.apple.backupd[48194]: Backing up to: /Volumes/Iomega HDD/Backups.backupdb

Feb 8 16:27:17 david-horowitzs-computer-3 com.apple.backupd[48194]: No pre-backup thinning needed: 352.5 MB requested (including padding), 710.59 GB available

Feb 8 16:40:57 david-horowitzs-computer-3 com.apple.backupd[48194]: Copied 51064 files (605 KB) from volume Macintosh HD.

Feb 8 16:46:50 david-horowitzs-computer-3 com.apple.backupd[48194]: No pre-backup thinning needed: 356.6 MB requested (including padding), 710.47 GB available

Feb 8 17:00:51 david-horowitzs-computer-3 com.apple.backupd[48194]: Copied 51002 files (138 KB) from volume Macintosh HD.

Feb 8 17:06:23 david-horowitzs-computer-3 com.apple.backupd[48194]: Starting post-backup thinning

Feb 8 17:11:27 david-horowitzs-computer-3 com.apple.backupd[48194]: Deleted backup /Volumes/Iomega HDD/Backups.backupdb/David Horowitz’s Computer/2012-02-07-155215: 710.58 GB now available

Feb 8 17:11:27 david-horowitzs-computer-3 com.apple.backupd[48194]: Post-back up thinning complete: 1 expired backups removed

Feb 8 17:11:29 david-horowitzs-computer-3 com.apple.backupd[48194]: Backup completed successfully.

Feb 8 17:22:38 david-horowitzs-computer-3 com.apple.backupd[48438]: Starting standard backup

Feb 8 17:22:38 david-horowitzs-computer-3 com.apple.backupd[48438]: Backing up to: /Volumes/Iomega HDD/Backups.backupdb

Feb 8 17:27:19 david-horowitzs-computer-3 com.apple.backupd[48438]: No pre-backup thinning needed: 356.4 MB requested (including padding), 710.58 GB available

Feb 8 17:40:55 david-horowitzs-computer-3 com.apple.backupd[48438]: Copied 51064 files (639 KB) from volume Macintosh HD.

Feb 8 17:46:49 david-horowitzs-computer-3 com.apple.backupd[48438]: No pre-backup thinning needed: 359.0 MB requested (including padding), 710.47 GB available

Feb 8 18:00:53 david-horowitzs-computer-3 com.apple.backupd[48438]: Copied 51002 files (138 KB) from volume Macintosh HD.

Feb 8 18:06:31 david-horowitzs-computer-3 com.apple.backupd[48438]: Starting post-backup thinning

Feb 8 18:11:42 david-horowitzs-computer-3 com.apple.backupd[48438]: Deleted backup /Volumes/Iomega HDD/Backups.backupdb/David Horowitz’s Computer/2012-02-07-165226: 710.57 GB now available

Feb 8 18:11:42 david-horowitzs-computer-3 com.apple.backupd[48438]: Post-back up thinning complete: 1 expired backups removed

Feb 8 18:11:44 david-horowitzs-computer-3 com.apple.backupd[48438]: Backup completed successfully.

This shows a couple of things.

1. TM backups are almost continuous. The first backup shown starts at 16:22 and ends at 17:11. Promptly at 17:22, the next backup begins. This backup is over a FW800 connection to a mostly empty disk.

2. I am not sure what system.log records, but it doesn't seem as though anything else is happening on this computer except TM backups. Nevertheless, TM finds exactly the same number of files in each backup; first, 51064 files, and then 51002 files.

There won't be any more logs like this because I am going to turn TM off.

David Horowitz wrote:

. . .

1. TM backups are almost continuous. The first backup shown starts at 16:22 and ends at 17:11. Promptly at 17:22, the next backup begins. This backup is over a FW800 connection to a mostly empty disk.

Yes, that's how the scheduling works. A new backup starts an hour after the previous one started, not an hour after it completed. Usually, that's not a problem.

2. I am not sure what system.log records, but it doesn't seem as though anything else is happening on this computer except TM backups. Nevertheless, TM finds exactly the same number of files in each backup; first, 51064 files, and then 51002 files.

There are some cases where the number of files is quite large, and if two drives are being backed-up, the same amount is reported for both. In those cases, the backups run at a reasonable rate, so it seems to be just some odd reporting glitch. So it's hard to tell whether the number of files reproted is significant in your case.

There won't be any more logs like this because I am going to turn TM off.

I'd suggest CarbonCopyCloner or SuperDuper as a substitute (or in addition to TM).

CCC now has an "archive" feature, to keep copies of things you've change or deleted. It's harder to find those backups than with TM, but at least they exist.

I had a chance to stop in the Apple Store this afternoon. Sadly, I didn't actually have my Time Machine with me to show the genius the problem first hand, because it's in a shipping box right now on its way to Pennsylvania. *BUT* I did describe the problem and the genius seemed to be familiar with the problem. He said that I should go into the TM folder on the external harddrive and somewhere within it is an "in progress" file which he believes is the problem and needs to be deleted and then TM will start to work normally. I don't have my TM to attempt this, and I'm not sure where in the folder the file would be (or if it would actually be named "in progress"), but since I stopped in, I thought I would share that nugget of information here. If anyone one else has better information, please share.

That does help on rare occasions, with other problems, but isn't likely to help here.

The .inProgress package (looks like a file but is a special folder containing the partial backup) is where the backup is "built" -- once everything is copied, it's converted into a normal backup folder.

If the backup fails, the partial backup remains in the .inProgress package. The next backup attempt will recover it, so the data doesn't have to be copied again. Once a backup is completed, the package is gone.

Bottom line: since your backups do complete successfully, there won't be any remains.

If you want to look, at the top level of the drive (for backups done to an internal or directly-connected external disk) is a single Backups.backupdb folder (for a backup done via a network, it's at the top level of the sparse bundle disk image).

Inside that is a single folder named for your computer; inside that is a series of date-stamped backup folders, a Latest alias, and (possibly) a date-stamped package with an .inProgress extension. Emptying the trash after deleting it may take quite a while, and cause problems with locked files.

Similar problem here on Mid 2010 13 inch MBP. Here is an example from the log file:

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:\n /Library/Plug-ins/DiskImages/VirtualPCDiskImagePlugin.bundle/Contents/MacO S/VirtualPCDiskImagePlugin: mach-o, but wrong architecture

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

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

No pre-backup thinning needed: 8.18 GB requested (including padding), 9.71 GB available

Copied 36386 files (6.8 GB) from volume Snow Leopard.

No pre-backup thinning needed: 100.0 MB requested (including padding), 2.88 GB available

Copied 182 files (393 bytes) from volume Snow Leopard.

Starting post-backup thinning

Deleted backup /Volumes/Time Machine/Backups.backupdb/Detlefs Computer/2012-02-20-195846: 10.10 GB now available

Post-back up thinning complete: 1 expired backups removed

Backup completed successfully.

Thanks for any help

Detlef

Detlef Otten wrote:

. . .

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:\n /Library/Plug-ins/DiskImages/VirtualPCDiskImagePlugin.bundle/Contents/MacO S/VirtualPCDiskImagePlugin: mach-o, but wrong architecture

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

You have an old, incompatible app: VirtualPC. That's at least part of the problem.

Uninstall it.

At the very least, delete:

/Library/Plug-ins/DiskImages/VirtualPCDiskImagePlugin.bundle

Dear Pondini,

Thanks for your reply, however this seemed only to be a little additional obstacle. Below you can see the logs from Console for the last three back-ups:

As you can see always massive data is copied to Time Machine. Do you think only a Combo update or re-install might cure the problem?

Thank you for your help.

Detlef

Detlef Otten wrote:

. . .

As you can see always massive data is copied to Time Machine.

See #D4 in Time Machine - Troubleshooting for some common causes of large backups, and ways to determine exactly what's getting backed-up each time.

Thanks for your hint and also the work you put into this amazing website. The problem children were two databases which I now omit from the backup.

Thanks and best

Detlef

Great! Glad it helped, and thanks for the feedback.

Last week my MBP became affected by the "too many items" bug as well. Usually around 20,000 files get backed up, but it went up to 40,000 following the recent security update.

Usually I'm backing up to a Time Capsule (gen 4), occassionally also to an USB drive.

Some observations:

• The source of this bug must be apparently on the Mac, not on the backup, because both backups are affected.

• From what I've seen so far using BackupLoupe, several thousands of those "ghost" files are symbolic links, located in /usr/share/man and similar directories, being copied over and over again for no obvious reason.

At first I thought there was a connection to the XtraFinder "hack" I've been using, because the bug has appeared around the time I have enabled several quite obscure functionalities in XtraFinder. But since the bug did NOT disappear after deinstalling XtraFinder, it's probably unrelated. Also, I've been actually using XtraFinder for many months now, without any obvious problems.

Also of note might be the following system.log entries on the day before this issue started:

******************************************************************************** ******************************************

Mar 14 05:17:57 [computer_name] com.apple.backupd[7539]: Starting standard backup

Mar 14 05:18:01 [computer_name] com.apple.backupd[7539]: Attempting to mount network destination using URL: afp://[user_name]@[time_capsule_name].local/[time_capsule_name]

Mar 14 05:18:21 [computer_name] com.apple.backupd[7539]: Mounted network destination using URL: afp://[user_name]@[time_capsule_name].local/[time_capsule_name]

Mar 14 05:19:00 [computer_name] com.apple.backupd[7539]: QUICKCHECK ONLY; FILESYSTEM CLEAN

Mar 14 05:19:04 [computer_name] com.apple.backupd[7539]: Disk image /Volumes/[time_capsule_name]/[computer_name].sparsebundle mounted at: /Volumes/Time Machine Backups

Mar 14 05:19:04 [computer_name] com.apple.backupd[7539]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb

Mar 14 05:22:41 [computer_name] com.apple.backupd[7539]: No pre-backup thinning needed: 6.75 GB requested (including padding), 580.03 GB available

Mar 14 05:37:41 [computer_name] com.apple.backupd[7539]: Error: (-8084) SrcErr:YES Copying /Users/[user_name]/Music/iTunes/iTunes Musikarchiv/Temp File.tmp to (null)

Mar 14 05:58:05 [computer_name] com.apple.backupd[7539]: Copied 19562 files (3.7 GB) from volume [computer_name]vice.

Mar 14 05:58:50 [computer_name] com.apple.backupd[7539]: No pre-backup thinning needed: 2.46 GB requested (including padding), 579.14 GB available

Mar 14 06:00:46 [computer_name] com.apple.backupd[7539]: Copied 1785 files (50.9 MB) from volume [computer_name]vice.

Mar 14 06:02:11 [computer_name] com.apple.backupd[7539]: Starting post-backup thinning

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: Error -36 deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/[computer_name]/2013-02-12-050300

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: No post-back up thinning needed: no expired backups exist

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: Error writing to backup log. NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Device not configured

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: Error writing to backup log. NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Device not configured

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: Error writing to backup log. NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Device not configured

Mar 14 11:25:11 [computer_name] mds[42]: (/Volumes/Time Machine Backups/.Spotlight-V100/Store-V1/Stores/677E0AD4-982A-4D9B-82D6-F8037A9D0A07)(E rror) IndexGeneral in fd_pwrite:pwrite(/Volumes/Time Machine Backups/.Spotlight-V100/Store-V1/Stores/677E0AD4-982A-4D9B-82D6-F8037A9D0A07/.s tore.db, o:5759000, s:16384) err:6

Mar 14 11:25:12 [computer_name] fseventsd[47]: disk logger: failed to open output file /Volumes/Time Machine Backups/.fseventsd/63657336facd1c9e (Device not configured). mount point /Volumes/Time Machine Backups/.fseventsd

Mar 14 11:25:12 [computer_name] mds[42]: (/Volumes/Time Machine Backups/.Spotlight-V100/Store-V1/Stores/677E0AD4-982A-4D9B-82D6-F8037A9D0A07)(E rror) IndexSDB in db_flush_datastore:/Volumes/Time Machine Backups/.Spotlight-V100/Store-V1/Stores/677E0AD4-982A-4D9B-82D6-F8037A9D0A07/st ore.db : db_sync_datastore: !WARNING! prior write-errors invalidate sync.

Mar 14 11:25:12 [computer_name] mds[42]: (/Volumes/Time Machine Backups/.Spotlight-V100/Store-V1/Stores/677E0AD4-982A-4D9B-82D6-F8037A9D0A07)(E rror) IndexCI in _ContentIndexSyncIndexBulk:preSync error:22 6

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Stopping backupd to allow ejection of backup destination disk!

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 2

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 3

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 4

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 5

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 6

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 7

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 8

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 9

Mar 14 11:25:12 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 10

[etc up to 999…]

Mar 14 11:25:13 [computer_name] com.apple.backupd[7539]: Error: (-36) Creating directory [computer_name] 999

Mar 14 11:25:13 [computer_name] com.apple.backupd[7539]: Couldn't create backup directory for computer name [computer_name]

Mar 14 11:25:14 [computer_name] com.apple.backupd[7539]: Backup completed successfully.

******************************************************************************** ******************************************

Oddly though, this "partially unsuccessful" backup was still followed by a couple of totally normal backups later that day, with only a few hundreds up to few thousands items being copied. The actual issue began on the next day.

I've tried the usual voodoo like fsck & permission repair & deep system cache cleanup via Applejack, TM reset etc., to no avail so far.

OSX is (was) having all sorts of trouble writing to the drive:

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: Error -36 deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/[computer_name]/2013-02-12-050300

Mar 14 11:25:11 [computer_name] com.apple.backupd[7539]: Error writing to backup log. NSFileHandleOperationException:*** -[NSConcreteFileHandle writeData:]: Device not configured

"Device not configured" means OSX has lost track of the sparse bundle.

That's caused all the errors following, and might also be the cause of the large backups.

The backups might be damaged (especially the one TM was trying to delete). Try Repairing them, per #A5 in Time Machine - Troubleshooting.

EDIT: It's also possible there's a problem with some names, of all odd things. They can cause intermittent problems. See #C9 in the same link.

Message was edited by: Pondini

Thanks for your reply.

Pondini wrote:

OSX is (was) having all sorts of trouble writing to the drive

"Device not configured" means OSX has lost track of the sparse bundle.

How the errors got in there is actually clear to me: the MBP went to sleep while the "Cleaning Up" process was still running. This is happening already for quite some time, but it was without any odd consequences until last week. Last week upon wakeup it failed to reconnect to the mounted disk image, that's the difference. The possible cause for the connection failure could be that the Time Capsule was rebooted due to power outage in the meantime while the MacBook was sleeping. Or that the MBP woke up while the TC was still booting. (I wasn't here during the power outage, so I don't know.)

Other than that, the Time Capsule is still working as expected. In the meantime I've also uploaded the latest firmware, then reverted back to the old one, then re-updated.

Pondini wrote:

Try Repairing them, per #A5 in Time Machine - Troubleshooting.

I already did the Verify Backup earlier this week, no problems found.

I'll try the Disk Utility method as well.

But…

That all still doesn't explain why the "too many items" bug now also affects the backup on the USB disk which wasn't in use since about a month. That's why the actual culprit must be on the MacBook, not on the Time Capsule. The only major difference is that the backup to the USB disk doesn't take as long as the backup to the Time Capsule which takes around 80 minutes, regardless if I connect through WLAN or Ethernet cable. The amount of items copied is approx. the same though.

Pondini wrote:

It's also possible there's a problem with some names, of all odd things. They can cause intermittent problems.

I don't think so. I'm using short simple names for all my devices and drives, usually three to seven plain ASCII characters which I'm not changing anymore as long as the device(s) remains in use. Which is quite a few years in some cases… (Heck, I still use a 2005 PowerBook G4 – which is also connected to this network – as a TV recorder… 🙂)