Looks like no one’s replied in a while. To start the conversation again, simply ask a new question.

Time Machine always requires deep traversal?

Hi all-


For the tl;dr crowd: every time my Mac Pro starts a backup, it does a deep traversal (this has gone on for about two months since I got the drive). I'm backing up to a 2TB USB external drive that is always connected. I've added the backup drive to Spotlight's exclude/privacy list. Yesterday I rebooted the machine using the OSX installation disk and performed disk repairs on both the system drive and the backup drive (neither was found to have any errors). I don't have clamXav or any other AV installed. What else can I try to avoid the deep traversal? Here are the console logs for two back-to-back backups (note that these are just before I got into the office, so I don't think user interaction is forcing the deep traversal):


5/31/12 6:53:32 AM
com.apple.backupd[5425]
Starting standard backup
5/31/12 6:53:33 AM
com.apple.backupd[5425]
Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
5/31/12 6:55:00 AM
com.apple.backupd[5425]
Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
5/31/12 6:57:11 AM
_spotlight[5455]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 6:57:11 AM
_spotlight[5460]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 6:57:21 AM
com.apple.backupd[5425]
No pre-backup thinning needed: 1.87 GB requested (including padding), 1.36 TB available
5/31/12 6:57:23 AM
_spotlight[5466]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 6:57:23 AM
_spotlight[5471]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 6:57:23 AM
_spotlight[5476]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 6:57:23 AM
_spotlight[5481]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 6:57:34 AM
com.apple.backupd[5425]
Copied 2085 files (17.3 MB) from volume Snow Leopard.
5/31/12 6:59:02 AM
com.apple.backupd[5425]
Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
5/31/12 7:01:05 AM
_spotlight[5498]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:01:05 AM
_spotlight[5503]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:01:13 AM
com.apple.backupd[5425]
No pre-backup thinning needed: 1.87 GB requested (including padding), 1.36 TB available
5/31/12 7:01:15 AM
_spotlight[5508]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:01:15 AM
_spotlight[5513]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:01:15 AM
_spotlight[5518]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:01:15 AM
_spotlight[5523]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:01:26 AM
com.apple.backupd[5425]
Copied 2085 files (16.9 MB) from volume Snow Leopard.
5/31/12 7:02:57 AM
com.apple.backupd[5425]
Starting post-backup thinning
5/31/12 7:32:41 AM
com.apple.backupd[5425]
Deleted backup /Volumes/Time Machine Backups/Backups.backupdb/warp/2012-05-29-143904: 1.36 TB now available
5/31/12 7:32:41 AM
com.apple.backupd[5425]
Post-back up thinning complete: 1 expired backups removed
5/31/12 7:32:42 AM
com.apple.backupd[5425]
Backup completed successfully.
5/31/12 7:53:33 AM
com.apple.backupd[5706]
Starting standard backup
5/31/12 7:53:33 AM
com.apple.backupd[5706]
Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
5/31/12 7:55:13 AM
com.apple.backupd[5706]
Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
5/31/12 7:57:26 AM
_spotlight[5735]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:57:26 AM
_spotlight[5740]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:57:35 AM
com.apple.backupd[5706]
No pre-backup thinning needed: 1.87 GB requested (including padding), 1.36 TB available
5/31/12 7:57:37 AM
_spotlight[5745]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:57:37 AM
_spotlight[5750]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:57:37 AM
_spotlight[5755]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:57:37 AM
_spotlight[5760]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 7:57:48 AM
com.apple.backupd[5706]
Copied 2085 files (18.9 MB) from volume Snow Leopard.
5/31/12 7:59:15 AM
com.apple.backupd[5706]
Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
5/31/12 8:01:24 AM
_spotlight[5778]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 8:01:24 AM
_spotlight[5783]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 8:01:32 AM
com.apple.backupd[5706]
No pre-backup thinning needed: 1.87 GB requested (including padding), 1.36 TB available
5/31/12 8:01:34 AM
_spotlight[5788]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 8:01:34 AM
_spotlight[5793]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 8:01:34 AM
_spotlight[5798]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 8:01:34 AM
_spotlight[5803]
vol.notice /usr/fl/etc/volume.cfg not found
5/31/12 8:01:43 AM
com.apple.backupd[5706]
Copied 2085 files (18.9 MB) from volume Snow Leopard.
5/31/12 8:03:15 AM
com.apple.backupd[5706]
Starting post-backup thinning
5/31/12 8:31:33 AM
com.apple.backupd[5706]
Deleted backup /Volumes/Time Machine Backups/Backups.backupdb/warp/2012-05-29-123915: 1.36 TB now available
5/31/12 8:31:33 AM
com.apple.backupd[5706]
Post-back up thinning complete: 1 expired backups removed
5/31/12 8:31:35 AM
com.apple.backupd[5706]
Backup completed successfully.


The long version: in March I got a 2TB USB external drive to back up the Mac Pro at my work. I've had good success with Time Machine at home, backing up two MacBooks and a Mac Mini with no problems what-so-ever (it really "just works"), so I was surprised when Time Machine struggled with the Mac Pro. I did a lot of research on the web, and followed as much advice as I could (excluding the backup drive from Spotlight, making sure backups completed uninterrupted, repairing drives, etc.), but I continue to have backups that take almost a full hour (and thus Time Machine is almost constantly running). The actual quantity of data backed up is pretty small (similar to the log above, it's usually 20-50 MB).


