7590 VPN Geschwindigkeit / Transferrate zu niedrig

[Phoenixtime]

Vielleicht ist Datenblatt übertrieben, eher Werbeanzeige ...
Ich hatte nach GRX550 gegoogelt und gleich der erste Treffer führt einem zur Intel Seite mit einem PDF zum GRX550.
Ich denke mit Beschleunigung ist das ganze Berechnungen für AES und hash summen gemeint ... und das auch nur in Teilen. Weil wie du sagst, es ist nicht mit Intels AES-NI zu vergleichen.

 

[Shirocco88]

Laut Intel Datenblatt hat der GRX550 für IPSec Hardware Acceleration.

geht es um diese Quellen:
https://www.intel.de/content/www/de/de/smart-home/connected-home/anywan-soc-grx350-grx550-brief.html

Key features:

• Hardware acceleration for VPN/IPsec, TLS, storage, etc

https://www.intel.de/content/dam/ww...uct-briefs/anywan-soc-grx350-grx550-brief.pdf

 

[PeterPawn]

Putzig ... wenn ich Google nach "GRX550" frage, kriege ich nur den Link zu: https://ark.intel.com/products/93818/Intel-AnyWAN-GRX550-Network-Processor

An zweiter Stelle dann den zum GRX350 in derselben Datensammlung ... das hatte ich ja auch noch nicht, daß sich Google-Ergebnisse so sehr unterscheiden.

Nach längerer Suche (die alten Links auf diese PDF-Dateien, die ich hier bei mir liegen habe und auch schon das eine oder andere Mal hier irgendwo verlinkt hatte, funktionieren alle nicht mehr so richtig) kommt dann tatsächlich noch das hier zum Vorschein: https://www.intel.com/content/dam/w...uct-briefs/anywan-soc-grx350-grx550-brief.pdf

Und da steht dann etwas von Hardware-Acceleration ... aber tatsächlich "für alles" - neben IPSec auch noch TLS und "storage" usw.

 

[eisbaerin]

nur noch 23 °C draußen, aber 30,8 °C an der Dostmann-Station

Entweder solltest du mal Lüften (Fenster weit aufmachen, am besten Durchzug) oder endlich deine Heizung abstellen

 

[johnripper]

Da die CPU Auslastung irgendwo bei wenigen Prozent rumdümpelt ist doch einw Hardwarebeschleinigung vollkommen egal.

 

[PeterPawn]

Bei allem, was ich bisher (auch in den GRX-Quellen für die 7580) gesehen hatte, konnte ich mich beim besten Willen nicht daran erinnern, daß da irgendwelcher Code für die Nutzung so einer Crypto-Engine dabeigewesen wäre ... das wäre ja dann sogar richtig sinnvoll (wenn es diese Engine auch gibt), die auch für irgendwelche SSL-Stacks (u.a. auch OpenSSL) zu verwenden.

Aber der Blick in die Quellen zeigt dann tatsächlich, daß es eine DEU (Data Encryption Unit) und die betreffenden Files gibt (hier schon in den Quellen der 7580 für 06.92):

390 config CRYPTO_DEV_LANTIQ_DEU
391     tristate "Support for Lantiq hardware crypto engine"
392     depends on LANTIQ && SOC_XWAY
393     select CRYPTO_AES
394     select CRYPTO_DES
395     select CRYPTO_CBC
396     select CRYPTO_CTR
397     select CRYPTO_ECB
398     select CRYPTO_SHA1
399     select CRYPTO_MD5
400     select CRYPTO_HASH
401     select CRYPTO_HMAC
402     select CRYPTO_ARC4
403     select CRYPTO_ALGAPI
404     select CRYPTO_BLKCIPHER
405     help
406       Selects Hardware accelerated crypto drivers.
407       Supports:
408         AES/DES/ARC4/SHA-1/MD5 (DANUBE)
409         AES/DES/ARC4/SHA-1/MD5/HMAC (xrx200, xrx300, xrx330)
410
411
412
413 source "drivers/crypto/lantiq_deu/Kconfig"
414 source "drivers/crypto/Kconfig.grx500"

Schaut man dann wieder in die Kernel-Symbole (irgendwo müssen die Einsprungpunkte von Funktionen ja dann aufgelistet sein), findet man zwar einige Symbole mit "ltq" im Namen, aber keines davon paßt auf "ltq.*deu" oder "deu.*ltq" - auch irgendwelche Symbole mit "aes" im Namen, zeigen nur auf AVM-Module oder auf die "üblichen" Crypto-Algorithmen aus dem Kernel:

# grep "aes" /proc/kallsyms
80852f08 T crypto_aes_expand_key
80853448 T crypto_aes_set_key
80853494 t aes_decrypt
80854724 t aes_encrypt
80e6929c t aes_init
8a64f66c t aes_icm_alloc_ismacryp.part.0        [krtp]
8a64aad8 t crypto_policy_set_aes_cm_256_null_auth       [krtp]
8a64aa78 t crypto_policy_set_aes_cm_256_hmac_sha1_80    [krtp]
8a64f840 t aes_icm_encrypt_ismacryp     [krtp]
8a64aa28 t crypto_policy_set_aes_cm_128_null_auth       [krtp]
8a64fcc0 t aes_cbc_dealloc      [krtp]
8a64fc4c t aes_icm_output       [krtp]
8a64ddf0 t aes_decrypt  [krtp]
8a64f410 t aes_icm_dealloc      [krtp]
8a64f5f4 t aes_icm_set_iv       [krtp]
8a64aaa8 t crypto_policy_set_aes_cm_256_hmac_sha1_32    [krtp]
8a64f7a4 t aes_icm_set_octet    [krtp]
8a64f71c t aes_icm_alloc        [krtp]
8a64f468 t aes_icm_context_init [krtp]
8a64c2a0 t aes_expand_encryption_key    [krtp]
8a64fc3c t aes_icm_encrypt      [krtp]
8a64fdf8 t aes_cbc_set_iv       [krtp]
8a64f750 t aes_icm_alloc_ismacryp       [krtp]
8a64b6cc t aes_decrypt_with_raw_key     [krtp]
8a64ffd8 t aes_cbc_decrypt      [krtp]
8a64a9f8 t crypto_policy_set_aes_cm_128_hmac_sha1_32    [krtp]
8a6500dc t aes_cbc_nist_decrypt [krtp]
8a64fea8 t aes_cbc_encrypt      [krtp]
8a64ff7c t aes_cbc_nist_encrypt [krtp]
8a64fcac t aes_icm_bytes_encrypted      [krtp]
8a64c4f4 t aes_expand_decryption_key    [krtp]
8a64fd18 t aes_cbc_context_init [krtp]
8a64fd50 t aes_cbc_alloc        [krtp]
8a64c7d4 t aes_encrypt  [krtp]
8a3b5c70 t aes_gcm_ghash        [umac]
8a3b5d70 t aes_gcm_prepare_j0   [umac]
8a3b5e7c t aes_gctr.part.2      [umac]
8a3b5fe4 t aes_gcm_gctr.part.3  [umac]
8a4a25c4 t aes_s2v      [umac]
8a3b60fc t aes_encrypt_deinit   [umac]
8a4a2f8c t omac1_aes_256        [umac]
8a4a2a74 t aes_siv_decrypt      [umac]
8a4a2f14 t omac1_aes_128_vector [umac]
8a3b63cc t aes_gmac     [umac]
8a4a2f4c t omac1_aes_128        [umac]
8a3b6068 t aes_encrypt_init     [umac]
8a4a2c94 t omac1_aes_vector     [umac]
8a3b6290 t aes_gcm_ad   [umac]
8a4a28ec t aes_siv_encrypt      [umac]
8a4a3108 t aes_128_ctr_encrypt  [umac]
8a4a2fd0 t aes_ctr_encrypt      [umac]
8a3b613c t aes_gcm_ae   [umac]
8a3b6050 t aes_encrypt  [umac]
8a1f4780 t aes_init_key [kdsldmod]
8a1f485c t aes_cipher   [kdsldmod]
8a17f278 t aes  [avm_dect]
# lsmod
Module                  Size  Used by    Tainted: P
kspeedtest             14644  0
spdmon                 18026  0
hwmon                   1065  1 spdmon
krtp                  226927  0
qca_ol               1065408  0
umac                 1714589  2 qca_ol
userman_mod            77186  4
ath_spectral           40084  2 qca_ol
ath_dfs                76293  2 qca_ol,umac
qdf                    23677  4 qca_ol,umac,ath_spectral,ath_dfs
asf                     7534  4 qca_ol,umac,ath_spectral,ath_dfs
mem_manager             7006  2 qca_ol,umac
aae                   116871  3 qca_ol,umac,ath_dfs
kdsldmod             1614499  9 userman_mod
cprocfsmod              7042  1 kdsldmod
dect_io                17443  0
avm_dect              320285  1 dect_io
capi_codec            379977  0
isdn_fbox_fon5        894601  6 krtp
pcmlink               412372  4 avm_dect,capi_codec,isdn_fbox_fon5
vrx318_tc             190908  0
drv_dsl_cpe_api       297452  2
drv_mei_cpe           162346  3 drv_dsl_cpe_api
xhci_hcd               95121  0
sch_tbf                 4979  1
sch_hw                  7256  0
ppa_api_proc           33447  0
ppa_api               388242  1 ppa_api_proc
ltq_directpath_datapath    28361  0
ltq_tmu_hal_drv       180535  1 ltq_directpath_datapath
ltq_pae_hal            68166  0
Piglet_noemif          41845  0
rtc_avm                 4604  1 pcmlink
led_modul_Fritz_Box_HW225   177207  6
# uname -a
Linux fritz.box 3.10.104 #1 SMP Tue Jul 17 17:42:16 CEST 2018 mips
#

