Friday, July 04, 2014

OS/X Time Machine, performance comparison to command line tools.

A performance comparison for Mac Owners:

Q: Just how quick is Apple’s Time Machine?
A: Way faster than you can do with OS/X command line tools.

The headline is that command line tools take 80 minutes to do what Time Machine does in 3-10 mins.

TimeMachine does this in 3mins (1st log example) or 10 mins (2nd log example),
vs 38mins for “cp -al” + 42mins for rsync. [80 mins]

While there’s only 40Mb-50Mb in actual directory entries [2.1M * 21ch], which can notionally be written in seconds, each directory takes one block minimum on disk, plus an inode. I wasn’t able to quickly discover the size of an in ode. In V6 Unix, it was 512by, from memory.

Finder’s “Get Info” on any small file shows the “Allocation Unit” - 4Kb on my HFS+ volumes.
or "/usr/bin/stat -f %k .” - the ‘optimum’ block size for a volume.

That’s 1.4GB, minimum, to be written. [360,000 * 4Kb = 360 * 4MB = 1.4GB]
Wikipedia maintains that HFS+ allows hard-links of directories to support Time Machine. This was removed from Unix pre SVR4 to prevent “cycles” in filesystems (infinite recursion).

Outputs from my Mac Mini, OS/X Mavericks.
Internal 300GB  2.5" drive, external USB 1TB 2.5" drive. Both 5400RPM
358,00 directories and 2.1M files

$ uname -a

Darwin mini 13.2.0 Darwin Kernel Version 13.2.0: Thu Apr 17 23:03:13 PDT 2014; root:xnu-2422.100.13~1/RELEASE_X86_64 x86_64

$ sudo cp -a / /Volume/SJ-1TB-2014/bkup/last
# full initial copy to USB drive

real 574m59.327s
user   0m57.402s
sys   26m43.417s

mini:SJ-1TB-2014 steve$ df -h .
Filesystem     Size   Used  Avail Capacity  iused     ifree %iused  Mounted on
/dev/disk2s1  932Gi  262Gi  669Gi    29% 68776493 175413457   28%   /Volumes/SJ-1TB-2014

mini:SJ-1TB-2014 steve$ df -h /
Filesystem     Size   Used  Avail Capacity  iused    ifree %iused  Mounted on
/dev/disk0s2  297Gi  250Gi   47Gi    85% 65515369 12417533   84%   /

mini:SJ-1TB-2014 steve$ time sudo gcp -al bkup/last/ bkup/new
 # Apple's "cp" does not support "-l" option. This used gnu's "cp" from Darwin Ports.

real 38m53.462s
user  0m19.785s
sys   7m2.447s

Try 2: [user & sys time similar, no explanation of longer elapsed time]
real 68m13.564s, user 0m22.919s, sys 7m35.730s

mini:SJ-1TB-2014 steve$ df -h .
Filesystem     Size   Used  Avail Capacity  iused     ifree %iused  Mounted on
/dev/disk2s1  932Gi  264Gi  667Gi    29% 69220039 174969911   28%   /Volumes/SJ-1TB-2014

Fri  4 Jul 2014 14:09:28 EST
mini:SJ-1TB-2014 steve$ time sudo rsync -aHSx / bkup/new # trimmed errors
rsync warning: some files vanished before they could be transferred (code 24) at /SourceCache/rsync/rsync-42/rsync/main.c(992) [sender=2.6.9]

real 41m0.578s
user  1m24.502s
sys   8m25.340s

$ time sudo rm -rf bkup/new

real 52m32.459s
user  0m10.641s
sys   5m31.523s

Dirs - 360,000

# time find bkup/last -type d|wc -l  # added commas

real 12m39.225s
user 0m7.775s
sys 2m55.545s

Files - 2.1M

# time find bkup/last -type f|wc -l # added commas

real 13m31.380s
user  0m8.334s
sys   2m54.752s

Time Machine logs, using command:

$ grep /var/log/system.log [selected and trimmed]

2.5 minutes, no system activity, trimmed

Jul  4 09:06:37 mini[33481]: Starting automatic backup
Jul  4 09:08:06 mini[33481]: Copied 245 items (9.3 MB) from volume Macintosh HD. Linked 3392.
Jul  4 09:08:36 mini[33481]: Copied 35 items (2 KB) from volume Macintosh HD. Linked 582.
Jul  4 09:08:52 mini[33481]: Backup completed successfully.

10.5 minutes, system active. full log.

Jul  4 10:10:05 mini[34131]: Starting automatic backup
Jul  4 10:10:08 mini[34131]: Backing up to /dev/disk1s1: /Volumes/SJ-1TB-SG/Backups.backupdb
Jul  4 10:10:20 mini[34131]: Will copy (13.6 MB) from Macintosh HD
Jul  4 10:10:20 mini[34131]: Found 202 files (13.6 MB) needing backup
Jul  4 10:10:20 mini[34131]: 2.97 GB required (including padding), 321.67 GB available
Jul  4 10:16:38 mini[34131]: Copied 377 items (13.6 MB) from volume Macintosh HD. Linked 3548.
Jul  4 10:16:49 mini[34131]: Will copy (19.3 MB) from Macintosh HD
Jul  4 10:16:49 mini[34131]: Found 131 files (19.3 MB) needing backup
Jul  4 10:16:49 mini[34131]: 2.97 GB required (including padding), 321.66 GB available
Jul  4 10:19:16 mini[34131]: Copied 310 items (19.3 MB) from volume Macintosh HD. Linked 2862.
Jul  4 10:19:50 mini[34131]: Created new backup: 2014-07-04-101949
Jul  4 10:20:33 mini[34131]: Starting post-backup thinning
Jul  4 10:20:33 mini[34131]: No post-backup thinning needed: no expired backups exist
Jul  4 10:20:33 mini[34131]: Backup completed successfully.

7.5 minutes, system active, trimmed

Jul  4 14:39:33 mini[37148]: Starting automatic backup
Jul  4 14:44:45 mini[37148]: Created new backup: 2014-07-04-144444
Jul  4 14:45:29 mini[37148]: Starting post-backup thinning
Jul  4 14:47:02 mini[37148]: Deleted /Volumes/SJ-1TB-SG/Backups.backupdb/mini too/2014-07-03-134254 (8.2 MB)
Jul  4 14:47:02 mini[37148]: Post-backup thinning complete: 1 expired backups removed
Jul  4 14:47:05 mini[37148]: Backup completed successfully.

No comments: