I've been trying to pin down the cause of some of my web servers being occasionally slow to respond. This problem seems to occur infrequently at first but then starts to happen more often for several days before going away again. They are Windows servers running an Apache 2.4.27 reverse proxy with a Tomcat (7 or 8) based web server behind them (various Atlassian products, one on each server). Using Wireshark I've managed to track down that there's a delay in the Server Hello being sent back from the server to the client, but I don't know what is causing this delay. I've setup a script to use cURL to request a page every minute to help with the diagnosis.
237 2017/297 07:57:30.571296 10.0.0.6 123.223.100.1 TLSv1.2 571 Client Hello
244 2017/297 07:57:30.796302 10.0.0.6 123.223.100.1 TCP 571 [TCP Retransmission] 56426 → 443 [PSH, ACK] Seq=1 Ack=1 Win=66560 Len=517
245 2017/297 07:57:30.814021 123.223.100.1 10.0.0.6 TCP 66 443 → 56426 [ACK] Seq=1 Ack=518 Win=132096 Len=0 SLE=1 SRE=518
389 2017/297 07:57:41.044311 123.223.100.1 10.0.0.6 TLSv1.2 1506 Server Hello
…
398 2017/297 07:57:41.086327 10.0.0.6 123.223.100.1 TLSv1.2 173 Application Data
Server Trace
64 2017-10-24 07:57:30.574615 212.159.78.240 123.223.100.1 TLSv1.2 571 Client Hello
72 2017-10-24 07:57:30.799403 212.159.78.240 123.223.100.1 TCP 571 [TCP Retransmission] 56426 → 443 [PSH, ACK] Seq=1 Ack=1 Win=66560 Len=517
73 2017-10-24 07:57:30.799441 123.223.100.1 212.159.78.240 TCP 66 443 → 56426 [ACK] Seq=1 Ack=518 Win=132096 Len=0 SLE=1 SRE=518
274 2017-10-24 07:57:41.028342 123.223.100.1 212.159.78.240 TLSv1.2 2958 Server Hello
…
295 2017-10-24 07:57:41.089469 212.159.78.240 123.223.100.1 TLSv1.2 173 Application Data
How can I track down what is causing the delay in the Server Hello message? Is this caused by Apache not responding for this delay or is it something else?
Using strace along with cURL on an Ubuntu client I can see the following extra lines that correspond with the delay, but I've no idea what they mean. Can anyone help with these as well?
19807 18:23:43.514170 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
19807 18:23:43.514371 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:43.514449 poll([{fd=3, events=POLLIN}], 1, 0) = 0 (Timeout)
19807 18:23:43.514502 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, 8) = 0
19807 18:23:43.514550 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:43.514596 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
19807 18:23:43.514642 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:43.514688 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
19807 18:23:44.515978 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, 8) = 0
19807 18:23:44.516264 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:44.516522 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
19807 18:23:44.516825 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:44.516946 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
19807 18:23:45.518250 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, 8) = 0
19807 18:23:45.518524 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:45.518780 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
19807 18:23:45.519008 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:45.519112 poll([{fd=3, events=POLLIN}], 1, 1000) = 0 (Timeout)
19807 18:23:46.520385 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, 8) = 0