und auch die "Erklärungen" unter "/proc/crypto" passen nicht zu denen, die in den Lantiq-Sourcen gesetzt würden:

# cat /proc/crypto
name         : ghash
driver       : ghash-generic
module       : kernel
priority     : 100
refcnt       : 1
selftest     : passed
type         : shash
blocksize    : 16
digestsize   : 16

name         : stdrng
driver       : krng
module       : kernel
priority     : 200
refcnt       : 1
selftest     : passed
type         : rng
seedsize     : 0

name         : xz
driver       : xz-generic
module       : kernel
priority     : 0
refcnt       : 2
selftest     : passed
type         : compression

name         : lzo
driver       : lzo-generic
module       : kernel
priority     : 0
refcnt       : 2
selftest     : passed
type         : compression

name         : crc32c
driver       : crc32c-generic
module       : kernel
priority     : 100
refcnt       : 2
selftest     : passed
type         : shash
blocksize    : 1
digestsize   : 4

name         : deflate
driver       : deflate-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : compression

name         : ecb(arc4)
driver       : ecb(arc4)-generic
module       : kernel
priority     : 100
refcnt       : 1
selftest     : passed
type         : blkcipher
blocksize    : 1
min keysize  : 1
max keysize  : 256
ivsize       : 0
geniv        : <default>

name         : arc4
driver       : arc4-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : cipher
blocksize    : 1
min keysize  : 1
max keysize  : 256

name         : aes
driver       : aes-generic
module       : kernel
priority     : 100
refcnt       : 2
selftest     : passed
type         : cipher
blocksize    : 16
min keysize  : 16
max keysize  : 32

name         : blowfish
driver       : blowfish-generic
module       : kernel
priority     : 100
refcnt       : 1
selftest     : passed
type         : cipher
blocksize    : 8
min keysize  : 4
max keysize  : 56

name         : des3_ede
driver       : des3_ede-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : cipher
blocksize    : 8
min keysize  : 24
max keysize  : 24

name         : des
driver       : des-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : cipher
blocksize    : 8
min keysize  : 8
max keysize  : 8

name         : sha1
driver       : sha1-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : shash
blocksize    : 64
digestsize   : 20

name         : md5
driver       : md5-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : shash
blocksize    : 64
digestsize   : 16

name         : digest_null
driver       : digest_null-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : shash
blocksize    : 1
digestsize   : 0

name         : compress_null
driver       : compress_null-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : compression

name         : ecb(cipher_null)
driver       : ecb-cipher_null
module       : kernel
priority     : 100
refcnt       : 1
selftest     : passed
type         : blkcipher
blocksize    : 1
min keysize  : 0
max keysize  : 0
ivsize       : 0
geniv        : <default>

name         : cipher_null
driver       : cipher_null-generic
module       : kernel
priority     : 0
refcnt       : 1
selftest     : passed
type         : cipher
blocksize    : 1
min keysize  : 0
max keysize  : 0

#

, denn dann müßte der "driver" eigentlich so aussehen:

struct crypto_alg ltqdeu_aes_alg = {
                .cra_name                               =               "aes",
                .cra_driver_name                =               "ltqdeu-aes",
                .cra_flags                              =               CRYPTO_ALG_TYPE_CIPHER,
                .cra_blocksize                  =               AES_BLOCK_SIZE,
                .cra_ctxsize                    =               sizeof(struct aes_ctx),
                .cra_module                             =               THIS_MODULE,
                .cra_list                               =               LIST_HEAD_INIT(ltqdeu_aes_alg.cra_list),
                .cra_u                                  =               {
                        .cipher = {
                                .cia_min_keysize        =               AES_MIN_KEY_SIZE,
                                .cia_max_keysize        =               AES_MAX_KEY_SIZE,
                                .cia_setkey                     =               aes_set_key,
                                .cia_encrypt            =               aes_encrypt,
                                .cia_decrypt            =               aes_decrypt,
                        }
                }
};

Schaut man dann noch in die ".config" (sowohl in die der 06.92 als auch der 07.00 - letztere halt für die 7590, weil die 7580-Quellen nicht veröffentlicht sind auf dem osp.avm.de), findet man gar keine Definitionen "CRYPTO.*LTQ", die nach der Datei "drivers/crypto/lantiq_deu/Kconfig" aber in jedem Falle vorhanden sein müßten, wenn die Lantiq-Quellen eingebunden wurden.

Das ist natürlich noch interessanter ... obwohl natürlich die Benutzung der DEU (und ggf. eine Serialisierung dafür) durchaus eine (sehr witzige) Erklärung liefern könnte, warum es mit HW-Support wieder langsamer wird als ohne - wenn es nur einen Crypto-Prozessor gibt und der belegt ist, müßten andere Verbindungen ja warten. Wäre wieder die Frage, wieviel schneller die DEU am Ende ist im Vergleich zu einem Core mit vollem Takt - hängt sicherlich auch wieder vom Algorithmus ab.

Ich würde also irgendwie (auch vom Bauch her) sagen, daß in den FRITZ!Box-Kernels von AVM diese Hardware-Beschleunigung tatsächlich nicht verwendet wird - oder ich suche an der vollkommen falschen Stelle. Aber wenn man sich die Symbole (bei /proc/kallsyms) so ansieht, müßte dann schon der "kdsldmod.ko" von AVM von dieser DEU Gebrauch machen ... denn an anderen Stellen wird offenbar davon ausgegangen, daß es keine Crypto-Hardware gibt und die Kernel-Module unter "/proc/crypto" das höchste der Gefühle sind (die brauchen wenigstens keinen Kontextwechsel in den User-Space, wenn eine Kernel-Komponenten einen der Algorithmen nutzen will). Ich würde trotzdem fast darauf wetten wollen, daß AVM auch noch mit einer eigenen AES-Implementierung hantiert ... da gibt es mir noch zuviele Referenzen auf den alten AES-Namen "Rijndael" in den Symbolen, die man in den AVM-Libraries findet.

