Os 900 ms que sumiam antes da primeira query

Algumas requisições passavam de cinco segundos. O APM marcava slow request em volume, e não num endpoint específico: em todos os endpoints autenticados do sistema. O padrão se repetia em todos — a demora estava na primeira instrução que tocava o banco. Num endpoint autenticado, essa instrução é sempre a mesma: carregar o usuário do token.

Quando entrei no projeto, o sintoma já estava lá havia seis meses.

Fui olhar o banco. Slow query log limpo. Nenhuma query lenta, nenhum lock, nada.

As duas coisas eram verdade ao mesmo tempo, e eu levei um tempo constrangedor para entender por quê: o banco só começa a cronometrar depois que a conexão existe. Todo o tempo gasto antes disso — resolver o host, abrir o socket, negociar TLS, autenticar — não aparece em métrica nenhuma do servidor. Sai do orçamento da requisição e não entra em nenhum relatório do banco.

O experimento que separou runtime de banco

Fiz o teste mais barato que consegui imaginar: dois projetos descartáveis, um em Node e um em Laravel, cada um com um endpoint que faz um select por chave primária e devolve o tempo. Mesma query, mesma tabela, mesmo banco.

Em Node, mediana de 123,2 ms, com quase nenhuma dispersão — p99 de 131,6 ms em mil amostras. Em Laravel, um piso de quase um segundo e requisições isoladas passando de onze.

O runtime explicava a diferença. O processo Node mantém um pool de conexões vivo entre requisições; o worker do PHP-FPM derruba a conexão no fim de cada request e o próximo paga tudo de novo.

E o log do Node mostra o pedágio acontecendo, uma vez só. São 1.076 amostras e exatamente duas acima de 200 ms: a primeira de cada vez que o processo subiu — 552,8 ms numa execução, 596,4 ms na outra. Fora essas duas, nada passou de 133,7 ms. Aquele meio segundo é o handshake, cobrado no primeiro request e amortizado por todos os seguintes. O Laravel pagava o mesmo pedágio em cada requisição.

Correlação não é causa, então parei de olhar o tempo total e passei a medir em três partes. Um middleware que reproduz o caminho real de uma requisição autenticada — valida o token, carrega o usuário —, com DB::purge no começo para garantir que cada requisição comece sem conexão. É exatamente o estado de um worker de PHP-FPM atendendo uma requisição nova:

DB::purge('mysql');

$t0 = hrtime(true);
DB::connection('mysql')->getPdo();   // só conecta
$connectMs = (hrtime(true) - $t0) / 1e6;

$t1 = hrtime(true);
$user = User::find($id);             // só consulta
$lookupMs = (hrtime(true) - $t1) / 1e6;app/Http/Middleware/PingTimings.php

Cinco mil amostras de cada lado, concorrência dez, contra o mesmo MySQL gerenciado. De um lado, conexão direta. Do outro, um ProxySQL local entre a aplicação e o banco.

O piso de quase um segundo estava explicado, e não era o banco: 645 de conexão mais 255 de query dão os 913 do total. Setenta por cento do tempo de resposta era gasto antes de a primeira query existir.

Cinco idas e voltas

O número que fecha o argumento não é a média — é o mínimo. O melhor tempo de conexão direta em cinco mil tentativas foi 622,5 ms. Não existe congestionamento, fila nem vizinho barulhento no melhor caso; o mínimo é o custo estrutural.

E ele é divisível. Uma query numa conexão já quente custou 124 ms — esse é o tempo de uma ida e volta até o banco. Dois caminhos independentes dão o mesmo número: a mediana do Node, com pool próprio, driver diferente e outro runtime, foi 123,2 ms. Os 622 ms do connect são, aproximadamente, cinco dessas idas e voltas: o handshake TCP, o handshake TLS e a troca de autenticação do protocolo MySQL, cada etapa esperando a resposta da anterior antes de mandar a próxima.

O protocolo serializa por definição. A documentação da fase de conexão do MySQL descreve a sequência com TLS em quatro tempos: o servidor manda o Protocol::Handshake, o cliente responde com um Protocol::SSLRequest, aí acontece “the usual SSL exchange leading to establishing SSL connection” — o handshake TLS inteiro, aninhado dentro do handshake do MySQL — e só então o cliente manda o Protocol::HandshakeResponse com as credenciais. Cada seta depende da anterior. Não há como paralelizar; só há como não fazer de novo.

Não é “banco lento”. É contagem de idas e voltas multiplicada pela latência da rede. Um banco ocioso e perfeito custaria exatamente o mesmo, porque nada disso depende do trabalho que o servidor faz — depende de quantas vezes o pacote atravessa o caminho. E cada requisição pagava a conta inteira, do zero.

O que morre no fim da requisição

Vale desmontar a frase “PHP-FPM não tem pool”, porque ela esconde a parte interessante. O processo não é descartado a cada requisição. Com pm = dynamic, o gerenciador mantém os filhos vivos entre requisições e só recicla cada um depois de um número configurado delas — pm.max_requests, que a documentação define como “the number of requests each child process should execute before respawning”. No sistema em que trabalho esse número é 400.

