You can make a difference in the Apple Support Community!

When you sign up with your Apple Account, you can provide valuable feedback to other community members by upvoting helpful replies and User Tips.

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 Top-ranking 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

Feb 6, 2013 2:04 AM in response to ZX48

An hour later and I'm up to 17,000...(or am I misinterpretting what this number is?). If it is a folder, can I delve into it to see where the specific files are being created?


total 48

-rw------- 1 root admin 17812 6 Feb 09:37 fc007475e29523e8

-rw------- 1 root admin 36 5 Feb 16:23 fseventsd-uuid


---

EDIT:


I now see that this number is the size of the file in bytes,a nd that the preceding "48" is not the number of files, but the number of 512-byte blocks used - so 48 = 24MB.


From the manual:


The Long Format

If the -l option is given, the following information is displayed for

each file: file mode, number of links, owner name, group name, number of

bytes in the file, abbreviated month, day-of-month file was last modi-

fied, hour file last modified, minute file last modified, and the path-

name. In addition, for each directory whose contents are displayed, the

total number of 512-byte blocks used by the files in the directory is

displayed on a line by itself, immediately before the information for the

files in the directory.


So, I guess the question is: Why do I have this one enormous (and growing) file in .fseventsd?

Feb 6, 2013 7:24 AM in response to ZX48

95% full on the backup hard drive is probably not a good thing. Perhaps Time Machine will trim down your backups after a few cycles? Otherwise you should do what you can to free space on the backup drive.


Are you backing up Parallels or VMware virtual machines?


How many TM runs have you been through since clearing .fseventsd?



B

Feb 6, 2013 7:35 AM in response to ZX48

ZX48 wrote:


Wait. I've just realised TM has initiated another backup straight after the one I jsut triggered - that is why the HD is spinning. I'm not sure it is fixed. I haven't done anything in the interim and the number of copied files is now already up to 36766 (21.3 MB). :-(


Look in /Library/Preferences and <home folder>/Library/Preferences -- see if there are thousands of empty files there with 4 or more nonsense characters in the names. If so, they might be the problem. Delete them.


total 48

-rw------- 1 root admin 17812 6 Feb 09:37 fc007475e29523e8

-rw------- 1 root admin 36 5 Feb 16:23 fseventsd-uuid

. . .

So, I guess the question is: Why do I have this one enormous (and growing) file in .fseventsd?


That shouldn't matter to Time Machine, since it doesn't back up the Event Store -- it's excluded automatically. It's used only to determine what other files have been changed and need to be backed-up. I'm no expert in this area, but your results don't seem out of line, compared to mine.

Feb 6, 2013 7:43 AM in response to bernuli

bernuli wrote:


95% full on the backup hard drive is probably not a good thing. Perhaps Time Machine will trim down your backups after a few cycles? Otherwise you should do what you can to free space on the backup drive.

No, that's not a problem. Time Machine is designed to use all the available space, and it will delete old backups automatically when it runs out of room. OSX needs a lot of free space on the startup drive, but a data-only drive doesn't, especially a backup drive where the files aren't accessed frequently.


If there's anything else there, besides the backups, that's usuallly not a good idea, though.

Feb 6, 2013 8:09 AM in response to Pondini


If there's anything else there, besides the backups, that's usuallly not a good idea, though.


There is actually (some manual copies of some large folders from a different computer). These are held in a separate folder at the root of the drive. Not in a separate partition.


But yes, the drive is full becasue it has been used as a backup for 3 years or so (it is a RAID 1 mirrored WD MyBook 2x1TB connected via FW800. Approx 50GB free.).


I don't have any of the errant pref files.


I just ran terminal command again:


total 88

-rw------- 1 root admin 17812 6 Feb 09:37 fc007475e29523e8

-rw------- 1 root admin 16405 6 Feb 15:25 fc007475e2a3514b

-rw------- 1 root admin 36 5 Feb 16:23 fseventsd-uuid


Then I just ran a backup:


06/02/2013 15:40:10 com.apple.backupd[5364] Starting standard backup
06/02/2013 15:40:10 com.apple.backupd[5364] Backing up to: /Volumes/MyBook/Backups.backupdb
06/02/2013 15:41:05 com.apple.backupd[5364] No pre-backup thinning needed: 3.56 GB requested (including padding), 49.31 GB available
06/02/2013 15:45:28 com.apple.backupd[5364] Copied 48527 files (345.5 MB) from volume Snow Leopard SSD.
06/02/2013 15:45:39 com.apple.backupd[5364] No pre-backup thinning needed: 3.15 GB requested (including padding), 48.95 GB available
06/02/2013 15:46:14 com.apple.backupd[5364] Copied 2812 files (1.9 MB) from volume Snow Leopard SSD.
06/02/2013 15:46:30 com.apple.backupd[5364] Starting post-backup thinning
06/02/2013 15:50:22 com.apple.backupd[5364] Deleted backup /Volumes/MyBook/Backups.backupdb/SL/2013-02-04-092140: 48.98 GB now available
06/02/2013 15:53:40 com.apple.backupd[5364] Deleted backup /Volumes/MyBook/Backups.backupdb/SL/2013-02-05-131940: 49.33 GB now available
06/02/2013 15:53:40 com.apple.backupd[5364] Post-back up thinning complete: 2 expired backups removed
06/02/2013 15:53:43 com.apple.backupd[5364] Backup completed successfully.


