Ao investigar um problema que aflige um cluster de proxies que são todos afetados simultaneamente, descobri um comportamento estranho no estabelecimento de conexões SSL.
O sintoma é que as solicitações HTTPS de saída são mais lentas do que o normal quando o impacto ocorre. Eu atribuí isso à lentidão ao concluir o handshake SSL. As solicitações/conexões HTTP não são afetadas da mesma forma.
O problema parece ser causado em conexões de saída por um atraso entre o final do handshake TCP de 3 vias e o envio do Client Hello
pelos proxies. Depois disso, o handshake é concluído normalmente, sem atrasos.
Aqui estão alguns exemplos de capturas de tráfego:
Para api.twitter.com
(atraso de 2,4 segundos):
Para graph.facebook.com
(atraso de 28,4 segundos):
Mesmo com as retransmissões do segundo exemplo, o Client Hello
pacote não deveria demorar tanto para sair.
Alguns fatos/considerações:
- O problema ocorre temporariamente em horários específicos do dia (por volta das 10h e 17h), afeta todos os hosts e desaparece em cerca de 30min. mais tarde, simultaneamente
- isso indicaria uma causa externa (rede, talvez), mas a saída do tcpdump parece colocar a culpa no servidor local
- CPU, carga, memória e todos os outros indicadores de desempenho monitorados estão normais naquele momento
- afeta todos os hosts remotos SSL
- afeta conexões aleatoriamente, algumas se comportam normalmente, mas muitas são extremamente lentas
- a taxa de transferência (após o aperto de mão) não parece ser afetada
- depois que o problema passa, as conexões SSL com os mesmos hosts remotos são consistentemente rápidas
- testes foram feitos com
curl
eopenssl s_client connect
, com os mesmos resultados
O que precisa de esclarecimento:
- O que poderia estar causando tal atraso no lado local?
- Poderia o wireshark estar me enganando?
- que outros indicadores/estatísticas/comandos de desempenho eu poderia examinar para solucionar melhor as causas do atraso?
- existe algum fator de rede (MTU, buffers de recebimento, fragmentação) que possa justificar esse comportamento?
- como posso encontrar evidências para esclarecer se é um problema de rede externo aos meus servidores?
Versões de software :
- Red Hat Enterprise Linux Server versão 5.11 (Tikanga)
- OpenSSL 0.9.8e-fips-rhel5 01 de julho de 2008
- kernel 2.6.18-416.el5 #1 SMP qua 26 de outubro 12:04:18 EDT 2016 x86_64 x86_64 x86_64 GNU/Linux
Editar: informações do strace
Fiz alguns straces conforme recomendado por uma resposta abaixo, peguei essas chamadas lentas:
strace -T -o output.strace openssl s_client -connect 104.244.42.66:443 </dev/null
connect(3, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("104.244.42.66")}, 16) = 0 <2.266597>
poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}]) <2.387366>
write(3, "\26\3\1\0S\1\0\0O\3\1X\342\24\3556c\354\270T\302\225[\236\317\327\305\205r\177\t/"..., 88) = 88 <0.000034>
read(3, "\26\3\1\0001\2\0", 7) = 7 <2.556229>
read(3, "\0-\3\1\332\37\254+\240\320\236qA\375\275L\23l\340\355\205x\264\274\273\213\377\323&\345\307O"..., 47) = 47 <0.000011>
read(3, "\26\3\1\v\273", 5) = 5 <0.000007>
(...)
read(3, "\24\3\1\0\1", 5) = 5 <2.223115>
A poll()
chamada é uma pesquisa DNS reversa, está fazendo:
sendto(4, "\3623\1\0\0\1\0\0\0\0\0\0\00266\00242\003244\003104\7in-ad"..., 44, MSG_NOSIGNAL, NULL, 0) = 44 <0.000157>
Outras poll()
chamadas no mesmo rastreamento são rápidas.
Você pode tentar executar seus comandos curl com strace para ver em qual chamada do sistema eles "travam". Descobri que essas coisas às vezes estão relacionadas a pesquisas de DNS (ou pesquisas reversas de DNS)