Yunong Xiao, engenheiro de software na Netflix, escreveu recentemente no blog oficial da empresa sobre os problemas de latência que seu time enfrentou enquanto trabalhavam para mover a interface de usuário do site Netflix para Node.js. No post, Yunong descreveu o complexo processo de engenharia usado para identificar a causa raiz do problema e como isso influenciou a decisão de substituir o framework.
Os primeiros sinais de problemas apareceram quando o time observou que a latência nas requisições para alguns endpoints na API estava crescendo com o decorrer to tempo (10ms/hora) e que em períodos de grande latência, a aplicação estava usando mais CPU do que o esperado. A hipótese inicial era que algum tipo de problema (por exemplo, um vazamento de memória) introduzido pelo time nos manipuladores das requisições estava causando o aumento de latência. Para avaliar isto, o time criou um ambiente controlado onde mediram a latência dos manipuladores de requisição e a latência total de uma requisição. Adicionalmente, aumentaram o tamanho do heap do Node.js para 32GB. Foi observado que a latência e o tamanho do heap permaneceram constantes durante o experimento mas a latência total e a utilização de CPU continuavam a subir.
A próxima abordagem foi instrumentar o uso de CPU pela aplicação com gráficos de chamas de CPU (CPU flame graphs) e Linux Perf Events. Observando atentamente o gráfico (apresentado a seguir), os desenvolvedores notaram várias referencias para as funções router.handle e router.handle.next do Express.js.
Após mergulhar no código do Express.js, o time da Netflix observou que:
- Os manipuladores de rotas para todos os endpoints são armazenados em um array global.
- O Express.js itera recursivamente e invoca todos os manipuladores até que ele encontre o manipulador de rota correto.
Segundo Yunong
Um array global não é a estrutura de dados ideal para este caso. Não é claro o porquê do Express.js escolher não usar uma estrutura de dados de tempo de acesso constante como um map para armazenar seus manipuladores. Cada requisição requer uma busca O(n) expensiva no array de rotas para encontrar o manipulador de rotas correto. Para piorar as coisas, o array é percorrido de forma recursiva. Isto explica porquê nós encontramos pilhas de chamadas tão altas nos gráficos de chamas. Curiosamente, o Express.js ainda permite que você defina muitos manipuladores de chamada idênticos para uma rota: [a, b, c, c, c, c, d, e, f, g, h].
Requisições para a rota c terminariam na primeira ocorrência do manipulador c (posição 2 no array). Entretanto, requisições para d somente terminariam na posição 6 do array, gastando tempo desnecessário percorrendo a, b e múltiplas instâncias de c.
Para entender um pouco melhor sobre como o Express.js estava armazenando as rotas, o time criou o seguinte exemplo:
var express = require('express');
var app = express();
app.get('/foo', function (req, res) {
res.send('hi');
});
// add a second foo route handler
app.get('/foo', function (req, res) {
res.send('hi2');
});
console.log('stack', app._router.stack);
app.listen(3000);
Que levou aos seguintes resultados:
stack [ { keys: [], regexp: /^\/?(?=/|$)/i, handle: [Function: query] },
{ keys: [],
regexp: /^\/?(?=/|$)/i,
handle: [Function: expressInit] },
{ keys: [],
regexp: /^\/foo\/?$/i,
handle: [Function],
route: { path: '/foo', stack: [Object], methods: [Object] } },
{ keys: [],
regexp: /^\/foo\/?$/i,
handle: [Function],
route: { path: '/foo', stack: [Object], methods: [Object] } } ]
Este experimento permitiu concluir que o Express.js não estava tratando corretamente a duplicação de rotas, conforme apontado por Yunong: "Veja que existem duas rotas idênticas para /foo. Seria bom que o Express.js indicasse erro sempre que exista mais de um manipulador para uma mesma rota na cadeia".
Após mergulhar no seu código fonte o time encontrou o problema. O problema estava em uma função que era executada 10 vezes por hora e cujo principal objetivo era atualizar manipuladores de rotas para recursos externos. Quando o time corrigiu o código para que a função parasse de adicionar manipuladores de rotas duplicados, os aumentos de latência e de uso de CPU desapareceram.
Após este incidente, Yunong sumarizou as conclusões do time:
Primeiro, nós precisamos entender completamente nossas dependências antes de as colocarmos em produção. Fizemos suposições incorretas sobre a API do Express.js sem mergulhar profundamente em seu código. Como resultado, nosso mal uso da API do Express.js foi a causa raiz de nosso problema de desempenho.
Em segundo lugar, dado um problema de desempenho, a capacidade de observação é de fundamental importância. Os gráficos de chamas nos ofereceram compreensão de onde nossa aplicação estava gastando a maior parte de tempo de processamento na CPU. Eu não consigo imaginar como teríamos resolvido este problema se não pudéssemos visualizar as pilhas de chamadas do Node.js nos gráficos de chamas.
Em nossa tentativa de melhorar ainda mais a capacidade de observação, estamos migrando para o Restify, que vai nos fornecer melhor compreensão, visibilidade e controle de nossas aplicações.