During my initial backup I ran into a problem with Git which may be pertitent, but I'm not sure. I was in charge of my company's conversion from Subversion to Git, and in the process I locally cloned a bunch of Git repositories (on the order of 300-400 repos). Since Git uses hard links between local clones, this all fit on my 500GB drive no problem. But Time Machine attempted to back up each directory independently, and the backup ballooned to over 2.5TB and didn't fit on the 2TB external drive. After I excluded the Git repos from the backup, the intial backup completed without any visible problems.


Otherwise the machine is used for pretty standard software development (python, gcc, gdb, git), plus standard office email/web browsing.


I've been digging into this on and off since I first noticed the problem shortly after getting the drive and I'm running out of ideas. Anyone have additional suggestions on how to avoid the deep traversal? Let me know if there's additional useful information I've left out.


Thanks!

Stephen

Mac Pro (Mid 2010), Mac OS X (10.6.8)

Posted on May 31, 2012 6:23 AM

Reply
Question marked as Best reply

Posted on May 31, 2012 6:03 PM

Stephen Bash wrote:

. . .

5/31/12 6:55:00 AM com.apple.backupd[5425] Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
...
5/31/12 6:59:02 AM com.apple.backupd[5425] Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|

That's curious. I've rarely seen those reason codes; it looks like there was a very large volume of file system changes, but that usually sends a different message.


Even stranger, it's doing a deep traversal on both passes of the same backup. I don't recall seeing that before, either, so I suspect a problem with the File System Event Store, the hidden log of file changes that OSX keps on each volume. TM normally uses it to see what needs to be backed-up, instead of the deep traversal.


Are you running any apps that routinely make many, many changes to the file system (files or folders added, changed, moved, renamed, etc.)?


5/31/12 7:01:05 AM _spotlight[5503] vol.notice /usr/fl/etc/volume.cfg not found

Spotlight is also very unhappy about whatever that is. I don't have an fl folder in my /usr folder, so have no idea what it is, or whether that's connected to the Time Machine problem, but it sure looks suspicious.


Any idea what it is?

174 replies
Question marked as Best reply

May 31, 2012 6:03 PM in response to Stephen Bash

Stephen Bash wrote:

. . .

5/31/12 6:55:00 AM com.apple.backupd[5425] Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
...
5/31/12 6:59:02 AM com.apple.backupd[5425] Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|

That's curious. I've rarely seen those reason codes; it looks like there was a very large volume of file system changes, but that usually sends a different message.


Even stranger, it's doing a deep traversal on both passes of the same backup. I don't recall seeing that before, either, so I suspect a problem with the File System Event Store, the hidden log of file changes that OSX keps on each volume. TM normally uses it to see what needs to be backed-up, instead of the deep traversal.


Are you running any apps that routinely make many, many changes to the file system (files or folders added, changed, moved, renamed, etc.)?


5/31/12 7:01:05 AM _spotlight[5503] vol.notice /usr/fl/etc/volume.cfg not found

Spotlight is also very unhappy about whatever that is. I don't have an fl folder in my /usr folder, so have no idea what it is, or whether that's connected to the Time Machine problem, but it sure looks suspicious.


