Ruby でのバックトレース活用法

初稿：2010-10-07

はじめに
バックトレース入門
現在の Ruby におけるバックトレース関連の問題点と解決案
- バックトレースを扱う際の問題点と解決案
- ライブラリ「called_from」
まとめ

著者: 桑田誠

はじめに

バックトレースとは、大雑把にいうと「メソッドの呼び出し状況を表したデータ」です。バックトレースを使うと、以下のようなことができます。

メソッドがどこから呼び出されたかを調べる
例外が発生された場所を偽装する

本稿では、あまり使い道はないけど知っていると人生で 2 回ぐらい嬉しいことがありそうなこのバックトレースについて、初心者向けに説明を行います。またバックトレースについて Ruby 本体で改善してほしい点についても説明します。

バックトレース入門

バックトレースとは

バックトレースとは、大雑把にいうと「メソッドの呼び出し状況を表したデータ」です。例外が発生したときにソースコードのファイル名や行番号が表示されますが、あれがバックトレースの情報です。

たとえば次の例をご覧下さい。この例では f1() → f2() → f3() のようにメソッドを呼び出し、最後の f3() で NameError 例外が発生します。

ex1.rb

def f1()
  f2()
end

def f2()
  f3()
end

def f3()
  foobar    # NameError 例外が発生
end

f1()

これを実行すると、ソースコードのファイル名と行番号が表示されています。これがバックトレース情報であり、メソッドの呼び出し状況を表しています。

実行結果

$ ruby ex1.rb
ex1.rb:10:in `f3': undefined local variable or method `foobar' for main:Object (NameError)
        from ex1.rb:6:in `f2'
        from ex1.rb:2:in `f1'
        from ex1.rb:13

バックトレースを取り出すには、Ruby ではグローバル関数 caller() を使います。引数には呼び出しの深さを指定することができ、「0」なら現在の場所から、「1」なら呼び出し元から、「2」なら呼び出し元の呼び出し元から、… という意味になります。デフォルトは「1」です。

ex2.rb

def f1()
  f2()
end

def f2()
  f3()
end

def f3()
  p caller()    #=> ["ex2.rb:6:in `f2'", "ex2.rb:2:in `f1'", "ex2.rb:15"]
  #p caller(0)  #=> ["ex2.rb:11:in `f3'", "ex2.rb:6:in `f2'", "ex2.rb:2:in `f1'", "ex2.rb:15"]
  #p caller(2)  #=> ["ex2.rb:2:in `f1'", "ex2.rb:15"]
end

f1()

実行結果

$ ruby ex2.rb
["ex2.rb:6:in `f2'", "ex2.rb:2:in `f1'", "ex2.rb:15"]

実行結果を見るとわかりますが、caller() の戻り値は文字列を要素とする配列であり、要素の文字列にファイル名と行番号が含まれています。これが Ruby におけるバックトレースになります。

メソッドがどこから呼び出されたかを調べる

バックトレースを使うと、メソッドがどこから呼び出されたかを調べることができます。

メソッドがどこから呼び出されたかを調べたい場面というのはどういうときでしょうか。筆者は、ログを取る場合やデバッグ用メッセージを出力する場合に、メソッドの呼び出し元を調べます。

たとえば次の例では、ファイル名と行番号を自動的に出力してくれる、デバッグ出力用のヘルパー関数 debug_puts() を定義しています。

ex3.rb

def debug_puts(message)
  caller()[0] =~ /(.*?):(\d+)/   # 呼び出し元を調べる
  filename, linenum = $1, $2
  $stderr.puts "[DEBUG] #{filename}:#{linenum}"
  $stderr.puts "[DEBUG] #{message}"
end

x = "foo"
debug_puts "x=#{x.inspect}"
x = "bar"
debug_puts "x=#{x.inspect}"

これを実行すると、デバッグ用のメッセージだけでなく、debug_puts() を使っている場所も同時に表示されることがわかります。実際使ってみると、これは大変便利です。

実行結果

$ ruby ex3.rb
[DEBUG] ex3.rb:9
[DEBUG] x="foo"
[DEBUG] ex3.rb:11
[DEBUG] x="bar"

また拙作のデータベースライブラリでは、SQL にエラーがあった場合、caller() を使ってその SQL を指定した場所をログに出力しています。これにより、SQL エラーがあったときに原因を突き止めやすくなりました。

例外の発生場所を偽装する

バックトレース情報は、例外オブジェクトにも自動的に格納されます。例外オブジェクトには、次のようなメソッドが用意されています。

Exception#backtrace() : 例外オブジェクトからバックトレースを取り出す
Exception#set_backtrace(arg) : 例外オブジェクトにバックトレースを設定する

これらを使うと、例外の発生箇所を偽装することができます。次の例では、本当は 8 行目で発生している例外を、あたかも 12 行目で発生したかのように偽装しています。

