Diagnóstico de latência em APIs Node.js com async_hooks, event-loop e GC

Motivacao e trade-offs

Por que medir latência além do request/response

Medir apenas o tempo entre o recebimento do request e o envio do response mascara fontes reais de latência: enfileiramento no event loop, pausas de GC, bloqueios síncronos e overhead de frameworks. Para aplicações REST/GraphQL com SLAs tensos, é necessário separar onde o tempo está sendo gasto, identificar contendas e decidir trade-offs entre complexidade, custo e precisão.

O objetivo aqui é dar ferramentas práticas para: atribuir latência a fases (parsing, I/O, CPU, enfileiramento), reconstituir traces locais usando async_hooks/AsyncLocalStorage e medir o impacto do garbage collector e do event-loop de forma contínua.

Trade-offs práticos

Medir agressivamente tem custo: hooks e context propagation adicionam overhead; monitoramento fino pode gerar ruído. Algumas decisões típicas:

• Precisão vs Overhead: monitorEventLoopDelay e async_hooks têm overhead não nulo. Use em ambientes de staging com amostragem em produção.
• Observabilidade local vs distribuída: AsyncLocalStorage funciona bem dentro do processo; traces distribuídos exigem headers/propagação externas.
• Intervenção vs Automação: coletar métricas para alertar é diferente de ligar um coletor contínuo. Prefira amostragem com gatilhos para dumps de heap ou profiles.

Regra prática: comece medindo o event-loop e GC continuamente; adicione tracing via async_hooks quando precisar decompor a latência por request.

Fundamentos tecnicos

async_hooks e AsyncLocalStorage

async_hooks fornece ganchos para o ciclo de vida das operações assíncronas. AsyncLocalStorage é uma camada prática construída sobre async_hooks que permite propagar contexto (por exemplo, requestId) ao longo de callbacks e promises. Usar AsyncLocalStorage facilita correlacionar logs e métricas por request sem alterar assinaturas de função.

Aspectos importantes:

• AsyncLocalStorage propaga contexto somente dentro do mesmo processo; chamadas para outros processos/serviços exigem propagação manual.
• Nem todo recurso assíncrono propaga contexto automaticamente entre worker threads e o processo principal.

Event loop e monitorEventLoopDelay

O event-loop lag (ou delay) é a diferença entre o tempo esperado para executar um callback e o tempo real. p.e.: timers adiados ou longos callbacks aumentam esse atraso. Node fornece perf_hooks.monitorEventLoopDelay() para medir distribuição de latências do loop.

Medir o event-loop dá sinais precoces de problemas de CPU ou I/O que não aparecem nas métricas de throughput.

Garbage Collector (GC)

O GC do V8 causa pausas que afetam latência. Dependendo das gerações, do tamanho do heap e do padrão de alocação, o tempo de pausa pode variar. Node não expõe todos os detalhes do GC em runtime sem flags, mas é possível monitorar:

• heapUsed / heapTotal via process.memoryUsage()
• ativar flags de runtime (p.ex. --trace_gc) para profiling
• forçar GC manual (global.gc()) em ambiente de teste com --expose-gc

Interpretação: pausas curtas e frequentes indicam alta alocação/fragmentação; pausas longas podem indicar falta de memória ou operações síncronas pesadas durante collection.

Exemplo 1: caso simples

Objetivo do exemplo

Instrumentar um servidor HTTP simples que registra: tempo total do request, tempo de enfileiramento no event-loop, marcações antes/depois de operações assíncronas e correlação por requestId usando AsyncLocalStorage.

Isso ajuda a separar o tempo gasto em I/O/serviço externo do tempo gasto aguardando execução no event-loop ou atrasos de GC.

Implementação mínima

O código abaixo cria um servidor HTTP que usa AsyncLocalStorage para atribuir um requestId e usa process.hrtime.bigint() para medir intervalos. Também registra event-loop delay instantâneo via uma amostra simples.

Contexto: copie este arquivo e execute com Node 14+.

const http = require('http');
const { AsyncLocalStorage } = require('async_hooks');
const { performance } = require('perf_hooks');

