PDA

View Full Version : Backups slow on Tiger


jmwilder
02-01-2009, 11:27 AM
Over the last few days, I've been backing up my two intel macbook pros to a NAS (ext2, Dlink DNS-321) on my LAN using SuperDuper. Both have 5400 rpm drives, as does the NAS. Both have write speeds over gigabit ethernet to the NAS of about 16 MB/s when using samba to transfer a file.

SuperDuper has been working flawlessly on the macbook pro with Leopard installed. It runs at about 9 MB/s over the course of the backup. Tiger is a different story. (By the way, I'm using version 2.5 on both machines.) Backup speeds are closer to 2 MB/s. Given past posts, it seemed that Spotlight might be the problem, but I don't believe Spotlight attempts to index a remote drive, and in any event I'm unable to add the NAS under the privacy tab in Spotlight prefs. I do not have any antivirus software installed. I also disabled all Dashboard processes and other menubar apps prior to initiating the backup.

I've included my most recent SuperDuper log for the Tiger machine below. Note that although the log stops at /Library, the cloning appears to have completed. (Incidentally, is this the 2.5 Tiger bug noted by other posters?)

Any ideas on how to troubleshoot this? I just installed 2.1.4 on the Tiger machine and will try that tonight. That said, I haven't heard anything to suggest that 2.1.4 is any faster than 2.5 on Tiger. Thanks.

12:16:21 AM | Info | SuperDuper!, 2.5 (84), path:
/Applications/SuperDuper!.app, Mac OS 10.4.11 build 8S2167 (i386)
| 12:16:21 AM | Info | Started on Sun, Feb 1, 2009 at 12:16 AM
| 12:16:21 AM | Info | Source Volume: Macintosh HD, mount: /, device:
/dev/disk0s2, media: FUJITSU MHW2120BH, interconnect: Internal SATA,
file system: "Journaled HFS+", OS: 10.4.11 (8S2167), capacity: 111.47
GB, used: 71.44 GB, directories: 119592, files: 551869, ejectable: NO,
ACLs: Disabled
| 12:16:21 AM | Info | Target Image:
/Volumes/jmw/jmw_feb1_09.sparseimage, name:
jmw_feb1_09
| 12:16:21 AM | Info | Copy Mode : Erase, then copy files
| 12:16:21 AM | Info | Copy Script : Backup - all files.dset
| 12:16:21 AM | Info | Transcript : BuildTranscript.plist
| 12:16:21 AM | Info | PHASE: 1. Prepare to Copy Files
| 12:16:21 AM | Info | ...ACTION: Preparing Macintosh HD
| 12:16:21 AM | Info | ......COMMAND => Verifying the integrity of
volinfo.database
| 12:16:21 AM | Info | volinfo.database OK
| 12:16:21 AM | Info | ......COMMAND => Enabling permissions on Macintosh HD
| 12:16:21 AM | Info | Refreshing Disk Arbitration ...
| 12:16:21 AM | Info | ......COMMAND => Verifying that permissions are
enabled for Macintosh HD
| 12:16:22 AM | Info | Permissions on '/' are enabled.
| 12:16:22 AM | Info | ...ACTION: Mounting jmw_feb1_09
| 12:16:22 AM | Info | ......COMMAND => Preparing jmw_feb1_09
| 12:16:43 AM | Info | created:
/Volumes/jmw/jmw_feb1_09.sparseimage
| 12:16:43 AM | Info | ......COMMAND => Setting ownership and access
modes for '/Volumes/jmw/jmw_feb1_09.sparseimage'
| 12:16:43 AM | Info | ......COMMAND => Mounting jmw_feb1_09
| 12:16:46 AM | Info | /dev/disk2 Apple_partition_scheme
/dev/disk2s1 Apple_partition_map /dev/disk2s2 Apple_HFS
/Volumes/jmw_feb1_09
| 12:16:46 AM | Info | ......COMMAND => Mounting jmw_feb1_09
| 12:16:46 AM | Info | ...ACTION: Erasing jmw_feb1_09
| 12:16:46 AM | Info | ......COMMAND => Preserving jmw_feb1_09 UUID
| 12:16:46 AM | Info | F673B0CBADB0FFF9
| 12:16:46 AM | Info | ......COMMAND => Preserving spotlight indexing state
| 12:16:46 AM | Info | ......COMMAND => Erasing jmw_feb1_09
| 12:16:56 AM | Info | ......COMMAND => Restoring jmw_feb1_09
UUID (SDUUID.hexString)
| 12:16:56 AM | Info | F673B0CBADB0FFF9
| 12:16:56 AM | Info | ......COMMAND => Restoring Spotlight search
indexing state on jmw_feb1_09
| 12:16:56 AM | Info | ...ACTION: Preparing jmw_feb1_09
| 12:16:56 AM | Info | ......COMMAND => Enabling permissions on
jmw_feb1_09
| 12:16:56 AM | Info | Refreshing Disk Arbitration ...
| 12:16:56 AM | Info | ......COMMAND => Verifying that permissions are
enabled for jmw_feb1_09
| 12:16:56 AM | Info | Permissions on
'/Volumes/jmw_feb1_09' are enabled.
| 12:16:56 AM | Info | ......COMMAND => Verifying that
jmw_feb1_09 ACL support matches Macintosh HD
| 12:16:56 AM | Info | ...ACTION: Preserving Spotlight state on
jmw_feb1_09
| 12:16:56 AM | Info | ......COMMAND => Disabling Spotlight search
indexing on jmw_feb1_09
| 12:16:56 AM | Info | PHASE: 2. Copy Files
| 12:16:56 AM | Info | ...ACTION: Copying files from Macintosh HD to
jmw_feb1_09
| 12:16:56 AM | Info | ......COMMAND => Cloning Macintosh HD to
jmw_feb1_09
| 12:16:57 AM | Info | Copying copy files using script:
/Users/jmw/Library/Application Support/SuperDuper!/Copy
Scripts/Standard Scripts/Backup - all files.dset
| 12:16:57 AM | Info | Loading 22 commands from copy script
/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude
system temporary files.dset
| 12:16:57 AM | Info | Loading 6 commands from copy script
/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude
system cache files.dset
| 12:16:57 AM | Info | Loading 1 commands from copy script
/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude
Norton FileSaver files.dset
| 12:16:57 AM | Info | Loading 1 commands from copy script
/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude
Google Desktop Index files.dset
| 12:16:57 AM | Info | Loading 1 commands from copy script
/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude
iTunes Temporary files.dset
| 12:16:57 AM | Info | Loading 0 commands from copy script
/Users/jmw/Library/Application Support/SuperDuper!/Copy
Scripts/Standard Scripts/Backup - all files.dset
| 12:16:57 AM | Info | /
| 12:17:00 AM | Info | /cores
| 12:17:00 AM | Info | /.Spotlight-V100
| 12:17:00 AM | Info | Preserving /.Spotlight-V100
| 12:17:00 AM | Info | /.Trashes
| 12:17:00 AM | Info | Ignoring /.hotfiles.btree
| 12:17:00 AM | Info | Ignoring /Desktop DF
| 12:17:00 AM | Info | /automount
| 12:17:04 AM | Info | /usr
| 12:35:20 AM | Info | /Library
| 08:33:23 AM | Info | ......COMMAND => Resetting Custom Icon bit on
jmw_feb1_09
| 08:33:23 AM | Info | PHASE: 3. After Successful Copy
| 08:33:23 AM | Info | ...ACTION: Making jmw_feb1_09 bootable
| 08:33:23 AM | Info | ......COMMAND => Blessing OS X System Folder
| 08:33:24 AM | Info | Successfully blessed Mac OS X folder on
jmw_feb1_09
| 08:33:24 AM | Info | ......COMMAND => Blessing OS 9 System Folder
| 08:33:24 AM | Info | Did not bless Mac OS 9 System Folder on
jmw_feb1_09 because it does not exist.
| 08:33:24 AM | Info | ...ACTION: Restoring Spotlight state on
jmw_feb1_09
| 08:33:24 AM | Info | ......COMMAND => Restoring Spotlight search
indexing state on jmw_feb1_09
| 08:33:25 AM | Info | ...ACTION: Unmounting jmw_feb1_09
| 08:33:25 AM | Info | ......COMMAND => Unmounting
'/Volumes/jmw/jmw_feb1_09.sparseimage'
| 08:33:27 AM | Info | "disk2" unmounted.
| 08:33:27 AM | Info | "disk2" ejected.
| 08:33:27 AM | Info | Copy complete.

jmwilder
02-01-2009, 11:29 AM
Also, here are portions of the system.log and console.log over the course of the backup.

Console

Feb 1 00:12:58 hecuba configd[34]: rtmsg: error writing to routing socket
crontab: no crontab for jmw
2009-02-01 00:13:57.414 SuperDuper![634] .scriptSuite warning for
attribute 'boundsAsQDRect' of class 'NSWindow' in suite 'NSCoreSuite':
'NSData<QDRect>' is not a valid type name.
2009-02-01 00:13:57.414 SuperDuper![634] .scriptSuite warning for type
'NSTextStorage' attribute 'name' of class 'NSApplication' in suite
'NSCoreSuite': AppleScript name references may not work for this
property because its type is not NSString-derived.
2009-02-01 00:13:57.414 SuperDuper![634] .scriptSuite warning for type
'NSTextStorage' attribute 'lastComponentOfFileName' of class
'NSDocument' in suite 'NSCoreSuite': AppleScript name references may
not work for this property because its type is not NSString-derived.
2009-02-01 00:13:57.415 SuperDuper![634] .scriptSuite warning for type
'NSTextStorage' attribute 'title' of class 'NSWindow' in suite
'NSCoreSuite': AppleScript name references may not work for this
property because its type is not NSString-derived.
2009-02-01 00:13:57.415 SuperDuper![634] .scriptSuite warning for
attribute 'boundsAsQDRect' of class 'NSWindow' in suite 'NSCoreSuite':
'NSData<QDRect>' is not a valid type name.
2009-02-01 00:13:57.415 SuperDuper![634] .scriptSuite warning for
superclass of class 'NSAttachmentTextStorage' in suite 'NSTextSuite':
'NSString' is not a valid class name.
Feb 1 00:15:44 hecuba authexec: executing
/Applications/SuperDuper!.app/Contents/MacOS/SDAgent

System.log

Jan 31 23:46:18 hecuba kernel[0]: ath_ampdu_tx_release,remove node
from queue 0x0x3c7fb004 macaddr 00:22:b0:b2:37:5a
Feb 1 00:12:54 hecuba configd[34]: posting notification
com.apple.system.config.network_change
Feb 1 00:12:54 hecuba lookupd[616]: lookupd (version 369.8) starting
- Sun Feb 1 00:12:54 2009
Feb 1 00:12:58 hecuba configd[34]: rtmsg: error writing to routing socket
Feb 1 00:13:05 hecuba kernel[0]: AppleYukon2 - en0 link active,
1000-Mbit, full duplex, symmetric flow control enabled port 0
Feb 1 00:13:09 hecuba launchd: Server 5e2b in bootstrap 1103 uid 0:
"/usr/sbin/lookupd"[616]: exited abnormally: Hangup
Feb 1 00:13:09 hecuba configd[34]: posting notification
com.apple.system.config.network_change
Feb 1 00:13:09 hecuba lookupd[622]: lookupd (version 369.8) starting
- Sun Feb 1 00:13:09 2009
Feb 1 00:14:01 hecuba kernel[0]: smbfs_smb_qfsattr: (fyi) share
'NTFS', attr 0x2b, maxfilename 255
Feb 1 00:14:01 hecuba kernel[0]: smbfs_aclsflunksniff: sm_args.uid 501, error 2
Feb 1 00:15:02 hecuba kernel[0]: Stealth Mode connection attempt to
TCP 192.168.0.194:50176 from 192.221.110.123:80
Feb 1 00:15:44 hecuba authexec: executing
/Applications/SuperDuper!.app/Contents/MacOS/SDAgent
Feb 1 00:16:21 hecuba KernelEventAgent[29]: tid 00000000 received
unknown event (256)
Feb 1 00:16:22 hecuba sudo: root : TTY=unknown ; PWD=/ ;
USER=jmw ; COMMAND=/usr/bin/hdiutil create -size 114145.42m
-fs HFS+J -type SPARSE -volname jmw_feb1_09 -ov
/Volumes/jmw/jmw_feb1_09.sparseimage
Feb 1 00:16:43 hecuba sudo: root : TTY=unknown ; PWD=/ ;
USER=jmw ; COMMAND=/bin/chmod 0664
/Volumes/jmw/jmw_feb1_09.sparseimage
Feb 1 00:16:45 hecuba kernel[0]: hfs: Initializing the journal
(joffset 0x37e000 sz 0x1000000)...
Feb 1 00:16:46 hecuba sudo: root : TTY=unknown ; PWD=/ ;
USER=jmw ; COMMAND=/bin/echo /dev/disk2 Apple_partition_scheme
/dev/disk2s1 Apple_partition_map /dev/disk2s2 Apple_HFS
/Volumes/jmw_feb1_09
Feb 1 00:16:47 hecuba kernel[0]: jnl: close: flushing the buffer
cache (start 0x8400 end 0xc600)
Feb 1 00:16:53 hecuba kernel[0]: hfs: Initializing the journal
(joffset 0x37e000 sz 0x1000000)...
Feb 1 00:16:56 hecuba KernelEventAgent[29]: tid 00000000 received
unknown event (256)
Feb 1 01:43:41 hecuba kernel[0]: Stealth Mode connection attempt to
UDP 192.168.0.194:50068 from 192.168.0.196:137
Feb 1 01:48:07 hecuba kernel[0]: Creating HFS+ Attribute B-tree File
(457 nodes) on jmw_feb1_09
Feb 1 04:53:09 hecuba cp: error processing extended attributes:
Operation not permitted

dnanian
02-01-2009, 05:19 PM
I don't see anything there indicating a general problem (other than the Intel Mac issue you noted, which is obviously happening on your Mac). It's quite possible that Leopard has improved I/O in your setup, sure...