Reconhecendo N+1 no log do Rails

Onde Querying: includes e joins parou

Querying: includes e joins passou sete aulas corrigindo N+1. .includes, .preload, .eager_load e .strict_loading transformam um acesso preguiçoso a uma associação numa consulta extra, ou num erro barulhento, em vez de uma consulta por linha. As sete aulas supunham que você já sabia que a página tinha o problema. Este curso responde à pergunta que vem antes: como descobrir que algumas centenas de consultas quase idênticas acabaram de rodar em vez de duas, antes que um usuário reclame que a página ficou lenta?

A resposta começa pela ferramenta mais simples que existe: o log que este app já escreve em toda requisição.

Uma rajada do log deste app

Imagine uma versão ingênua da lista de cursos do roadmap, sem a correção que o Catalog::ListCoursesQuery traz, que chama course.lessons.count dentro de um loop por todo curso ativo. Rodá-la no catálogo deste app e olhar o log/development.log dá isto:

  Catalog::Lesson Count (9.2ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5070 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.2ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 4933 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 4947 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5198 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5199 /*application='NewbieOnRails'*/
  ...
  Catalog::Lesson Count (0.1ms)  SELECT COUNT(*) FROM "lessons" WHERE "lessons"."course_id" = 5168 /*application='NewbieOnRails'*/
  Catalog::Lesson Count (3.3ms)  SELECT COUNT(*) AS "count_all", "lessons"."course_id" AS "lessons_course_id" FROM "lessons" GROUP BY "lessons"."course_id" /*application='NewbieOnRails'*/

Só o meio da rajada foi cortado. Há uma linha Catalog::Lesson Count por curso ativo, algumas centenas delas, todas iguais menos o número depois de course_id = . No fim há uma linha diferente: uma consulta com GROUP BY que responde à mesma pergunta, o número de aulas de cada curso, de uma vez.

Essa última linha é o que o Catalog::ListCoursesQuery, o query object que este app já usa, roda:

# app/queries/catalog/list_courses_query.rb
lesson_counts = ::Catalog::Lesson.group(:course_id).count

Uma chamada, uma consulta e um Hash de {course_id => count} que a view consulta para cada card. A rajada acima é o que a mesma página registraria se essa linha fosse trocada por course.lessons.count dentro do .each. A página teria a mesma cara, mas rodaria uma consulta por curso mais uma, em vez de 2.

O que torna uma rajada reconhecível

Três coisas separam uma rajada de N+1 de uma página só movimentada.

Um rótulo repetido. Toda linha acima diz Catalog::Lesson Count, o nome que o ActiveRecord dá a esse formato de consulta: o nome do model mais o tipo de consulta (Load, Count, Exists?). Um rótulo aparecendo dezenas de vezes seguidas é o primeiro sinal. Uma página que mexe em muitas tabelas registra muitos rótulos diferentes, e não o mesmo sem parar.

Tudo é igual, menos um literal. Tire o número depois de course_id = de cada linha acima e as consultas ficam iguais. Esse único valor que muda, quase sempre um id, mostra que é a mesma chamada Ruby rodando uma vez por linha de uma coleção externa, e não centenas de perguntas diferentes.

A quantidade segue o tamanho de uma coleção, e não é constante. Uma linha por curso ativo é a própria definição de N+1. Uma consulta busca N linhas (o "+1", aqui Catalog::Course.active, que rodou antes da rajada visível), e depois rodam mais N consultas, uma por linha.

Duas linhas de config que tornam este log legível

O config/environments/development.rb deste app liga duas opções relevantes. Elas já estavam lá antes desta aula:

config.active_record.verbose_query_logs = true
config.active_record.query_log_tags_enabled = true

query_log_tags_enabled é o motivo de toda linha acima terminar num comentário SQL, /*application='NewbieOnRails'*/. Numa requisição do navegador, o comentário também inclui o controller e a action, como /*action='index',application='NewbieOnRails',controller='courses'*/. verbose_query_logs vai além. Numa consulta disparada por uma requisição HTTP, ele imprime uma segunda linha embaixo da consulta com o arquivo e a linha que a emitiu. Uma consulta rodada de um script bin/rails runner não ganha essa linha. Aqui está um par capturado numa versão anterior da página do roadmap:

  SolidCache::Entry Load (0.1ms)  SELECT "solid_cache_entries"."key", "solid_cache_entries"."value" FROM "solid_cache_entries" WHERE "solid_cache_entries"."key_hash" IN (3575527472517797304) /*action='index',application='NewbieOnRails',controller='courses'*/
  ↳ app/views/catalog/courses/_course_card.html.erb:3

Esse par não é um bug, e vale olhar com calma. Na época, a linha 3 de _course_card.html.erb era um bloco cache, o helper de cache de fragmentos do Rails, apoiado no config.cache_store = :solid_cache_store deste app. Cada card lia a própria entrada de cache, então um carregamento de página registrava uma série de consultas SolidCache::Entry Load. Isso tem o formato de N+1 (um rótulo repetido, um valor que muda, uma quantidade que segue uma coleção) sem o custo, porque uma leitura de cache não é problema a corrigir. Hoje os cards são renderizados como uma coleção em cache (cached: em index.html.erb), que busca as chaves de cada grupo com um read_multi, então a série é menor. Só o formato do log não distingue um N+1 de um cache de fragmentos que funciona. Ele diz onde olhar: a linha ↳ aponta a linha a ler, e ler essa linha é o que diz se há problema.

Pontos-chave

• A assinatura de N+1 num log: um rótulo de consulta repetido muitas vezes, igual exceto por um literal que muda (quase sempre um id), com a quantidade seguindo o tamanho de uma coleção externa.
• O Catalog::ListCoursesQuery deste app evita esse formato com uma linha, Catalog::Lesson.group(:course_id).count, que troca uma consulta por curso por uma única consulta agrupada.
• verbose_query_logs, ligado no development.rb deste app, imprime uma anotação ↳ arquivo:linha embaixo de cada consulta disparada por uma requisição. Consultas rodadas de bin/rails runner não ganham essa linha.
• Uma rajada de consultas repetidas é um sinal forte, não uma prova: leituras de cache de fragmentos produzem o mesmo formato e não são bug. Por isso as próximas aulas montam ferramentas mais precisas do que ler um log no olho.