Ler uma linha do SQLite no Node ficou uns 17% mais rápido. Um loop que puxava 1,48 milhão de linhas por segundo agora puxa 1,73 milhão, mesma máquina, mesma query. Nos vinte benchmarks de leitura que o Node tem, a maioria ficou mais rápida e nenhum ficou mais lento.

O patch que fez isso tira 35 linhas do arquivo. Ele não reescreve nada e não adiciona nada: o caminho rápido já estava lá, usado por exatamente uma das três funções que queriam ele. E entrou no core do Node.js semana passada. Daí a parte que vale um post não é qual foi a mudança - é como uma coisa tão barata ficou à vista de todos num arquivo em que eu moro há meses.

Ler o código não foi o que achou. Medir foi. O Nate Berkopec põe essa disciplina inteira numa frase no The Complete Guide to Rails Performance, e é a única parte daquele curso que eu chamaria de obrigatória:

Repita comigo: eu não vou otimizar nada na minha aplicação até minhas métricas mandarem.

O Brendan Gregg dá nome aos jeitos de errar isso no Systems Performance. O Street Light Anti-Method é investigar com a ferramenta que você já conhece, que é procurar a chave onde tem luz em vez de onde ela caiu. O Random Change Anti-Method é mudar coisa até algum número se mexer. Os dois produzem atividade. Nenhum produz conhecimento.

Então segue a alternativa, na ordem em que eu rodei de verdade - e a virada acontece no passo 4, onde apareceu que um décimo de cada leitura de uma linha ia pra montar os nomes das colunas. Quatro strings que nunca mudam, reconstruídas do zero toda vez.

1. Deixe a baseline honesta

$ git rev-list --left-right --count main...upstream/main
0	91

Noventa e um commits atrás. Faz o merge, recompila, e daí vem a linha que importa mais do que parece:

$ make -j10
$ cp out/Release/node /tmp/node-main

O make deixa um symlink ./node apontando pra out/Release/node. Aponta um benchmark pro ./node e ele silenciosamente segue o que você compilou por último, então você acaba comparando com todo cuidado um binário contra ele mesmo e chamando o resultado de ganho. Copie o binário de verdade pra fora antes de mexer em qualquer coisa.

2. Descubra o noise floor

Agora rode o benchmark da baseline contra ela mesma - binário idêntico dos dois lados, então toda diferença que aparecer é ruído de medição. Essa variação é o seu limite de detecção, e qualquer “ganho” menor que ela depois é infalsificável.

Mesmo motivo pelo qual você sobe na balança duas vezes antes de acreditar que perdeu 200 gramas.

$ ./out/Release/node benchmark/compare.js \
    --old /tmp/node-main --new /tmp/node-main \
    --runs 10 --no-progress \
    --set n=20000 --set tableSeedSize=10000 \
    --filter sqlite-prepare-select-get.js \
    --filter sqlite-prepare-select-all.js sqlite > noise-floor.csv

O Node já tem o benchmark/sqlite/, e vale usar: é a régua pela qual um maintainer vai julgar o seu PR, e tira qualquer discussão sobre se o seu harness era justo.

improvement  p-value    old rate    new rate   config
  -1.52%     0.1832      2.31M      2.28M  select-all 'SELECT text_column, integer_column FROM foo LIMIT 1'
  -0.31%     0.8124      1.52M      1.52M  select-get 'SELECT * FROM foo LIMIT 1'
+   1.30%     0.3721      1.49M      1.51M  select-get 'SELECT text,int,real,blob FROM foo LIMIT 1'
+   1.96%     0.2159      3.30M      3.37M  select-get 'SELECT 1'

configs: 20  significant: 0
geomean speedup (all configs): 0.38%

Três coisas dessa saída, se ela for nova pra você, porque o resto do post se apoia nelas. O p-value é a chance de aparecer uma diferença desse tamanho se a mudança não fizesse nada - então um valor alto, que nem o 0.81 ali, quer dizer “isso pode facilmente ser nada”. Um resultado é chamado de significativo quando essa probabilidade fica pequena o bastante pra você apostar contra, e mais pra frente no post você vai ver as linhas significativas marcadas com estrelas. E geomean é a linha de resumo: uma média entre as vinte configurações, feita de um jeito que um número espetacular não carrega o total sozinho.