48,527 files and 345MB taking 5-6 minutes, plus another 7 minutes for the thinning.


I then immediately clicked "Backup Now":


06/02/2013 15:54:43 com.apple.backupd[5364] Starting standard backup
06/02/2013 15:54:43 com.apple.backupd[5364] Backing up to: /Volumes/MyBook/Backups.backupdb
06/02/2013 15:55:25 com.apple.backupd[5364] No pre-backup thinning needed: 3.16 GB requested (including padding), 49.33 GB available
06/02/2013 15:59:40 com.apple.backupd[5364] Copied 48510 files (7.5 MB) from volume Snow Leopard SSD.
06/02/2013 15:59:50 com.apple.backupd[5364] No pre-backup thinning needed: 3.16 GB requested (including padding), 49.31 GB available
06/02/2013 16:00:22 com.apple.backupd[5364] Copied 2812 files (1.5 MB) from volume Snow Leopard SSD.
06/02/2013 16:00:39 com.apple.backupd[5364] Starting post-backup thinning


As you can see, it still copied another 48,510 files (but only 7.5MB this time) taking 6 minutes total.

While it is better than before (I don't have the fans spinning up durign the backup process) it still seems just as broken as before I cleaned up .fseventsd


Please note that after clearing .fseventsd, I managed only 3 backups (of approx 1800 files each), before that number lept to 36k, and now 48k.


Do you think this is as good as I can get it?

Feb 6, 2013 8:50 AM in response to ZX48

ZX48 wrote:

. . .

There is actually (some manual copies of some large folders from a different computer). These are held in a separate folder at the root of the drive. Not in a separate partition.

That should be ok, but really ought to have been put in a separate partition (it's probably too late to partition it now).


Time Machine won't delete it, but if you ever want or need to delete all the backups, it will take a very long time (many minutes, perhaps hours) since you can't just erase the partition.


In addition, be very careful about adding to it -- if the drive gets entirely full, TM won't be able to get started far enough to begin deleting old backups, and will just crash.



total 88

-rw------- 1 root admin 17812 6 Feb 09:37 fc007475e29523e8

-rw------- 1 root admin 16405 6 Feb 15:25 fc007475e2a3514b

-rw------- 1 root admin 36 5 Feb 16:23 fseventsd-uuid

I'm not sure that's bad. Here's mine so far this month:


-rw------- 1 root wheel 27723 Feb 1 10:37 636573335c1af6a7

-rw------- 1 root wheel 36246 Feb 1 17:59 636573335c1ef5a0

-rw------- 1 root wheel 42744 Feb 1 19:15 636573335c20ac62

-rw------- 1 root wheel 26874 Feb 2 16:18 636573335c2a41b1

-rw------- 1 root wheel 35134 Feb 3 00:02 636573335c2f8efd

-rw------- 1 root wheel 26827 Feb 3 16:48 636573335c360052

-rw------- 1 root wheel 32491 Feb 4 09:00 636573335c3acf51

-rw------- 1 root wheel 28111 Feb 4 19:15 636573335c428bf3

-rw------- 1 root wheel 26441 Feb 5 17:29 636573335c4cf953

-rw------- 1 root wheel 18985 Feb 5 20:15 636573335c4edbb9

-rw------- 1 root wheel 75 Feb 5 20:15 636573335c4edbba

-rw------- 1 root wheel 70 Feb 5 20:17 636573335c4efe52

-rw------- 1 root wheel 75 Feb 5 20:17 636573335c4efe53

-rw------- 1 root wheel 125 Feb 5 20:24 636573335c4f0d7b

-rw------- 1 root wheel 75 Feb 5 20:24 636573335c4f0d7c

-rw------- 1 root jamespond 36 Feb 5 20:24 fseventsd-uuid


I've not been doing much besides email, but have rebooted a couple of times.



As you can see, it still copied another 48,510 files (but only 7.5MB this time) taking 6 minutes total.

While it is better than before (I don't have the fans spinning up durign the backup process) it still seems just as broken as before I cleaned up .fseventsd


Please note that after clearing .fseventsd, I managed only 3 backups (of approx 1800 files each), before that number lept to 36k, and now 48k.


Do you think this is as good as I can get it?

Sorry, I really don't know what's going on. 😟


Have you tried seeing what's getting backed-up, via one of the apps in #A2 of Time Machine - Troubleshooting?


If you haven't yet, try a Safe Boot -- that might help, or find something else wrong.



For some reason, it does seem limited to 10.6.8. I believe a few folks have fixed it by reinstalling Snow Leopard, then only updating to 10.6.7 (but be aware of the 3rd item in #D5 of the same link).

Feb 6, 2013 9:11 AM in response to Pondini

Thanks. I can't run 10.6.7 - my machine is only compatible with 10.6.8 (2011 Mac mini i7).


I used Time Tracker - a neat piece of software - thanks!


I think the occasions when I get ~300MB backup are when I've saved something within my Dropbox folder, as I have a 277.7MiB file inside the hidden ".dropbox" folder that is not backed up every time (i.e. not when the backup is 10MB or so). The large file is named: "sigstore.dbx"


That seems like a pretty huge file, and I guess it gets modified any time I make even just a small change to one of the files within Dropbox. Perhaps that whole ".dropbox" folder should be excluded from TM?


In any case, if I expand all of the tree, there is nowhere near the 48,000 files indicated by TM. I can only assume that the TM/console is reporting oncorrectly. (or that TimeTracker can't see all the supposed files).


So excluding the sigstore.dbx woudln't make much difference.


Cheers though!

Feb 6, 2013 9:39 AM in response to ZX48

ZX48 wrote:


Thanks. I can't run 10.6.7 - my machine is only compatible with 10.6.8 (2011 Mac mini i7).

Rats. Thought that might be a viable workaround.


That seems like a pretty huge file, and I guess it gets modified any time I make even just a small change to one of the files within Dropbox. Perhaps that whole ".dropbox" folder should be excluded from TM?

Yes, that's just Dropbox's way of seeing what needs to be sent to their servers. No reason for Time Machine to back it up. Mine's excluded.



In any case, if I expand all of the tree, there is nowhere near the 48,000 files indicated by TM. I can only assume that the TM/console is reporting oncorrectly. (or that TimeTracker can't see all the supposed files).

Time Tracker will usually show something on a file/folder you're not authorized to see, such as:


User uploaded file


Those are folders we're not permitted to see (inside a hidden folder!) You can grant yourself permission to see them, but if you don't see anything in red via Time Tracker, the problem is elsewhere.



The counts are always high (but not as high as you've geen getting). I suspect it's counting metadata separately (extended attributes, permissions, ACLs, etc.) but I have no idea how to determine that, or whether that's what it's stumbling over for you.

Feb 6, 2013 10:45 PM in response to ZX48

I have found that the number of files backupd reports as copied is much larger than the number of new files copied to the TM archive.


What is happening, at least to me, on 10.6.8 is that TM for some reason thinks a folder has been modified, even though it hasn't. It then backs up the folder but checks each file individually and skips when it finds no modification compared to what is on the TM drive. It reports back that it copied every file, though really they are just all hard links. This all takes extra processing time and slows it down needlessly.


Restarting seems to help with this.


I'll keep digging to try and find out why.



B

Feb 7, 2013 7:25 AM in response to bernuli

OK. So I guess at least I've figured a few things out. TM makes backups of both my .dropbox folder (containing a 270MB .sigstore.dbx database file AND it backs up my Sente library file (>100MB). Both of these get upadted by the OS/software for very little actual change to my data. So at least this explains why I see sequential backups being approx 500MB even when I do very little actual modification.


It would also explain why the drive is filling up so fast. Hourly backups and approx 0.5GB per hour = 10-12GB per day.

None of this explains why TM thinks I have 49000 files needing backing up, but I guess I have to live with that bug. At least for me, clearing out fseventsd didn't last for more than 3 backup cycles.


In TimeTracker I do have a number of "red" files. Is it worth investigating inside these?


https://www.dropbox.com/s/0bs96ctkng241ig/TT%20grab.png

Feb 7, 2013 8:31 AM in response to ZX48

ZX48 wrote:

. . .

TM makes backups of both my .dropbox folder (containing a 270MB .sigstore.dbx database file AND it backs up my Sente library file (>100MB). Both of these get upadted by the OS/software for very little actual change to my data.

Yup. TM backs-up almost everything that's changed at all. (It does exclude system files, most logs & caches, trash, etc.).



None of this explains why TM thinks I have 49000 files needing backing up, but I guess I have to live with that bug. At least for me, clearing out fseventsd didn't last for more than 3 backup cycles.

That's a tough one. I can only suspect that you have some non-standard process or app running that's marking things as changed when they really aren't.


Are you running any anti-virus software? Some of those can cause all sorts of problems, although I don't recall seeing this particular one.


Or any sort of system monitoring app?


In TimeTracker I do have a number of "red" files. Is it worth investigating inside these?

Those all look like standard system files/folders, and should be small.

Feb 7, 2013 8:42 AM in response to ZX48

This is strange – I came to the forum as I've been having a very similar problem. Could be coincidence, but I'm replying to this thread in case there is a connection.


I have been using TM without issue for 2 years, but over the last week or so I have noticed that it is taking a long time to complete it's hourly backups. Despite the fact that I am only working on one file, it prepares and backs up several hundred items, a total of aound 40mb – every hour.

Feb 7, 2013 8:43 AM in response to ZX48

ZX48 wrote:


Could it be CrashPlan Pro?

That's an online backup app, right? You're using that in addition to Dropbox?


I don't use it, and doubt it's a problem, but suppose anything's possible. Do you know where it keeps it's files, and are they excluded from TM? Does anything show up via TimeTracker?


Anything in their help/support?



The only other thing (I know of) is SecondBar and FanControl

I'd doubt either of those is a problem, but as I don't use them myself, can't be sure.

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 Account.