-------------------------------------------------------------------------------

Die Aussage dazu, daß die Frage "DEU oder nicht" ohnehin egal wäre, weil die Auslastung bei wenigen Prozent "herumdümpelt", kann ich wieder nicht nachvollziehen ... diese Auslastung bezieht sich ja auf alle vorhandenen Cores (die sind ja nicht einzeln aufgeführt) und damit sind schon 25% (wenn sie auf einem Core (bzw. für einen Thread auf mehreren Kernen, wenn der nach einem Kontextwechsel auf einem anderen Core laufen sollte) stattfinden) doch Volllast für einen einzelnen Core.

Irgendwo bei heise.de habe ich die Tage (auch im Kontext des Erscheinens von FRITZ!OS 7) jemanden gesehen, der für sich feststellte, daß der CPU-Load auf seiner Box extrem gesunken sei und das auch über einen längeren Zeitpunkt protokolliert und visualisiert hatte: https://i.imgur.com/OPJS24g.png (Vorsicht: externer Link, leider nicht mein Bild)

Schaut man sich das an, ist der CPU-Load tatsächlich mit der 07.00 von Werten zwischen 4 und 6 (im "mean", Ausreißer lassen wir mal weg) auf Werte zwischen 2 und 3 gesunken. Wenn das aber auch der Sprung von zwei verwendbaren Cores auf vier war (irgendwo gibt es Threads dazu hier im IPPF), dann hat sich da nicht wirklich etwas geändert und es wurde lediglich deshalb weniger, weil es zwei Cores mehr gibt und der protokollierte Wert "average" ist.

Nun weiß ich ja nicht, was "wenige Prozent" ansonsten so sind ... aber bei den erwähnten 25% kann eben ein Kern bereits komplett ausgelastet sein.

Ich habe gerade mal nachgesehen, was eigentlich in meiner unkonfigurierten Box so passiert (nicht mal der Einrichtungsassistent ist da "durch", auch wenn das GUI nicht geöffnet ist) und siehe da ... der "ctlmgr" (das ist ja gleichzeitig der Prozess, der für das GUI verantwortlich ist) beschäftigt in diesem Zustand tatsächlich einen Core zu 100%, was im "top" dann so aussieht:

Mem: 145816K used, 286692K free, 3304K shrd, 17716K buff, 51644K cached
CPU0: 92.4% usr  7.3% sys  0.0% nic  0.1% idle  0.0% io  0.0% irq  0.0% sirq
CPU1:  0.2% usr  0.2% sys  0.0% nic 99.5% idle  0.0% io  0.0% irq  0.0% sirq
CPU2:  0.0% usr  1.6% sys  0.0% nic 98.3% idle  0.0% io  0.0% irq  0.0% sirq
CPU3:  0.2% usr  0.4% sys  0.0% nic 99.3% idle  0.0% io  0.0% irq  0.0% sirq
Load average: 4.12 4.06 4.05 3/130 26473
  PID  PPID USER     STAT   VSZ %VSZ CPU %CPU COMMAND
1911     1 root     R    22096  5.1   3 25.1 ctlmgr
25476     2 root     SW       0  0.0   2  0.4 [kworker/2:0]

... damit ist "unkonfiguriert" dann eher nicht mit "unbeschäftigt" gleichzusetzen (der Load sinkt auch nicht wirklich, selbst wenn das oben natürlich nur ein Schnappschuss ist).

 

[eisbaerin]

... damit ist "unkonfiguriert" dann eher nicht mit "unbeschäftigt" gleichzusetzen

Kein Wunder, daß deine 7580 dann auch so heiß wird. (und dein Zimmer auf 38°C)
Ist das nach einem reboot auch noch so?
Wie gehst du auf das CLI? Telnet? SIAB? Ich per dropbear und putty. Das nenne ich Leerlauf:

Mem: 136856K used, 295652K free, 2132K shrd, 15288K buff, 52088K cached
CPU0:  0.4% usr  3.5% sys  0.0% nic 96.0% idle  0.0% io  0.0% irq  0.0% sirq
CPU1:  0.0% usr  0.8% sys  0.0% nic 99.1% idle  0.0% io  0.0% irq  0.0% sirq
CPU2:  0.2% usr  0.0% sys  0.0% nic 99.8% idle  0.0% io  0.0% irq  0.0% sirq
CPU3:  0.6% usr  0.0% sys  0.0% nic 99.2% idle  0.0% io  0.0% irq  0.2% sirq
Load average: 1.16 1.18 1.15 2/125 30168
  PID  PPID USER     STAT   VSZ %VSZ CPU %CPU COMMAND
29946     2 root     SW       0  0.0   0  0.5 [kworker/0:2]
30090 26776 root     R     1448  0.3   0  0.3 top
29100     2 root     SW       0  0.0   1  0.1 [kworker/1:0]

Dein "Load average" von "4" ist IMO schon recht hoch.
Die 7580 geht auch neuerdings mit der 59660 gegen "1".
Früher mit z.B. der 51193 ging sie noch gegen "0".
BTW: Die 7590 ging früher gegen "1" und jetzt gegen "2".
Das konnte mir bisher auch noch keiner erklären.

Was ich an deinem "top" merkwürdig finde:
Vor den 25.1% steht CPU 3. Oben ist aber CPU0 mit 92.4% ausgelastet.
Ist das zu erklären?

Übrigens habe ich ganz schön lange gesucht wie man die 4 einzelnen CPUs dargestellt bekommt.
In der Hilfe "top -h" wird es nicht erklärt, daß man da auch "c" drücken kann:

7580:$(pwd)# top -h
top: invalid option -- h
BusyBox v1.24.2 (2018-04-17 12:40:18 CEST) multi-call binary.

Usage: top [-b] [-nCOUNT] [-dSECONDS] [-m]

Provide a view of process activity in real time.
Read the status of all processes from /proc each SECONDS
and display a screenful of them.
Keys:
        N/M/P/T: show CPU usage, sort by pid/mem/cpu/time
        S: show memory
        R: reverse sort
        H: toggle threads, 1: toggle SMP
        Q,^C: exit

Options:
        -b      Batch mode
        -n N    Exit after N iterations
        -d N    Delay between updates
        -m      Same as 's' key
7580:$(pwd)#

 

[dau_user]

Moin,

@PeterPawn, du hast recht bei meinem Screenshot handelt es sich nur eine VPN Verbindung. Ich habe heute zeit und werde es nachstellen, ich habe drei VPN User und werde mich mit drei verschiedenen Geräte mal ein wählen. Ich habe eine 1GB/s Glasfaserleitung ins Internet zur Verfügung. Ich hatte das schon mal gemacht, dabei habe ich beobachtet dass der Strich der CPU Auslastung nur drei viertel hoch ging und alle drei sich die 5MBit/s Bandbreite teilten. Temperatur hat sich kaum geändert bei dem Test, da es sehr kühl war in meinem Home Office bei 38 Grad Außentemperatur. Wie gesagt die Box hängt an der Wand, aber in einem Schrank bei dem die Rückwand ausgeschnitten ist, dort strömt immer ein wenig Luft durch. Ich muss noch nachtragen, AVM hatte erst das Netzteil in verdacht, aber es lag das richtige bei. Es gibt wohl für dieses Modell Verschiedene. Ich glaube einfach da ist Software seitig noch was im argen, da ich beim Aufbau einer VPN einen Kernel Oops hatte, dies hatte ich über Jahre mit der 7490 nicht.
Ich werde es laufe des Vormittags ausführlich testen und werde berichten ....

 

