Observing the stupid at work
Watch how TimeMachine's backupd performs its only task, backing up stuff, like an utter moron. Kindly witness the timestamps...
I massaged the log output heavily for readability.
14:35:30 backupd: Node requires deep traversal:/Volumes/Source reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 14:42:55 backupd: Node requires deep traversal:/Volumes/Installer reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 14:43:07 backupd: Node requires deep traversal:/Volumes/Users reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 14:49:37 backupd: Node requires deep traversal:/Volumes/Old Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 14:50:05 backupd: Node requires deep traversal:/Volumes/Musik reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 14:50:18 backupd: Node requires deep traversal:/Volumes/Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 14:51:23 backupd: Node requires deep traversal:/Volumes/Tiger reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:00:08 backupd: Node requires deep traversal:/Volumes/Free reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:00:08 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| ugh ugh, kFSEDBEventFlagReasonEventDBUntrustable means 25 minutes of scanning. 15:00:13 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 52.98 GB available So the disk is pretty full, and more space is needed. So obviously some older backups should be deleted.. 15:07:22 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-21-004709: 53.05 GB now available It deleted one and it found out it's still not enough. Should delete another one... 15:07:22 backupd: Stopping backup. No! Wait! 15:07:28 backupd: Backup canceled. OMG. 15:07:34 backupd: Ejected Time Machine disk image. 15:07:34 backupd: Compacting backup disk image to recover free space 15:08:10 backupd: Completed backup disk image compaction 15:08:10 backupd: Starting standard backup 15:08:10 backupd: Network volume mounted at: /Volumes/Time Capsule 15:08:13 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden 15:08:13 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb 15:08:13 backupd: Querying receipt database for system packages 15:08:15 backupd: Using system path cache. 15:08:23 backupd: Event store UUIDs don't match for volume: Leopard 15:08:23 backupd: Event store UUIDs don't match for volume: Source 15:08:23 backupd: Event store UUIDs don't match for volume: Installer 15:08:23 backupd: Event store UUIDs don't match for volume: Users 15:08:23 backupd: Event store UUIDs don't match for volume: Old Applications 15:08:23 backupd: Event store UUIDs don't match for volume: Musik 15:08:23 backupd: Event store UUIDs don't match for volume: Applications 15:08:23 backupd: Event store UUIDs don't match for volume: Tiger 15:08:23 backupd: Event store UUIDs don't match for volume: Free 15:08:23 backupd: Event store UUIDs don't match for volume: Unix Oh noes, it figures out how much space it needs again ? 15:08:23 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:17:34 backupd: Node requires deep traversal:/Volumes/Source reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:24:52 backupd: Node requires deep traversal:/Volumes/Installer reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:25:04 backupd: Node requires deep traversal:/Volumes/Users reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:31:35 backupd: Node requires deep traversal:/Volumes/Old Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:32:03 backupd: Node requires deep traversal:/Volumes/Musik reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:32:16 backupd: Node requires deep traversal:/Volumes/Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:33:25 backupd: Node requires deep traversal:/Volumes/Tiger reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:42:06 backupd: Node requires deep traversal:/Volumes/Free reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 15:42:06 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| Here we go again. (Removing a lot of output further on) 15:42:11 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.05 GB available 15:50:21 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-20-003027: 53.27 GB now available 15:50:21 backupd: Stopping backup. 15:50:27 backupd: Backup canceled. 15:50:33 backupd: Ejected Time Machine disk image. 15:50:33 backupd: Compacting backup disk image to recover free space 15:51:12 backupd: Completed backup disk image compaction 15:51:12 backupd: Starting standard backup 15:51:12 backupd: Network volume mounted at: /Volumes/Time Capsule 15:51:15 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden 15:51:15 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb 15:51:26 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 16:25:04 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 16:25:09 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.27 GB available 16:31:25 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-19-004747: 53.47 GB now available 16:31:25 backupd: Stopping backup. 16:31:30 backupd: Backup canceled. 16:31:36 backupd: Ejected Time Machine disk image. 16:31:36 backupd: Compacting backup disk image to recover free space 16:32:15 backupd: Completed backup disk image compaction 16:32:15 backupd: Starting standard backup 16:32:15 backupd: Network volume mounted at: /Volumes/Time Capsule 16:32:17 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden 16:32:17 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb 16:32:27 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 17:06:10 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 17:06:15 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.47 GB available 17:14:00 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-18-014306: 53.54 GB now available Two hours later, 0.5 GB have been recovered of the needed 20GB. So I'd expect only 4 days more to go... 17:14:00 backupd: Stopping backup. 17:14:06 backupd: Backup canceled. 17:14:13 backupd: Ejected Time Machine disk image. 17:14:13 backupd: Compacting backup disk image to recover free space 17:14:52 backupd: Completed backup disk image compaction 17:14:52 backupd: Starting standard backup 17:14:52 backupd: Network volume mounted at: /Volumes/Time Capsule 17:14:55 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden 17:14:55 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb 17:15:04 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 17:49:00 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| 17:49:05 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.54 GB available 17:55:13 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-30-001331: 53.60 GB now available 17:55:13 backupd: Stopping backup. 17:55:19 backupd: Backup canceled. 17:55:25 backupd: Ejected Time Machine disk image. 17:55:25 backupd: Compacting backup disk image to recover free space 17:56:06 backupd: Completed backup disk image compaction 17:56:06 backupd: Starting standard backup 17:56:06 backupd: Network volume mounted at: /Volumes/Time Capsule 17:56:09 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden 17:56:09 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb 17:56:18 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable| (Removing even more output further on) 18:30:08 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.60 GB available 18:38:20 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-29-021844: 53.67 GB now available 19:13:07 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.67 GB available 19:15:46 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-28-010002: 53.73 GB now available 19:23:19 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-05-27-221015: 53.79 GB now available wohoo, deleted two! 19:58:16 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.79 GB available 20:00:06 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-06-11-142433: 53.83 GB now available 20:00:52 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-06-11-130026: 53.85 GB now available 20:00:52 backupd: Removed all 2 expired backups, more space is needed - deleting oldest backups to make room 20:06:26 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-03-25-000709: 54.24 GB now available 20:06:26 backupd: Deleted 3 backups: oldest backup is now 01.04.2008 20:41:38 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 54.24 GB available 20:41:38 backupd: No expired backups exist - deleting oldest backups to make room 20:46:05 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-04-01-015143: 54.52 GB now available 20:49:50 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-04-08-003544: 54.78 GB now available 20:49:50 backupd: Deleted 2 backups: oldest backup is now 23.04.2008 21:24:38 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 54.78 GB available 21:24:38 backupd: No expired backups exist - deleting oldest backups to make room 23:23:02 backupd: Deleted backup /Volumes/Backup of Aden/Backups.backupdb/Aden/2008-04-23-120205: 56.29 GB now available 23:23:02 backupd: Deleted 1 backups: oldest backup is now 30.04.2008 ... ad nauseam