netatalk 2.2.1 + kernel 3.2 + grosse Dateien

[Hermann Schaefer]

Linux-NAS (Intel SS4200) mit OpenMediaVault + Selbstbaukernel 3.2.20 aus den
Squeeze-Backports. Netatalk ist aus omv, scheint netatalk aus den Backports zu
verwenden.
afpd -V
afpd 2.2.1 - Apple Filing Protocol (AFP) daemon of Netatalk

afpd has been compiled with support for these features:

AFP versions: 1.1 2.0 2.1 2.2 3.0 3.1 3.2 3.3
DDP(AppleTalk) Support: Yes
CNID backends: dbd last tdb
SLP support: No
Zeroconf support: Yes
TCP wrappers support: Yes
Quota support: Yes
Admin group support: Yes
Valid shell checks: Yes
cracklib support: Yes
Dropbox kludge: No
Force volume uid/gid: No
ACL support: No
EA support: ad | sys
LDAP support: No

afpd.conf: /etc/netatalk/afpd.conf
AppleVolumes.system: /etc/netatalk/AppleVolumes.system
AppleVolumes.default: /etc/netatalk/AppleVolumes.default
afp_signature.conf: /etc/netatalk/afp_signature.conf
afp_voluuid.conf: /etc/netatalk/afp_voluuid.conf
afp_ldap.conf: not supported
UAM search path: /usr/lib/netatalk/
Server messages path: /etc/netatalk/msg/
lockfile: /var/run/afpd.pid

cat /proc/cpuinfo
model name : Intel(R) Pentium(R) Dual CPU E2160 @ 1.80GHz
cat /proc/meminfo
MemTotal: 2066152 kB

md-RAID 5 mit 4x1TB.

Helios LanTest mit 300MB: 10x ~60MB/s schreibend, ~70MB/s lesend.
Helios LanTest mit 3000MB: erst 1x ~60MB/s, dann 9x ~25MB/s, ~70MB/s lesend.

Warum dieser heftige Einbruch bei 3GB? Jemand eine Idee, wo man da suchen kann?
Thomas? :D

[r***@rsrc.de]

Post by Hermann Schaefer
Warum dieser heftige Einbruch bei 3GB? Jemand eine Idee, wo man da suchen kann?

- Wireshark port 548
- strace -vtt
- single malt

-r

[Thomas Kaiser]

Post by Hermann Schaefer
Linux-NAS (Intel SS4200) mit OpenMediaVault + Selbstbaukernel 3.2.20
aus den Squeeze-Backports. Netatalk ist aus omv, scheint netatalk aus
den Backports zu verwenden.
[...]
md-RAID 5 mit 4x1TB.
Helios LanTest mit 300MB: 10x ~60MB/s schreibend, ~70MB/s lesend.
Helios LanTest mit 3000MB: erst 1x ~60MB/s, dann 9x ~25MB/s, ~70MB/s lesend.
Warum dieser heftige Einbruch bei 3GB? Jemand eine Idee, wo man da suchen kann?

Nur das Übliche bzgl. Eingrenzung. Mit anderen Protokollen (NFS/SMB)
auch schon versucht? Mal mittels "iozone -s" dem Filesystem auf dem
Server selbst auf den Zahn gefühlt?

Gruss,

Thomas

[Hermann Schaefer]

Post by Thomas Kaiser
Nur das Übliche bzgl. Eingrenzung. Mit anderen Protokollen (NFS/SMB)
auch schon versucht? Mal mittels "iozone -s" dem Filesystem auf dem
Server selbst auf den Zahn gefühlt?

iozone -a -g 2G -i 0 unverdächtig. Zwar sinkt die Performance mehr oder weniger
kontinuierlich, sinkt aber nicht unter 100MB/s. Bei 2G sollte RAM keine
relevante Rolle mehr spielen, da die Kiste eh nur 2GB hat. Ein normales iozone
-a ebenfalls OK, allerdings merkt man da, daß RAM mit im Spiele ist, dann
250MB/s dürften bei dem Ding dezent illusorisch sein.. ^^

dd ist auch nicht weiter erhellend:
dd if=/dev/zero of=./testfile bs=8192 count=2000000
2000000+0 Datensätze ein
2000000+0 Datensätze aus
16384000000 Bytes (16 GB) kopiert, 157,504 s, 104 MB/s
16GB mit im Schnitt 100MB, mehr dürfte das Ding eh nicht schaffen.

