investigate(fpc): possível latência de ~40 ms no keep-alive do fphttpserver

[regyssilveira]

Contexto

O PR #554 relatou uma possível regressão de desempenho no provider padrão do FPC após a ativação de conexões persistentes no fphttpserver: aproximadamente 40–44 ms adicionais por requisição sequencial em uma mesma conexão.

A observação merece investigação, mas a causa ainda não foi demonstrada de forma conclusiva. A implementação proposta no PR removia o keep-alive, introduzia TCP_NODELAY e aceitava o fechamento silencioso de conexões HTTP/1.1, criando riscos de ECONNRESET para clientes com pool.

Objetivo

Determinar de forma reproduzível:

1. se existe regressão de latência com KeepConnections=True;
2. em quais versões do FPC e sistemas operacionais ela ocorre;
3. se o atraso está no Socket.CanRead(KeepConnectionTimeout), no padrão de escrita da resposta, em Nagle/delayed ACK ou em outra parte do fphttpserver;
4. se a correção deve ser feita no Horse ou enviada ao FPC upstream.

Reprodutor necessário

O teste deve:

• usar um cliente TCP bruto ou outro cliente cuja reutilização possa ser comprovada;
• enviar várias requisições HTTP/1.1 sequenciais pelo mesmo socket;
• registrar no servidor um identificador da conexão para confirmar que não houve reconexão;
• comparar keep-alive ligado e desligado na mesma execução;
• medir distribuição/mediana da latência, sem reprovar por um limite absoluto de milissegundos;
• executar também um cenário com requisições já disponíveis no socket;
• validar os headers Connection e o comportamento após o fechamento;
• testar um cliente com pool para detectar reutilização de socket obsoleto e ECONNRESET.

Diagnóstico recomendado

• Capturar as syscalls com strace para medir a duração real de select/poll/leitura/escrita.
• Capturar o tráfego com Wireshark ou tcpdump para verificar delayed ACK e segmentação.
• Testar TCP_NODELAY isoladamente, sem alterar simultaneamente o keep-alive.
• Comparar FPC 3.2.2, 3.3.1/trunk e a versão estável mais recente disponível.
• Repetir em loopback e em uma conexão não-loopback/container.

Critérios para uma correção no Horse

Uma eventual correção não deve:

• desabilitar keep-alive silenciosamente para todas as aplicações;
• fechar uma resposta HTTP/1.1 sem comunicar Connection: close;
• substituir callbacks existentes como OnAllowConnect;
• depender de limites absolutos de tempo em testes;
• misturar TCP_NODELAY sem evidência de que ele faz parte da causa.

Se o atraso for confirmado dentro do fphttpserver, devemos abrir um relatório mínimo no projeto FPC e acompanhar a correção upstream.

[regyssilveira]

Resultado inicial da investigação

Reproduzi o problema contra o master atual do Horse usando o FPC trunk 3.3.1, um cliente TCP bruto e 30 requisições HTTP/1.1 sequenciais comprovadamente enviadas pelo mesmo socket.

Resultado

• socket reutilizado: sim;
• mediana: ~44,0 ms;
• p95: ~44,1 ms;
• primeira requisição: abaixo de 3 ms;
• requisições seguintes: aproximadamente 44 ms.

Portanto, a regressão relatada no #554 é real no FPC 3.3.1.

Onde o tempo é gasto

O strace mostra que o Horse/FPC envia os headers e o corpo imediatamente, em duas chamadas consecutivas:

sendto(..., "HTTP/1.1 200 OK...", 79, ...) = 79
sendto(..., "pong", 4, ...) = 4

Depois disso, a próxima requisição chega aproximadamente 43–44 ms mais tarde. O select de RequestPending não dorme sempre por um intervalo fixo: ele retorna quando os dados chegam. Assim, o atraso ocorre antes da chegada da próxima requisição e é compatível com a interação entre os dois writes pequenos e delayed ACK/Nagle.

O FPC trunk define:

DefaultKeepConnectionIdleTimeout = 50;

e usa:

Socket.CanRead(KeepConnectionIdleTimeout)

Isso explica por que o intervalo observado fica próximo do tick, mas não confirma que o polling seja a causa primária.

Por que o TCP_NODELAY do PR #554 não funcionou

O teste foi repetido com a implementação de OnAllowConnect proposta no #554 e o resultado permaneceu em ~44 ms. O strace confirmou que nenhum setsockopt(TCP_NODELAY) foi executado.

No FPC trunk, TFPCustomHttpServer.SetOnAllowConnect armazena FOnAllowConnect, porém TFPCustomHttpServer.DoOnAllowConnect não chama esse callback. Ele apenas aplica o limite de conexões e define Allow := True. Assim, o hook usado pelo PR é atualmente inoperante. Isso também deve ser relatado ao FPC upstream.