Aqui, zero resultados são significativos, que é o que binários idênticos deviam produzir. A variação inteira, de -1,52% a +1,96%, é a máquina conversando com ela mesma.

Então: 2%. Abaixo disso, não estou autorizado a chamar de ganho pelo resto deste post.

“O primeiro princípio é que você não deve se enganar - e você é a pessoa mais fácil de enganar.” O Feynman estava falando de física, mas o noise floor é essa frase virada em comando de shell.

3. Benchmark e profiling respondem perguntas diferentes

O Berkopec conta a melhor versão dessa história. Ele tinha feito benchmark de uma mudança, achado o shuffle 12x mais rápido que sort_by { rand }, e levou o número pro Ryan Davis, autor do minitest. A resposta:

“você fez benchmark, mas fez profiling?”

Um benchmark te dá um número por configuração. Ele te diz sem pestanejar que sua mudança deixou tudo 3% mais rápido, e está completamente errado, porque 3% está dentro do ruído da máquina onde você rodou. E ele não tem nada a dizer sobre por que algo está lento: rode a suíte de sqlite inteira do Node num main limpo e você recebe vinte taxas e zero suspeitos.

Um profiler te dá atribuição. O que ele não te dá é se consertar aquilo vale alguma coisa, porque profile não tem grupo de controle.

O profiler aponta o suspeito, o benchmark condena. Nessa ordem.

4. Faça o profile, daí leia a árvore de chamadas

O sample já vem no macOS. Duas coisas pegam todo mundo na primeira vez: ele se anexa a um processo que já está rodando, nunca sobe um, e ele casa nome parcial, então sample node com um language server aberto pode acabar perfilando outra coisa completamente. Use o PID. E rode dsymutil out/Release/node antes, ou você recebe endereços crus em vez de símbolos.

Também não faça profile do harness de benchmark - ele mistura seed, warmup e medição num processo só. Escreva uma carga que chega num estado estável e fica lá:

const stmt = db.prepare(`SELECT ${cols} FROM foo LIMIT ${limit}`);
const run = op === 'all' ? () => stmt.all() : () => stmt.get();

for (let i = 0; i < 20000; i++) run();          // aquecimento
process.stderr.write(`READY pid=${process.pid}\n`);

const deadline = Date.now() + seconds * 1000;   // estado estável
while (Date.now() < deadline) {
  for (let i = 0; i < 1000; i++) sink = run();
}

Duas armadilhas na leitura do que volta. Os maiores símbolos da página são __psynch_cvwait, kevent e semaphore_wait_trap - threads ociosas do threadpool do libuv paradas no kernel. Não querem dizer nada. E um mesmo custo se espalha por vários nomes de símbolo, então agrupe por categoria antes de comparar magnitudes.

Aqui está o get() numa linha de quatro colunas, como fração das amostras não ociosas:

  1865   20.4%  pthread mutex
  1732   18.9%  sqlite VDBE + btree (real query work)
  1382   15.1%  V8 object construction (dictionary-mode rows)
  1067   11.7%  malloc/free
   739    8.1%  column-name interning (V8 strings)
   542    5.9%  V8 buffers (BLOB -> Uint8Array)
   411    4.5%  sqlite C API entry points
   159    1.7%  node:sqlite binding

A linha que eu quero é a quinta: column-name interning, 8.1%.

Eu já tinha um palpite sobre essa. O iterate() vinha entregando nomes de coluna cacheados há um tempo, e eu já tinha me perguntado mais de uma vez se o get() e o all() não podiam beber da mesma fonte. O que eu não tinha era motivo pra mexer. Palpite não é número, e a regra do Berkopec é que palpite não autoriza patch. Eu tenho uma pasta cheia de palpites sobre aquele arquivo e a maioria não vale nada. 8.1% foi o que tirou esse da pasta.

A linha de cima é um número maior e não é dela que esse post trata. É o mutex por conexão do SQLite, some com uma flag de compilação, e tirar ele significa escrever na mão o lock que falta. Outra investigação, outro PR, e eu ainda não sei se aquele entra - e é por isso que ele não divide post com um patch que já entrou.

Agora, 8,1% das amostras em símbolos que nem StringTable::LookupKey não diz de quem são aquelas strings, e a V8 interna string por uma dúzia de motivos. Esse é o trabalho da árvore de chamadas:

141 node::sqlite::StatementExecutionHelper::Get(...) + 396
  | 121 v8::String::NewFromUtf8(...)
  | : 88 v8::internal::Factory::InternalizeUtf8String(...)
  | : | 54 v8::internal::FactoryBase<...>::InternalizeString(...)
  | : | + 36 v8::internal::StringTable::LookupKey<...>(...)
  | : | 23 v8::internal::FactoryBase<...>::InternalizeString(...)
  | : | + 23 v8::internal::StringHasher::HashSequentialString<...>(...)
  | : 30 v8::internal::Factory::InternalizeUtf8String(...)
  | : | 30 v8::internal::Utf8DecoderBase<...>::Utf8DecoderBase(...)
 78 node::sqlite::StatementExecutionHelper::Get(...) + 372
  | 29 columnName  (in node)
  | : 13 _pthread_mutex_lock_init_slow  (in libsystem_pthread.dylib)
  | 21 columnName  (in node)
  | 18 columnName  (in node)

Dois offsets de instrução vizinhos dentro da mesma função, e são as duas metades de uma operação só. O +372 chama sqlite3_column_name(), cuja implementação no sqlite3.c é o columnName. O +396 chama String::NewFromUtf8 com kInternalized, e a V8 faz o serviço inteiro: decodifica o UTF-8, calcula o hash, procura na string table.

Tudo isso por coluna, por chamada, para um prepared statement cujos nomes de coluna não podem mudar.

Está aqui no fonte, e não tem nada errado com ele - é o jeito óbvio de escrever:

  const char* col_name = sqlite3_column_name(stmt, column);
  // ...
  return String::NewFromUtf8(
             env->isolate(), col_name, NewStringType::kInternalized)
      .As<Name>();

Ninguém lendo essa função pensa “gargalo”, porque isolada ela não é. O profiler é o que põe ela lado a lado com o sqlite3VdbeExec e mostra o preço: montar as chaves custa um pouco menos da metade do que custa rodar a query inteira.

5. Faça profile de mais de uma forma de carga

Mesmo binário, mesmo código, perfilando all() com LIMIT 100 em vez de uma linha. O column-name interning desapareceu - não diminuiu, desapareceu. Todo símbolo daquela categoria caiu abaixo do corte de 5 amostras do sample:

símbolo get() LIMIT 1 all() LIMIT 100
StringTable::LookupKey 150 -
Utf8DecoderBase 126 -
StringHasher::HashSequentialString 102 -
columnName 88 -
String::NewFromUtf8 65 -

Nada mudou no código. O custo é idêntico por chamada - o all() monta as chaves uma vez e reusa pras 100 linhas, então o que resta desaparece debaixo de todo o resto. Enquanto isso o mutex quase não se mexeu, 20,4% pra 19,0%, porque esse é pago por valor.

É custo de frete. Pede um livro na internet e o frete é metade do que você paga. Pede cem e ele é erro de arredondamento na nota - frete idêntico, nas duas vezes. Se você só olhar a nota dos cem livros, vai concluir que frete é grátis.

Ou seja: um custo pago uma vez por chamada desaparece quando você perfila muitas linhas, e um custo pago uma vez por linha é invisível quando você perfila uma. A carga mais pesada é a natural pra perfilar, e é a que eu teria escolhido se fosse escolher uma. Faça uma das suas cargas ser pequena.

6. Leia o fonte do que você está mudando

Então, de volta ao palpite. O cache já estava no arquivo, no StatementSync, chaveado pelo contador de re-prepare do SQLite pra invalidar corretamente quando uma mudança de schema força um re-prepare silencioso:

std::vector<v8::Global<v8::Name>> cached_column_names_;
int cached_column_names_reprepare_count_ = -1;

Esse contador é a parte que importa. É o motivo de mandar mais dois callers pro cache ser seguro em vez de esperto - a invalidação já estava escrita e já estava rodando em produção sob o iterate().

Daí a mudança não escreve cache nenhum. Ela apaga dois loops:

Antes, no get() e no all()

row_keys.reserve(num_cols);
for (int i = 0; i < num_cols; ++i) {
  Local<Name> key;
  if (!ColumnNameToName(env, stmt, i)
           .ToLocal(&key)) {
    return MaybeLocal<Value>();
  }
  row_keys.emplace_back(key);
}