Mit smb konstant um die 45MB/s, sowohl mit 300MB als auch mit 3GB, der smbd maxt
halt einen Core aus, mehr geht da nicht. Immerhin kein Einbruch, sogar Last =
Average bei schreiben und lesen..
NFS liefert unter SL üble - aber konstante - Werte unterhalb smb, aber das bin
ich leider gewohnt, mit Lion noch nicht getestet.

Insgesamt also eine nicht allzu dolle, aber für ein "Home-NAS" stattliche
Performance. Nur dieser seltsame Einbruch bei afp wundert mich.

[Thomas Kaiser]

Post by Hermann Schaefer
Insgesamt also eine nicht allzu dolle, aber für ein "Home-NAS" stattliche
Performance. Nur dieser seltsame Einbruch bei afp wundert mich.

Mich _jetzt_ auch. "Auf blöd" auch mal iozone/dd vom Client aus per AFP
loslegen lassen?

Gruss,

Thomas

[Ralph Boehme]

Post by Thomas Kaiser

Post by Hermann Schaefer
Insgesamt also eine nicht allzu dolle, aber für ein "Home-NAS" stattliche
Performance. Nur dieser seltsame Einbruch bei afp wundert mich.

Mich _jetzt_ auch. "Auf blöd" auch mal iozone/dd vom Client aus per AFP
loslegen lassen?

Besser: iperf oder netperf mit r/w size = DSI blocksize. DSI blocksize ist je nach AFP Server unterschiedlich
im Bereich zw. 128 und ~350k (letzteres Netatalk afair).
Aber: wenn das ähnliche Einbrüche wie die ursrünglichen Lantest Testwerte liefert weisst du immer noch nicht
die Ursache und bist zurück auf Los: strace, tcpdump.

-r

[Thomas Kaiser]

Post by Ralph Boehme

Post by Thomas Kaiser

Post by Hermann Schaefer
Insgesamt also eine nicht allzu dolle, aber für ein "Home-NAS"
stattliche Performance. Nur dieser seltsame Einbruch bei afp wundert
mich.

Mich _jetzt_ auch. "Auf blöd" auch mal iozone/dd vom Client aus per
AFP loslegen lassen?

Besser: iperf oder netperf mit r/w size = DSI blocksize. DSI blocksize
ist je nach AFP Server unterschiedlich im Bereich zw. 128 und ~350k
(letzteres Netatalk afair).

Wird ausgehandelt, d.h. kann ich im Trace [nach Verbindungsaufbau | nach
Volumemount] erkennen?

Post by Ralph Boehme
Aber: wenn das ähnliche Einbrüche wie die ursrünglichen Lantest
Testwerte liefert weisst du immer noch nicht die Ursache und bist
zurück auf Los: strace, tcpdump.

Hmm... stimmt. Aber wenn's per iperf ähnlich bescheiden aussieht, ist
zumindest Netatalk bzw. das Filesharing-Protokoll an sich aus dem Kreis
der Verdächtigen ausgeschieden.

Interessant -- wenn aus dem Urlaub retour schaue ich mir das mal am
lebenden Objekt alles an.

Gruss,

Thomas

[Ralph Boehme]

Hi Thomas,

Post by Thomas Kaiser

Post by Ralph Boehme

Post by Thomas Kaiser

Post by Hermann Schaefer
Insgesamt also eine nicht allzu dolle, aber für ein "Home-NAS"
stattliche Performance. Nur dieser seltsame Einbruch bei afp wundert
mich.

Mich _jetzt_ auch. "Auf blöd" auch mal iozone/dd vom Client aus per
AFP loslegen lassen?

Besser: iperf oder netperf mit r/w size = DSI blocksize. DSI blocksize
ist je nach AFP Server unterschiedlich im Bereich zw. 128 und ~350k
(letzteres Netatalk afair).

Wird ausgehandelt, d.h. kann ich im Trace [nach Verbindungsaufbau | nach
Volumemount] erkennen?

Das ist der maximale Wert und der Wird vom Server vorgegeben, nicht wirklich
ausgehandelt. Netatalk default ist 303840 Bytes (0x4A2E0). Der AFP Client
kann allerdings jederzeit kleinere Happen losschicken (bspw. wenn er in in
den WAN mode geht).

