Hard drive size doubled after backup....

[sanketr]

Well, it seems that the size of startup disk has doubled after I tried doing the first "SmartUpdate" backup of the startup disk to an external drobo RAID. Here is what I did:

- Created a 150GB size disk image on external storage, and mounted the image - it is the backup destination
- Select "Backup - all files" for startup disk, smart update option, and the disk image as destination.
- Selected "Preseve ACL" in advanced options

After the backup ran, here is what happened:

- Startup disk almost doubled in size. I ran "sudo du -sh /*" to see disk usage. But, I don't see any doubled amount. The total sums up to approximately original size

- SuperDuper! backed up only 2GB out of ~50GB to disk image, and still didn't show any errors. It claimed to make a successful bootable backup which wasn't the case because of incomplete backup.

- I ran the backup again just now. Now, SuperDuper! seems to be working correctly, and backing up the missing contents to the disk image.

Here is the startup disk usage information before the backup:
Filesystem 1024-blocks Used Available Capacity Mounted on
/dev/disk0s2 115212288 54303356 60652932 48% /

After backup:
Filesystem 1024-blocks Used Available Capacity Mounted on
/dev/disk0s2 115212288 101827060 13129228 89% /

Also, space taken up on destination disk image during the backup:
/dev/disk3s2 156950508 2178188 154772320 2% /Volumes/Desktop Bootable Backup


If SuperDuper! doesn't overwrite the backup log when creating new backup (since I am now running the backup procedure again), where can I find the log?


The problem is how to troubleshoot and fix the issue of doubled startup disk usage given that it doesn't show up in "du". SuperDuper! is strong suspect here because of the incorrect backup I described above.

[sanketr]

SuperDuper log for second backup attempt below. Please note that it evaluated ~95GB but copied ~47GB which is the right size. So, it seems that there are hidden files somewhere which SuperDuper seems to recognize and exclude...


