Rubyでdebug用のloggerをお手軽低コストに仕込む

まとめ

  • production での実行記録をちゃんと残すという意味ではなく
  • (なんか変かも?)と思って調べる時やテスト実行時に役に立つ debug 用の logger の設定方法をまとめる
  • logger の block 記法と caller が便利

Loggerのblock記法はRails GuideでImpact of Logs on Performanceとして紹介されている

Debugging Rails Applications — Ruby on Rails Guides

曰く

logger.debug("")

で文字列を与えると log_level で出力を制御していても String オブジェクトを生成するコストは必ず発生してしまう。そうではなくて以下のように

logger.debug { "" }

で block を与えると debug レベルが出力対象となっている場合だけ block の中が評価される。

なるほど、これはよい。恥ずかしながらあまり log を重視していなかったので知らなかったのだけれど、実は Ruby 標準の Logger もそういう動作をする。

library logger (Ruby 2.6.0)

へーへーへー。

単にある処理を通過したことをdebug用に記録する

logger.debug {
  ["passed", caller(3, 1), "of instance #<#{self.to_s}>"].join(" ")
}

みたいなものでどこの処理を通ったかを logger に出力することができる。

instance の部分については class メソッドの場合は class に変えればよい。その場合はシンプルに

class #{self.to_s}

でよい。

caller(3, 1) が何をしているかというと、caller には以下のように呼んだ人が収まっているので、

  • `block`
  • `add` ( in `debug` )
  • `debug`
  • #{method}

この 0 から数えて3番に当たる caller が書かれたメソッド名と caller が書かれた行番号を返してくれる。

もちろんこれは構造が複雑になれば変わってしまうので、その場合は caller(0, 1) でもよい。それでもファイルの中に該当する行番号と `block in #{method}` の出力を得ることはできる。

これで何か特別な情報を付与しなくても、必要な時以外には負荷が上がらないようにしつつ処理の通過状況を logger に出力できるようになる。

cf. module function Kernel.#caller (Ruby 2.6.0)

More