Time Machine always requires deep traversal?

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

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

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

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"):

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

Well, I ran out of time this afternoon to try the safe boot, so I'll dig into it Monday morning (doing my best to NOT be in the office over the weekend).

Thanks!

Stephen

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

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