perform_nowだとquery cacheが効かない?が、perform_laterだと効く

会社のslackの分報でrailsでsqlの結果をメモ化するにはどんな方法がいいんだ？

みたいなことを呟いたら、そもそもquery cacheが効くんじゃない？と言われましたが、

https://railsguides.jp/caching_with_rails.html#sql%E3%82%AD%E3%83%A3%E3%83%83%E3%82%B7%E3%83%A5

railsガイドでも↑のような書き方で、Active Jobには関係ないのかとずっと思ってました。

ただ、perform_laterだとquery cacheが効くという助言をいただいたので、検証して見ることに。

https://github.com/na8esin/rails7_mysql_docker/tree/21630b376013d0059daab1553760bb15f4eb636b

rails7 + aws-sdk-rails + mysql8 + localstack(sqs)の組み合わせです。

まず、jobのコードはこんな感じです

class BookJob < ApplicationJob
  queue_as :default

  def perform
    Book.find(1)

    Book.find(1)
  end
end

perform_nowの結果です。

irb(main):002:0> BookJob.perform_now
Performing BookJob (Job ID: de1e614d-42d8-4568-9766-f38218dfac4c) from AmazonSqs(default) enqueued at 
  Book Load (3.9ms)  SELECT `books`.* FROM `books` WHERE `books`.`id` = 1 LIMIT 1
  Book Load (0.2ms)  SELECT `books`.* FROM `books` WHERE `books`.`id` = 1 LIMIT 1
Performed BookJob (Job ID: de1e614d-42d8-4568-9766-f38218dfac4c) from AmazonSqs(default) in 81.96ms
=> 
#<Book:0x0000ffff83294108
 id: 1,
 status: "available",
 created_at: Tue, 12 Sep 2023 10:05:54.264743000 UTC +00:00,
 updated_at: Tue, 12 Sep 2023 10:05:54.264743000 UTC +00:00>

ログにはCACHEとはでてないですね。でも2回目は3.7msも早い。本当に効いてないのか？ちょっと不安になったので、タイトルにも?がついてます。

次は perform_laterです。

まずは、rails cでBookJob.perform_laterを実行しておきます。

そのあと、rails cを抜けてから、RAILS_ENV=development bundle exec aws_sqs_active_job --queue defaultを実行して、少々待つと下記のようなログがファイルに出力されます

[ActiveJob] [BookJob] [b8cd5b55-1d44-420d-bfe5-89b7c67be8d5] Performing BookJob (Job ID: b8cd5b55-1d44-420d-bfe5-89b7c67be8d5) from AmazonSqs(default) enqueued at 2023-09-14T10:28:21Z
[ActiveJob] [BookJob] [b8cd5b55-1d44-420d-bfe5-89b7c67be8d5]   [1m[36mBook Load (0.1ms)[0m  [1m[34mSELECT `books`.* FROM `books` WHERE `books`.`id` = 1 LIMIT 1[0m
[ActiveJob] [BookJob] [b8cd5b55-1d44-420d-bfe5-89b7c67be8d5]   ↳ app/jobs/book_job.rb:8:in `perform'
[ActiveJob] [BookJob] [b8cd5b55-1d44-420d-bfe5-89b7c67be8d5]   [1m[36mCACHE Book Load (0.0ms)[0m  [1m[34mSELECT `books`.* FROM `books` WHERE `books`.`id` = 1 LIMIT 1[0m
[ActiveJob] [BookJob] [b8cd5b55-1d44-420d-bfe5-89b7c67be8d5]   ↳ app/jobs/book_job.rb:10:in `perform'
[ActiveJob] [BookJob] [b8cd5b55-1d44-420d-bfe5-89b7c67be8d5] Performed BookJob (Job ID: b8cd5b55-1d44-420d-bfe5-89b7c67be8d5) from AmazonSqs(default) in 20.99ms
[Aws::SQS::Client 200 0.009193 0 retries] delete_message(queue_url:"http://localstack:4566/000000000000/my-queue",receipt_handle:"MWM5Mzg3MjktZmM2Yy00YzcyLTgxMDktZWMwMDNlZGFmMTUwIGFybjphd3M6c3FzOmFwLW5vcnRoZWFzdC0xOjAwMDAwMDAwMDAwMDpteS1xdWV1ZSBhNGRlMWQyMy1lOWZiLTQzZWUtYjcxYS01MzE1Nzc0OGRjMTkgMTY5NDY4NzMyNS44OTY2MTA1")

CACHEと出てますね。

ただ、この例だと、ログにCACHEと出ているだけなのか、本当にCACHEが効いてるのかはわかりづらいですね。

時間がある時にrails本体のソースを読んでみたいと思います。