Rails 7.2をちょこっと試す（query and cached ログ編）

はじめに

rails 7.2beta2 がリリースされたので、ちょっと試してみました。

rails 7.2 では、Rails のログに、実行されたSQLの数が表示されるようになりました。

ログの確認

Rails 7.1 では、以下のようなログが出力されます。
Rails 7.2 で変るのは、最後の Completed の行の ActiveRecord: 2.2ms の部分です。

Started GET "/books" for 172.25.0.1 at 2024-06-09 08:27:47 +0900
Cannot render console from 172.25.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1
  ActiveRecord::SchemaMigration Load (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by BooksController#index as HTML
  Rendering layout layouts/application.html.erb
  Rendering books/index.html.erb within layouts/application
  Book Load (0.3ms)  SELECT "books".* FROM "books"
  ↳ app/views/books/index.html.erb:6
  Rendered books/index.html.erb within layouts/application (Duration: 21.2ms | Allocations: 4137)
  Rendered layout layouts/application.html.erb (Duration: 110.5ms | Allocations: 37526)
Completed 200 OK in 129ms (Views: 111.8ms | ActiveRecord: 2.2ms | Allocations: 47264)

Rails 7.2

では、Rails 7.2 で試してみます。

rails new sandbox
cd sandbox
rails g scaffold Book title
bin/rails db:create db:migrate
bin/rails s

http://localhost:3000/books にアクセスすると、以下のようなログが出力されます。

最後の行が ActiveRecord: 0.1ms (1 query, 0 cached) となっているのがわかります。

Started GET "/books" for 172.26.0.1 at 2024-06-09 08:36:38 +0900
Cannot render console from 172.26.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1
Processing by BooksController#index as HTML
  Rendering layout layouts/application.html.erb
  Rendering books/index.html.erb within layouts/application
  Book Load (0.2ms)  SELECT "books".* FROM "books"
  ↳ app/views/books/index.html.erb:8
  Rendered books/index.html.erb within layouts/application (Duration: 3.5ms | GC: 0.0ms)
  Rendered layout layouts/application.html.erb (Duration: 6.8ms | GC: 0.0ms)
Completed 200 OK in 10ms (Views: 8.0ms | ActiveRecord: 0.1ms (1 query, 0 cached) | GC: 0.0ms)

せっかくなので、コントローラーで複数のクエリを実行するようにしてみます。

  def index
    Book.where(title: "foo").first # 追加
    @books = Book.all
  end

http://localhost:3000/books にアクセスすると、以下のようなログが出力されます。
2 queries に変わりました。

Completed 200 OK in 10ms (Views: 4.4ms | ActiveRecord: 0.2ms (2 queries, 0 cached) | GC: 0.2ms)

ついでに、cache を増やしてみます。

  def index
    Book.where(title: "foo").first
    Book.where(title: "foo").first # 追加。cached が増えるか確認
    @books = Book.all
  end

http://localhost:3000/books にアクセスすると、以下のようなログが出力されます。
3 queries, 1 cached になっているのがわかります。

Completed 200 OK in 42ms (Views: 24.7ms | ActiveRecord: 1.3ms (3 queries, 1 cached) | GC: 8.6ms)

まとめ

Rails 7.2 では、ログに実行されたSQLの数が表示されるようになりました。
パフォーマンスチューニングの際に、実行されたSQLの数を確認するのに使えそうですね。

参考

• Add queries count to template rendering instrumentation