Testes lentos no WSL2: a suíte Laravel que o fsync travava

A suíte de testes levava 35 minutos. São 1.312 testes em Pest, quase todos de feature, batendo num MySQL de verdade. Trinta e cinco minutos é o tipo de número que ninguém defende, mas que todo mundo aprende a contornar: você roda um arquivo, confia, e deixa a suíte inteira para o pipeline.

O que me incomodava era outra coisa. Um colega roda a mesma suíte, no mesmo docker-compose.yml, em 8 minutos. Ele trabalha num Mac; eu, em WSL2.

Anotei isso como “coisa de máquina”. Era o diagnóstico.

As duas hipóteses óbvias

A primeira foi paralelizar. O --parallel do Pest — que por baixo é o paratest, já instalado no composer.json havia tempo, sem ninguém usar. Rodei a suíte inteira com oito processos: 23 minutos.

Ganho de 1,5x com oito workers. Não é assim que paralelismo funciona quando o gargalo é trabalho de CPU, então fui olhar de onde vinha o limite. Amostrei os containers no meio da execução: o PHP em 30% de CPU, o MySQL em 150% — cada um com teto de 400%. Ninguém saturado. Oito workers e todo mundo esperando.

A segunda hipótese foi trocar o banco. Testes em SQLite :memory: são o truque clássico do ecossistema Laravel, e o ganho seria enorme.

Fui olhar antes de mexer e achei, no histórico do repositório, alguém fazendo o caminho inverso: anos atrás a suíte tinha sido migrada de SQLite para MySQL, e no mesmo commit o modo de limpar o banco entre testes tinha mudado. O schema de teste tem 11 views e 2 stored procedures, e treze migrations executam SQL cru específico de MySQL. SQLite não tem procedure.

Voltar para SQLite seria trocar tempo de suíte por uma classe de bug que já aconteceu nesse sistema em produção: aquilo que passa no teste e quebra no banco de verdade, porque o teste roda em outro banco.

O que a limpeza entre testes estava cobrando

O Laravel oferece duas estratégias para deixar o banco limpo entre um teste e outro. RefreshDatabase envolve cada teste numa transação e dá ROLLBACK no fim. DatabaseTruncation trunca as tabelas. A suíte usava truncate, em 193 arquivos de teste — e a documentação avisa em uma linha, sem explicar por quê, que essa opção é “significantly slower than the RefreshDatabase trait”.

Truncate parece um DELETE mais rápido. Não é, e o manual do MySQL é explícito nos dois pontos que importam aqui: “although TRUNCATE TABLE is similar to DELETE, it is classified as a DDL statement rather than a DML statement”, e “truncate operations drop and re-create the table”. Não é uma remoção de linhas — é o arquivo da tabela sendo destruído e refeito. E a implementação do framework faz isso a cada teste: varre a lista de tabelas do schema e trunca as que têm linha.

São 107 tabelas nesse schema.

Fui ao slow query log, com a suíte paralela rodando. Lá estavam, com nome e sobrenome:

70.7s    29x  TRUNCATE
23.8s     6x  DROP
21.8s   313x  SELECTmysql-slow.log

Vinte e nove truncates que passaram do limiar de dois segundos do slow log, somando setenta. E esses são só os que apareceram: o slow log mostra a cauda, não a média. Com o banco ocioso, o mesmo comando custa cerca de um milissegundo.

Minha primeira leitura foi que os oito workers disputavam o dicionário do InnoDB. Estava errada, e o próprio setup desmente: o paratest cria um banco por worker, e tabelas de bancos diferentes não brigam por lock de metadado. O que os oito workers dividem não é o dicionário. É o disco embaixo dele.

O que ainda não estava explicado era por que um único truncate custava caro.

A medição que fechou

Truncate dropa e recria arquivo. Arquivo é filesystem. Fui medir o filesystem, no teste mais barato que existe:

dd if=/dev/zero of=/var/lib/mysql/_t bs=4k count=2000 oflag=dsync

O oflag=dsync força a gravação a chegar ao disco a cada bloco, em vez de ficar em cache. É o comportamento que um banco precisa ter para não perder dado.

Quatrocentos e sessenta e seis kilobytes por segundo. Cerca de 8,8 ms para cada fsync de 4 KB — algo entre cinquenta e cem vezes mais lento que um NVMe decente. E o número mais importante é o da segunda linha: medido direto na VM, sem Docker no caminho. Não era o container, não era o MySQL, não era o Laravel.

Com esse número dá para fazer a conta pelo alto. Um teste que sujasse as 107 tabelas pagaria 107 fsyncs de 8,8 ms — 0,94 s só de limpeza, antes de rodar qualquer asserção. Vezes 1.312 testes, quase 21 minutos, dentro dos 35 medidos. É teto, não medição: não instrumentei quantas tabelas cada teste realmente suja, nem quantas operações de arquivo um truncate dispara. Mas é a ordem de grandeza certa, e nenhuma outra camada do sistema tem um número desse tamanho para oferecer.

E o Mac do colega, eu não sei. A hipótese provável é que a virtualização do Docker Desktop no macOS não pague o mesmo preço por durabilidade que o ext4 sobre VHDX paga; a documentação do Docker Desktop descreve compartilhamento de arquivo e opções de hypervisor, e não diz nada sobre como as escritas são efetivadas em disco dentro da VM. Sem medir a máquina dele, fica em hipótese.