Segundo problema encontrado: HTTP pipelining

Quando várias requisições são enviadas antecipadamente no mesmo socket, o FPC lê várias delas para FBuffer, processa a primeira e depois chama Socket.CanRead(...). Como os bytes restantes já estão no buffer de usuário, o descritor não aparece como legível e as requisições seguintes não são processadas.

O reprodutor ficou aguardando até o timeout mesmo com as requisições já presentes em FBuffer. RequestPending deveria considerar Length(FBuffer) > 0 antes de consultar o socket.

Conclusão

• A regressão de ~44 ms é confirmada no FPC 3.3.1.
• Remover keep-alive continua sendo uma correção inadequada.
• A explicação de “poll fixo” do fix(fpc): remove keepalive — fphttpserver poll interval causes ~40ms per-request stall #554 era incompleta.
• O TCP_NODELAY daquele PR nunca foi efetivamente aplicado por causa de um callback não encaminhado pelo FPC.
• Há ao menos dois pontos para o FPC upstream:
  1. DoOnAllowConnect não encaminha o callback armazenado em FOnAllowConnect;
  2. RequestPending ignora requisições já presentes em FBuffer.

Próximo passo recomendado

Criar um reprodutor mínimo somente com TFPHTTPServer, sem Horse, e abrir o relatório upstream no FPC. Em paralelo, podemos avaliar uma mitigação no Horse que preserve keep-alive, preferencialmente evitando os dois writes pequenos ou instalando TCP_NODELAY por um hook que realmente seja executado, sem substituir callbacks do usuário.

[freitasjca]

I reproduced this and found the cause. It is not a poll interval in the
keep-alive loop — it is Nagle on the accepted socket interacting with the
client's delayed ACK. Everything below uses only Horse's own sample and stock
tools, so it can be reproduced without any extra code.

Reproducing

Build and run samples/lazarus/console with FPC trunk and keep-alive enabled,
listening on 9000 with a /ping route returning a short body. Then, in another
terminal, capture loopback while issuing several requests on one connection:

sudo -v                     # cache the credential first, see note below
sudo tcpdump -i lo -n -ttt 'tcp port 9000' -c 60 > /tmp/ka.txt 2>&1 &
curl -s -o /dev/null -w '%{time_total}\n' \
     http://127.0.0.1:9000/ping \
     http://127.0.0.1:9000/ping \
     http://127.0.0.1:9000/ping
sudo pkill tcpdump ; cat /tmp/ka.txt

curl with several URLs on the same host reuses one connection, which is what
triggers it. The first request is fast; the rest are not.

(Note: a backgrounded sudo tcpdump will silently suspend on the password
prompt and capture nothing — hence the sudo -v first. That cost me a run.)

What the capture shows

Leading column is the delta from the previous packet. One socket, four
sequential requests, 79-byte header block and a 4-byte body.

Request 1 — fast, 0.28 ms end to end:

0.000239  9000 > client  length 79     headers
0.000014  client > 9000  ack 80        client ACKs immediately
0.000010  9000 > client  length 4      body, 10 us later

Requests 2, 3 and 4 — stalled:

0.000040  9000 > client  length 79     headers out immediately
0.042530  client > 9000  ack 163       client's delayed ACK, 42.5 ms
0.000014  9000 > client  length 4      body released 14 us after the ACK

0.000102  9000 > client  length 79
0.043827  client > 9000  ack 246
0.000011  9000 > client  length 4

0.000088  9000 > client  length 79
0.043857  client > 9000  ack 329
0.000011  9000 > client  length 4

The mechanism

1. fphttpserver writes each response as two send() calls — the header
   block, then the body. (Visible under strace: sendto of 79 bytes, then 4.)
2. TCP_NODELAY is never set on the accepted socket, so Nagle applies to the
   second write: it is smaller than MSS and there is unacknowledged data
   outstanding (the 79 bytes). The kernel holds it.
3. The client has nothing to send, so its ACK waits for the delayed-ACK timer,
   ~40 ms on Linux.
4. The ACK arrives, Nagle releases, the body goes out.

The reason I am confident this is causation and not correlation: the body
segment leaves 11–14 µs after the ACK, three times, while the ACK delay
itself varies (42.530 / 43.827 / 43.857 ms). The body tracks the ACK to within
microseconds across a varying delay. A fixed server-side poll interval would
produce a body timed independently of the ACK — and a bare incoming ACK does
not make a socket readable, so it cannot wake a select() waiting for request
data anyway.

Why it only appears with keep-alive

Two controls fall out of the same capture:

• Only the first request on a connection is fast. Linux starts a socket in
  quickack mode; delayed ACK engages afterwards. With Connection: close every
  request is request 1 on a fresh socket, so the stall never appears.
