[Postfixbuch-users] Verzögerung von 33 Sekunden

[Andreas Meyer]

Peer Heinlein <p.heinlein at heinlein-support.de> wrote:

> Am 13.10.2013 19:31, schrieb Andreas Meyer:
> 
> >> a) In das Logfile schauen von dem, wo die Verzögerung auftritt. Also
> >> Amavis. Loglevel auf 3 setzen, dann stehen da alle Timings sauber drin.
> > 
> > Vom calling SA parse bis zur Übergabe an localhost:10025 vergehen diese 33 Sekunden.
> > Das ist aber nicht üblich, dass der SA-check solange braucht?
> 
> In deinen Logmeldungen waren keine Timings drin.
> 
> Nochmal: Loglevel auf 3 setzen und dann die beiden TIMING-Zeilen anschauen.

Oct 13 19:17:52 mail.bitcorner.eu /usr/sbin/amavisd[20779]: (20779-10) TIMING-SA total 32105 ms - parse: 0.75 (0.0%), extract_message_metadata: 27050 (84.3%), poll_dns_idle: 27034 (84.2%), get_uri_detail_list: 0.24 (0.0%), tests_pri_-1000: 2 (0.0%), tests_pri_-950: 1.46 (0.0%), tests_pri_-900: 1.12 (0.0%), tests_pri_-400: 8 (0.0%), check_bayes: 7 (0.0%), tests_pri_0: 5031 (15.7%), check_spf: 0.27 (0.0%), check_razor2: 5004 (15.6%), check_pyzor: 0.16 (0.0%), tests_pri_500: 3 (0.0%), get_report: 0.86 (0.0%)
Oct 13 19:17:53 mail.bitcorner.eu /usr/sbin/amavisd[20779]: (20779-10) size: 484, TIMING [total 32207 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 0 (0%)0, check_init: 0 (0%)0, digest_hdr: 1 (0%)0, digest_body_dkim: 0 (0%)0, mime_decode: 4 (0%)0, get-file-type1: 11 (0%)0, decompose_part: 0 (0%)0, parts_decode: 0 (0%)0, check_header: 0 (0%)0, AV-scan-1: 6 (0%)0, spam-wb-list: 1 (0%)0, SA msg read: 0 (0%)0, SA parse: 1 (0%)0, SA check: 32100 (100%)100, decide_mail_destiny: 6 (0%)100, notif-quar: 1 (0%)100, fwd-connect: 18 (0%)100, fwd-mail-pip: 10 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 0 (0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 30 (0%)100, prepare-dsn: 0 (0%)100, main_log_entry: 6 (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100
Oct 13 19:18:25 mail.bitcorner.eu /usr/sbin/amavisd[20778]: (20778-12) TIMING-SA total 32108 ms - parse: 0.76 (0.0%), extract_message_metadata: 27050 (84.2%), poll_dns_idle: 27035 (84.2%), get_uri_detail_list: 0.31 (0.0%), tests_pri_-1000: 2 (0.0%), tests_pri_-950: 1.46 (0.0%), tests_pri_-900: 1.08 (0.0%), tests_pri_-400: 9 (0.0%), check_bayes: 8 (0.0%), tests_pri_0: 5033 (15.7%), check_spf: 0.28 (0.0%), check_razor2: 5004 (15.6%), check_pyzor: 0.19 (0.0%), tests_pri_500: 3 (0.0%), get_report: 0.91 (0.0%)

Oct 13 19:18:25 mail.bitcorner.eu /usr/sbin/amavisd[20778]: (20778-12) size: 517, TIMING [total 32182 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 0 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 0 (0%)0, check_init: 0 (0%)0, digest_hdr: 1 (0%)0, digest_body_dkim: 0 (0%)0, mime_decode: 4 (0%)0, get-file-type1: 13 (0%)0, decompose_part: 0 (0%)0, parts_decode: 0 (0%)0, check_header: 0 (0%)0, AV-scan-1: 7 (0%)0, spam-wb-list: 1 (0%)0, SA msg read: 0 (0%)0, SA parse: 1 (0%)0, SA check: 32103 (100%)100, decide_mail_destiny: 6 (0%)100, notif-quar: 0 (0%)100, fwd-connect: 4 (0%)100, fwd-mail-pip: 2 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 0 (0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 23 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 5 (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-2-files: 0 (0%)100, rundown: 0 (0%)100

> 
> > Vom calling SA parse bis zur Übergabe an localhost:10025 vergehen
> > diese 33 Sekunden.
> > Das ist aber nicht üblich, dass der SA-check solange braucht?
> 
> Eine konkrete häufige Ursache habe ich ja bereits genannt:
> 
> > b) DNS-Timeouts? Prüfe alle DNS-Resolver aus /etc/resolv.conf und
> > prüfe  auch, ob die resolv.conf in einer etwaigen chroot-Umgebung
> > noch aktuell ist.
> 
> Was war das Ergebnis Deiner Analyse?

Nunja, die resolv.conf sieht gut aus:
(Nicht dass Du jetzt denkst ich wär ein Weibsbild, wo's drauf ankommt,
dass es chique ist)

nameserver 213.133.99.99
nameserver 213.133.100.100
nameserver 213.133.98.98
nameserver 2a01:4f8:0:a102::add:9999
nameserver 2a01:4f8:0:a0a1::add:1010
nameserver 2a01:4f8:0:a111::add:9898

Es läuft kein nameserver auf dem Server und momentan auch kein chroot.
Aber ich sehe gerade, es gibt noch eine resolv.conf.netconfig

search hetzner.de
nameserver 213.133.100.100

Ich kommentiere das mal. Keine Ahnung, ob die berücksichtigt wird.

  Andreas