Any idea what it is?

May 31, 2012 6:41 PM in response to Pondini

Pondini wrote:


Stephen Bash wrote:

. . .

5/31/12 6:55:00 AM com.apple.backupd[5425] Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
...
5/31/12 6:59:02 AM com.apple.backupd[5425] Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|

That's curious. I've rarely seen those reason codes; it looks like there was a very large volume of file system changes, but that usually sends a different message.


Even stranger, it's doing a deep traversal on both passes of the same backup. I don't recall seeing that before, either, so I suspect a problem with the File System Event Store, the hidden log of file changes that OSX keps on each volume. TM normally uses it to see what needs to be backed-up, instead of the deep traversal.


Are you running any apps that routinely make many, many changes to the file system (files or folders added, changed, moved, renamed, etc.)?


To be honest, that's the question I've been racking my brain with this whole time. I tend to prefer a clean, light system, and as such try to avoid long running processes in favor of starting things when I need them and then shutting them down. It's possible some of the commercial applications that work with my company's software are doing something in the background...


Googling around for "File System Event Store" (thanks!) leads me back to fs_usage, which I've used (briefly) in the past but may be the best tool for this job. Running it shows that at least one of the aforementioned commercial applications is running background services. Whether those particular processes are the culprit or not I don't know, but I've shut them down and I'll check the logs in the morning to see if the TM behavior changes.


I also noticed that Google Chrome is hitting the filesystem a lot, but as I also use Chrome on my home Macs without problem I'm doubtful.


Pondini wrote:

5/31/12 7:01:05 AM _spotlight[5503] vol.notice /usr/fl/etc/volume.cfg not found

Spotlight is also very unhappy about whatever that is. I don't have an fl folder in my /usr folder, so have no idea what it is, or whether that's connected to the Time Machine problem, but it sure looks suspicious.


Any idea what it is?


None whatsoever. I've checked on multiple 10.6.8 Macs and none of them have that elusive /usr/fl directory. Guess it's worth a little more Googling to see where it gets me... Thanks for echoing my suspicion.


Thanks!

Stephen

Jun 1, 2012 5:48 AM in response to Pondini

So shutting down Chrome and turning off the background processes helped, but not in the way I'd expect:


6/1/12 7:15:35 AMcom.apple.backupd[22679]Starting standard backup
6/1/12 7:15:36 AMcom.apple.backupd[22679]Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
6/1/12 7:17:01 AMcom.apple.backupd[22679]Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
6/1/12 7:19:09 AM_spotlight[22698]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:19:09 AM_spotlight[22703]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:19:36 AMcom.apple.backupd[22679]No pre-backup thinning needed: 1.85 GB requested (including padding), 1.36 TB available
6/1/12 7:19:55 AM_spotlight[22710]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:19:55 AM_spotlight[22715]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:19:55 AM_spotlight[22720]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:19:55 AM_spotlight[22725]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:20:35 AMcom.apple.backupd[22679]Copied 12385 files (18 KB) from volume Snow Leopard.
6/1/12 7:22:04 AMcom.apple.backupd[22679]Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
6/1/12 7:24:12 AM_spotlight[22753]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:24:12 AM_spotlight[22758]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:24:38 AMcom.apple.backupd[22679]No pre-backup thinning needed: 1.85 GB requested (including padding), 1.36 TB available
6/1/12 7:24:57 AM_spotlight[22765]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:24:57 AM_spotlight[22770]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:24:57 AM_spotlight[22775]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:24:57 AM_spotlight[22780]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 7:25:33 AMcom.apple.backupd[22679]Copied 12385 files (11 KB) from volume Snow Leopard.
6/1/12 7:27:17 AMcom.apple.backupd[22679]Starting post-backup thinning
6/1/12 7:27:26 AMcom.apple.backupd[22679]Deleted backup /Volumes/Time Machine Backups/Backups.backupdb/warp/2012-05-31-070255: 1.36 TB now available
6/1/12 7:27:26 AMcom.apple.backupd[22679]Post-back up thinning complete: 1 expired backups removed
6/1/12 7:27:26 AMcom.apple.backupd[22679]Backup completed successfully.
6/1/12 8:15:36 AMcom.apple.backupd[22962]Starting standard backup
6/1/12 8:15:36 AMcom.apple.backupd[22962]Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
6/1/12 8:17:05 AMcom.apple.backupd[22962]Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
6/1/12 8:19:17 AM_spotlight[22981]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:19:17 AM_spotlight[22986]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:19:44 AMcom.apple.backupd[22962]No pre-backup thinning needed: 1.85 GB requested (including padding), 1.36 TB available
6/1/12 8:20:03 AM_spotlight[22993]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:20:03 AM_spotlight[22998]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:20:03 AM_spotlight[23003]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:20:03 AM_spotlight[23008]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:20:39 AMcom.apple.backupd[22962]Copied 12385 files (18 KB) from volume Snow Leopard.
6/1/12 8:22:08 AMcom.apple.backupd[22962]Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
6/1/12 8:24:16 AM_spotlight[23036]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:24:16 AM_spotlight[23041]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:24:42 AMcom.apple.backupd[22962]No pre-backup thinning needed: 1.85 GB requested (including padding), 1.36 TB available
6/1/12 8:25:00 AM_spotlight[23048]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:25:00 AM_spotlight[23053]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:25:00 AM_spotlight[23058]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:25:00 AM_spotlight[23063]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 8:25:34 AMcom.apple.backupd[22962]Copied 12385 files (11 KB) from volume Snow Leopard.
6/1/12 8:27:22 AMcom.apple.backupd[22962]Starting post-backup thinning
6/1/12 8:27:33 AMcom.apple.backupd[22962]Deleted backup /Volumes/Time Machine Backups/Backups.backupdb/warp/2012-05-31-080313: 1.36 TB now available
6/1/12 8:27:33 AMcom.apple.backupd[22962]Post-back up thinning complete: 1 expired backups removed
6/1/12 8:27:33 AMcom.apple.backupd[22962]Backup completed successfully.