• A 300 ms idle gap also makes it fast (ACK in 16 µs, body 6 µs later).
  Linux re-enters quickack after idling, so only back-to-back requests stall.

Why setting OnAllowConnect does not help

The obvious fix is setsockopt(TCP_NODELAY) on each accepted fd via
TFPCustomHttpServer.OnAllowConnect. I tried that first; it never fires, and
the reason is in fcl-web rather than in the calling code. In fphttpserver.pp:

• CreateServerSocket wires FServer.OnConnectSocketQuery := @DoOnAllowConnect
• DoOnAllowConnect applies only the MaxLiveConnectionCount / 503 logic and
  then sets Allow := True
• FOnAllowConnect is written by SetOnAllowConnect and read nowhere

So OnAllowConnect is effectively a dead property in this version — assigning
it can never invoke the handler. Confirmed at runtime: strace of the server
shows zero setsockopt(TCP_NODELAY) calls, and fphttpserver.pp contains
no TCP_NODELAY anywhere, so nothing else sets it either. That looks like an
fcl-web bug in its own right and I am happy to report it upstream to FPC
separately.

Suggested fix

Set TCP_NODELAY per connection from THorseProvider.DoGetModule in
Horse.Provider.FPC.HTTPApplication. OnGetModule is called for every request
by custweb.pp's TWebHandler.OldHandleRequest (Horse sets
LegacyRouting := True), and it hands over the TRequest — from which
TFPHTTPConnectionRequest.Connection → TFPHTTPConnection.Socket.Handle
reaches the accepted descriptor. Both members are public, and Socket.Handle
is the accessor fphttpserver uses internally.

DoGetModule is preferable to THorseWebModule.HandleRequest here because the
web module is shared by every FPC provider — putting the code there would pull
fphttpserver into the epoll and daemon builds that never use it.

This also covers the very first request on a connection, since the option is
set before the response is written, and it needs no change to fcl-web.

With that in place, KeepConnections can be turned back on: the ~44 ms cost
that made keep-alive look unusable was this bug, not keep-alive itself.

The alternative — coalescing headers and body into a single send() so no
small trailing segment exists — is the cleaner fix but is not reachable from
Horse; both writes happen inside fphttpserver.

Measured

I implemented the first approach and measured it on FPC trunk 3.3.1 / Linux,
against the same samples/lazarus/console server — 20 sequential requests on
one socket:

	before	after
min	0.28 ms	0.04 ms
p50	43.98 ms	0.07 / 0.08 ms (two runs)
max	44.00 ms	0.25 / 0.21 ms

The stall disappears rather than shrinking — what is left is loopback
round-trip time with no 40 ms component in the distribution.

Worth stating the control explicitly, since "fast" would also be the signature
of keep-alive quietly not being enabled: the same run verifies the connection
is still usable after the exchange, so this is genuine keep-alive with the
Nagle cost removed, not keep-alive switched off.

One unrelated observation while measuring, which I mention only so it does not
surprise you later: HTTP/1.1 pipelining (3 requests written in one syscall)
returns 1 response and then times out. I have no pre-fix baseline for it, so I
am not claiming it changed — it looks like fphttpserver reading one request
per cycle, and it is unaffected by anything above.

The probe, if you want the numbers rather than the shape

The curl reproducer above needs nothing extra and is enough to see the stall.
To get the percentile table instead, the probe and its runner are here:

https://github.com/freitasjca/horse/tree/fix/fpc-keepalive-nagle/tests/fpc-keepalive

• KeepAliveLatencyProbe.lpr — raw TCP client, three scenarios (sequential on
  one socket, pipelined, reuse-after-close). Reports percentiles and makes no
  pass/fail judgement of its own.
• run-keepalive-test.sh — builds the stock samples/lazarus/console server
  and the probe, runs them, and compares scenario A's p50 against a threshold.
• NAGLE-EVIDENCE.md — the full capture and analysis.

HORSE_SRC=/path/to/horse/src FPC=/path/to/fpc-trunk bash run-keepalive-test.sh

It refuses to run on FPC < 3.3.1 (both keep-alive and the fix sit behind
{$IF FPC_FULLVERSION >= 30301}, so an older compiler would report a
meaningless pass), refuses a tree without the fix applied, and refuses to start
if something already holds the port. Horse's own suite is DUnitX and
Delphi-only, so this follows the same standalone-program pattern as the FPC
WebSocket test from #549.

I can open a PR with this if you would like. Keep-alive stays enabled either
way; this is not a reason to leave KeepConnections off.

One correction to my earlier reading

I previously reported this as the keep-alive loop's select() poll interval.
That was wrong, and I want to flag it explicitly rather than quietly replace it.
The server is blocked ~43 ms in select(), but it is idle there waiting for
the next request — which the client cannot send because it is still waiting for
a body that Nagle is holding. I had cause and effect inverted.