Chasser les requêtes N+1 avec Bullet

Aujourd’hui nous allons parler des requêtes N+1 dans une application Rails : vous savez ces lignes quasiment identiques, qui s’ajoutent de manière exponentielle aux logs, dès lors que l’on appelle les enfants d’un objet à l’intérieur d’une boucle.

Lorsque l’on traite les données relatives à un objet, ActiveRecord fait une requête en base de façon transparente au moment où il a besoin de données enfants (lazy loading). Le syndrome de requête N+1 résulte en une augmentation incontrôlée de ces requêtes, ce qui a pour conséquence de ralentir l’application. Et c’est en consultant les journaux de Rails, que l’on constate ce symptôme.

C’est ici qu’intervient Bullet, qui va générer des messages d’avertissement lorsque des requêtes N+1 sont observées et nous faire son rapport.

Il sera ainsi plus facile de détecter le code fautif, pour limiter ou résorber totalement ce syndrome via des bonnes pratiques que je m’apprête à vous présenter.

Les requêtes N+1 et comment les éviter

Le lazy loading des données est activé par défaut dans Rails, ce qui évite de charger des données enfants non nécessaires. Mais c’est aussi la raison pour laquelle, lors de l’accès aux attributs enfants dans une boucle, des requêtes N+1 sont émises.

Prenons un cas simple pour illustrer ces propos :

class Article < ActiveRecord::Base
  belongs_to :author
end

class Author < ActiveRecord::Base
  has_many :articles
end

class ArticlesController < ApplicationController
  def index
    @articles = Article.all
  end
end

# app/views/invoices/index.html.erb
<% @articles.each do |article| %>
  <%= @article.author.name %>
  <%= @article.text %>
<% end %>

Cela va produire les fameuses requêtes N+1 à la consultation de la page :

Article Load (0.7ms) SELECT 'articles'.* FROM 'articles'
Author Load (0.4ms) SELECT 'authors'.* FROM 'authors' WHERE 'authors'.'id' = ?
                    ORDER BY 'authors'.'id' ASC LIMIT 1 [["id", 1]]
Author Load (0.3ms) SELECT 'authors'.* FROM 'authors' WHERE 'authors'.'id' = ?
                    ORDER BY 'authors'.'id' ASC LIMIT 1 [["id", 2]]
Author Load (0.4ms) SELECT 'authors'.* FROM 'authors' WHERE 'authors'.'id' = ?
                    ORDER BY 'authors'.'id' ASC LIMIT 1 [["id", 3]]
Author Load (0.3ms) SELECT 'authors'.* FROM 'authors' WHERE 'authors'.'id' = ?
                    ORDER BY 'authors'.'id' ASC LIMIT 1 [["id", 4]]
…

Nous allons avoir ici autant de requêtes que d’articles. Si nous avons des milliers d’articles, je vous laisse imaginer le temps de réponse de l’application sur cette page.

Heureusement, il suffit d’ajouter une instruction includes (pour les auteurs) à notre demande d’articles, pour résoudre le problème :

class ArticlesController < ApplicationController
  def index
    @articles = Article.includes(:author).all
  end
end

Nous obtenons ceci :

Article Load (0.7ms) SELECT 'articles'.* FROM 'articles'
Author Load (0.11ms) SELECT 'authors'.* FROM 'authors' WHERE 'authors'.'id' IN (1,2,3,4,…)

Ce qui est beaucoup mieux et moins couteux.

Une deuxième solution serait de mettre en cache chaque objet parcouru par la boucle :

# app/views/invoices/index.html.erb
<% @articles.each do |article| %>
  <% cache article %>
    <%= @article.author.name %>
    <%= @article.text %>
  <% end %>
<% end %>

Ce qui donnerait (après la première mise en cache) :

Started GET "/articles" for 0:0:0:0:0:0:0:1 at 2018-03-19 14:27:36 +0100
Processing by ArticlesController#index as HTML
  Rendering articles/index.html.erb within layouts/application
  Article Load (0.7ms) SELECT 'articles'.* FROM 'articles'
  Read fragment views/articles/8158d13c8f5c84d1581e6bca35312319 (0.1ms)
  Read fragment views/articles/f244d972216df100e804cecca2e53ed1 (0.1ms)
  Read fragment views/articles/a9sy43nqs0ye7gnxbb51ym5rkgggx3ld (0.1ms)
  Read fragment views/articles/bz5ytopxsj9rfe3irtwyvtbdv8z8fjo4 (0.1ms)
…

Dans ce cas-là, l’instruction includes n’est plus utile, puisque les données sont désormais en cache. Cela aurait même l’effet inverse de celui recherché, car des requêtes inutiles seraient générées.

Pour voir le fragment caching en action en développement, il faut aussi penser à activer cette option :

# config/development.rb
config.action_controller.perform_caching = true

Il est donc relativement simple d’éviter ces requêtes N+1, mais toujours est-il que cela implique une vigilance régulière, ainsi qu’un contrôle des logs émis.

Comment Bullet peut nous aider

Bullet va pouvoir nous aider à être vigilants, car lui ne faillira pas. Bullet inspecte les logs à notre place et fait la traque aux requêtes N+1, pour ensuite nous faire son rapport. Ce rapport peut nous être fourni de différentes manières, sur différents supports, il suffit de le paramétrer en fonction de nos préférences.

Voici à quoi peut ressembler le rapport en question :

2018-03-15 15:45:58[WARN] user: numa
/articles
N+1 Query detected
  Article => [:author]
  Add to your finder: :includes => [:author]
N+1 Query method call stack
  /app/controllers/articles_controller.rb:3:in `index'

C’est très précis ! Il nous suffit d’aller à l’endroit indiqué et d’appliquer le changement conseillé.

Par ailleurs, Bullet conseille aussi de mettre en place des counter_cache, là ou ça lui semble nécessaire. Et si nous avons eu un excès de zèle et avons appliqué des includes non nécessaire, Bullet le détecte également et l’inclut dans son rapport.

Installer et paramétrer Bullet

Cela commence par :

group :development do
  gem 'bullet'
end

Puis un bundle install comme à l’accoutumée.

Il faut ensuite activer Bullet et le paramétrer suivant nos cas d’utilisation :

# config/environments/development.rb
config.after_initialize do
   Bullet.enable = true # active Bullet
   Bullet.bullet_logger = true # génère des logs dans log/bullet.log
   Bullet.console = true # génère des warnings dans la console du navigateur
   Bullet.add_footer = true # ouvre un encart en bas à gauche de la page consultée
end

J’ai mis ici quelques options simples et utiles au quotidien, mais il y en a d’autres qui peuvent être plus indiquées, en fonction de vos préférences et outils.

Il est possible de profiter des tests pour détecter ces problèmes de requêtage, en les faisant échouer lorsque des anomalies sont observées. Pour faire cela, Bullet peut émettre une erreur, ce qui aura l’effet escompté :

# config/environments/test.rb
config.after_initialize do
  Bullet.enable = true # active Bullet
  Bullet.bullet_logger = true # génère des logs dans log/bullet.log
  Bullet.raise = true # émet une erreur lors de la rencontre d'une anomalie de requêtage
end

Conclusion

Bullet est donc un outil nous permettant de s’alléger l’esprit. Grâce à lui, les requêtes N+1 viennent à nous pendant la phase de développement. Cela fait donc gagner en temps et en sérénité.

On peut exécuter 1 requête pour avoir 1000 résultats, mais on ne peut pas exécuter 1000 requêtes…

L’équipe Synbioz.
Libres d’être ensemble.