BEAM Stacktraces Missing Frame

If you write Erlang/Elixir, you might use the erlang.apply or Kernel.apply functions for dynamic calling. You might have also noticed something weird, which is that when a function calls apply on the last line, you'll get a stackframe eaten!

For example:

defmodule Demo do
  def start do
    perform(__MODULE__, :target, [])
  end

  def perform(module, function, args) do
    {_, stacktrace} = Process.info(self(), :current_stacktrace)
    IO.inspect(stacktrace, label: "Stack trace in 'perform'")
    apply(module, function, args)
  end

  def target do
    {_, stacktrace} = Process.info(self(), :current_stacktrace)
    IO.inspect(stacktrace, label: "Stack trace in 'target'")
  end
end

Demo.start()

Outputs:

iex(10)> Demo.start()
Stack trace in 'perform': [
  {Process, :info, 2, [file: ~c"lib/process.ex", line: 860]},
  {Demo, :perform, 3, [file: ~c"iex", line: 14]},
  {:elixir, :eval_external_handler, 3, [file: ~c"src/elixir.erl", line: 405]},
  {:erl_eval, :do_apply, 7, [file: ~c"erl_eval.erl", line: 750]},
  {:elixir, :eval_forms, 4, [file: ~c"src/elixir.erl", line: 378]},
  {Module.ParallelChecker, :verify, 1,
   [file: ~c"lib/module/parallel_checker.ex", line: 112]},
  {IEx.Evaluator, :eval_and_inspect, 3,
   [file: ~c"lib/iex/evaluator.ex", line: 331]},
  {IEx.Evaluator, :eval_and_inspect_parsed, 3,
   [file: ~c"lib/iex/evaluator.ex", line: 305]}
]
Stack trace in 'target': [
  {Process, :info, 2, [file: ~c"lib/process.ex", line: 860]},
  {Demo, :target, 0, [file: ~c"iex", line: 20]},
  {:elixir, :eval_external_handler, 3, [file: ~c"src/elixir.erl", line: 405]},
  {:erl_eval, :do_apply, 7, [file: ~c"erl_eval.erl", line: 750]},
  {:elixir, :eval_forms, 4, [file: ~c"src/elixir.erl", line: 378]},
  {Module.ParallelChecker, :verify, 1,
   [file: ~c"lib/module/parallel_checker.ex", line: 112]},
  {IEx.Evaluator, :eval_and_inspect, 3,
   [file: ~c"lib/iex/evaluator.ex", line: 331]},
  {IEx.Evaluator, :eval_and_inspect_parsed, 3,
   [file: ~c"lib/iex/evaluator.ex", line: 305]}
]

You'll notice that despite being called by :perform, the stacktrace for :target doesn't have :perform in it.

If you've done TCO before, this should smell similar to you, where recursive functions that call themselves reuse an existing stackframe so that the system doesn't blow up with frames.

I ran into this problem when trying to build a mechanism for debugging stacktraces, specifically you can find some discussion on it here: https://github.com/elixir-lang/elixir/issues/6357#issuecomment-316154723.

Effectively, this is a super-TCO, where calling apply as the last function reuses the frame. Now, if we introduce some side effects by modifying the :perform function to execute additional code before apply is called:

def perform(module, function, args) do
  {_, stacktrace} = Process.info(self(), :current_stacktrace)
  IO.inspect(stacktrace, label: "Stack trace in 'perform'")
  res = apply(module, function, args)
  String.trim("")
  res
end

This now outputs:

Stack trace in 'target': [
  {Process, :info, 2, [file: ~c"lib/process.ex", line: 860]},
  {Demo, :target, 0, [file: ~c"iex", line: 28]},
  {Demo, :perform, 3, [file: ~c"iex", line: 22]},
  {:elixir, :eval_external_handler, 3, [file: ~c"src/elixir.erl", line: 405]},
  {:erl_eval, :do_apply, 7, [file: ~c"erl_eval.erl", line: 750]},
  {:elixir, :eval_forms, 4, [file: ~c"src/elixir.erl", line: 378]},
  {Module.ParallelChecker, :verify, 1,
   [file: ~c"lib/module/parallel_checker.ex", line: 112]},
  {IEx.Evaluator, :eval_and_inspect, 3,
   [file: ~c"lib/iex/evaluator.ex", line: 331]}
]

and you can see :perform shows up in the stacktrace as expected.

The Erlang documentation has a cute warning on this:

Basically, this means that you should be careful if you use apply and are trying to debug with stacktraces, you might miss a frame in your trace.