Go to Qiita Advent Calendar 2024 Top
LoginSignup
9
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

fukuoka.ex Elixir／PhoenixAdvent Calendar 2021

Day 22
@sotashiro(創大 田代)

ActiveRecord::LogSubscriber#log_query_source（private）をElixir/Ectoに移植するぞ

Last updated at Posted at 2021-12-21

はじめに

昨日は @GKBRさんのLiveviewでお手軽オンラインゲーム開発でした！
LiveviewやHotwireといったServerエンジニアからのモダンなFrontendは、自分が普段Reactを使っている事もあってまだ試せていませんが、socket周りの興味は大きいので近々昨日の記事を参考に遊んでみたいと思います。

以下軽い自己紹介です。

普段はスタートアップでRailsを中心にインフラやらCMSやらの開発をしております。
最近の業務はRuby, MySQL, Elasticsearch, CircleCiの整備等、SREよりな業務が多いです。

エンジニアとして4年ほど経験を積み、そろそろもう一皮向けたいな、と思ってElixirを触り始めました。

今回は勉強ついでに、なにか目的が欲しく、慣れ親しんだRailsと絡めた挑戦を記事にまとめます。
CodeReadingや、localでのライブラリの開発環境を準備する辺りも経緯として記載させて頂きましたので、なにかの参考になりましたら嬉しいです。

（Elixirでのアウトプットは初めてです。よろしくお願い致します。）
※ この記事は fukuoka.ex Elixir／Phoenix Advent Calendar 2021の22日の内容となります。