Even scanning quickly it's obvious all the same error messages are in the log (the TM deep traversal and the Spotlight vol.notice), but looking at the times the backup is over three times faster now! (12ish minutes today vs. 39ish yesterday) Now that I'm in the office I've restarted Chrome, and I'll keep an eye on the logs to see if it has an effect on the total backup time or not (my hypothesis is no).


So my underlying concern that TM was always running has been somewhat allayed, but now I'm curious if it could be even faster without the deep traversal. I foresee more fs_usage testing in my future...


I'll update this thread if I learn more...


Thanks,

Stephen

Jun 1, 2012 8:17 AM in response to Stephen Bash

Stephen Bash wrote:

. . .

So my underlying concern that TM was always running has been somewhat allayed, but now I'm curious if it could be even faster without the deep traversal. I foresee more fs_usage testing in my future...

Yeah, it shouldn't be doing deep traversals all the time, much less on both passes of the same backup.


They should only happen after things like a system crash or power failure, backup drive power failure or disconnected improperly, or a large volume of changes, such as an OSX update.


I'm still suspicious of the Spotlight messages. Is Spotlight working ok otherwise? Do the right things turn up where/when they should? Does it seem to be indexing constantly? If it doesn't seem to behave correctly, it's possible the index is damaged in a way Disk Utility/fsck can't detect. We see that occasionally on Lion (a whole new indexing scheme), but it happens on SL now and then, too. It's a long shot, but you might try deleting the index so it will be recreated from scratch. It's the hidden .Spotlight-V100 folder. See the pink box in #D2 of Time Machine - Troubleshooting for details.

Jun 1, 2012 1:29 PM in response to Pondini

Pondini wrote:


I'm still suspicious of the Spotlight messages. Is Spotlight working ok otherwise? Do the right things turn up where/when they should? Does it seem to be indexing constantly? If it doesn't seem to behave correctly, it's possible the index is damaged in a way Disk Utility/fsck can't detect. We see that occasionally on Lion (a whole new indexing scheme), but it happens on SL now and then, too. It's a long shot, but you might try deleting the index so it will be recreated from scratch. It's the hidden .Spotlight-V100 folder. See the pink box in #D2 of Time Machine - Troubleshooting for details.


I haven't noticed major issues with Spotlight, but I don't use it often. My most common use for it is to launch Console or Activity Monitor when I'm too lazy to take my hands off the keyboard.