Post by Thomas Kaiser
Interessant -- wenn aus dem Urlaub retour schaue ich mir das mal am
lebenden Objekt alles an.

Na, das ist doch mal was auf das man sich freuen kann... ;)

Gruß
-Ralph

[Hermann Schaefer]

Post by Thomas Kaiser
Mich _jetzt_ auch. "Auf blöd" auch mal iozone/dd vom Client aus per AFP
loslegen lassen?

Heute mal unter Lion / Mac Pro:

LanTest nach wie vor seltsam, 3GB, 5 Durchläufe.
Erster Wert schreiben: 60,3 MB/s
danach konstant ca. 25,0 MB/s

Lesen konstant mit rund 77,5 MB/s

Lokale Platte gegengetestet: Kein Einbruch, konstant 80MB/s (nicht die
schnellste Platte) schreibend und lesend.

dd auf afp-mount /Volumes/public mehrfach möglichst schnell hintereinander,
ziemlich konstant:

***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=8192 count=400000
400000+0 records in
400000+0 records out
3276800000 bytes transferred in 47.569569 secs (68884374 bytes/sec)

Also rund 65 MB/s, knapp mehr als mit dem ersten LanTest. Diverse Block Size
ausprobiert:

***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=4096 count=800000
800000+0 records in
800000+0 records out
3276800000 bytes transferred in 48.796494 secs (67152365 bytes/sec)
***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=2048 count=1600000
1600000+0 records in
1600000+0 records out
3276800000 bytes transferred in 57.568089 secs (56920423 bytes/sec)
***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=1024 count=3200000
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 57.716282 secs (56774274 bytes/sec)
***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=512 count=6400000
6400000+0 records in
6400000+0 records out
3276800000 bytes transferred in 72.420352 secs (45246949 bytes/sec)
***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=256 count=12800000
12800000+0 records in
12800000+0 records out
3276800000 bytes transferred in 101.450334 secs (32299549 bytes/sec)
***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=128 count=25600000
25600000+0 records in
25600000+0 records out
3276800000 bytes transferred in 158.002429 secs (20738922 bytes/sec)

Gut, bei bs=128 nur noch 20MB/s. Kein Wunder bei dem Overhead. Das umgekehrte
Extrem:

***@mac:/Volumes/public # dd if=/dev/zero of=./test.dd bs=1048576 count=3072
3072+0 records in
3072+0 records out
3221225472 bytes transferred in 47.516930 secs (67791111 bytes/sec)


Naja, außerdem kann ich Befehle nicht schnell genug eintippen, also kleines
Script ("dding.sh") gemacht:

#!/bin/bash
COUNTER=5
until [ $COUNTER -lt 0 ]; do
echo COUNTER $COUNTER
dd if=/dev/zero of=/Volumes/public/test.dd bs=1024 count=3200000
dd if=/Volumes/public/test.dd of=/dev/null bs=1024 count=3200000
let COUNTER-=1
done

