Rails 7の新機能「query_log_tags」でSQLクエリに自動でコメントを追加する

はじめに

こんにちは。
GMOアドマーケティングの石丸(@thomi40)です。

以前、本ブログでRails 6.1に新しく追加された機能について紹介しました。

Rails 6.1の新機能「annotate_rendered_view_with_filenames」を試す

この記事は GMOアドマーケティング Advent Calendar 2020 8日目の記事です。はじめにこんにちは。GMOアドマーケティングの石丸(@thomi40)です。弊社では複数のプロダクトでRuby on Railsを使って開発を行っています。今回はRails 6.1で導入が予定されている「annotate_rendered_view_with_filenames」について紹介します。annotate_rendered_view_with_filenamesとは？annotate_rendered_view_with_filenames は config/environments/development.rb や config/environments/test.rb で設定できるオプションで、今後リリース予定のRuby...

GMOインターネットアドエンジニア TECH BLOG byGMO

Rails 6.1の新機能「strict_loading」でN+1を検知する

こんにちは。GMOアドマーケティングの石丸(@thomi40)です。昨年の12月にRuby on Rails 6.1の新機能の1つである「annotate_rendered_view_with_filenames」について紹介しました。今回は、同じくRuby on Rails 6.1で追加された「strict_loading」について紹介します。strict_loadingとは？strict_loadingはRails 6.1から実装された機能で、主に関連付け(Association)で発生する遅延読み込み(Lazy Loading)を防ぐ目的で追加されました。この機能を活用することで、N+1問題を防ぐことが期待できます。では実際に試してみましょう。検証用...

今回はRails 7から追加された「query_log_tags」について紹介します。

query_log_tagsとは？

query_log_tags は Active Record のオプションの一つで、設定を有効にすることでクエリのログに自動でコメントを追加することができる機能です。
元々は「Marginalia」というGemで実装されていた機能とのこと。

詳細リンク
Add Marginalia to Rails, via QueryLogs by keeran · Pull Request #42240 · rails/rails
https://github.com/rails/rails/pull/42240

早速実際の動きを見てみましょう。

検証用の環境構築

query_log_tagsはRails 7から追加された機能なので、Rails 7の環境を構築していきます。
今回もDocker環境で、Rubyは3.1.2, Railsは7.0.3を指定しました。

詳細は割愛しますが、今回用意したGemfileやDockerファイルは以下の通りです。

source 'https://rubygems.org'
gem 'rails', '7.0.3'

1 2	source 'https://rubygems.org' gem 'rails', '7.0.3'

FROM ruby:3.1.2
RUN mkdir /myapp
WORKDIR /myapp
COPY Gemfile /myapp/Gemfile
COPY Gemfile.lock /myapp/Gemfile.lock
RUN bundle install
COPY . /myapp

# Add a script to be executed every time the container starts.
COPY entrypoint.sh /usr/bin/
RUN chmod +x /usr/bin/entrypoint.sh
ENTRYPOINT ["entrypoint.sh"]
EXPOSE 3000

# Start the main process.
CMD ["rails", "server", "-b", "0.0.0.0"]

FROM ruby:3.1.2

RUN mkdir /myapp

WORKDIR /myapp

COPY Gemfile /myapp/Gemfile

COPY Gemfile.lock /myapp/Gemfile.lock

RUN bundle install

COPY . /myapp

# Add a script to be executed every time the container starts.

COPY entrypoint.sh /usr/bin/

RUN chmod +x /usr/bin/entrypoint.sh

ENTRYPOINT ["entrypoint.sh"]

EXPOSE 3000

# Start the main process.

CMD ["rails", "server", "-b", "0.0.0.0"]

以下の通り rails new や scaffold などを実行します。

$ docker-compose run web rails new . --force --no-deps --database=mysql
$ docker-compose build
$ docker-compose run --rm web bin/rails db:migrate
$ docker-compose up
$ docker-compose run web rails g scaffold user name:string email:string password_digest:string
$ docker-compose run web rails g scaffold task name:string user:references

$ docker-compose run web rails new . --force --no-deps --database=mysql

$ docker-compose build

$ docker-compose run --rm web bin/rails db:migrate

$ docker-compose up

$ docker-compose run web rails g scaffold user name:string email:string password_digest:string

$ docker-compose run web rails g scaffold task name:string user:references

query_log_tagsの実装

機能を有効化するために、config/application.rb に一行追加します。

module Myapp
  class Application < Rails::Application
    config.active_record.query_log_tags_enabled = true # 追加
  end
end

module Myapp

class Application < Rails::Application

config.active_record.query_log_tags_enabled = true # 追加

end

query_log_tags_enabled を true に設定することで、SQLのクエリログに自動でコメントが追加されます。
設定を有効にした状態で GET "/tasks" にアクセスしてみます。

controllerは以下の通り。

class TasksController < ApplicationController

  def index
    @tasks = Task.all
  end

end

class TasksController < ApplicationController

def index

@tasks = Task.all

end

以下のようにクエリの末尾にコメントが追加されました。
デフォルトでは application, controller, action が表示されるようです。
実行元のcontrollerやactionがコメントとして追加されるのは便利ですね。

Task Load (7.4ms)  SELECT `tasks`.* FROM `tasks` /*application:Myapp,controller:tasks,action:index*/

1	Task Load (7.4ms) SELECT `tasks`.* FROM `tasks` /application:Myapp,controller:tasks,action:index/

以下のように query_log_tags を指定することで、出力されるコメントを定義することも可能です。
まずは ActiveRecord::QueryLogs 側で用意されているタグを追加してみます。

config.active_record.query_log_tags = [
  :application,
  :db_host,
  :database,
  :pid
]

config.active_record.query_log_tags = [

:application,

:db_host,

:database,

:pid

]

以下が実際のコメントです。
データベースのホスト名やデータベース名がコメントとして表示されました。

Task Load (0.7ms)  SELECT `tasks`.* FROM `tasks` /*application:Myapp,db_host:db,database:myapp_development,pid:1,controller:tasks,action:index*/

1	Task Load (0.7ms) SELECT `tasks`.* FROM `tasks` /application:Myapp,db_host:db,database:myapp_development,pid:1,controller:tasks,action:index/

タグは動的, 静的問わず自由に追加することもできます。試しに以下のようにタグを指定してみます。

config.active_record.query_log_tags = [
  :application,
  {
    app_ver: 'v1',
    current_time: -> { Time.now }
  }
]

config.active_record.query_log_tags = [

:application,

{

app_ver: 'v1',

current_time: -> { Time.now }

}

]

Task Load (0.5ms)  SELECT `tasks`.* FROM `tasks` /*application:Myapp,app_ver:v1,current_time:2022-05-30 10:09:49 +0000,controller:tasks,action:index*/

1	Task Load (0.5ms) SELECT `tasks`.* FROM `tasks` /application:Myapp,app_ver:v1,current_time:2022-05-30 10:09:49 +0000,controller:tasks,action:index/

app_ver として固定の文字列, current_time として現在の時間を表示することができました。

まとめ

今回はクエリのログにコメントを追加する機能 query_log_tags について紹介しました。

今回の機能を活用することで、スロークエリの調査が効率的になったり、current_user.xxx などの定義を追加することでクエリを実行したユーザーをコメントとしてログに出力することも可能です。

オプションの詳細や実装の背景に関しては以下の参考リンクからご確認ください。