Apache 2.4.54-1: Erster HTTPS-Request 10mal langsamer als die nächsten

GwenDragon

GwenDragon

Registered User
Aus mir nicht nachvollziehbarne Gründen zeigen seit Update auf Apache 2.4.54-1 seit ein paar Tagen folgendes:
Erster SSL-Request dauert 100 ms, die darauf folgenden 10 ms.

Die Requests werden per cURL lokal auf dem Server abgesetzt und dienen zur Messung der Response der auf dem Server gehosteten Domains.
Code: 
/usr/bin/curl -L -s --user-agent "Test/0.42"  \
   -H 'Expires: 0' -H 'Cache-Control: no-cache, no-store, must-revalidate' -H 'Pragma: no-cache'  \
   --connect-timeout 10 -o /dev/null  \
   --write-out "#TIMING# L:%{time_namelookup} C:%{time_connect} T:%{time_starttransfer} F:%{time_total} #\n" https://server1.domain.tld

Im Apache-Changelog finde ich nichts, was auf diese Installationen zuträfe, die dort für SSL gefunden Einträge (CVEs oder Fixes( sind nicht relevant da dir drt gelisteten Module nicht genutz werden.

Was kann die Urscache sein?
 
Last edited:
Erster Request langsamer deutet irgendwie Richtung DNS. Kannst du evtl. mal strace an den Apache Prozess hängen? Drauf achten dass follow childs mit aktiviert ist…
 
Code: 
 strace -f -c /usr/sbin/apache2
[Mon Jul 11 17:10:37.192262 2022] [core:warn] [pid 44066] AH00111: Config variable ${APACHE_RUN_DIR} is not defined
apache2: Syntax error on line 80 of /etc/apache2/apache2.conf: DefaultRuntimeDir must be a valid directory, absolute or relative to ServerRoot
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 85.79    0.013351           3      4221           getrandom
  6.58    0.001024          13        74           mmap
  2.81    0.000437          13        32           munmap
  0.87    0.000136           9        14           mprotect
  0.65    0.000101           7        13           openat
  0.54    0.000084           5        16           close
  0.42    0.000066           4        14           read
  0.36    0.000056           3        15           fstat
  0.31    0.000049          49         1           bind
  0.26    0.000040          10         4         1 connect
  0.21    0.000032          10         3           socket
  0.18    0.000028           9         3           brk
  0.17    0.000027          13         2           write
  0.15    0.000023           7         3           recvmsg
  0.13    0.000020          20         1           sendto
  0.09    0.000014           4         3           getsockname
  0.08    0.000013          13         1           select
  0.07    0.000011           5         2           rt_sigaction
  0.05    0.000008           8         1         1 stat
  0.04    0.000006           6         1           rt_sigprocmask
  0.04    0.000006           6         1           prlimit64
  0.03    0.000005           5         1           fcntl
  0.03    0.000005           5         1           arch_prctl
  0.03    0.000005           5         1           set_tid_address
  0.03    0.000005           5         1           set_robust_list
  0.03    0.000004           4         1           lseek
  0.03    0.000004           4         1           getpid
  0.02    0.000003           3         1           futex
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.015563           3      4434         3 total
 
Fehlt deinem System Entropie?

cat /proc/sys/kernel/random/entropy_avail
Click to expand...
Ist 256, dauerhaft.

Die Änderung des Kernels wegen random fand aber schon Mitte Juni statt und hatte keinerlei Einfluss auf erste und weitere Connects. Aber das war ein Apache 2.4.53-1.
 
Last edited:
Jetzt wollte ich auf einem Ubuntu 22-Server-Image installieren und testen, aber die haben noch nicht mal Apache 2.4.53 und 2.4.54

Mal morgen sehen ob Arch und FreeBSD sich genauso fehlerhaft bei den Requests verhalten.
 
FreeBSD 13.1, Apache 2.4.54:
Code: 
[root@devgate:~] # echo '---' && date && echo '---' && curl -L -s --user-agent "Test/0.42" -H 'Expires: 0' -H 'Cache-Control: no-cache, no-store, must-revalidate' -H 'Pragma: no-cache' --connect-timeout 10 -o /dev/null --write-out "#TIMING# L:%{time_namelookup} C:%{time_connect} T:%{time_starttransfer} F:%{time_total} #\n" https://www.rootforum.org
---
Tue Jul 12 19:31:47 CEST 2022
---
#TIMING# L:0.541507 C:0.541587 T:0.557466 F:0.557550 #
[root@devgate:~] # echo '---' && date && echo '---' && curl -L -s --user-agent "Test/0.42" -H 'Expires: 0' -H 'Cache-Control: no-cache, no-store, must-revalidate' -H 'Pragma: no-cache' --connect-timeout 10 -o /dev/null --write-out "#TIMING# L:%{time_namelookup} C:%{time_connect} T:%{time_starttransfer} F:%{time_total} #\n" https://www.rootforum.org
---
Tue Jul 12 19:31:52 CEST 2022
---
#TIMING# L:0.000796 C:0.000874 T:0.016368 F:0.016455 #
[root@devgate:~] # echo '---' && date && echo '---' && curl -L -s --user-agent "Test/0.42" -H 'Expires: 0' -H 'Cache-Control: no-cache, no-store, must-revalidate' -H 'Pragma: no-cache' --connect-timeout 10 -o /dev/null --write-out "#TIMING# L:%{time_namelookup} C:%{time_connect} T:%{time_starttransfer} F:%{time_total} #\n" https://www.rootforum.org
---
Tue Jul 12 19:31:56 CEST 2022
---
#TIMING# L:0.000375 C:0.000414 T:0.013886 F:0.013970 #
[root@devgate:~] #
 
Mein Test mit Arch in einer VM hat mir heute gezeigt, hat unterschiedliche Verzögerungen, 10-15% der Request sind ca. 4-5 mal so langsame wie die meisten. Wenn die meisten Request 15 msec haben, haben die Ausreißer teilweise mehr als 50 msec. Früher (2.53) gab es die Ausreißer nicht.
Wohlgemerkt eine Plain-HTML-Seite über SSL, keine dynamische Seite.

Irgendwas hat sich intern in der 2.54 geändert.

Ich bin ratlos.
 
Ich habe mal Tests laufen lassen bei verschiedenen Domains auf dem Apache und stellte fest, dass die ersten 4-6 Requests (ca. 100-300 ms) 10× so langsam waren wie die nachfolgenden 100 mit 10ms für alle anderen.
 
Dass der erste Request etwas länger dauert, ist norml, schliesslich muss dabei die DNS-Auflösung und Zertifikatsprüfung stattfinden. Die nachfolgenden Requests brauchen Beides dann nicht mehr, solange sie im KeepAlive (HTTP/1.x) beziehungsweise in Multiplexing (HTTP/2.x) stattfinden.

Beides kann aber auch das https://en.wikipedia.org/wiki/Head-of-line_blocking verursachen, was vermutlich Deine Beobachtungen zeigen.
 
Leuchtet mir ein.
Nur muss eine erhebliche Änderung von 2.4.53 → 2.4.54 stattgefunden haben, denn früher (2.4.52, 2.4.53) gab es diese Probleme eben nicht mit HTTP/1 & HTTP/2 bei Apache.

Am Blocking/Pipelining kann ich ja sowieso nichts drehen.
 
Last edited:
Also ich kanns mit einem aus dem Source compilierten Apachen direkt nachvollziehen...
Version 2.4.54:
Code: 
#TIMING# L:0,031000 C:0,031000 T:0,547000 F:0,547000 #
#TIMING# L:0,016000 C:0,032000 T:0,078000 F:0,078000 #
#TIMING# L:0,016000 C:0,016000 T:0,063000 F:0,063000 #

Wobei es jetzt auch nicht mehr langsamer wird, selbst nachdem ich den Apachen neu gestartet habe.
Wie lange dauert es denn bis es wieder langsam ist?

Aktuell würde ich auch auf DNS und Zertifikatsprüfung tippen, also kein wirkliches Problem auf Apache Seite.
Erklärt aber halt nicht warum es da Unterschiede in den Versionen gibt...

Also aktuell ist eher mein Problem dass es schlicht nicht mehr langsam wird. Tritt bei euch das Problem bei http auch auf, oder nur bei https?
 
Ist auch bei Non-SSL ähnlich langsam. Selbst wenn ich bei cUrl die Zertifikatsprüfung ausschalte.
Wenn ich sowas länger in einer schleife laufen lasse, gibt es ab und an auch wieder extreme Ausreißer dazwischen, bei 2000 Reqs aber ca. 10-12, ist also vernachlässigbar.

DNS? Wenn hatte es solche Anfragen doch auch schon gegeben als ich in der 2.5.53 nutzte.
Bist du sicher dass der Apache nun auf Grund von DNS-Auflösung so lahmt?
Intern benutze ich ja nicht HostnameLookups in den Apache-Konfigs.
 
Also ich hab jetzt mal einen aus dem Source kompilierten Apache zur Hand (jetzt auch mit diesem SSL Zeugs) und wenn du mir sagst ob ich irgendwie dafür sorgen kann dass ich wieder ne langsame Abfrage habe würd ich das versuchen.
Aber wenn das nur groß alle 200 Requests vorkommt dann wirds halt auch verdammt kniffelig mit dem debuggen :-)
 
You must log in or register to reply here.
Back
Top