Ergebnis:
***@mac:/Volumes/public # ./dding.sh
COUNTER 5
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 58.290950 secs (56214558 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 45.815218 secs (71522087 bytes/sec)
COUNTER 4
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 57.721618 secs (56769025 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 9.806133 secs (334158232 bytes/sec)
COUNTER 3
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 60.943228 secs (53768074 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 9.722514 secs (337032166 bytes/sec)
COUNTER 2
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 57.856931 secs (56636257 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 9.853970 secs (332536022 bytes/sec)
COUNTER 1
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 57.855262 secs (56637891 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 9.751705 secs (336023293 bytes/sec)
COUNTER 0
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 57.448027 secs (57039383 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 9.743702 secs (336299277 bytes/sec)

Jo, konstant 57MB/s schreibend bei 1k bs. ABER: Lesend 330MB/S??? Also holt da
der Mac was aus dem Cache. Um Fehler u.ä, auszuschließen hab ich das Script dann
geändert - und urandom gequält:

#!/bin/bash
COUNTER=5
until [ $COUNTER -lt 0 ]; do
echo COUNTER $COUNTER
dd if=/dev/urandom of=/Volumes/public/test.dd bs=1024 count=3200000
dd if=/Volumes/public/test.dd of=/dev/null bs=1024 count=3200000
let COUNTER-=1
done

Jetzt sollte er jedes Mal neu lesen. Denkste:

***@mac:/Volumes/public # ./dding.sh
COUNTER 5
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 392.409432 secs (8350462 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 45.417678 secs (72148118 bytes/sec)
COUNTER 4
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 392.524878 secs (8348006 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 10.838204 secs (302337918 bytes/sec)
COUNTER 3
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 392.598300 secs (8346445 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 46.919836 secs (69838267 bytes/sec)
COUNTER 2
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 393.774673 secs (8321510 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 14.727322 secs (222498019 bytes/sec)
COUNTER 1
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 391.454039 secs (8370842 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 11.152968 secs (293805202 bytes/sec)
COUNTER 0
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 391.970281 secs (8359817 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 9.799366 secs (334388980 bytes/sec)

Teils aus dem RAM, teils gelesen. Kann mir das einer erklären?
Pipe ich if nach md5, liest er auch nicht jedes Mal, sondern nimmt 3 Mal den
Cache. Das verstehe wer will.

#!/bin/bash
COUNTER=5
until [ $COUNTER -lt 0 ]; do
echo COUNTER $COUNTER
dd if=/dev/urandom of=/Volumes/public/test.dd bs=1024 count=3200000
dd if=/Volumes/public/test.dd bs=1024 count=3200000 | md5
let COUNTER-=1
done

***@mac:/Volumes/public # ./dding.sh
COUNTER 5
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 392.054205 secs (8358028 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 52.321539 secs (62628127 bytes/sec)
6fb7a62b639868b6d1a372fc5cdf3c6e
COUNTER 4
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 393.172524 secs (8334255 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 52.646936 secs (62241039 bytes/sec)
f63b1234cc04e66f01e880313e5332b2
COUNTER 3
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 393.179234 secs (8334113 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 52.536970 secs (62371317 bytes/sec)
5b472448eebe30ceea0e45b464cf34c6
COUNTER 2
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 393.056234 secs (8336721 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 17.002874 secs (192720359 bytes/sec)
1557af02673a83ae62758d31add0d61b
COUNTER 1
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 391.870674 secs (8361942 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 16.553828 secs (197948175 bytes/sec)
0434fc395cf0a0f5a1cbea5c976d140e
COUNTER 0
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 391.916097 secs (8360973 bytes/sec)
3200000+0 records in
3200000+0 records out
3276800000 bytes transferred in 14.993080 secs (218554158 bytes/sec)
3aaabf779267ca3766498d7d559f9f94


Am DSI rumzuspielen brachte erst mal auch nichts, mit
- -tcp -nosavepassword -nozeroconf -uamlist
uams_dhx.so,uams_dhx2.so,uams_guest.so -dsireadbuf 36 -server_quantum 3038400
gleiches Ergebnis mit LanTest, wieder erstes Schreiben schnell mit 64MB/s,
danach nur noch 25MB/s.

Irgendwas macht LanTest anders resp. dd auf die Freigabe triggert nicht den
Einbruch. Etwas ist mir noch aufgefallen: Beim LanTest-Schreiben hat der Mac
zwischen 10 und 20% CPU beim kernel_task, beim Lesen knapp über 100%. Entweder
wird der Mac einfach nicht mehr gefordert, oder er will nicht mehr. Glaube
langsam an einen Bug im LanTest.

[Ralph Boehme]

Post by Hermann Schaefer

Post by Thomas Kaiser
Mich _jetzt_ auch. "Auf blöd" auch mal iozone/dd vom Client aus per AFP
loslegen lassen?

dd ist an der Stelle in der Tat "auf blöd".

Post by Hermann Schaefer
#!/bin/bash
COUNTER=5
until [ $COUNTER -lt 0 ]; do
echo COUNTER $COUNTER
dd if=/dev/zero of=/Volumes/public/test.dd bs=1024 count=3200000
dd if=/Volumes/public/test.dd of=/dev/null bs=1024 count=3200000
...
Teils aus dem RAM, teils gelesen. Kann mir das einer erklären?

Ja. mmap. Du willst nicht dd, du willst iperf/netperf. Und ne realistische DSI
blocksize. Das misst dann zwar nur das Netzwerk, aber alles andere liefert
halt gerne nicht analysierbare Artefakte (filesystem cache, block cache, write
cache etc.).

Und nochmal: um zu ermitteln welche IO syscalls am Server Zeit verbraten gibts
strace (strace -vttp PID).

Übrigens liest Netatalk 2.x wider jede Vernunft die Daten vom socket afair immer
nur 8k Häppchenweise.

-r