Depois, o mesmo que o iterate() faz

if (!statement->GetCachedColumnNames(
        &row_keys)) {
  return MaybeLocal<Value>();
}

Nove linhas viram quatro, em dois lugares. O patch inteiro é 31 inserções contra 66 remoções: ele tira linhas do arquivo e deixa as leituras mais rápidas.

E nenhum profiler ia me entregar isso. Ele apontou a função; ler o arquivo é o que transformou “isso é caro” em “isso é caro e evitável, com código que já está aqui e em que já se confia”.

7. Use o benchmark pra condenar

Recompila, e mede contra o binário da baseline do passo 1:

improvement  p-value    old rate    new rate   config
  -0.97%     0.3266      26.7k      26.4k  select-all 'SELECT * FROM foo LIMIT 100'
+   0.92%     0.1861      14.8k      15.0k  select-all 'SELECT text_8kb_column FROM foo_large LIMIT 100'
+   2.57% *   0.0245      70.0k      71.8k  select-all 'SELECT text_column FROM foo LIMIT 100'
+   8.62% *** 0.0005      3.22M      3.50M  select-get 'SELECT 1'
+  12.88% *** 0.0000      1.40M      1.58M  select-all 'SELECT * FROM foo LIMIT 1'
+  15.51% *** 0.0000      1.48M      1.71M  select-get 'SELECT text,int,real,blob FROM foo LIMIT 1'
+  17.03% *** 0.0000      1.48M      1.73M  select-get 'SELECT * FROM foo LIMIT 1'
+  17.71% *** 0.0000      1.38M      1.63M  select-all 'SELECT text,int,real,blob FROM foo LIMIT 1'

configs: 20  significant: 14
geomean speedup (all configs): 8.25%

Ordenada, a lista parte em duas: tudo com três estrelas é LIMIT 1, tudo perto de zero é LIMIT 100. E o select-all aparece nos dois grupos, então a divisão não é get() contra all() - é quantas linhas voltam por chamada.

Esse é o profile do passo 5, confirmado por medição. Que é o motivo de verdade pra rodar os dois: o benchmark não disse só “mais rápido”, ele disse mais rápido na forma exata que o mecanismo prevê. Quando os dois concordam, você entende a sua própria mudança.

A linha de -0,97% não é regressão, aliás. Sem estrela, p-value 0,33, noise floor de ±2%. É zero, e o passo 2 é o que me deixa afirmar isso sem discussão.

Uma ideia morreu aqui, e era a que eu mais gostava. A maior categoria no profile de 100 linhas é construção de objeto na V8, com 22,5%, e o DictionaryTemplate existe pra resolver isso - descreve a forma da linha uma vez, compartilha um mapa entre as instâncias. As leituras ficaram 23-29% mais rápidas e a construção ficou 11-20% mais lenta, porque as linhas do node:sqlite têm protótipo nulo, o DictionaryTemplate te entrega Object.prototype, e o SetPrototypeV2 por linha custa mais do que o mapa compartilhado economiza. Descartada. Hipótese morrendo numa medição é o método funcionando.

O método inteiro

  1. Conserte a baseline e copie o binário pra fora, pra não comparar um build contra ele mesmo.
  2. Ache o noise floor rodando o benchmark da baseline contra ela mesma. O meu foi ±2%. Sem isso, todo número aqui é opinião.
  3. Faça profile antes de mexer em qualquer coisa. Agrupe por custo, descarte as threads ociosas, e use a árvore de chamadas pra descobrir de quem é o trabalho do símbolo quente.
  4. Perfile mais de uma forma de carga, e faça uma delas pequena. Os 8,1% que eu consertei eram invisíveis no profile de 100 linhas.
  5. Leia o fonte. O cache que eu “adicionei” já existia.
  6. Use o benchmark pra condenar, e confira a forma do ganho contra o mecanismo que você alegou.

A ordem importa: cada passo está ali pra manter o próximo honesto. E o passo 3 é o que eu entregaria pra quem está começando: eu podia ter lido o node_sqlite.cc por uma semana sem desconfiar daquelas quatro strings, e rodado a suíte de benchmark cem vezes sem ela dizer uma palavra sobre elas.

Por hoje é só.