Por que não bastou afrouxar a durabilidade do MySQL

A objeção natural de quem chegou até aqui: se o problema é fsync, por que não dizer ao MySQL para não sincronizar? Existe knob para isso.

Já estava ligado. O my.cnf do ambiente local rodava com innodb_doublewrite = OFF, sync_binlog = 0 e innodb_flush_log_at_trx_commit = 2 — e o próprio setup de teste ainda baixava esse último para 0, o modo menos durável que existe. A suíte levava 35 minutos assim.

O motivo é o que a citação do manual já entregou: esses parâmetros governam o redo log. Eles decidem com que frequência o log de transação vai ao disco. Um TRUNCATE não escreve no redo log — ele cria e destrói arquivo. Nenhuma configuração de flush de transação alcança a chamada de sistema que remove um tablespace e cria outro no lugar. O banco já estava configurado para não se importar com durabilidade; quem se importava era a camada debaixo, e é lá que eu precisava mexer.

O conserto

Se o problema é durabilidade cara, a saída é não precisar de durabilidade. Um banco de testes é descartável por definição: ele nasce de um migrate:fresh e morre no fim do dia.

A receita não é minha — datadir em memória para banco de teste é truque velho, e foi justamente por ser conhecida demais que eu tinha passado por ela sem olhar. O que faltava era saber por que ela valeria aqui, e isso só o dd respondeu.

Subi um segundo servidor MySQL, exclusivo da suíte, com o datadir em tmpfs — memória. O banco de desenvolvimento continua onde estava, em disco, intocado.

  mysql-test:
    build: ./docker/mysql
    tmpfs:
      - /var/lib/mysql:rw,size=3g
    environment:
      - MYSQL_DATABASE=app_testing
      - MYSQL_ROOT_PASSWORD=...docker-compose.yml

Uma pegadinha me custou uma rodada. A conexão do projeto tem read/write split configurado — host de escrita e host de leitura separados. Apontar só o host principal para o servidor novo faz os INSERT irem para a memória e os SELECT continuarem indo para o disco. Os dois precisam mudar juntos.

Nenhum teste foi alterado. Nenhuma linha de aplicação foi alterada. O custo em memória são 316 MB, porque o schema tem 5 MB de dados e o resto é arquivo de controle do InnoDB.

O ganho maior aparece nos runs curtos, e é o que mais importa: o loop real de desenvolvimento é rodar um arquivo depois de mexer no código, e esse caiu de 95 para 22 segundos. Parte disso é o migrate:fresh que a estratégia de truncate dispara no início de cada processo — 35 a 55 segundos em disco, cerca de 10 em memória.

A volta que eu não esperava

Olha de novo a última linha da tabela. Com o datadir em memória, a suíte serial levou 659 segundos e a paralela com oito workers levou 698.

Paralelizar ficou mais lento.

Faz sentido depois que se entende de onde vinha o ganho anterior. Enquanto o gargalo era o fsync, os oito workers passavam a maior parte do tempo bloqueados em I/O; sobrava CPU, e sobrepor a espera de um worker com a espera do outro rendia alguma coisa — 1,5x, mal e mal. Removido o fsync, não há mais espera para sobrepor. O que sobra é o custo de coordenar: o migrate:fresh roda uma vez por worker em vez de uma vez só, oito bancos são criados em vez de um, e o teto de CPU do container passa a ser o limite real.

O paralelismo não estava acelerando a suíte. Estava disfarçando o I/O — e mal.

Foi a parte do diagnóstico que mais me fez rever hábito. --parallel é a primeira coisa que eu ligo quando alguma coisa está lenta, e nesse caso ele funcionou como analgésico: entregou uma melhora real o suficiente para eu parar de procurar a causa.

A otimização óbvia que eu não fiz

Sobrou a pergunta incômoda: e se, em vez de tudo isso, eu simplesmente trocasse o truncate por transação com ROLLBACK? Rollback não toca em arquivo. Seria mais rápido que tmpfs e não exigiria container nenhum.

Medi no mesmo módulo da tabela: 200 segundos viraram 20. Dez vezes — e três vezes mais rápido que os 62 segundos que o tmpfs tinha entregado ali.

E quebrou 26 dos 98 testes.

O detalhe que separa quem quebra de quem não quebra é sutil, e demorei a ver: id fixo apontando para linha criada por seeder sobrevive, porque o seed roda uma vez, fora da transação de cada teste. Id fixo apontando para linha criada por factory dentro do teste quebra. Um módulo inteiro passou nos seus 125 testes com rollback; outro derrubou um quarto dos seus 98.

Isso é dívida de teste, não de infraestrutura, e algum dia vale pagar. Mas é uma refatoração em mais de cem arquivos, com risco de tornar verde um teste que deveria estar vermelho — e eu já tinha 3,2x sem tocar em nada.

O que ficou

Cada teste pedia ao sistema operacional uma garantia de durabilidade que ninguém queria, em dado que seria jogado fora meio segundo depois. E a pista estava na primeira frase, na forma mais fácil de ignorar que existe: na máquina do outro roda rápido.