const als = new AsyncLocalStorage();

function nowNs() { return Number(process.hrtime.bigint()); }

const server = http.createServer((req, res) => {
  const requestId = `${Date.now()}-${Math.floor(Math.random()*10000)}`;
  const start = nowNs();

  als.run(new Map([['id', requestId], ['start', start]]), async () => {
    // Simula I/O assíncrono
    await new Promise(r => setTimeout(r, 10));

    const middle = nowNs();
    // Operação síncrona curta
    for (let i = 0; i < 1000; i++) Math.sqrt(i);

    const end = nowNs();
    const ctx = als.getStore();

    res.writeHead(200, {'Content-Type': 'application/json'});
    res.end(JSON.stringify({
      requestId: ctx.get('id'),
      totalMs: (end - start) / 1e6,
      ioMs: (middle - start) / 1e6,
      syncMs: (end - middle) / 1e6
    }));
  });
});

server.listen(3000, () => console.log('server on 3000'));

O que faz: cria um requestId por request, cria contexto via AsyncLocalStorage, mede tempos antes e depois de uma operação assíncrona e de uma sequência síncrona.

Ao executar e bater o endpoint repetidamente, será possível identificar se a maior parte do tempo está em espera (I/O) ou em execução síncrona no event-loop.

Resultados esperados e interpretação

Se syncMs for dominante, então há trabalho síncrono que bloqueia o loop — candidato a mover para worker threads. Se ioMs for dominante, otimizar chamadas I/O ou paralelizar faz sentido. Se totalMs apresentar spikes não correspondentes às fases, suspeite de GC ou contendas no event-loop.

Exemplo 2: caso avancado do mundo real

Cenário

Aplicação GraphQL que responde lentamente sob picos. Logs mostram latência variável mesmo com baixa CPU aparente. Suspeita: enfileiramento no event-loop e pausas de GC causam picos; além disso, há resolvers que fazem processamento CPU-bound (serial JSON.stringify e compressão).

Objetivo: instrumentar para: 1) medir event-loop delay com monitorEventLoopDelay, 2) detectar pausas de GC via observação de heap e timers, 3) extrair traces por request e propagar requestId para workers quando usarmos offload.

Medindo event-loop delay e GC

O trecho abaixo ativa monitorEventLoopDelay e faz amostragem de memória. Em produção, execute com amostragem/aggregation e exporte para o seu sistema de métricas.

const { monitorEventLoopDelay } = require('perf_hooks');
const histogram = monitorEventLoopDelay({ resolution: 10 });
histogram.enable();

setInterval(() => {
  const meanMs = histogram.mean / 1e6;
  const maxMs = histogram.max / 1e6;
  const mem = process.memoryUsage();
  console.log(`evLoop mean=${meanMs.toFixed(2)}ms max=${maxMs.toFixed(2)}ms heapUsed=${Math.round(mem.heapUsed/1024/1024)}MB`);
  histogram.reset();
}, 2000);

// Cada log mostra se o loop está com lag e o uso de heap que pode indicar pressao de GC

O que faz: cria um histograma do event-loop, imprime média e máximo a cada 2s e mostra heapUsed. Picos no max associados a aumento de heapUsed são fortes indícios de pausas de GC.

Offload para worker threads com propagacao de context

Resolver CPU-bound em workers reduz o bloqueio do event-loop principal. É necessário propagar requestId para manter correlação. Exemplo abaixo cria um pool mínimo de workers e envia job com requestId.

const { Worker } = require('worker_threads');
const path = require('path');

function runInWorker(job) {
  return new Promise((resolve, reject) => {
    const w = new Worker(path.resolve(__dirname, 'worker-job.js'), { workerData: job });
    w.once('message', resolve);
    w.once('error', reject);
    w.once('exit', code => { if (code !== 0) reject(new Error('Worker exit ' + code)); });
  });
}

// worker-job.js deve ler workerData e postar o resultado
// Exemplo de uso:
(async () => {
  const res = await runInWorker({ requestId: '1234', payload: { n: 1e7 } });
  console.log('worker done', res);
})();