[Shirocco88]

Dein "Load average" von "4" ist IMO schon recht hoch.

ein Load-Avg von 4 bei 4 Cores ist nicht unbedingt hoch; dies entspricht einem Load-Avg von 1 bei einem SingleCore-System; Hinweis: Load-Avg zieht ein Mittel über Metriken (CPU-Load, IO, ...).

Was ich an deinem "top" merkwürdig finde:
Vor den 25.1% steht CPU 3. Oben ist aber CPU0 mit 92.4% ausgelastet.

die Frage ist was der jeweilige Core dieser Zeit macht;
für mich ist die CPU-RunQueue (cpu-rz im sar) pro Core die wichtigste Metrik zur Bewertung der CPU-Auslastung, ergänzend ist iostat Output wichtig.

 

[dau_user]

Mahlzeit!

ich habe den Test nochmals gemacht, wie man schön sieht kam es wieder zum Kernel Oops. Ich werde wohl bei der 7490 bleiben, die lief über Jahre stabil.
Wie man aber schön sehen kann ging die CPU Last hoch nach dem ich drei VPN Verbindungen aufgebaut habe, 5-6 MBit/s Datentraffic konnte ich durch jagen.

 

[dau_user]

und jetzt noch was für @PeterPawn, geht auch gleich an AVM raus, ich hoffe die können damit was anfangen

Kernel bug detected[#2]:
[ 6292.936000][3]      43s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]CPU: 2 PID: 0 Comm: swapper/2 Tainted: P      D    O 3.10.104 #1
[ 6292.936000][3]      33s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]task: 9fc810a0 ti: 9fcb4000 task.ti: 9fcb4000
BUG() at function 'cbm_buffer_alloc' line: 2119 file: drivers/net/ethernet/lantiq/cbm/cbm.c



[ 6292.936000][2]Call Trace:
[ 6292.936000][2]3918: [<809d18a4>] 0x809d18a4 cbm_buffer_alloc+0x4b4/0x58c
[ 6292.936000][3]      44s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3968: [<809d63b0>] 0x809d63b0 cbm_cpu_pkt_tx+0x140/0x520
[ 6292.936000][3]      41s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]39d0: [<809ab080>] 0x809ab080 dp_xmit+0x11a8/0x1398
[ 6292.936000][2]3a30: [<809dea08>] 0x809dea08 ltq_start_xmit+0x74/0x110
[ 6292.936000][3]      43s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3a58: [<80a647a8>] 0x80a647a8 dev_hard_start_xmit+0x32c/0x564
[ 6292.936000][2]3aa0: [<80a93470>] 0x80a93470 sch_direct_xmit+0x9c/0x2c8
[ 6292.936000][3]      51s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3ad0: [<80a64c44>] 0x80a64c44 dev_queue_xmit+0x264/0x590
[ 6292.936000][2]3b08: [<80b78314>] 0x80b78314 br_dev_queue_push_xmit+0x278/0x2d0
[ 6292.936000][3]      44s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3b40: [<80b78be8>] 0x80b78be8 br_flood_deliver+0x38/0x48
[ 6292.936000][2]3b68: [<80b761c4>] 0x80b761c4 br_dev_xmit+0x224/0x250
[ 6292.936000][3]      52s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3b90: [<80a647a8>] 0x80a647a8 dev_hard_start_xmit+0x32c/0x564
[ 6292.936000][2]3bd8: [<80a64e24>] 0x80a64e24 dev_queue_xmit+0x444/0x590
[ 6292.936000][3]       2s ago: received with dport=7 sport=0 cbm_port=2
[ 6292.936000][2]3c10: [<80aeba2c>] 0x80aeba2c arp_solicit+0x1c8/0x1ec
[ 6292.936000][2]3c70: [<80a6c910>] 0x80a6c910 neigh_probe+0x68/0x90
[ 6292.936000][3]      44s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3c90: [<80a71408>] 0x80a71408 neigh_timer_handler+0x200/0x2bc
[ 6292.936000][2]3cb8: [<8055bb1c>] 0x8055bb1c call_timer_fn.isra.6+0x4c/0xc8
[ 6292.936000][3]      44s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3ce8: [<8055bd80>] 0x8055bd80 run_timer_softirq+0x1e8/0x284
[ 6292.936000][2]3d30: [<805543dc>] 0x805543dc __do_softirq+0x180/0x2a4
[ 6292.936000][3]      45s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3d90: [<805545d8>] 0x805545d8 do_softirq.part.1+0x3c/0x5c
[ 6292.936000][2]3da8: [<80554868>] 0x80554868 irq_exit+0x60/0xb8
[ 6292.936000][3]      49s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3dc0: [<80535ec0>] 0x80535ec0 gic_shared_irq_vi5_dispatch+0x110/0x168
[ 6292.936000][2]3df8: [<8050850c>] 0x8050850c ret_from_irq+0x0/0x4
[ 6292.936000][3]      43s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3ec8: [<80527344>] 0x80527344 __pastwait+0x0/0xc
[ 6292.936000][2]3ec8: [<8052733c>] 0x8052733c r4k_wait_irqoff+0x2c/0x34
[ 6292.936000][3]      45s ago: received with dport=2 sport=0 cbm_port=2
[ 6292.936000][2]3ee0: [<8058c988>] 0x8058c988 cpu_startup_entry+0x100/0x160
[ 6292.936000][3]      44s ago: received with dport=2 sport=0 cbm_port=2

 

[PeterPawn]

Die AVM-Leute können damit garantiert etwas anfangen ... der Fehler tritt im Treiber für eine (Lantiq-)Komponente auf, die sich "Central Buffer Manager" nennt und folgendermaßen in der zugehörigen Option für Kconfig beschrieben ist:

config LTQ_CBM
tristate "Central Buffer Manager Driver"
depends on SOC_GRX500
default n
---help---
Turn on this option to enable CBM driver which is a special hardware
present in the XRX500 series of SoCs to manage the network buffers
in HW.

Also schon mal spezifisch für GRX500 ... was (a) erklärt, daß es bei neueren Modellen ein Problem gibt, was bei älteren nicht existiert und (b) auch zeigt, daß es wohl nicht der erste Fall ist, wo AVM beim CBM ein paar Buffer "aus den Augen verliert".

Denn schaut man sich dann die betreffende Stelle in "cbm.c" an, sieht man vor dem "BUG()" - was infolge eines Problems, über längere Zeit einen freien Buffer zu finden, auftritt - direkt noch eine zusätzliche (m.E. von AVM eingebaute) Funktion "cbm_show_ownership_stats()", wo offensichtlich versucht wird, den verlorenen Segmenten hinterherzusuchen.