| 06:36:24 AM | Info | SuperDuper!, 2.5 (84), path: /Applications/SuperDuper.app, Mac OS 10.5.4 build 9E17 (i386)
| 06:36:24 AM | Info | Started on Sat, Aug 2, 2008 at 6:36 AM
| 06:36:24 AM | Info | Source Volume: Macintosh HD, mount: /, device: /dev/disk0s2, media: Hitachi HDT725032VLA360, interconnect: Internal SATA, file system: "Journaled HFS+", OS: 10.5.4 (9E17), capacity: 109.88 GB, used: 97.00 GB, directories: 411759, files: 1936224, ejectable: NO, ACLs: Enabled
| 06:36:24 AM | Info | Target Volume: Desktop Bootable Backup, mount: /Volumes/Desktop Bootable Backup, device: /dev/disk2s2, media: Apple read/write, interconnect: File Virtual Interface, file system: "Journaled HFS+", OS: N/A, capacity: 149.68 GB, used: 2.08 GB, directories: 4661, files: 43741, ejectable: YES, ACLs: Enabled
| 06:36:24 AM | Info | Copy Mode : Smart Update
| 06:36:24 AM | Info | Copy Script : Backup - all files.dset
| 06:36:24 AM | Info | Transcript : BuildTranscript.plist
| 06:36:24 AM | Info | PHASE: 1. Prepare to Copy Files
| 06:36:24 AM | Info | ...ACTION: Preparing Macintosh HD
| 06:36:24 AM | Info | ......COMMAND => Verifying the integrity of volinfo.database
| 06:36:24 AM | Info | volinfo.database OK
| 06:36:24 AM | Info | ......COMMAND => Enabling permissions on Macintosh HD
| 06:36:25 AM | Info | Refreshing Disk Arbitration ...
| 06:36:30 AM | Info | ......COMMAND => Verifying that permissions are enabled for Macintosh HD
| 06:36:30 AM | Info | Permissions on '/' are enabled.
| 06:36:30 AM | Info | ...ACTION: Preparing Desktop Bootable Backup
| 06:36:30 AM | Info | ......COMMAND => Enabling permissions on Desktop Bootable Backup
| 06:36:30 AM | Info | Refreshing Disk Arbitration ...
| 06:36:30 AM | Info | ......COMMAND => Verifying that permissions are enabled for Desktop Bootable Backup
| 06:36:30 AM | Info | Permissions on '/Volumes/Desktop Bootable Backup' are enabled.
| 06:36:30 AM | Info | ......COMMAND => Verifying that Desktop Bootable Backup ACL support matches Macintosh HD
| 06:36:30 AM | Info | ...ACTION: Preserving Spotlight state on Desktop Bootable Backup
| 06:36:30 AM | Info | ......COMMAND => Disabling Spotlight search indexing on Desktop Bootable Backup
| 06:36:31 AM | Info | PHASE: 2. Copy Files
| 06:36:31 AM | Info | ...ACTION: Copying files from Macintosh HD to Desktop Bootable Backup using Smart Update
| 06:36:31 AM | Info | ......COMMAND => Cloning Macintosh HD to Desktop Bootable Backup
| 06:36:31 AM | Info | Copying copy files with delete using script: /Users/sanket/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 06:36:31 AM | Info | Loading 22 commands from copy script /Applications/SuperDuper.app/Contents/Resources/Copy Scripts/Exclude system temporary files.dset
| 06:36:31 AM | Info | Loading 6 commands from copy script /Applications/SuperDuper.app/Contents/Resources/Copy Scripts/Exclude system cache files.dset
| 06:36:31 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper.app/Contents/Resources/Copy Scripts/Exclude Norton FileSaver files.dset
| 06:36:31 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper.app/Contents/Resources/Copy Scripts/Exclude Google Desktop Index files.dset
| 06:36:31 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper.app/Contents/Resources/Copy Scripts/Exclude iTunes Temporary files.dset
| 06:36:31 AM | Info | Loading 0 commands from copy script /Users/sanket/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 06:36:31 AM | Info | /
| 06:36:47 AM | Info | /.svn
| 06:36:47 AM | Info | /cores
| 06:36:47 AM | Info | /Network
| 06:36:47 AM | Info | /.vol
| 06:36:47 AM | Info | Ignoring /.vol
| 06:36:47 AM | Info | /development
| 06:36:47 AM | Info | /private
| 06:36:52 AM | Info | Ignoring /private/var/vm/sleepimage
| 06:36:55 AM | Info | Ignoring /private/var/vm/swapfile0
| 06:36:55 AM | Info | Ignoring /private/var/db/BootCache.playlist
| 06:36:55 AM | Info | Ignoring /private/var/db/volinfo.database
| 06:36:55 AM | Info | Ignoring /private/var/run/syslog.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/configd.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/DirectoryService.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/pcscd.pub
| 06:36:55 AM | Info | Ignoring /private/var/run/diskarbitrationd.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/appfwd.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/ntpd.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/mds.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/com.apple.blued.launchd
| 06:36:55 AM | Info | Ignoring /private/var/run/automount.initialized
| 06:36:55 AM | Info | Ignoring /private/var/run/resolv.conf
| 06:36:55 AM | Info | Ignoring /private/var/run/pvsnatd.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/mds
| 06:36:55 AM | Info | Ignoring /private/var/run/mach.sym
| 06:36:55 AM | Info | Ignoring /private/var/run/llipdaemon.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/cron.pid
| 06:36:55 AM | Info | Ignoring /private/var/run/utmpx
| 06:36:55 AM | Info | Ignoring /private/var/run/hdiejectd.pid
| 06:36:55 AM | Info | Ignoring /private/var/tmp/launchd
| 06:36:55 AM | Info | Ignoring /private/var/tmp/krb5kdc_rcache
| 06:36:55 AM | Info | Ignoring /private/var/tmp/mds
| 06:36:58 AM | Info | Ignoring /private/tmp/launchd-18.owt3vV
| 06:36:58 AM | Info | Ignoring /private/tmp/launchd-106.4V0nvo
| 06:36:58 AM | Info | Ignoring /private/tmp/launch-yift1g
| 06:36:58 AM | Info | Ignoring /private/tmp/launch-sS5yWQ
| 06:36:58 AM | Info | Ignoring /private/tmp/launch-Tmm7WH
| 06:36:58 AM | Info | Ignoring /private/tmp/launchd-300.duZST5
| 06:36:58 AM | Info | Ignoring /private/tmp/target.indexState
| 06:36:58 AM | Info | /.Spotlight-V100
| 06:36:58 AM | Info | Preserving /.Spotlight-V100
| 06:36:58 AM | Info | /.Trashes
| 06:36:58 AM | Info | /Users
| 06:38:24 AM | Info | /sw
| 06:38:33 AM | Info | /Developer
| 06:53:40 AM | Info | /usr
| 07:01:15 AM | Info | /Library
| 07:34:20 AM | Info | Ignoring /Desktop DF
| 07:34:20 AM | Info | Ignoring /Desktop DB
| 07:34:20 AM | Info | /WinDesktop
| 07:43:25 AM | Info | Ignoring /.hotfiles.btree
| 07:43:25 AM | Info | /bin
| 07:43:25 AM | Info | /sbin
| 07:43:28 AM | Info | /System
| 07:58:32 AM | Info | /Applications
| 08:27:05 AM | Info | /dev
| 08:27:05 AM | Info | /.fseventsd
| 08:27:05 AM | Info | Preserving /.fseventsd
| 08:27:05 AM | Info | /net
| 08:27:05 AM | Info | /home
| 08:27:05 AM | Info | /Volumes
| 08:27:05 AM | Info | Ignoring /Volumes/Data
| 08:27:05 AM | Info | Ignoring /Volumes/Disk Image
| 08:29:16 AM | Info | Ignoring /Volumes/Shared Drive
| 08:29:16 AM | Info | Ignoring /Volumes/Macintosh HD
| 08:29:16 AM | Info | Ignoring /Volumes/Desktop Bootable Backup
| 08:29:16 AM | Info | Evaluated 2314938 items occupying 95.83 GB (411758 directories, 1853305 files, 49875 symlinks)
| 08:29:16 AM | Info | Copied 1136243 items totaling 45.08 GB (203640 directories, 909339 files, 23264 symlinks)
| 08:29:16 AM | Info | Cloned 46.49 GB of data in 6765 seconds at an effective transfer rate of 7.04 MB/s
| 08:29:16 AM | Info | ......COMMAND => Resetting Custom Icon bit on Desktop Bootable Backup
| 08:29:16 AM | Info | PHASE: 3. After Successful Copy
| 08:29:16 AM | Info | ...ACTION: Making Desktop Bootable Backup bootable
| 08:29:16 AM | Info | ......COMMAND => Blessing OS X System Folder
| 08:29:17 AM | Info | Successfully blessed Mac OS X folder on Desktop Bootable Backup
| 08:29:17 AM | Info | ......COMMAND => Blessing OS 9 System Folder
| 08:29:17 AM | Info | Did not bless Mac OS 9 System Folder on Desktop Bootable Backup because it does not exist.
| 08:29:17 AM | Info | ...ACTION: Restoring Spotlight state on Desktop Bootable Backup
| 08:29:17 AM | Info | ......COMMAND => Restoring Spotlight search indexing state on Desktop Bootable Backup
| 08:29:17 AM | Info | Copy complete.