Conteúdo de worker-job.js (contexto: processamento CPU-bound e envio de result):

const { parentPort, workerData } = require('worker_threads');
// heavy CPU work: sum numbers
let sum = 0;
for (let i = 0; i < workerData.payload.n; i++) sum += i;
parentPort.postMessage({ requestId: workerData.requestId, sum });

O que acontece: o processamento pesado roda em outro thread, preservando o event-loop principal. Logs e métricas devem correlacionar requestId recebido no worker com a resposta para traçar a latência total.

O que procurar nos resultados

Combinar métricas do histograma do event-loop com tempos de execução dos workers e medidas de heap permite responder perguntas como:

• Os picos de latência coincidem com picos de heapUsed? (suspeita GC)
• Requests lentos tiveram longos tempos de enfileiramento no event-loop ou long waits por workers? (saturação do pool)
• Há padrões com tipos de requisição que alocam muito memória rapidamente (p.ex. parsing de grandes payloads)?

Debugging e troubleshooting

Erros comuns e armadilhas

Listo as armadilhas que mais vejo em debugging de latência em Node:

• Medir no lugar errado: logs agregados por request sem contexto levam a conclusões erradas. Use correlação por requestId.
• Overhead de tracing: async_hooks/AsyncLocalStorage adicionam overhead. Em loops de alto throughput, isso pode mascarar problemas; amostre.
• Ignorar env de execução: flags de runtime (GC tracing, --expose-gc) mudam comportamento. Não confunda resultados de teste com produção.
• Assumir que worker threads propagam contexto: é necessário enviar requestId explicitamente.
• Forçar GC em produção: chamar global.gc() pode causar picos de latência; use somente em testes controlados.

Dicas práticas de investigação

Um fluxo de troubleshooting eficiente:

1. Capturar métricas de event-loop e heap por minuto (histograma + memoryUsage).
2. Correlacionar períodos de latência com picos de heap/máx do histograma.
3. Habilitar tracing por request (AsyncLocalStorage) em staging e reproduzir carga.
4. Se suspeita de GC, capturar heapdump e usar ferramentas (Chrome DevTools, heap-profiler).
5. Se suspeita de CPU-bound, mover função para worker thread e comparar latência.

Quando necessário, reduzir variáveis: teste com payloads pequenos, depois aumente. Isole I/O externo desligando integrações para ver se o problema persiste.

Comandos e flags úteis

Algumas flags e ferramentas úteis no diagnóstico:

• node --inspect e Chrome DevTools para profiler de CPU e heap snapshots
• node --trace_gc para logs de GC em ambiente de staging
• node --expose-gc para testar manualmente global.gc()
• clinic (clinic doctor, clinic flame) para identificar hotspots CPU/IO

Conclusao pratica

Resumo das ações concretas

Para diagnosticar latência em APIs Node.js, aplique um conjunto de medidas incrementais: comece coletando event-loop delay e memória; adicione correlação por request com AsyncLocalStorage para decompor tempos; use worker_threads para descarregar CPU-bound; use heapdump/profiler quando GC for o suspeito. Sempre valide alterações em staging com carga representativa.

Checklist rápido

• Ativar monitorEventLoopDelay em todos os nós e exportar métricas
• Usar AsyncLocalStorage para requestId e correlação de logs
• Mover trabalho CPU-bound para worker threads e propagar contexto
• Monitorar heapUsed, e habilitar tracing de GC em staging
• Amostrar traces e evitar overhead excessivo em produção

Implementações concretas como as mostradas permitem isolar a fonte da latência e selecionar a intervenção correta — seja otimizar código síncrono, reduzir alocações, aumentar pool de workers, ou ajustar GC/heap. A combinação de async_hooks/AsyncLocalStorage, perf_hooks e worker_threads forma um kit robusto para diagnóstico e correção.

Se precisar, forneço um repositório de referência com essas ferramentas integradas em um template Express/GraphQL para aplicar e testar em ambiente controlado.