2013 static void cbm_show_ownership_stats()
2014 {
2015     int (*wlan_get_cnt)(void);
2016     uint32_t tmu_gocc; /* global occupancy count */
2017     uint32_t cbm_fssc, cbm_fjsc; /* free segment counts */
2018
2019     /* CBM */
2020     cbm_fssc = xrx500_cbm_r32(FSQM_BASE(0) + OFSC); /* standard */
2021     cbm_fjsc = xrx500_cbm_r32(FSQM_BASE(1) + OFSC); /* jumbo */
2022     printk("Buffers available in CBM: %u standard, %u jumbo\n", cbm_fssc, cbm_fjsc);
2023
2024     /* TMU */
2025     tmu_global_occupancy_get(&tmu_gocc);
2026     printk("Occupancy count of TMU: %u\n", tmu_gocc);
2027
2028     /* WLAN */
2029     wlan_get_cnt =
2030      (void *)kallsyms_lookup_name("avm_wlan_get_cbm_cnt");
2031     if(wlan_get_cnt) {
2032         printk("Buffers pending in WLAN host queue: %d\n", wlan_get_cnt());
2033     } else {
2034         printk("WLAN host queue count is not available.\n");
2035     }
2036
2037     /* net core */
2038     printk("Searching sockets for CBM buffers...\n");
2039     cbm_show_socket_stats();
2040
2041     /* TODO find more occupiers */
2042 }
2043
2044
2045 /*
2046  * returns 2k or 8k aligned buffers, respectively
2047  */
2048 void *cbm_buffer_alloc(uint32_t pid, uint32_t flag)
2049 {
2050     uint32_t buf_addr = 0;
2051     uint32_t i = 0;
2052     unsigned long sys_flag;
2053     void *va_res = NULL;
2054 #if defined(DEBUG_CBM_STATS)
2055     static atomic_t last_avail_2k = ATOMIC_INIT(0);
2056     static atomic_t last_avail_8k = ATOMIC_INIT(0);
2057     static atomic_t consec_fails_2k = ATOMIC_INIT(0);
2058     static atomic_t consec_fails_8k = ATOMIC_INIT(0);
2059     atomic_t *consec_fails;
2060     atomic_t *last_avail;
2061     u64 *alloc_good;
2062     u64 *alloc_fail;
2063     unsigned long old_val;
2064     enum { timeout = 20 };
2065     enum { min_samples = 20 };
2066 #endif
2067
2068     if (pid >= CPU_EQM_PORT_NUM /*|| (((1 << pid) & g_cpu_port_alloc) == 0)*/) {
2069         cbm_err("illegal pid: %d, legal cpu bitmap: 0x%x\n", pid, (unsigned int) (g_cpu_port_alloc));
2070         return NULL;
2071     }
2072     local_irq_save(sys_flag);
2073     if(injected_failures == 0) do {
2074         buf_addr = xrx500_cbm_r32(bufreq[!!(flag >> 1)] + (pid * 0x1000));
2075     } while ((buf_addr & 0xFFFFF800) == 0xFFFFF800 && (i++) < DEFAULT_WAIT_CYCLES);
2076     else {
2077         injected_failures--;
2078         buf_addr = 0xffffffff;
2079     }
2080     local_irq_restore(sys_flag);
2081
2082     if ((buf_addr & 0xFFFFF800) == 0xFFFFF800) {
2083         pr_debug("alloc buffer fail for portid: %d type %d", pid, flag);
2084     } else {
2085         pr_debug("buffer alloc got: %#x \n", buf_addr);
2086         va_res = (void *)__va(buf_addr);
2087     }
2088
2089 #if defined(DEBUG_CBM_STATS)
2090     if(flag == CBM_PORT_F_JUMBO_BUF) {
2091         consec_fails = &consec_fails_8k;
2092         last_avail = &last_avail_8k;
2093         alloc_good = &alloc_cbm_8k_good;
2094         alloc_fail = &alloc_cbm_8k_fail;
2095     } else {
2096         consec_fails = &consec_fails_2k;
2097         last_avail = &last_avail_2k;
2098         alloc_good = &alloc_cbm_2k_good;
2099         alloc_fail = &alloc_cbm_2k_fail;
2100     }
2101
2102     if(va_res == NULL) {
2103         *alloc_fail += 1;
2104
2105         old_val = atomic_cmpxchg(last_avail, 0, jiffies);
2106         if(old_val && min_samples <= atomic_inc_return(consec_fails) &&
2107            time_after(jiffies, old_val + msecs_to_jiffies(timeout * 1000))) {
2108             if(flag == CBM_PORT_F_JUMBO_BUF) {
2109                 cbm_track_dump(cbm_recs.jbo, ARRAY_SIZE(cbm_recs.jbo));
2110             } else {
2111                 cbm_track_dump(cbm_recs.std, ARRAY_SIZE(cbm_recs.std));
2112             }
2113             pr_err("Could not allocate new CBM %s buffer %d times over "
2114                    "%d seconds.\n",
2115                    flag == CBM_PORT_F_JUMBO_BUF ? "jumbo" : "standard",
2116                    atomic_read(consec_fails),
2117                    jiffies_to_msecs(jiffies - old_val) / 1000);
2118             cbm_show_ownership_stats();
2119             BUG();
2120         }
2121     } else {
2122         *alloc_good += 1;
2123         atomic_set(last_avail, 0);
2124         atomic_set(consec_fails, 0);
2125     }
2126 #endif
2127     if(va_res) cbm_track_alloc(va_res, __builtin_return_address(0));
2128     return va_res;
2129 }
2130 EXPORT_SYMBOL(cbm_buffer_alloc);

Gleichzeitig fällt auf, daß AVM auch in der Release-Version der Firmware offensichtlich das Symbol "DEBUG_CBM_STATS" aktiviert hat, denn ansonsten würde ja der ganze Block, in dem das "BUG()" enthalten ist, gar nicht mit eingeschlossen bei der Übersetzung des Codes.

Wo genau die Buffer sich hier jetzt alle versammeln (und damit über längere Zeit kein freier Buffer gefunden werden kann), könnte man halt in der "/dev/debug" verfolgen oder in einer anderen "printk()"-Ausgabe ... je nachdem, wohin die von AVM gerade umgeleitet wird. Es gibt da ja einen Mechanismus bei AVM, diese Ausgaben nach "/dev/debug" umzuleiten (dann sieht man mit einem "normalen" printk()-Listener (wie einem Syslog-Daemon mit printk-Support) nichts mehr) ... wer es genauer wissen will bzw. auch mal sehen will, was man noch alles nach "/dev/debug" schreiben kann, um das zu steuern, der sucht sich die Quellen für das "avm_debug"-Device.