[dnanian]

Are you running any kind of antivirus? It's hard to know what's going on here if the space just 'vanished' and then 'came back' -- we're not using temporary files or anything weird...

[sanketr]

Originally Posted by dnanian

Are you running any kind of antivirus? It's hard to know what's going on here if the space just 'vanished' and then 'came back' -- we're not using temporary files or anything weird...

Nope, I am not running any anti-virus.... it has got to be some kind of hidden files somewhere which are being recognized and excluded by SuperDuper...

[sanketr]

Originally Posted by dnanian

Are you running any kind of antivirus? It's hard to know what's going on here if the space just 'vanished' and then 'came back' -- we're not using temporary files or anything weird...

Also, I was running Disk Utility at the time of first backup attempt to create a second disk image in parallel on the external storage (where I had already created a 150GB disk image for backup, and was backing up using SuperDuper). The disk utility aborted creating that disk image - didn't tell me why. I wonder if it affected the backup operation in anyway.

Which files are being excluded by SuperDuper? If I find it out the list of those files, I can find out which files are contributing to doubling of the space...SuperDuper is correctly copying original 47GB instead of doubled 97Gb...So, the excluded set is mostly made up of the files that doubled the disk space...

[dnanian]

That might be relevant, depending on what it's doing. Check in the hidden /Volumes folder for any directory entries that are folders. (It's possible that when you created the image it created a new mount point in /Volumes that we didn't ignore because of when it was added.)

[sanketr]

Nailed it.... "/Volumes/Disk Image" (which was also ignored in SuperDuper log above)...perfect bootable image that was doubling every thing... the backup was supposed to be made in "/Volumes/Desktop Bootable Backup" in first attempt but somehow ended up there - might have been an inadvertent mistake on my part though...

[dnanian]

Ah, good. I think this must have been the image you created with Disk Utility during the backup. In general, I'd suggest avoiding that kind of thing during a copy: the exclusions are precalculated, and adding a big mount point during the run will definitely mess things up.