本稿は「Elixirでスタックトレースを取得する」をもとに加筆・補正し、文章を整えました。Elixirで例外が起きたときだけでなく、普通の場合も含めて、スタックトレースの情報の取り出し方についてご説明します。
例外が起きたとき
例外が起きたときには当然、詳細なログを出すためにスタックトレース情報が必要です。例外時のスタックトレースの情報は、Elixir 1.7に備わった__STACKTRACE__/0で得られます。それより前のバージョンでは、System.stacktrace/0をお使いください。ただし、v1.7以降で用いることは推奨されません(「Elixir v1.7がリリースされた」「__STACKTRACE__構造体」参照)。たとえば、つぎのコードをtest.exsに書いてみましょう。1
defmodule X do
def f() do
throw 42
end
def g() do
f() + 1
end
def h() do
g() + 1
end
end
try do
X.h()
catch
42 ->
# IO.inspect System.stacktrace() # v1.7より前に対応させたいとき
IO.inspect __STACKTRACE__ # v1.7以降
end
コマンドラインツールにiex test.exsと打ち込むと、スタックトレース情報が出力されます。
[
{X, :f, 0, [file: 'test.exs', line: 3]},
{X, :g, 0, [file: 'test.exs', line: 6]},
{X, :h, 0, [file: 'test.exs', line: 9]},
{:elixir_compiler_0, :__FILE__, 1, [file: 'test.exs', line: 14]},
{:elixir_compiler, :dispatch, 4, [file: 'src/elixir_compiler.erl', line: 79]},
{:elixir_compiler, :compile, 3, [file: 'src/elixir_compiler.erl', line: 63]},
{:elixir_lexical, :run, 2, [file: 'src/elixir_lexical.erl', line: 17]},
{:elixir_compiler, :quoted, 2, [file: 'src/elixir_compiler.erl', line: 23]}
]
__STACKTRACE__/0の戻り値をさらにException.format_stacktrace/1に渡せば、出力が整形されます。
try do
X.h()
catch
42 ->
# IO.inspect __STACKTRACE__
IO.puts Exception.format_stacktrace(__STACKTRACE__)
end
test.exs:3: X.f/0
test.exs:6: X.g/0
test.exs:9: X.h/0
test.exs:14: (file)
(elixir) src/elixir_compiler.erl:79: :elixir_compiler.dispatch/4
(elixir) src/elixir_compiler.erl:63: :elixir_compiler.compile/3
(elixir) src/elixir_lexical.erl:17: :elixir_lexical.run/2
(elixir) src/elixir_compiler.erl:23: :elixir_compiler.quoted/2
通常のとき
例外が起きていなくても、関数がどこから呼ばれたか確かめたいことはあります。たとえば、共通処理の関数内でLogger.infoによりログを出力するとき、スタックトレースの情報があれば、問題はすぐにつきとめられるでしょう。
通常のときにスタックトレースの情報を取得するのは、Process.info/2です。関数には、つぎのように現在のプロセスを与えます。
defmodule X do
def f() do
{:current_stacktrace, t} = Process.info(self(), :current_stacktrace)
IO.inspect t
0
end
def g() do
f() + 1
end
def h() do
g() + 1
end
end
X.h() + 1
[
{Process, :info, 2, [file: 'lib/process.ex', line: 767]},
{X, :f, 0, [file: 'test.exs', line: 3]},
{X, :g, 0, [file: 'test.exs', line: 8]},
{X, :h, 0, [file: 'test.exs', line: 11]},
{:elixir_compiler_0, :__FILE__, 1, [file: 'test.exs', line: 15]},
{:elixir_compiler, :dispatch, 4, [file: 'src/elixir_compiler.erl', line: 79]},
{:elixir_compiler, :compile, 3, [file: 'src/elixir_compiler.erl', line: 63]}
]
例外時と同じく、Exception.format_stacktrace/1で出力は整形できます。
def f() do
{:current_stacktrace, t} = Process.info(self(), :current_stacktrace)
# IO.inspect t
IO.puts Exception.format_stacktrace(Enum.drop(t, 1))
0
end
Process.info/2から得た値をEnum.drop/2に渡したのは、Process.info/2の呼び出し情報は除きたかったためです。
test.exs:3: X.f/0
test.exs:8: X.g/0
test.exs:11: X.h/0
test.exs:15: (file)
(elixir) src/elixir_compiler.erl:79: :elixir_compiler.dispatch/4
(elixir) src/elixir_compiler.erl:63: :elixir_compiler.compile/3
Exception.format_stacktrace/1のドキュメントは、引数がないときはProcess.info/2から得た現行プロセスのスタックトレース情報を返すように書いています。ただしこの場合、呼び出しもと関数の情報が含まれません。
def f() do
# {:current_stacktrace, t} = Process.info(self(), :current_stacktrace)
# IO.puts Exception.format_stacktrace(Enum.drop(t, 1))
IO.puts Exception.format_stacktrace()
0
end
つぎのように、X.f/0の情報が抜けてしまいます。
test.exs:7: X.g/0
test.exs:10: X.h/0
test.exs:14: (file)
(elixir) src/elixir_compiler.erl:79: :elixir_compiler.dispatch/4
Exception.format_stacktrace/1のコードを見ると、Enum.drop/2で、はじめの3つのトレース情報を削っているのです。
はじめのふたつはProcess.info/2とException.format_stacktrace/1ですから、省くことはわかります。けれど、なぜかさらにもうひとつ、呼び出しもと関数(X.f/0)の情報も消しているのです。これはあった方がよいという場合は、ダミーのスタック情報をひとつ積んで呼び出せばよいでしょう。
def format_stacktrace() do # スタック情報をひとつ積む
Exception.format_stacktrace() <> ""
end
def f() do
# IO.puts Exception.format_stacktrace()
IO.puts format_stacktrace()
0
end
test.exs:6: X.f/0
test.exs:10: X.g/0
test.exs:13: X.h/0
test.exs:17: (file)
なお、スタックトレースの情報は7個までしか取得していないようです。ただでさえ少ない情報が3つも削られてしまうのは、かなりもったいないといえます。どのように取得するのがよいかは、少し考えた方がよさそうです。
-
f() + 1のように+1を加えているのは、末尾呼び出し最適化を妨げるためです。詳しくは「Elixirのスタックトレースと末尾呼び出し最適化」をお読みください。 ↩
Top comments (0)