Die Nachrichten dazwischen mit der Angabe von irgendwelchen Sekunden stammen jedenfalls auch aus dem CBM-Code ... wenn ich das richtig interpretiere, sind das alles Pakete, die vor der angegebenen Zeit empfangen (received) und noch nicht "dequeued" wurden (es gibt jeweils einen "enqueue manager" (eqm) und einen "dequeue manager" (dqm) ... wo also vermutlich der empfangende Prozess abhanden gekommen ist oder es irgendeinen Deadlock gibt, der den Empfang (bzw. genauer die Verarbeitung) weiterer Pakete verhindert.

Für einen Deadlock würde es sprechen, wenn der Zeitpunkt des versuchten Aufbaus der VPN-Verbindung mit der größten Zeit, die ein Paket hier schon wartet (das sind 51 Sekunden) korrespondiert - dann könnte (reine Vermutung bzw. Schlußfolgerung) beim Start der VPN-Verbindung aus irgendeinem seltenen Grund (denn der Fehler tritt ja auch nicht bei allen 7590-Besitzern auf) eine Semaphore nicht wieder korrekt zurückgesetzt werden (was schon mal passieren kann, wenn eine Ausnahmebedingung vor der Freigabe der Semaphore eintritt und nicht richtig abgefangen wird), was in der Folge die weitere Verarbeitung von Paketen blockiert und somit - durch die wachsende Queue - zum erwähnten Buffer-Problem führt.

Denn ein "Abhandenkommen" des empfangenden Prozesses sollte ja ganz simpel zum Verwerfen des eingehenden Paketes führen (nachdem es "dequeued" wurde und damit der Hardware-Buffer wieder frei ist) ... wenn dabei jedesmal die Hardware-Buffer für den Empfang von Paketen zulaufen würden, wären wohl viel mehr solcher "oops"-Probleme am Start.

Jedenfalls würde ich auch deshalb am ehesten auf einen Deadlock tippen, weil 51 Sekunden schon eine erhebliche Zeit sind und wenn man sich die ganzen Vorkehrungen mittels Spinlocks alleine in dieser einen Source-Datei ansieht, ist es nicht so ganz unwahrscheinlich, daß da irgendeine Race-Condition auftritt ... erst recht, wenn da mehr als ein Core involviert ist (und auch das ist ja eine Neuerung, daß es nicht mehr zwei, sondern vier Cores für das OS gibt).

AVM verwendet offenbar auch noch eine CBM-Erweiterung namens "LS" (Load Spreader), die wohl zum Verteilen der Verarbeitung eingehender Netzwerkpakete dient. In Verbindung mit der AVM-eigenen "low cost"-Verarbeitung von Interrupts (AVM's yield()-Kontext), für die ja auch noch gesonderte Vorkehrungen getroffen werden müssen, indem z.B. ein guter Teil der LKM nur noch in "non-pageable memory" geschrieben wird, weil in der eingeschränkten Umgebung so einer "low cost"-Interrupt-Behandlung keine weiteren Memory-Exceptions mehr auftreten dürfen, wie die bei ausgelagerten Pages vorkommen würden (für diese Speicherzuweisungen an die AVM-LKM wird - nur nebenbei - die Modul-Tabelle im AVM-Kernel gebraucht, für die AVM keine Quellen mitliefert), würde mich da ein Problem auch nicht wirklich überraschen ... erst recht dann, wenn es nur unter außergewöhnlichen Umständen auftritt.

Und daß es nicht das erste Mal ist, daß AVM an dieser Stelle suchen muß, sieht man wieder am oben gezeigten Code ... denn die Vorkehrungen zur Protokollierung sind ja auch nicht aus dem Nichts entsprungen und nur vorhanden, um den Code ausreichend aufzublähen - da gab es garantiert schon andere Probleme, die mit diesen Erweiterungen gefunden werden sollten. Auch die Feststellung, daß dieses "Verfolgen", wo die Buffer nun wohl geblieben sind, erst mit der letzten Version der Sourcen Einzug gehalten hat in die "cbm.c", spricht für ein "Überbleibsel" eines vorher häufiger auftretenden Fehlers, der mit diesen zusätzlichen Informationen bekämpft wurde, wenn er unter anderen Umständen auftrat.

 

[dau_user]

Kann es auch die Ursache für den schlechten Datendurchsatz sein?

 

[PeterPawn]

Glaube ich eher nicht ... wenn ich nicht etwas fundamental falsch verstehe, ist das mit dem CBM so eine Art Sende- und Empfangs-Queue, wo die Buffer für die zu sendenden bzw. zu empfangenen Daten von der Hardware zugeordnet (beim Empfangen) bzw. freigegeben (nach dem Senden) werden und die CPU per IRQ über eingegangene Pakete informiert wird - praktisch das, was jeder Netzwerk-Treiber auch machen muß, nur daß hier noch eine Hardware-Queue dazwischengeschaltet ist, die Spitzen abpuffern kann und damit geringere Anforderungen an die "Echtzeitfähigkeit" des Systems beim Empfangen von Netzwerk-Paketen stellt. Beim Senden wird wohl eher nur die "Nachbereitung" entfallen ... so nach dem Motto "Aus den Augen, aus dem Sinn" - ist das Paket erst mal "enqueued", braucht man sich um seine Zukunft keine Sorgen mehr zu machen (abgesehen von höheren Schichten, wo dann vielleicht ein TCP-ACK erwartet wird o.ä.).

Meines Erachtens betrifft das ohnehin nur noch Pakete, die von der Hardware-Beschleunigung nicht direkt verteilt werden oder tatsächlich für die CPU bestimmt sind ... die landen dann halt in diesen Puffern und müssen entsprechend ausgekettet (dequeued) und verarbeitet werden.

Wie weit das jetzt auch für "unsolicited traffic" gilt (und damit "Angriffe" auf den Router an dieser Stelle zu zusätzlicher Last führen, weil erst die AVM-Firewall dann solche Pakete droppt) oder ob der auch schon von der Hardware-Beschleunigung abgewiesen wird (zumindest ein "drop" sollte eigentlich machbar sein, bei "reject" ist es ggf. etwas komplizierter), wäre eine gute Frage.

Wobei natürlich auch eine entsprechend lange Queue mit solchem Traffic, der erst mal vom DSLAM zum CPE weitergereicht wird, bevor er da verworfen werden kann, zu Durchsatzproblemen führen könnte. Wenn sich der wirklich gewünschte Traffic "hinten anstellen" muß, weil die Leitung dicht ist, wäre das zumindest auch eine Erklärung ... wo und wie genau AVM jetzt die "utilization" im Downstream mißt und visualisiert, weiß ich auch nicht.

Aber da ja auch die "beschleunigten Pakete" in diesen Wert eingehen, muß irgendwo die Hardware-Beschleunigung auch entsprechende Zähler führen ... keine Ahnung, ob da auch der "abgewiesene" Traffic beinhaltet ist. Wobei ... wenn der in jedem Falle zur CPU geht und gar nicht die Hardware die Pakete direkt verwirft, kann der AVM-WAN-Stack ja dann zählen.

Bei kleineren Leitungen kann ich mir also (wenn da wirklich eine asymmetrische Verbindung über DSL besteht) ein solches "Zufahren" des Downstreams durch einen Angreifer vorstellen (16 MBit/s zu generieren und auf ein Ziel zu jagen, ist nun wirklich keine Kunst mehr - da reicht im Extremfall ein einziger 100/40-Anschluß mit Vectoring schon aus und es braucht gar kein "Botnet") ... bei einer symmetrischen GbE-Leitung eher nicht, weil das garantiert schon vorher im Netz des Providers irgendwo Stau geben würde.

 

[Peters]

Wer hat schon mal in der vpn.cfg den Parameter "phase2ss = "esp-null-sha/ah-no/comp-no/no-pfs";" gesetzt und danach die max. Transferraten gemessen?

 

[Shirocco88]

vpn.cfg den Parameter "phase2ss = "esp-null-sha/ah-no/comp-no/no-pfs";" gesetzt

da wird aber VPN auf "unverschlüsselte Übertragung" (d.h. VN statt VPN) umgestellt; dies würde ich nur für "unproduktive Umgebungen" d.h. als Ersatz für Layer3-Tunnnel/Transitnetzwerke testen, nicht jedoch nicht Verbindungen, die für sensible Datenübertragungen vorgesehen sind.

 

[Peters]

@ Shirocco88: Das ist klar.

Wenn es wirklich performanter sein sollte, würde ich einfach mehrere unterschiedl. VPN Verbindungen einrichten.

Ich frage mich echt, wieso hier einige 30 Mbit/s beim VPN zw. zwei Fritzbox Standorten übers Internet an max Transferrate bekommen und ich hier mit 5-6 Mbit/s rumdümpel.

 

[dau_user]

Ich habe auch nicht mehr als 5-6 MBit/s.
Ich habe einen Support Case bei AVM aufgemacht, aber keine Lust mehr für die zu Debuggen. Ich kann leider meine Box nicht ständig rebooten da da eine Menge dranhängt. Ich glaube langsam die haben gar keine Test Abteilung.

 

[Peters]

Ich habe AVM auch angeschrieben und es wird an das Produktmanagement weitergeleitet.

"Es kann durchaus möglich sein, dass man in einer VPN-CFG-Datei die Verschlüsselung modifizieren kann, dies ist aber nichts, was zu unserem garantierten Leistungsumfang gehört."

Wäre halt echt schwach, wenn mehr ginge aber AVM nur ein Minimum von 5 Mbit tatsächlich freigibt.

 

[PeterPawn]

Ich habe mir jetzt zum ersten Mal die Zeit genommen, die Änderungen beim VPN in der Version 07.00 zu untersuchen.

Erst einmal hat AVM die Protokollierung erweitert (man könnte das auch noch mit "massiv" ausschmücken, zumindest bei dem, was ich auf den ersten Blick gesehen habe) und zeigt jetzt auch die verwendeten Proposal für eine SA an:

2018-08-24 20:36:21 avmike:< add(appl=dsld,cname=10.16.32.65,localip=10.16.32.1, remoteip=10.16.32.65, p1ss=all/all/all, p2ss=esp-all-all/ah-none/comp-all/pfs p1mode=4 keepalive_ip=192.168.130.1 flags=0x8001 tunnel no_xauth no_cfgmode n)
2018-08-24 20:36:21 avmike:new neighbour 10.16.32.65:  nat_t
2018-08-24 20:36:21 avmike:10.16.32.65 keepalive enabled
2018-08-24 20:36:21 avmike:10.16.32.65 start_vpn_keepalive 192.168.130.1
2018-08-24 20:36:26 avmike:< create_sa(appl=dsld,cname=10.16.32.65)
2018-08-24 20:36:26 avmike:10.16.32.65: Phase 1 starting
2018-08-24 20:36:26 avmike:>>> aggressive mode [10.16.32.65] 10.16.32.65: V1.0 696 IC 7662f4f5d98a84b1 RC 00000000 0000 SA flags=
2018-08-24 20:36:26 avmike:<<<  aggressive mode[10.16.32.65] 10.16.32.65: V1.0 432 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 0000 SA flags=
2018-08-24 20:36:26 avmike:aggressive mode 10.16.32.65: selected lifetime: 3600 sec(no notify)
2018-08-24 20:36:26 avmike:10.16.32.65: add phase 1 SA: DH2/AES-256/SHA1/3600sec id:1
2018-08-24 20:36:26 avmike:10.16.32.65 receive VENDOR ID Payload: XAUTH
2018-08-24 20:36:26 avmike:10.16.32.65 receive VENDOR ID Payload: DPD
2018-08-24 20:36:26 avmike:10.16.32.65 receive VENDOR ID Payload: NAT-T RFC 3947
2018-08-24 20:36:26 avmike:10.16.32.65: sending embedded inital contact message (0,10.16.32.65,10.16.32.65)
2018-08-24 20:36:26 avmike:>>> aggressive mode [10.16.32.65] 10.16.32.65: V1.0 140 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 0000 HASH flags=e
2018-08-24 20:36:26 avmike:10.16.32.65: Phase 1 ready
2018-08-24 20:36:26 avmike:10.16.32.65: start waiting connections
2018-08-24 20:36:26 avmike:10.16.32.65: Phase 2 starting (start waiting)
2018-08-24 20:36:26 avmike:>>> quickmode [10.16.32.65] 10.16.32.65: V1.0 2300 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 89b80f6a HASH flags=e
2018-08-24 20:36:27 avmike:<<<  quickmode[10.16.32.65] 10.16.32.65: V1.0 2108 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 22944b69 HASH flags=e
2018-08-24 20:36:27 avmike:WARNING !!! local id differs from received id
2018-08-24 20:36:27 avmike:>>> quickmode [10.16.32.65] 10.16.32.65: V1.0 332 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 22944b69 HASH flags=e
2018-08-24 20:36:27 avmike:<<<  quickmode[10.16.32.65] 10.16.32.65: V1.0 332 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 89b80f6a HASH flags=e
2018-08-24 20:36:27 avmike:>>> quickmode [10.16.32.65] 10.16.32.65: V1.0 60 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 89b80f6a HASH flags=e
2018-08-24 20:36:27 avmike:10.16.32.65: Phase 2 ready
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 834D9B51 LT: 3600 I/O: IN
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 79DB3B4E LT: 3600 I/O: OUT
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: IPComp-LZJH SPI: 379F LT: 3600 I/O: IN
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: IPComp-LZJH SPI: 2401 LT: 3600 I/O: OUT
2018-08-24 20:36:27 avmike:< cb_sa_created(name=10.16.32.65,id=1,...,flags=0x00002101)
2018-08-24 20:36:27 avmike:10.16.32.65 stop_vpn_keepalive to 192.168.130.1
2018-08-24 20:36:27 avmike:10.16.32.65 start_keepalive_timer 3540 sec
2018-08-24 20:36:27 avmike:10.16.32.65: start waiting connections
2018-08-24 20:36:27 avmike:10.16.32.65: NO waiting connections
2018-08-24 20:36:27 avmike:<<<  quickmode[10.16.32.65] 10.16.32.65: V1.0 60 IC 7662f4f5d98a84b1 RC 6465373552fba9a6 22944b69 HASH flags=e
2018-08-24 20:36:27 avmike:10.16.32.65: Phase 2 ready
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 650202D3 LT: 3600 I/O: IN
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: ESP-AES-256/SHA1 SPI: 23FB19FA LT: 3600 I/O: OUT
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: IPComp-LZJH SPI: B038 LT: 3600 I/O: IN
2018-08-24 20:36:27 avmike:NEW Phase 2 SA: IPComp-LZJH SPI: A1A4 LT: 3600 I/O: OUT
2018-08-24 20:36:27 avmike:< cb_sa_created(name=10.16.32.65,id=2,...,flags=0x00002001)
2018-08-24 20:36:27 avmike:10.16.32.65 stop_vpn_keepalive to 192.168.130.1
2018-08-24 20:36:27 avmike:10.16.32.65 restart keepalive_timer timer_id 2001907792
2018-08-24 20:36:27 avmike:10.16.32.65: start waiting connections
2018-08-24 20:36:27 avmike:10.16.32.65: NO waiting connections

Hier habe ich eine 7580 und eine 7490 - beide im Router-Mode, ansonsten geht auch kein VPN - über einen VLAN-Switch (HP ProCurve) verbunden (statische IP-Konfiguration für die WAN-Seiten) und in beiden Boxen die US/DS-Kapazität auf 1 GBit/s eingestellt.

Anschließend in beiden Boxen passende VPN-Konfigurationen eingestellt und auf der 7580 auf einem USB3-Stick eine 1 GByte-Datei mit zufälligem Inhalt (damit die Kompressionsgewinne nicht zu hoch werden, einfach ein "dd" von "/dev/urandom" in eine Datei auf dem Stick) erzeugt.

Die erste Messung erfolgte bei der Übertragung von der 7580 (in der oben angezeigten Verbindung mit AES-256/SHA1 und Kompression - kostet ja alles Zeit), wobei das Ziel der übertragenen Datei dann nicht auf der 7490 lag (um die Messung nicht durch Schreibzugriffe auf irgendwelchen Speicher zu verfälschen), sondern auf einem dahinterliegenden FTP-Server (ebenfalls per GbE angebunden, vsFTPd auf einem Linux-System) - weniger Overhead als beim FTP-Protokoll geht bei gesicherter Übertragung (also TCP) fast nicht mehr.

Die Übertragung dieser 1 GByte großen Datei sah dann so aus:

# time ftpput 192.168.130.2 upload/test_data.bin &
real  9m 14.88s
user    0m 0.00s
sys     0m 51.02s

Das macht dann also 1.073.741.824 Byte (8.589.934.592 Bit) in (9 * 60 + 15) = 555 Sekunden oder auch 15.477.360 Bit/s (14,8 MBit/s) - aber immerhin mit der höchsten Verschlüsselung, die AVM für P2 unterstützt.

Der nächste Test nutzt dieselbe Richtung der Datenübertragung, allerdings wird jetzt tatsächlich auf die Verschlüsselung verzichtet:

1970-01-01 01:03:49 avmike:10.16.32.65: Phase 2 starting (start waiting)
1970-01-01 01:03:49 avmike:>>> quickmode [10.16.32.65] 10.16.32.65: V1.0 156 IC b316a7c3e5af776e RC f40eb70a2c690d0 ad28f645 HASH flags=e
1970-01-01 01:03:49 avmike:<<<  quickmode[10.16.32.65] 10.16.32.65: V1.0 156 IC b316a7c3e5af776e RC f40eb70a2c690d0 ad28f645 HASH flags=e
1970-01-01 01:03:49 avmike:>>> quickmode [10.16.32.65] 10.16.32.65: V1.0 60 IC b316a7c3e5af776e RC f40eb70a2c690d0 ad28f645 HASH flags=e
1970-01-01 01:03:49 avmike:10.16.32.65: Phase 2 ready
1970-01-01 01:03:49 avmike:NEW Phase 2 SA: ESP-NULL/SHA1 SPI: 3AFEFEB7 LT: 3600 I/O: IN
1970-01-01 01:03:49 avmike:NEW Phase 2 SA: ESP-NULL/SHA1 SPI: 771D59BD LT: 3600 I/O: OUT
1970-01-01 01:03:49 avmike:< cb_sa_created(name=10.16.32.65,id=1,...,flags=0x00002101)
1970-01-01 01:03:49 avmike:10.16.32.65 stop_vpn_keepalive to 192.168.130.1
1970-01-01 01:03:49 avmike:10.16.32.65 start_keepalive_timer 3540 sec
1970-01-01 01:03:49 avmike:10.16.32.65: start waiting connections
1970-01-01 01:03:49 avmike:10.16.32.65: NO waiting connections
1970-01-01 01:31:16 avmike:<<<  infomode[10.16.32.65] 10.16.32.65: V1.0 92 IC b316a7c3e5af776e RC f40eb70a2c690d0 b89f9ee8 HASH flags=e
1970-01-01 01:31:16 avmike:>r> infomode [10.16.32.65] 10.16.32.65: V1.0 92 IC b316a7c3e5af776e RC f40eb70a2c690d0 b89f9ee8 HASH flags=e

(die 7580 hatte einen Neustart und findet jetzt keinen NTP-Server wg. der WAN-Konfiguration - daher die komische Datumsangabe)

und die Datei erneut übertragen - dabei kommt das Folgende heraus:

# time ftpput 192.168.130.2 upload/test_data.bin &
real  5m 20.40s
user    0m 0.01s
sys     0m 24.21s

... macht 320 Sekunden oder auch 26.843.546 Bit/s (25,6 MBit/s).

Das ist schon mal deutlich flotter ... wobei natürlich die 7490 immer noch etwas in die max. Transferrate eingreift, weil sie ja die passenden Bestätigungen senden muß und dazu muß sie zumindest mal die SHA1-HMAC testen, was auch Zeit braucht. Zwischen zwei GRX-Boxen könnte das also auch noch etwas schneller vonstatten gehen - aber ob hier die 40 MBit/s tatsächlich auch mit VPN erreicht werden können, würde ich fast bezweifeln wollen.

Spaßig ist es dabei dann, daß die Anzeige im GUI der FRITZ!Box 7580 wohl eher die Brutto-Datenrate anzeigt ... also inkl. IPSec-Overhead - und das waren hier auch ~30 MBit/s. Aber ansonsten begrenzt die 7580 wohl schon selbst den möglichen Durchsatz.

Woran liegt das nun wohl? Es müssen hier ja alle Pakete für das VPN zunächst mal tatsächlich durch die CPU geschleust werden ... schon das ist ja ein gewaltiger Unterschied zu den Daten, die auf direktem Weg (nur mit ein paar Änderungen am Inhalt eines Paketes durch die Hardware-Beschleunigung) vom LAN an das WAN (entweder in Form eines Ethernet-Ports oder das DSL-Modem) expediert werden.

Stellt sich die Frage, welchen Durchsatz denn die beiden Boxen bringen können, wenn hier kein VPN zum Einsatz kommt ... das erspart dann ja auch den Umweg über die CPU. Dazu wird in der 7580 einfach direkt (aber natürlich über das WAN-Interface) auf den Ziel-Host per FTP geschrieben:

# time ftpput 192.168.131.2 upload/test_data.bin
real    1m 27.26s
user    0m 0.00s
sys     1m 11.39s

Hier haben wir also den Durchsatz im Routing, wobei die Beschränkung hier ggf. tatsächlich aus der Fähigkeit des FTP-Servers, die Daten schnell genug wegzuschreiben, resultieren könnte. In Zahlen sind das dann jedenfalls nur 87 Sekunden oder auch 98.734.880 Bit/s (94,2 MBit/s) - und um der Frage zuvorzukommen: Ja, nach der Anzeige des HP ProCurve ist der WAN-Port tatsächlich im GbE-Mode (1000FDX).

Wobei es am Ende wohl doch eher die 7580 ist, die hier auch den Routing-Durchsatz begrenzt ... denn wenn ich dieselbe Datei von einem anderen Host auf den FTP-Server übertrage, dauert das noch deutlich weniger lang:

$ time busybox ftpput 192.168.xxx.xxx upload/test_data.bin

real    0m38.424s
user    0m0.004s
sys     0m27.532s

Das sind dann 223.115.184 Bit/s (212 MBit/s oder auch 26,6 MByte/s) und eben doch wieder deutlich mehr, als bei der 7580 - ich habe extra noch einmal alle Switches zwischen 7580 und FTP-Server gecheckt, daß da tatsächlich alles GbE ist und wenn ich an demselben Switch-Port ein anderes Gerät anschließe, kommt das auch auf > 100 MBit/s.

Wer wirklich selbst testen will, was die DEU von Intel/Lantiq beim VPN an Zugewinn beim Durchsatz bringen kann, braucht jedenfalls einen eigenen Kernel ... und auch damit könnte man wohl noch nicht sicher sein, daß beim AVM-VPN das Ver- und Entschlüsseln tatsächlich davon profitiert.

Wenn man sich die Lastverteilung bei so einer VPN-Verbindung ansieht, fällt ja auf, daß der größte Teil der Zeit in der Behandlung von Software-Interrupts verbracht wird und das Ver- und Entschlüsseln offenbar dort läuft ... damit helfen vielleicht sogar die AVM-Arbeiten an dem "yield context" wieder etwas und sorgen für mehr Performance. Gleichzeitig könnte das aber auch dafür sorgen, daß aus diesem Code heraus die Kernel-Implementierung von Crypto-Funktionen gar nicht genutzt wird oder genutzt werden kann (es findet ja kein "vollständiger" Kontextwechsel statt bei dieser Art der Interrupt-Behandlung - was u.a. darin gipfelt, daß AVM jede weitere Exception innerhalb dieses Codes nach Kräften vermeiden muß) und das würde zumindest mal erklären, wieso AVM den Kernel gleich ohne Nutzung der DEU baut.

PS: Eine kleinere Differenz ergibt sich ggf. auch daraus, daß ich bei der Umrechnung in "M" oder "G" immer mit 2 ** 10 rechne und nicht mit 10 ** 3.