But based on your suggestion I deleted the .Spotlight-V100 folder from the backup drive. The next few backups all had the same spotlight error message (and the deep traversal). So out of curiousity I deleted the .Spotlight-V100 folder from the system drive. Looking at console that's when things got interesting (though it's possible a lot of this is "normal"):


6/1/12 2:02:08 PMmds[51](Normal) DiskStore: Creating index for /
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:03:33 PMmdworker[24915]MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds
6/1/12 2:09:28 PMmdworker[24749]CFPropertyListCreateFromXMLData(): Old-style plist parser: missing semicolon in dictionary.
6/1/12 2:12:19 PMmdworker32[24938]Error loading /Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: dlopen(/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight, 262): no suitable image found. Did find:
/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: mach-o, but wrong architecture
6/1/12 2:12:19 PMmdworker32[24938]Cannot find function pointer MetadataImporterPluginFactory for factory BA504EF9-52E6-42F1-8032-3A651F8EC1E7 in CFBundle/CFPlugIn 0x11ab30 </Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter> (bundle, not loaded)
6/1/12 2:12:19 PMmdworker32[24938]Error loading /Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: dlopen(/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight, 262): no suitable image found. Did find:
/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: mach-o, but wrong architecture
6/1/12 2:12:19 PMmdworker32[24938]Cannot find function pointer MetadataImporterPluginFactory for factory BA504EF9-52E6-42F1-8032-3A651F8EC1E7 in CFBundle/CFPlugIn 0x11ab30 </Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter> (bundle, not loaded)
6/1/12 2:14:46 PMmdworker[24749]CFPropertyListCreateFromXMLData(): Old-style plist parser: missing semicolon in dictionary.
6/1/12 2:15:37 PMcom.apple.backupd[24998]Starting standard backup
6/1/12 2:15:37 PMcom.apple.backupd[24998]Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
6/1/12 2:17:17 PMcom.apple.backupd[24998]Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|
6/1/12 2:17:45 PMmdworker[24749]multibyte IDs are unsupported.
6/1/12 2:19:40 PMmdworker32[24938]kCGErrorFailure: Set a breakpoint @ CGErrorBreakpoint() to catch errors as they are logged.
6/1/12 2:20:22 PMmdworker[24915]### Error:-25257 File:/SourceCache/CommerceCore/CommerceCore-9.1/ISPurchaseReceipt.m Line:335
6/1/12 2:20:23 PMmdworker[24915]### Error:-25257 File:/SourceCache/CommerceCore/CommerceCore-9.1/ISPurchaseReceipt.m Line:335
6/1/12 2:21:50 PMnathan[25042]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 2:21:50 PMnathan[25047]vol.notice /usr/fl/etc/volume.cfg not found
6/1/12 2:22:21 PMcom.apple.backupd[24998]No pre-backup thinning needed: 100.0 MB requested (including padding), 1.36 TB available
6/1/12 2:22:21 PMcom.apple.backupd[24998]Waiting for index to be ready (100)
6/1/12 2:22:32 PMmdworker[24749]ENSpotlightImporter:persistentStoreCoordinator unable to add persistent store coordinator - Error Domain=NSCocoaErrorDomain Code=513 UserInfo=0x1035ce1f0 "The file couldn’t be saved because you don’t have permission."
6/1/12 2:22:32 PMmdworker[24749]ENSpotlightImporter:importFileAtPath:attributes:error: to find object id from path /Users/bash/Library/Caches/Metadata/CoreData/com.evernote.Evernote/11589546-3FC 1-4E97-97CD-3EF3DA3E4B3D/ENNote/_records/1/0/p114.ennote


Followed by many repititions of the last two error messages over the next 10-15 minutes (for different files). It looks like a lot of permission errors and such... Any of this make sense to you?


Thanks,

Stephen

Jun 1, 2012 2:03 PM in response to Stephen Bash

Stephen Bash wrote:

. . .

I deleted the .Spotlight-V100 folder from the system drive.

Oh, sorry, I see I wasn't clear -- I meant the system drive, not the TM drive. 😊


MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds


That's quite unusual. A few reports of that were fixed by a Safe Boot, which sounds like a good idea anyway.


Error loading /Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: dlopen(/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight, 262): no suitable image found. Did find:/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: mach-o, but wrong architecture