ActiveRecord::LogSubscriber#log_query_source（private）とは？

    User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2
  ↳ app/controllers/users_controller.rb:70:in `index'

↑ はRailsのActiveRecordが吐いてくれているログです。イケてますね。
この ↳ app/controllers/users_controller.rb:70:in 'index'の部分の表示が ActiveRecord::LogSubscriber#log_query_sourceの挙動です。

元々は @joker1007 さんの activerecord-causeというgemを入れていて同等な機能を享受していたのですが、いつの間にかRailsにも同じようなログが表示されるようになっていました。(多分Rails 5.2？)
今回は両方の実装を参考にしていこうと思います。

ActiveRecord::LogSubscriber#log_query_sourceの実装はどうなっているか

本物はこちら

  def log_query_source
    source = extract_query_source_location(caller)
    if source
      logger.debug("  ↳ #{source}")
    end
  end

  def extract_query_source_location(locations)
    backtrace_cleaner.clean(locations.lazy).first
  end
  1. log_query_sourceをdebugログ表示時にcall
  2. log_query_source内でKernel.#callerを使ってstacktraceの一覧を抽出メソッドに渡す
  3. 抽出メソッド（extract_query_source_location） 内で backtrace_cleaner（ActiveSupport::BacktraceCleaner） を用いて不要traceを排除して、その中の先頭を表示させる

なるほど、callerが抽出の本体となっているようです。
さすがRails、ActiveSupport::BacktraceCleanerなんていうイケてるものも用意してくれちゃってるのですね。

activerecord-causeの実装はどうなっているか

  # 参照: https://github.com/joker1007/activerecord-cause/blob/master/lib/activerecord/cause.rb
  def sql(event)
    return unless logger.debug?
    # 省略
    locations = get_locations
    # 省略
    if ActiveRecord::Cause.log_mode != :all
      locations = locations.take(1)
    end
    locations.each do |loc|
       # 省略
       name = name_with_color(payload[:name])
       sql = sql_with_color(payload[:sql])
       cause = color(loc.to_s, nil, true)
       output =
         if ActiveRecord::Cause.log_with_sql
           "  #{name}  #{sql}#{binds} caused by #{cause}"
         else
           "  #{name}  caused by #{cause}"
         end
       debug(output)
    end
  end

  def get_locations
    return [] if ActiveRecord::Cause.match_paths.empty?
    caller_locations.select do |l|
      ActiveRecord::Cause.match_paths.any? do |re|
        re.match(l.absolute_path)
      end
    end
  end

  ActiveSupport.on_load(:active_record) do
  if ActiveRecord.version >= Gem::Version.new("5.1.0")
    if ActiveRecord.version >= Gem::Version.new("5.1.5")
      ActiveRecord::Cause::LogSubscriberAR515.attach_to :active_record
    else
      ActiveRecord::Cause::LogSubscriberAR503.attach_to :active_record
    end
  # 省略
  else
    # 省略
    ActiveRecord::Cause::LogSubscriberAR4.attach_to :active_record
  end
end
  1. sqlというmethodを定義してdebugモード時にログを表示。ActiveSupport.on_load(:active_record) do 辺りで各Subscriberにattachしているので、そういうcallback的なものがあるのかも？もしくはoverride？
  2. #get_locationsでフレームを取得。内部的には Kernel.#caller_locationsの中で一致したものを選択 ※ defaultのmatch_pathsは [/#{Regexp.quote(Rails.root.join("app").to_s)}/] でした。
  3. 取得したlocationsをイイカンジに加工して debug で表示

こちらではcaller_locationsを使って取得しているようでした。
どちらもシンプルに、 stacktraceを取得する => 整形する => 表示するを順次行っているだけのようです。
なんだかできちゃう気がしてきました。

実装方針

ActiveRecord::LogSubscriber#log_query_source, activerecord-causeで何をしているのかが見えてきたので、これを移植するにはどうしたらよいのか、実装方針に関してまとめます。

  1. Kernel.#caller_locationやKernel.#callerの代わりとなるようなElixirのfunctionを探す
  2. Phoenixでの QUERY logはどこに実装があるのかを探す
  3. 実装してみる
  4. local環境で動かす
  5. PRを出す

1. Kernel.#caller_locationやKernel.#callerの代わりとなるようなElixirのfunctionを探す

とりあえず Elixir caller_locations でググってみたのですが、なかなか該当のmethodは出てきませんでした。

はて、どうしたものか、
ElixirSlackのbeginnersチャンネルで質問したところ、Process.info(self(), :current_stacktrace) で取得出来るということを教えて頂きました。

iex(1)> Process.info(self(), :current_stacktrace)
{:current_stacktrace,
 [
   {Process, :info, 2, [file: 'lib/process.ex', line: 769]},
   {:erl_eval, :do_apply, 6, [file: 'erl_eval.erl', line: 685]},
   {:elixir, :recur_eval, 3, [file: 'src/elixir.erl', line: 289]},
   {:elixir, :eval_forms, 3, [file: 'src/elixir.erl', line: 274]},
   {IEx.Evaluator, :handle_eval, 3, [file: 'lib/iex/evaluator.ex', line: 310]},
   {IEx.Evaluator, :do_eval, 3, [file: 'lib/iex/evaluator.ex', line: 285]},
   {IEx.Evaluator, :eval, 3, [file: 'lib/iex/evaluator.ex', line: 274]},
   {IEx.Evaluator, :loop, 1, [file: 'lib/iex/evaluator.ex', line: 169]}
 ]}

iex上での動作確認です。なんだかこれで行けそうな気がします。

hexdocにも一応 Process.info(self(), :current_stacktrace) に関しての記述があるのですが、Kernel.SpecialForms.html#__STACKTRACE__/0 の項目で、おまけ程度の記載しかありませんでした。

 # __STACKTRACE__での取得はrescue or catchの中でのみ可能
iex(2)> try do
...(2)>   raise "Oh no!"
...(2)> rescue
...(2)>  _ ->  __STACKTRACE__
...(2)> end
[
  {:erl_eval, :do_apply, 6,
   [file: 'erl_eval.erl', line: 685, error_info: %{module: Exception}]},
  {:erl_eval, :try_clauses, 8, [file: 'erl_eval.erl', line: 919]},
  {:elixir, :recur_eval, 3, [file: 'src/elixir.erl', line: 289]},
  {:elixir, :eval_forms, 3, [file: 'src/elixir.erl', line: 274]},
  {IEx.Evaluator, :handle_eval, 3, [file: 'lib/iex/evaluator.ex', line: 310]},
  {IEx.Evaluator, :do_eval, 3, [file: 'lib/iex/evaluator.ex', line: 285]},
  {IEx.Evaluator, :eval, 3, [file: 'lib/iex/evaluator.ex', line: 274]},
  {IEx.Evaluator, :loop, 1, [file: 'lib/iex/evaluator.ex', line: 169]}
]

2. Phoenixでの QUERY logはどこに実装があるのかを探す

とりあえずPhoenixから見ていこうと思います。

  1. QUERY のようなPhoenixで表示されているログをコピペしてgrepしてみました。
    • ノーヒット
  2. 次に log でファイル名検索
    • いました
    • 読んでみると、こちらはAPIやsocketでのConnection等のログ表示のようでした。
  3. ↑ のファイル内で require Logger されており、他にlogger系の情報は出て来ませんでした。Phoenix内での調査はここまでのようです。

Ectoを探します。

  1. QUERY のようなPhoenixで表示され...
    • Getting startedのみ
  2. 次に log でファイル名検索
    • ノーヒット & 絶望
  3. Queryを流している部分を探す
    • repo/queryable.exっぽいぞ
    • adapter.execute(adapter_meta, query_meta, prepared, params, opts) executeで大体実行されるのでこれを探そう

adapterのexecute funcなので、postgrex を見る、db_connection も見る => ない

全然ない...logを場所を探してるのにconnectionの部分まで行ってるの絶対おかしい、、、
そもそもの探し方がおかしいのかもしれない、、、見落としてるかもしれないの、、、sampleのphoenixをちょい見てみよう、、、

  defp deps do
    [ 
      {:phoenix, "~> 1.6.2"},
      {:phoenix_ecto, "~> 4.4"},
      {:ecto_sql, path: "../ecto_sql"},
      {:postgrex, ">= 0.0.0"},
      # 省略
    ]
  end

あれ、phoenix_ecto と ecto_sql ってなんだ？ ectoのことdepsしてないじゃん。

phoenix_ectoとは？

Integrates Phoenix with Ecto.
It implements many protocols that makes it easier to use
Ecto with Phoenix either when working with HTML or JSON.

ectoとphoenixの間の便利なやつっぽい。
repoのstatusチェックとかもここでやってそう。logっぽい実装は見当たらず。
こいつがectoを持ってるらしい。

ログの実装は見当たらない

ecto_sqlとは？

Ecto SQL (documentation](https://hexdocs.pm/ecto_sql/index.html) provides building blocks for writing SQL adapters for Ecto.

各DBadapterでEctoを用いてSQLを使えるように切り出されたライブラリらしい。
migrationやらsandbox機能もこの子が提供している。
QUERYでgrepしたところ**ここに実装がありました** 歓喜！！！

3. ecto_sqlを拡張してみる

defp log_iodata(measurements, metadata) do # ①
  # 省略
  iodata = [
      "QUERY",
      ?\s,
      log_ok_error(result),
      log_ok_source(source),
      log_time("db", measurements, :query_time, true),
      log_time("decode", measurements, :decode_time, false),
      log_time("queue", measurements, :queue_time, false),
      log_time("idle", measurements, :idle_time, true),
      ?\n,
      query,
      ?\s,
      inspect(params, charlists: false)
    ]
    log_stacktrace_match_path = Keyword.get(opts, :log_stacktrace_match_path) || Keyword.get(opts, :otp_app) |> to_string()
    if current_stacktrace = log_current_stacktrace(log_stacktrace_match_path) do # ①-2
      ["  ↳ #{current_stacktrace |> inspect}" | [?\n |iodata]] |> Enum.reverse()
    else
      iodata
    end
  end

  defp log_current_stacktrace(stacktrace_match_path) do # ②
    case Regex.compile(stacktrace_match_path) do
      {:ok, regex_stacktrace_match_path} ->
        log_current_stacktrace(
          regex_stacktrace_match_path,
          Process.info(self(), :current_stacktrace) |> elem(1)
        )
      {:error, _} -> nil
    end
  end

  defp log_current_stacktrace(regex_stacktrace_match_path, [stacktrace | stacktraces]) do # ③
    log_current_stacktrace(regex_stacktrace_match_path, stacktraces, [elem(stacktrace, 3)])
  end

  defp log_current_stacktrace(regex_stacktrace_match_path, [stacktrace | stacktraces], stacktraces_for_log) do # ④
    log_current_stacktrace(regex_stacktrace_match_path, stacktraces, stacktraces_for_log ++ [elem(stacktrace, 3)])
  end

  defp log_current_stacktrace(regex_stacktrace_match_path, [], stacktraces_for_log) do  # ⑤
    stacktraces_for_log
    |> Enum.find(
      &(
        Enum.at(&1, 0)
        |> elem(1)
        |> to_string()
        |> String.match?(regex_stacktrace_match_path))
      )
  end
end

① : 表示するlog内容を定める log_iodata に対して処理を追加していく

①-2: log_iodata 内で log_stacktrace_match_path をデフォルト値:otp_app からの取得として設定log_current_stacktraceを呼び出す

②,③,④,⑤ : log_stacktrace_match_path を複数定義してパターンマッチによって順次データ整形を行う

4. local環境で動かす

localで動作していることを確認するために sampleで用意したphoenixアプリのecto_sqlをlocalpathからの参照にして動かしてみる

{:foobar, git: "https://github.com/elixir-lang/foobar.git", tag: "0.1"}
{:foobar, path: "path/to/foobar"}

こんな感じでlocalのライブラリをpathで指定することが出来ます。
詳しくはこちら

折角なのでEarthlyを使ってecto_sqlのリポジトリ内でTestを動かしてみる

我らが創造神が Earthly を押していたので触ってみました。

❤️ Makefile + Dockerfile = Earthfile
https://earthly.dev/

今回とは別件で自分で定義して使ってみたりもしたのですが、確かにどうせMakefile作りますし、使い回しも考えたらこれは便利かもしれません。
ちなみに僕は運良く gitinitしてるdirでearthlyを動かすと死ぬバグ（Path解決の関係）を踏んでしまったのですが、こちらは解消されています。
ただ、下手に使うとdocker-composeとearthfileとmakefileがあるようなレポジトリーになりかねないので、気をつけねばと思いました。

開発ではちょっと遅いので、適当にDBを立ててtestを追加していく

Earthlyで都度buildしてテストを確認しているのも時間が取られてしまうので、localに適当なdocker-composeを用意して、都度動かしながらテストを追加していきます。

OSSの開発やらdebugをする時はherokuで適当なadd-onと追加してDBだけ動かしたり、docker-composeで動かしたり、雑に使うことの出来るDB構築をよく行います。

こちらはよく使うdocker-composeです

version: "2"
services:
  postgresql:
    image: postgres:13.4
    container_name: postgresql
    ports:
      - 5432:5432
    volumes:
      - ./postgres/init:/docker-entrypoint-initdb.d
    environment:
      POSTGRES_USER: root
      POSTGRES_PASSWORD: root
      POSTGRES_INITDB_ARGS: "--encoding=UTF-8"
    hostname: postgres
    restart: always
    user: root
    volumes:
      - ./tmp/db:/var/lib/postgresql/data
    
  pgadmin4:
    image: dpage/pgadmin4:5.6
    container_name: pgadmin4
    ports:
      - 80:80
    volumes:
      - ./pgadmin:/var/lib/pgadmin/storage
    environment:
      PGADMIN_DEFAULT_EMAIL: root@example.com
      PGADMIN_DEFAULT_PASSWORD: root
    hostname: pgadmin4
    restart: always

5. PRを出す

長い道のりでしたが、ようやくPRを出せました。。。

Elixirのすごいところは、現在進行形で開発が盛んなため、今PRをだしてから確か 20分そこら でメンションが帰ってきました。
ちょっと実装を直したあと、機能に関してのディスカッションを行い、結果 ecto側にも実装をいれてキレイにしましょうと提案とPRを頂きました。

おわりに

今回の提案に関して雰囲気 José Valimとv0idpwnは機能自体には賛成してくれそうだったので、近々拡充されてくれないかと、とても楽しみにしです。

恐らく僕が出したPRに関しては改善点が多々あると思われるので、そこはこれからElixir力を鍛えていってカバーするしかないです。
個人的に、ここ数年はOSS頑張りたいと思っている気持ちが強いです。
CodeReadingやissues倒し等から初めていった来年のアドベントカレンダーでは取り込まれた報告が出来るように頑張っていきます。

明日は @im_miolab さんの "技術コミュニティ運営を続けていく上で意識してること（kokura.exオーガナイザーとして）" です！！ お楽しみに！

9
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
9
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?