Why is my rsync transfer slow?

Sat Feb 6 18:44:34 UTC 2016

I scrapped all my previous progress and started over with a different 
"connection setup", now the NAS is connected to the computer using 1 
Gbit wired ethernet, while the source disk is still using FW800.

On bigger files I now typically get 20-30 MB/s so that was a substantial 
improvement. It still are occaissonal hiccups (I'm waiting for one as I 
write this, and this has lasted half an hour) but my impression is that 
they are fewer than before.

However, there are still problems.

1. Does rsync leak memory? When I started this transfer Jan 31 (yes, a 
week ago) the three rsync processes that was spawned took a tens or 
maybe hundreds of kB of memory.

Currently, according to Activity Monitor they use

Memory (both "regular" and compressed)

2.69 GB
2.47 GB
2.41 GB (2.40 GB compressed)

They have also used a lot of CPU time:

% ps -auxww | grep rsync
rsync            19545  11 20 SN+  723:20.57   0.0
rsync            19544  46 20 UN+  263:32.55   0.0
rsync            19543  31 20 SN+  936:51.55   0.0

Mostly I still let this computer idle but when I use it it sometimes 
freezes in a way that reminds of how it feels when you use a computer 
that hasn't enough memory (it has 8 GB). Although, according to Activity 
Monitor, memory pressure is still green (used 6.5 GB, Cache 1.4 GB, Swap 
10 GB).

2. Something is broken with the transfer and rsync's handling of hard links.

On the source:
% du -sh
1.0T	.

on the destination

% du -sh
3.9T	.

Yes, the destination is 4 times bigger and I have only transferred about 
40% (some 80 directories out of 198) (I am currently at 63 millions of 
files) of the contents of the source.

I think I read somewhere that Time Machine use a special filesystem 
feature, hard links to directories. Does rsync handle this?

I have also gathered some rudimentary statistics, the size of the 
logfile of rsync as well as the number of lines (two lines per 
transferred file) in the log file. Start time was Jan 31, 13:11

zsh-% ls -lh /tmp/rsync.log
-rw-r--r--  1 db  wheel   1.6G  1 Feb 01:06 /tmp/rsync.log
zsh-% ls -lh /tmp/rsync.log
-rw-r--r--  1 db  wheel   2.9G  1 Feb 09:11 /tmp/rsync.log
zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 8.4G 2 Feb 18:26 /tmp/rsync.log

zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 9.7G 3 Feb 01:37 /tmp/rsync.log
zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 12G 3 Feb 22:21 /tmp/rsync.log

zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 15G 4 Feb 21:20 /tmp/rsync.log
zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 15G 4 Feb 23:49 /tmp/rsync.log
zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 17G 5 Feb 07:22 /tmp/rsync.log

zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 18G 5 Feb 18:24 /tmp/rsync.log

zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 19G 6 Feb 10:18 /tmp/rsync.log

zsh-% ls -lh /tmp/rsync.log
-rw-r--r-- 1 db wheel 20G 6 Feb 19:04 /tmp/rsync.log

As you can see in the first 12 h the log grew to 1.6 GB. After 53 h it 
was 8.4 GB but then the growth slowed down and in the last 24 h it just 
grew 2 GB (18 to 20) (the last and the third last points). This is not 
super exact but I think it gives a rough indication of the performance.

A similar metric but this time counting the lines in the log:

zsh-% date; wc -l /tmp/rsync.log
Mon  1 Feb 2016 09:23:41 CET
  20045861 /tmp/rsync.log

zsh-% date; wc -l /tmp/rsync.log
Mon  1 Feb 2016 18:20:21 CET
  29886346 /tmp/rsync.log

zsh-% date; time wc -l /tmp/rsync.log
Mon  1 Feb 2016 18:21:01 CET
  29906243 /tmp/rsync.log
wc -l /tmp/rsync.log  6.53s user 4.51s system 46% cpu 23.860 total
zsh-%

zsh-% date; time wc -l /tmp/rsync.log
Wed  3 Feb 2016 01:37:28 CET
  66717053 /tmp/rsync.log
wc -l /tmp/rsync.log  14.57s user 9.09s system 55% cpu 42.701 total

zsh-% date; time wc -l /tmp/rsync.log
Wed  3 Feb 2016 22:21:29 CET
  83738765 /tmp/rsync.log
wc -l /tmp/rsync.log  18.44s user 12.98s system 39% cpu 1:19.75 total

zsh-% date; time wc -l /tmp/rsync.log
Thu  4 Feb 2016 21:20:57 CET
  103578124 /tmp/rsync.log
wc -l /tmp/rsync.log  22.70s user 16.81s system 30% cpu 2:07.54 total

zsh-% date; time wc -l /tmp/rsync.log
Thu  4 Feb 2016 23:46:19 CET
  106439787 /tmp/rsync.log
wc -l /tmp/rsync.log  23.41s user 18.00s system 26% cpu 2:34.63 total

zsh-% date; time wc -l /tmp/rsync.log
Fri  5 Feb 2016 07:22:06 CET
  113853825 /tmp/rsync.log
wc -l /tmp/rsync.log  24.99s user 18.90s system 31% cpu 2:20.75 total

zsh-% date; time wc -l /tmp/rsync.log
Fri  5 Feb 2016 18:24:44 CET
  122665638 /tmp/rsync.log
wc -l /tmp/rsync.log  26.91s user 19.15s system 42% cpu 1:48.37 total

zsh-% date; time wc -l /tmp/rsync.log
Sat  6 Feb 2016 10:18:36 CET
  134194513 /tmp/rsync.log
wc -l /tmp/rsync.log  29.38s user 20.62s system 41% cpu 1:59.18 total

zsh-% date; time wc -l /tmp/rsync.log
Sat  6 Feb 2016 19:05:15 CET
  136240005 /tmp/rsync.log
wc -l /tmp/rsync.log  29.85s user 21.57s system 33% cpu 2:32.81 total
zsh-%

What gives?