Time Machine always requires deep traversal?

Pondini wrote:

Is it really looking at all the snapshots? I'd expect it to only look at the last one (probably via the Latest alias).

Yes, it scans ALL the snapshots (or at least stat's all of the directories), but I don't think it recurses into any of them.

Pondini wrote:

Is (or was) the snapshot it's getting the Event ID and UUID from the last one?

Yes, I've had TM turned off a lot recently due to the issues and it correctly found the most recent backup and queried it.

Pondini wrote:

Have you tried another external HD? It almost sounds like something is going on with that drive that's returning a false/invalid value for the Event ID and/or UUID, in a way that TM doesn't seem to realize is wonky. An extremely long shot, but we're in extremely weird territory here. 😉

I'm currently creating a new partition on the existing drive to emulate wiping the drive (my plan is to unmount the original and reinitialize TM on the new partition). If that still behaves badly (which it might), I'm going to attempt to scrounge another external drive for testing.

And yes, we're very much in the weeds at this point...

Thanks,

Stephen

Pondini wrote:

Stephen Bash wrote:

. . .

And yes, we're very much in the weeds at this point...

Weeds, I'm used to.

This is more like the Okefenokee swamp. 😉

Ha! Seems that way.

Well, the initial backup on the new partition just finished, and even before the first hourly backup runs I have some interesting data:

2012-07-16-13:27:51 - Starting backup

Previous snapshot:
        None

Will traverse "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
=== Starting backup loop #1 ===
  Will use FirstBackupCopier


... snip...

Finished copying items for "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 1 hour, 37 minutes, 27.000 seconds
        Copied 440896 items (85.6 GB)
Gathering events since 9223372036854775807.
Needs new backup due to change in /
=== Starting backup loop #2 ===
  Will use IncrementalBackupCopier

... snip ...

Finished copying items for "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 2 minutes, 51.000 seconds
        Copied 20517 items (320.0 MB)
Gathering events since 9223372036854775807.
Needs new backup due to change in /
Some filesystem changes made during the course of the backup may not be accounted for. Still busy after 2 retries.
Finalizing completed snapshot
Finished finalizing completed snapshot

Backup complete.
Total time elapsed: 1 hour, 49 minutes, 57.000 seconds

So that cursed 2^63-1 event ID is still floating around. I'll let the first hourly go through just in case, but I'm guessing the behavior won't change. Then I'll try a different external disk. Perhaps a logical extension would be to initialize a new internal HD from one of my backups and see if the behavior persists across that (or even just a clean system perhaps). But that's getting into major time sink land...

Stephen

Pondini wrote:

Stephen Bash wrote:

. . .

So that cursed 2^63-1 event ID is still floating around. I'll let the first hourly go through just in case, but I'm guessing the behavior won't change.

Yeah, doubtful.

Yep, problem persisted.

Pondini wrote:

Then I'll try a different external disk.

Worth a shot.

No joy there either.

Pondini wrote:

I don't see anything in the earlier posts about installing the "combo" update and/or a fresh version of OSX, per Installing the ''combo'' update and/or Reinstalling OSX. If you haven't done that yet, that's also worth a try. If something is bunged up in your version of Snow Leopard, all sorts of bizarre things may occur.

Downloading now...

Thanks,

Stephen

Stephen Bash wrote:

Pondini wrote:

I don't see anything in the earlier posts about installing the "combo" update and/or a fresh version of OSX, per Installing the ''combo'' update and/or Reinstalling OSX. If you haven't done that yet, that's also worth a try. If something is bunged up in your version of Snow Leopard, all sorts of bizarre things may occur.

Downloading now...

Combo Update didn't change anything; TM's log still identifies 2^63-1 as the last event ID.

Reinstalling OS X gets interesting. This particular machine came with a 10.7 install disk (hence I still have a Lion partition floating around), while the 10.6 partition (my main platform) came from this process. That could be the crux of the problem, but I was (still am?) hoping that's not the case. To test that theory I could image a new partition with the same image and see if TM is broken there or not (the image is just the bare system, no development tools or common applications)... I'll have to think about it.

Thanks,

Stephen

Pondini wrote:

Stephen Bash wrote:

. . .

This particular machine came with a 10.7 install disk (hence I still have a Lion partition floating around), while the 10.6 partition (my main platform) came from this process. That could be the crux of the problem,

Yes, it cerainly could. 😟

Doesn't look like it's directly related. I was able to image a new partition (nice aspect of the process is imaging goes fast), and doing an initial backup the second pass did not require the deep traversal. To my surprise though, the log still has the 2^63-1 event ID, so that may actually be a red herring:

2012-07-17-13:40:15 - Starting backup

Previous snapshot:
          None

Will traverse "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
=== Starting backup loop #1 ===
  Will use FirstBackupCopier

Running preflight for "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
          Excluding /.Spotlight-V100: 25.9 MB (54 items)
          Excluding /.Trashes: 0 bytes (0 items)
          Excluding /.fseventsd: 12 KB (3 items)
          Excluding /.hotfiles.btree: 64 KB (0 items)
          Excluding /private/var/db/Spotlight: 36.2 MB (2 items)
          Excluding /Volumes: 4 KB (8 items)
          Excluding /Network: 0 bytes (0 items)
          Excluding /.vol: 0 bytes (0 items)
          Excluding /cores: 0 bytes (0 items)
          Excluding /private/tmp: 4 KB (6 items)
          Excluding /private/tftpboot: 0 bytes (0 items)
          Excluding /private/var/folders: 240.4 MB (74 items)
          Excluding /private/var/run: 40 KB (13 items)
          Excluding /private/var/tmp: 0 bytes (1 items)
          Excluding /private/var/vm: 64.0 MB (1 items)
          Excluding /private/var/db/dhcpclient: 4 KB (2 items)
          Excluding /Library/Caches: 68 KB (5 items)
          Excluding /Library/Logs: 12 KB (3 items)
          Excluding /System/Library/Caches: 17.2 MB (23 items)
          Excluding /private/var/log: 132 KB (33 items)
          Excluding /private/var/spool/cups: 0 bytes (3 items)
          Excluding /private/var/spool/fax: 0 bytes (0 items)
          Excluding /private/var/spool/uucp: 0 bytes (0 items)
          Excluding /private/var/db/dyld: 610.9 MB (13 items)
          Excluding /Users/bash/Library/Calendars/Calendar Cache: 112 KB (1 items)
          Should copy 392422 items (5.9 GB) representing 1542420 blocks of size 4096. 121911221 blocks available.
Preflight complete for "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 0.340 seconds

Processing preflight info
          Space needed for this backup: 7.1 GB (1851027 blocks of size 4096)
Finished processing preflight info

Copying items from "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
Finished copying items for "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 14 minutes, 2.000 seconds
          Copied 123885 items (5.9 GB)
Gathering events since 9223372036854775807.
Needs new backup due to change in /
=== Starting backup loop #2 ===
  Will use IncrementalBackupCopier

Running preflight for "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
          Calculating size of changes
          Should copy 74 items (8 KB) representing 2 blocks of size 4096. 120314246 blocks available.
Preflight complete for "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 3.483 seconds

Processing preflight info
          Space needed for this backup: 334.9 MB (85722 blocks of size 4096)
          Preserving last snapshot /Volumes/TM Test Backup/Backups.backupdb/...
Finished processing preflight info

Copying items from "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
Finished copying items for "TM Test" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 8.027 seconds
          Copied 926 items (9 KB)
Gathering events since 9223372036854775807.
Needs new backup due to change in /
Some filesystem changes made during the course of the backup may not be accounted for. Still busy after 2 retries.
Finalizing completed snapshot
Finished finalizing completed snapshot

Backup complete.
Total time elapsed: 14 minutes, 15.000 seconds

Pondini wrote:

What's on your Lion partition? What happens when you boot into it and back it up (preferably to a different disk or partition than your current backups)?

If I get a chance, I'll give it a try... I think I've been messing around enough this afternoon already 😉

blazetopher wrote:

Did either other folks on this thread find any solutions (if you're still listening)?

I'm still kicking around (and subscribed to updates on this thread). I haven't found a solution yet other turning off automatic backups and manually kicking one off once or twice a day. If the 10.6.7 update works for you, I'd like to know. I reinstalled the 10.6.8 combo update but wasn't sure about downgrading my main work computer...

blazetopher wrote:

The file counts are definitely in the 10's of thousands.

This made me curious, so I checked some of my logs on the TM volume itself (/Volumes/Backups/Backups.backupdb/warp/2012-07-17-005335/.Backup.log):

Running preflight for "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
        Scanning nodes needing deep traversal
        Node requires deep traversal: / reason:contains changes|must scan subdirs|fsevent|
        Calculating size of changes
        Should copy 889 items (18.1 MB) representing 4627 blocks of size 4096. 220574366 blocks available.
Preflight complete for "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 2 minutes, 46.000 seconds

Processing preflight info
        Space needed for this backup: 1.2 GB (321635 blocks of size 4096)
        Preserving last snapshot /Volumes/Backups/Backups.backupdb/warp/2012-07-16-235334
Finished processing preflight info

Copying items from "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
Finished copying items for "Snow Leopard" (mount: '/' fsUUID: ... eventDBUUID: ...)
Time elapsed: 2 minutes
        Copied 20501 items (18.2 MB)

And there's a major disconnect between what preflight thinks it should back up and what is actually copied (889 vs 20501)... I don't know if that's normal or not.

Thanks,

Stephen