That may be a clue. Somehow, you've got the wrong version ("wrong architecture") of an mdimporter (used by Spotlight to find extra metadata in files made by certain apps) for the Motion app. Several of the messages following that one seem related.


That used to happen when folks upgraded from a PPC processor to a Mac with an Intel processor, and some PPC files didn't get replaced. I doubt the safe boot will fix it, and know nothing about the Motion app, so the only thing I can suggest is to temporarily exclude those files from Spotlight indexing (System Prefs > Spotlight > Privacy), until you can figure out what's going on.


Followed by many repititions of the last two error messages over the next 10-15 minutes (for different files). It looks like a lot of permission errors and such.


After the safe boot, if those continue, try repairing permissions.


This just gets weirder and weirder, doesn't it? I keep thinking we're going to find a culprit, sooner or later . . .

EDIT: by the way, could you just copy log messages directly from Console? That format is rather difficult to deal with here. Thanks.


Message was edited by: Pondini

Jun 4, 2012 12:46 PM in response to Pondini

Pondini wrote:

Error loading /Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: dlopen(/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight, 262): no suitable image found. Did find:/Applications/Motion.app/Contents/Library/Spotlight/Motion Spotlight.mdimporter/Contents/MacOS/Motion Spotlight: mach-o, but wrong architecture

That may be a clue. Somehow, you've got the wrong version ("wrong architecture") of an mdimporter (used by Spotlight to find extra metadata in files made by certain apps) for the Motion app. Several of the messages following that one seem related.


That used to happen when folks upgraded from a PPC processor to a Mac with an Intel processor, and some PPC files didn't get replaced. I doubt the safe boot will fix it, and know nothing about the Motion app, so the only thing I can suggest is to temporarily exclude those files from Spotlight indexing (System Prefs > Spotlight > Privacy), until you can figure out what's going on.


Motion is a companion to Apple Final Cut Pro, so it makes sense Apple would have custom indexing of Motion projects. It surprises me a little the wrong indexer is active, but in the past year I've upgraded from Motion 4 (32-bit) to Motion 5 (64-bit) so it could be something lingering from that. I'll add the directories to the Spotight exclude list.


Pondini wrote:

MDS Error: unable to create user DBs in /var/folders/zz/zzzivhrRnAmviuee++++KE+++3Y/-Caches-//mds


That's quite unusual. A few reports of that were fixed by a Safe Boot, which sounds like a good idea anyway.


Followed by many repititions of the last two error messages over the next 10-15 minutes (for different files). It looks like a lot of permission errors and such.


After the safe boot, if those continue, try repairing permissions.


This just gets weirder and weirder, doesn't it? I keep thinking we're going to find a culprit, sooner or later . . .


So I started the day with a Safe Boot and a repair permissions. The repair permissions found lots of problems that it fixed, but nothing that sounded horrible. After that I went ahead and restarted normally. At that point Spotlight insisted on indexing the TM volume even though I re-added it to the Spotlight exclude list. Eventually Spotlight finished indexing both the system drive and the TM drive. The Motion issue cropped up during indexing, but none of the permission errors from Friday. Several hours later this cropped up several times:

6/4/12 12:06:05 PM mdworker[3335] CgBI: unknown critical chunk


Unfortunately there's no context to go with it... the previous message was 20 minutes before it started, and the message is repeated multiple times per second for about 7 minutes. Then nothing for another few minutes.


Since then about three or four backups have gone through, all with the same behavior (deep traversal, Spotlight complaining about /usr/fl/ missing). So while the repair permissions seems to have helped Spotlight indexing, neither it nor the Safe Boot seemed to help TM.

Pondini wrote:


EDIT: by the way, could you just copy log messages directly from Console? That format is rather difficult to deal with here. Thanks.


Actually, that's how Chrome is pasting from Console. Pasting into vim shows the text Console is copying is tab-delimited, so it seems either Chrome or the discussion board editor is translating the tabs into table divisions. That surprised me when I first did it, but I couldn't find a better solution... This time I just stripped the tabs and put it in a quote... *shrug*


Thanks,

Stephen

Jun 4, 2012 1:23 PM in response to Stephen Bash

Stephen Bash wrote:

. . .

At that point Spotlight insisted on indexing the TM volume even though I re-added it to the Spotlight exclude list.