ex4.rb

class AssertionError < StandardError
end

def _assert expr
  return if expr
  ex = AssertionError.new("assertion failed")
  ex.set_backtrace(caller())
  raise ex  # 本当はここで例外が発生してるけど
end

def main
  _assert 1+1 == 3   # あたかもここで発生したかの
end                  # ように偽装している

main()

実行例: 12 行目で例外が発生したかのように見える

$ ruby ex4.rb
ex4.rb:12:in `main': assertion failed (AssertionError)
        from ex4.rb:15

例外の発生場所を偽装するのは、何らかのパーサを作っているときにもよくやります。たとえば自分で JSON パーサを作成していて、JSON ファイルのシンタックスエラーを見つけたとします。この場合、単に raise JsonSyntaxError.new としてもいいですが、あたかも JSON ファイル中で例外が発生したかのように偽装することが考えられます。

現在の Ruby におけるバックトレース関連の問題点と解決案

バックトレースを扱う際の問題点と解決案

筆者は、現在の Ruby にはバックトレース関連で 2 つの問題点があると思っています。

1 つ目は、バックトレース内でファイル名や行番号がひとつの文字列に埋め込まれている点です。

caller()    #=> ["ex2.rb:6:in `f2'", "ex2.rb:2:in `f1'", "ex2.rb:15"]

このせいで、ファイル名や行番号を取り出すのにいちいち正規表現を使って切り出さなければならず、手間がかかるだけでなく結構な動作コストがかかってしまいます。

caller().each do |str|
  str =~ /(.*?):(\d+)/
  filename, linenum = $1, $2
end

できれば、これらを分離したまま返すようなオプションが用意されてほしいと思います。

## たとえばこんな感じ
caller!()    #=> [["ex2.rb",6,"f2"], ["ex2.rb",2,"f1"], ["ex2.rb",15,nil]]

2 つ目は、呼び出し元を調べたいだけのときにバックトレースを取り出すのは重すぎるということです。たとえばログを記録するときにメソッドの呼び出し元もログに記録したい場合、そのたびにバックトレースを取り出していたのではあまりに動作コストがかかりすぎます。

def exec_sql(sql)
  str = caller()[0]   # 呼び出し元を調べたいだけなのに、動作コストが高すぎる
  logger.info("#{str}: sql=#{sql}")
  Adapter.exec(sql)
end

できれば caller() の引数として、開始点の深さだけでなくバックトレースの長さも指定できればと思います。こうするとバックトレース全体を取り出す必要がなくなり、動作コストを大幅に減少できます。

depth = 1
length = 1
p caller(depth, length)   #=> [["ex2.rb",6,"f2"]]

以上が、筆者が Ruby のバックトレースについて思っている問題点とその解決案でした。

ライブラリ「called_from」

最後に、筆者が作成した「called_from」というライブラリを紹介します。これは上で説明した caller() の問題点を解決するためのライブラリです。

インストールは gem を使って行います。なお現在のところ 1.8 でのみ動作確認しています。

$ gem install called_from

使い方は次のようになります。

require 'called_from'

## 呼び出し元を調べる
filename, linenum, function = called_from(1)

called_from を使わない場合のコードは以下のようになります。called_from を利用することで可読性が向上していることがよく分かると思います。

## 呼び出し元を調べる
caller(1)[0] =~ /(.*?):(\d+)(:in `(.*)')?/
filename, linenum, function = $1, $2, $3

また、called_from はバックトレース全体を取り出さないので、動作が非常に高速です。以下は README.txt に載ってあるベンチマーク結果です (ベンチマークも called_from のソースに含まれています)。

*** n=100000
                             user     system      total        real
caller()[0]              7.920000   0.400000   8.320000 (  8.985343)
caller()[0]   (*1)       8.590000   0.420000   9.010000 (  9.804065)
called_from()            0.240000   0.010000   0.250000 (  0.257151)
called_from() (*2)       0.250000   0.000000   0.250000 (  0.268603)


(*1) retrieve filename and line number using pattern match (=~ /:(\d+)/)
(*2) retrieve filename and line number

called_from は超マイナーなライブラリですが、Rails コアチームのメンバーである Jeremy Kemper から「great extension!」というお褒めの言葉をいただいたので、筆者としては満足してます。

まとめ

本稿では、初心者向けにバックトレースについて説明しました。バックトレースを使うと、メソッドの呼び出し元を調べたり、例外の発生箇所を偽装することができます。また現在の Ruby におけるバックトレース関連の問題点とその解決策を紹介し、そのためのライブラリである called_from を紹介しました。

バックトレースはあまり触る機会がないとは思いますが、こういう機能があるということを頭の片隅にでも覚えておいていただくと、何かの機会に役立つかもしれません。

バックナンバー