O que não sobrevive é a conexão. O manual do PHP define conexão persistente como “links that do not close when the execution of the script ends” — ou seja, a conexão comum, que é o padrão, fecha exatamente aí. O worker segue vivo para a requisição seguinte; o socket que custou cinco idas e voltas, não.

É a inversão que me chamou atenção depois de entender: o processo, que é barato de recriar, é justamente o que o PHP-FPM se dá o trabalho de preservar. A conexão, que custa meio segundo, é jogada fora quatrocentas vezes na vida de cada worker.

Por que não conexão persistente

A objeção óbvia de quem trabalha com PHP: o driver já tem conexão persistente. Liga PDO::ATTR_PERSISTENT e a conexão sobrevive ao fim da requisição, presa ao processo do worker. Resolve o handshake sem instalar nada.

Resolve o handshake e cria dois problemas, e o próprio manual do PHP descreve os dois sem meias palavras.

A conexão fica presa a um processo, não compartilhada entre eles: “if 20 different child processes each run a script that makes a persistent connection to the SQL server, there will be 20 separate connections to that server, one from each child.” O teto de conexões do banco passa a ser função da contagem de workers PHP, não da carga real.

Ela também carrega estado. O manual lista o que sobrevive ao fim da requisição — banco selecionado, locks de tabela, transações não commitadas, tabelas temporárias, configurações específicas da conexão — e avisa que “table locks and transactions that are not cleaned up or closed may cause other queries to be blocked indefinitely and/or cause subsequent reuse of the connection to cause unexpected changes.” O próximo request que herdar aquele worker herda junto.

Um pool externo é a mesma ideia, mas do lado certo da fronteira. Para a aplicação ele fica na rede local — handshake barato, sem TLS, sem viagem. Para o banco, ele mantém um punhado de conexões quentes e as reaproveita entre todos os workers. O número que interessa é o mesmo de antes: 1,5 ms de conexão contra 645,7 ms.

Só que essa reutilização tem condição, e ela é mais restritiva do que eu imaginava. A documentação de multiplexing do ProxySQL lista o que desliga o compartilhamento de conexão de backend, e boa parte da lista nunca mais religa na mesma conexão: qualquer query com @ no digest — ou seja, variável de usuário —, CREATE TEMPORARY TABLE, GET_LOCK(), SQL_CALC_FOUND_ROWS. Transação aberta desliga até o commit; LOCK TABLES, até o unlock. Ou seja: o pool devolve o handshake, mas o quanto ele economiza em conexões de backend depende de a aplicação não sujar a sessão. Vale medir o ConnUsed do pool depois de subir, e não assumir o número que o cálculo prometia.

O que mudou

A cauda é a parte que mais me interessa. O p99 da conexão direta foi de 22,67 s, com máximo de 36,84 s — em concorrência dez, que não é carga. Não é a mesma curva do piso de 645 ms: é um segundo fenômeno, empilhado em cima do primeiro. Trinta e sete segundos para abrir uma conexão tem outra causa: alguma coisa enfileira ou desiste no caminho. Não sei o quê. Não capturei pacote, não olhei métrica do lado do servidor, e não vou preencher esse buraco com palpite bem-escrito.

De volta para a produção

Um bench de laptop prova mecanismo, não decide arquitetura. Então vale separar o que eu medi do que eu sei.

O que eu sei da produção é grosso: quando um request autenticado estourava, a primeira instrução ao banco levava cinco segundos ou mais. Nunca medi, de dentro do cluster, quanto disso era conexão e quanto era query — essa falta é exatamente o que o bench veio cobrir.

E o bench reposiciona a tese em vez de confirmá-la de graça. Se lá dentro a ida e volta até o banco é de ordem de um milissegundo, as cinco idas e voltas do handshake custam alguns milissegundos e somem no ruído. O piso de 645 ms não era o que doía em produção. O que doía era a cauda do mesmo mecanismo: o connect que, no bench, deu 22 s no p99 e 37 s no máximo — com concorrência dez. A aritmética do mínimo explica de onde vem o custo; é a cauda dele que vira incidente.

O desfecho foi colocar um ProxySQL na frente do MySQL em todas as aplicações PHP que conectavam por PHP-FPM. O APM marcava slow request tudo que passasse de cinco segundos; depois da mudança, parou de marcar.

Reparem no que essa frase não diz. Não diz que tudo ficou rápido, nem que a cauda foi explicada — continuo sem saber o que enfileirava a abertura de conexão. Diz que nada mais cruzou a linha dos cinco segundos. O pool não resolveu o mistério; ele parou de pagar a aposta a cada requisição.

A pergunta que ficou aberta

Voltando à primeira tabela: o lookup da conexão direta custou 255,4 ms, contra 127,9 ms passando pelo pool. Mesma query, mesma chave primária, mesmo banco de destino. A conexão fria custou o dobro da conexão quente depois do handshake já ter terminado e sido cronometrado à parte.

A hipótese é uma ida e volta a mais na primeira troca de dados de uma conexão recém-negociada. Mas hipótese com aritmética bonita é justamente a que engana, e eu não capturei os pacotes para confirmar. Fica registrada como pergunta, não como achado — se estiver certa, o pool economiza um round-trip a mais do que eu contei.