Yeah, you can't really exclude your backups from indexing -- TM won't work without it. See the note in #2 here: http://docs.info.apple.com/article.html?path=Mac/10.6/en/8991.html. (Effective with Lion, when you exclude a TM drive, you get a message that it will index the backups, but not any other files on the disk.)


6/4/12 12:06:05 PM mdworker[3335] CgBI: unknown critical chunk

A quick search points to problems with a PNG file). See https://discussions.apple.com/thread/1976694


Since then about three or four backups have gone through, all with the same behavior (deep traversal, Spotlight complaining about /usr/fl/ missing). So while the repair permissions seems to have helped Spotlight indexing, neither it nor the Safe Boot seemed to help TM.

Rats. I doubt the two (deep traversal and Spotlight message) are connected, but you never know.


It's the "reason:contains changes|must scan subdirs|fsevent|" message that's rather unusual. I take it you didn't find anything with fs_usage or the like?


Pondini wrote:


EDIT: by the way, could you just copy log messages directly from Console? That format is rather difficult to deal with here. Thanks.

Actually, that's how Chrome is pasting from Console. Pasting into vim shows the text Console is copying is tab-delimited, so it seems either Chrome or the discussion board editor is translating the tabs into table divisions. https://discussions.apple.com/thread/1976694

Must be Chrome -- neither Safari nor Firefox does it. I have see it a few times before; at least now I know what it is. No big deal; sometimes it's a bit difficult to quote a message.

Jun 12, 2012 8:04 AM in response to Pondini

Pondini wrote:


It's the "reason:contains changes|must scan subdirs|fsevent|" message that's rather unusual. I take it you didn't find anything with fs_usage or the like?


I watched the system on and off for the last week, and didn't find any clues from either fs_usage or lsof. There's a lot of UNIX socket/named pipe/IPC activity due to my use of Synergy, but I turned that off yesterday for testing and the deep traversal still happened every backup. The message is so unique I'm surprised there aren't more Google results for it...


I'm running out of ideas...


Thanks,

Stephen

Jun 12, 2012 11:11 AM in response to Stephen Bash

Stephen Bash wrote:

. .

I'm running out of ideas...

Yeah, me, too. About all I can suggest now is, something damaged in your installation of OSX. You might try installing the "combo" update, per Installing the ''combo'' update and/or Reinstalling OSX. If that doesn't help, installing a fresh version of OSX (that won't disturb anything else), per the same article, might do the trick.

Jun 27, 2012 8:10 AM in response to Pondini

Hello,


I seem to meet a similar problem with TM on my MacBook pro...

TM takes ages (i.e. more than 30 minutes) to save around 7 Go changes...

Here is the log I get from TM Buddy widget:

"

Starting standard backup

Backing up to: /Volumes/TimeMachSauv/Backups.backupdb

Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|

No pre-backup thinning needed: 9.14 GB requested (including padding), 104.63 GB available

Copied 332143 files (4.2 GB) from volume Macintosh HD.

Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|

"

and then I have to wait... I started the last backup at 16:35, it's 17:09, and backup is not finished...

Everytime I launch TM backup I get the bolded messages.

I tried almost everything I found on the net including formating the TM drive (with 0s), doing a full maintenance of my sytem, excluding the TM drive from spotlight, etc... TM drive seems OK, my HHD has recently been changed and appears OK.

Do you have any idea please?

Regards


pierrick

Jun 27, 2012 5:29 PM in response to PierrickL

PierrickL wrote:

. . .

Node requires deep traversal:/ reason:contains changes|must scan subdirs|fsevent|

That's the same message Stephen is getting, and is quite odd to get it twice in the same backup. It sounds like a very high volume of file changes, which could happen for the first "pass," but makes no sense for the second.


If you've tried everything he or I listed above, all I can suggest now is, something damaged in your installation of OSX. You might try installing the "combo" update, per Installing the ''combo'' update and/or Reinstalling OSX. If that doesn't help, installing a fresh version of OSX (that won't disturb anything else), per the same article, might do the trick.


(Since Stephen hasn't posted back with his results of that, we don't have a very good idea whether that may fix it or not.)

Time Machine always requires deep traversal?

Welcome to Apple Support Community
A forum where Apple customers help each other with their products. Get started with your Apple ID.