【Ruby Advent Calendar 2021】Ruby の TracePoint を使ってメソッド呼び出しをトレースしよう【1日目】

Ruby Advent Calendar 2021 1日目の記事です。
さてさて今年も Advent Calendar の時期がやってきましたね。
今年の Ruby Advent Calendar はありがたい事に1周目が既に埋まっており、2周目のカレンダーが立っています。
Advent Calendar を書いてみたい方がいればぜひぜひ2周目のカレンダーに登録しましょう！！！

と、いう事で1日目の記事なんですが実はいまは11月29日で完全にノープランでこの記事を書いています。
例年だと Advent Calendar を立てる頃にはだいたい書くネタは考えているんですが今年は完全に何も思いついていませんどうしよう。
ところでわたしは OSS 活動の一環として Ruby の標準ライブラリの Reline のコードを読んだりすることがあります。
ただ、Reline のコードってまあまあ読むのが大変だったりするんですよねえ、具体的には実際のコードを見てもらうとわかりやすいんですが。
で、最近も Reline のバグ修正をしようと思って Reline の実装を追っていたんですがまーどこでなにがどう呼ばれているのかさっぱりわからないんですよね。
そこで Reline のコードの流れを可視化するために『メソッド呼び出しのトレーサ』をつくったので今回はそれの話を書いてみようと思います。

メソッド呼び出しのトレースとは？

簡単な例として次のような User クラスがあるとします。

class User
  def initialize(name, age)
    self.name = name
    self.age = age
  end

  def self.create(name:, age:)
    new(name, age)
  end

  def update(name: @name, age: @age)
    self.name = name
    self.age = age
  end

  def name; @name end
  def name=(name); @name = name end

  def age; @age end
  def age=(age); @age = age end

  def to_s
    "name: #{name}, age: #{age}"
  end
end

では、次のようなコードを実行するとどのメソッドがどのような順番で呼ばれるでしょうか。

user = User.create(name: "homu", age: 14)
user.update(age: 15)
puts user

Ruby に慣れている人ならある程度は脳内でコードを実行して処理を追うことができると思います。
しかし、コードの呼び出しが深くなったり他のファイルを横断すると脳内で処理を追うのが難しくなってきます。
そこであるコードを実行した時にどのようなメソッドがどのような順番で呼び出されるのかを視覚的にわかりやすくするトレーサをこれから作っていきます。
最終的には以下のようなトレースを出力することを目標にしていきます。

User.create(name = "homu", age = 14) # sample.rb:37 {
  User#initialize(name = "homu", age = 14) # sample.rb:12 {
    User#name=(name = "homu") # sample.rb:7 {
      # changes instance variables {
        @name : nil => "homu"
      }
    } => "homu"
    User#age=(age = 14) # sample.rb:8 {
      # changes instance variables {
        @age : nil => 14
      }
    } => 14
    # changes instance variables {
      @name : nil => "homu"
      @age : nil => 14
    }
  } => 14
} => #<User:0x00005646462be818 @name="homu", @age=14>
User#update(name: "homu", age: 15) # sample.rb:38 {
  User#name=(name = "homu") # sample.rb:16 {
  } => "homu"
  User#age=(age = 15) # sample.rb:17 {
    # changes instance variables {
      @age : 14 => 15
    }
  } => 15
  # changes instance variables {
    @age : 14 => 15
  }
} => 15
User#to_s() # sample.rb:39 {
  User#name() # sample.rb:31 {
  } => "homu"
  User#age() # sample.rb:31 {
  } => 15
} => "name: homu, age: 15"

メソッド呼び出しをトレースする

まずはメソッド呼び出しをトレースしてみます。
ありがたい事に Ruby には任意の処理を実行した時に処理をフックすることができる TracePoint というライブラリが標準に存在しています。
これを利用すると『Ruby のメソッドが呼び出された時』に処理をフックする事ができます。
トレースできる種類に付いてはここを参照してください。

def hoge
  "Hoge"
end

def foo
  hoge
end

def bar
  foo
end

trace = TracePoint.new(:call) do |tp|
  # メソッドが呼び出された時にこのブロックが呼ばれる
  # tp からいろいろな情報を取得できる
  # method_id だとメソッド名
  puts tp.method_id
end

# #enable のブロック内で呼ばれたメソッドがトレースされる
trace.enable {
  bar
}
# => bar
#    foo
#    hoge

こんな感じでメソッド呼び出しをトレースすることができました。
このようにして TracePoint を利用してメソッドの呼び出しをトレースしていきます。
また、このままだと扱いづらいのでちょっと形を変えて実装していきましょう。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  def trace_call_func(&block)
    trace = TracePoint.new(:call) do |tp|
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  def initialize(name, age)
    self.name = name
    self.age = age
  end

  def self.create(name:, age:)
    new(name, age)
  end

  def update(name: @name, age: @age)
    self.name = name
    self.age = age
  end

  def name; @name end
  def name=(name); @name = name end

  def age; @age end
  def age=(age); @age = age end

  def to_s
    "name: #{name}, age: #{age}"
  end
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts user
end
__END__
# output
create
initialize
name=
age=
update
name=
age=
to_s
name
age

これをベースにしてどんどん実装していきます。

インデントを付ける

ただメソッドの名前を出力しただけではどういう順序で呼び出されたのかがよくわかりませんし味気ないですね。
そこでメソッドを呼び出した深さをインデントして『どの階層で』呼ばれたのか視覚的にわかりやすくしてみましょう。
先程は :call を使って『メソッドの呼び出し時』をトレースしたんですが今度は :return を利用して『メソッドの終了時』に処理をフックします。
これを利用してインデントを計算してみましょう。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  def trace_call_func(&block)
    indent_level = 0

    # :return のトレースも追加する
    trace = TracePoint.new(:call, :return) do |tp|
      indent = "  " * indent_level

      # tp.event でトレースの種類を取得できる
      case tp.event
      when :call
        puts "#{indent}#{tp.method_id}"
        # メソッド呼び出し時にインデントを深くする
        indent_level += 1
      when :return
        # メソッド終了時にインデントを戻す
        indent_level -= 1
      end
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  # ...省略...
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts user
end
__END__
output:
create
  initialize
    name=
    age=
update
  name=
  age=
to_s
  name
  age
output: name: homu, age: 15

さっきよりも階層が分かりすくなりましたね！

メソッドの引数を表示する

次はメソッドの引数の値も一緒に表示するようにしてみましょう。
TracePoint では TracePoint#parameters でそのメソッドの引数情報を取得する事ができます。
これは Method#parameters と同じ情報を返します。
また TracePoint#binding でそのメソッド内の Binding オブジェクトを取得する事ができます。
この 2つの情報を使ってメソッドの引数の値を取得します。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  # Refinements で特定のクラスに便利なメソッドを定義する
  using Module.new {
    refine Hash do
      # キーワード引数かそうでないかで表示を切り分けるメソッド
      def to_arg_s
        if self[:op] == :key
          "#{self[:name]}: #{self[:value].inspect}"
        else
          "#{self[:name]} = #{self[:value].inspect}"
        end
      end
    end

    refine TracePoint do
      # TracePoint から引数の情報とその値を取得するメソッド
      # #parameters でメソッドの引数の一覧を取得し #binding で変数の値を取得する
      def arguments
        parameters.map { |op, name|
          { op: op, name: name, value: binding.local_variable_get(name) }
        }
      end

      # メソッドのシグネチャを生成するメソッド
      def method_sig
        "#{method_id}(#{arguments.map(&:to_arg_s).join(", ")})"
      end
    end
  }

  def trace_call_func(&block)
    indent_level = 0

    trace = TracePoint.new(:call, :return) do |tp|
      indent = "  " * indent_level

      case tp.event
      when :call
        # 引数情報が含まれているメソッドのシグネチャを取得する
        puts "#{indent}#{tp.method_sig}"
        indent_level += 1
      when :return
        indent_level -= 1
      end
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  # ...省略...
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts user
end
__END__
output:
create(name = "homu", age = 14)
  initialize(name = "homu", age = 14)
    name=(name = "homu")
    age=(age = 14)
update(name: "homu", age: 15)
  name=(name = "homu")
  age=(age = 15)
to_s()
  name()
  age()
output: name: homu, age: 15

おお、これでかなりデバッグに必要な情報が増えてきましたね。

戻り値を表示する

さて、引数が表示できたので次はメソッドの戻り値を表示してみましょう。
戻り値の情報は TracePoint#return_value で取得できます。
ついでに {} も表示してみましょう。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  using Module.new {
    refine Hash do
      def to_arg_s
        if self[:op] == :key
          "#{self[:name]}: #{self[:value].inspect}"
        else
          "#{self[:name]} = #{self[:value].inspect}"
        end
      end
    end

    refine TracePoint do
      def arguments
        parameters.map { |op, name|
          { op: op, name: name, value: binding.local_variable_get(name) }
        }
      end

      def method_sig
        "#{method_id}(#{arguments.map(&:to_arg_s).join(", ")})"
      end
    end
  }

  def trace_call_func(&block)
    indent_level = 0

    trace = TracePoint.new(:call, :return) do |tp|
      indent = "  " * indent_level

      case tp.event
      when :call
        puts "#{indent}#{tp.method_sig} {"
        indent_level += 1
      when :return
        indent_level -= 1
        # tp.return_value で戻り値を表示する
        puts "#{"  " * indent_level}} => #{tp.return_value.inspect}"
      end
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  # ...省略...
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts user
end
__END__
output:
create(name = "homu", age = 14) {
  initialize(name = "homu", age = 14) {
    name=(name = "homu") {
    } => homu
    age=(age = 14) {
    } => 14
  } => 14
} => #<User:0x0000556ccdd46770 @name="homu", @age=14>
update(name: "homu", age: 15) {
  name=(name = "homu") {
  } => homu
  age=(age = 15) {
  } => 15
} => 15
to_s() {
  name() {
  } => homu
  age() {
  } => 15
} => name: homu, age: 15
output: name: homu, age: 15

うーん、情報が増えてきたらちょっと表示が乱雑になってきましたね。
表示する情報とみやすさがトレードオフなのでここら辺のバランスがちょっとむずかしいところ。
もっといい感じに表示したいですねえ。

クラス名も表示する

今回の例では User クラスだけしか使われていないんですが実際には様々なクラスのインスタンスメソッドが呼び出されます。
そこでどのクラスのインスタンスメソッドなのかがわかるようにクラス名も一緒に表示するようにしてみましょう。
TracePoint#defined_class でメソッドが定義されているクラス情報が取得できます。
また、クラスメソッドの場合は特異クラスが返ってくるので注意する必要があります。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  using Module.new {
    refine Module do
      # 特異クラスからもクラス名を取得できるようにするヘルパメソッド
      def original_classname
        if singleton_class?
          self.inspect[/#<Class:(.*)>/, 1]
        else
          self.name
        end
      end
    end

    refine Hash do
      def to_arg_s
        if self[:op] == :key
          "#{self[:name]}: #{self[:value].inspect}"
        else
          "#{self[:name]} = #{self[:value].inspect}"
        end
      end
    end

    refine TracePoint do
      def arguments
        parameters.map { |op, name|
          { op: op, name: name, value: binding.local_variable_get(name) }
        }
      end

      def method_sig
        # 特異クラスかどうかで表示の仕方を切り分ける
        # 特異クラスの場合            -> Hoge.foo
        # 特異クラスでない場合        -> Hoge#foo
        # トップレベル(Object) の場合 -> foo
        if defined_class.singleton_class?
          "#{defined_class.original_classname}.#{method_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        elsif defined_class == Object
          "#{callee_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        else
          "#{defined_class.original_classname}##{callee_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        end
      end
    end
  }

  def trace_call_func(&block)
    indent_level = 0

    trace = TracePoint.new(:call, :return) do |tp|
      indent = "  " * indent_level

      case tp.event
      when :call
        puts "#{indent}#{tp.method_sig} {"
        indent_level += 1
      when :return
        indent_level -= 1
        puts "#{"  " * indent_level}} => #{tp.return_value.inspect}"
      end
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  # ...省略...
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts user
end
__END__
output:
User.create(name = "homu", age = 14) {
  User#initialize(name = "homu", age = 14) {
    User#name=(name = "homu") {
    } => homu
    User#age=(age = 14) {
    } => 14
  } => 14
} => #<User:0x0000556ccdd46770 @name="homu", @age=14>
User#update(name: "homu", age: 15) {
  User#name=(name = "homu") {
  } => homu
  User#age=(age = 15) {
  } => 15
} => 15
User#to_s() {
  User#name() {
  } => homu
  User#age() {
  } => 15
} => name: homu, age: 15
output: name: homu, age: 15

ガンガン情報が増えてきます！！！！

メソッドの呼び出し場所を表示する

どんどんやっていきます。
ここまできたらメソッドがどこで呼び出されたのかの情報も表示したくなりますよね？ しかし、残念ながら TracePoint ではどこでメソッドが呼び出されたのかの情報を取得することができません。
そこで :line というトレースを利用します。
これは式が評価された時に呼び出されるトレースです。
これを利用して、

1. hoge メソッド呼び出す
2. :line が TracePoint で呼び出される
3. 2. の時に呼び出された位置情報を保持しておく
   • TracePoint#lineno で hoge が呼び出された行情報が取得できる
4. 実際に hoge メソッドが呼び出されて :call が TracePoint で呼び出される
5. 3. で保持していた位置情報を参照して表示する

と、言うような感じです。
はい、実装してみました。
また、位置情報は TracePoint#lineno で行情報、TracePoint#path でファイルパスを取得できます。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  using Module.new {
    refine Module do
      def original_classname
        if singleton_class?
          self.inspect[/#<Class:(.*)>/, 1]
        else
          self.name
        end
      end
    end

    refine Hash do
      def to_arg_s
        if self[:op] == :key
          "#{self[:name]}: #{self[:value].inspect}"
        else
          "#{self[:name]} = #{self[:value].inspect}"
        end
      end
    end

    refine TracePoint do
      def arguments
        parameters.map { |op, name|
          { op: op, name: name, value: binding.local_variable_get(name) }
        }
      end

      def method_sig
        if defined_class.singleton_class?
          "#{defined_class.original_classname}.#{method_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        elsif defined_class == Object
          "#{callee_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        else
          "#{defined_class.original_classname}##{callee_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        end
      end
    end
  }

  def trace_call_func(&block)
    indent_level = 0
    # call された場所をスタックする
    # call はネストして呼び出される必要があるので位置情報もスタックしておく必要がある
    call_stack = [{}]

    trace = TracePoint.new(:line, :call, :return) do |tp|
      indent = "  " * indent_level

      case tp.event
      when :line
        # :line が呼び出された時はスタックの最後に位置情報を保存しておく
        call_stack.last[:called_lineno] = tp.lineno
        call_stack.last[:called_path] = tp.path
      when :call
        # :call が呼び出されたときのその位置をスタックして上書きされないようにする
        call_stack << call_stack.last.dup
        called_lineno = call_stack.last[:called_lineno]
        called_path = call_stack.last[:called_path]
        puts "#{indent}#{tp.method_sig} # #{File.basename(called_path)}:#{called_lineno} {"
        indent_level += 1
      when :return
        # :return が呼び出されたときは積んであった位置情報を削除する
        call_stack.pop
        indent_level -= 1
        puts "#{"  " * indent_level}} => #{tp.return_value.inspect}"
      end
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  include Comparable

  def initialize(name, age)
    self.name = name
    self.age = age
  end

  def self.create(name:, age:)
    new(name, age)
  end

  def update(name: @name, age: @age)
    self.name = name
    self.age = age
  end

  def name; @name end
  def name=(name); @name = name end

  def age; @age end
  def age=(age); @age = age end

  def <=>(other)
    self.age <=> other.age
  end

  def to_s
    "name: #{name}, age: #{age}"
  end
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts "output: #{user}"
end
__END__
User.create(name = "homu", age = 14) # sample.rb:38 {
  User#initialize(name = "homu", age = 14) # sample.rb:13 {
    User#name=(name = "homu") # sample.rb:8 {
    } => homu
    User#age=(age = 14) # sample.rb:9 {
    } => 14
  } => 14
} => #<User:0x0000556ccdd46770 @name="homu", @age=14>
User#update(name: "homu", age: 15) # sample.rb:39 {
  User#name=(name = "homu") # sample.rb:17 {
  } => homu
  User#age=(age = 15) # sample.rb:18 {
  } => 15
} => 15
User#to_s() # sample.rb:40 {
  User#name() # sample.rb:32 {
  } => homu
  User#age() # sample.rb:32 {
  } => 15
} => name: homu, age: 15
output: name: homu, age: 15

行番号が表示されていないとかなり分かりづらいんですが、これでそのメソッドが呼び出された位置情報も表示されるようになりました。
これでもうどこでなにが呼び出されたのか一目瞭然ですね！！！

変更されたインスタンス変数を

最後にメソッド内で変更されたインスタンス変数の表示もやっちゃいましょう！！
TracePoint#self でイベントを発生させたオブジェクトが取得できます。
それを経由してインスタンス変数情報を取得します。

# method_call_tracer.rb

class MethodCallTracer < Struct.new(:option)
  using Module.new {
    refine Object do
      # レシーバのインスタンス変数を変数名と値の Hash で取得する
      def instance_variable_table
        instance_variables.to_h { |name|
          [name, instance_variable_get(name)]
        }
      end
    end

    refine Module do
      def original_classname
        if singleton_class?
          self.inspect[/#<Class:(.*)>/, 1]
        else
          self.name
        end
      end
    end

    refine Hash do
      def difference(other)
        other.map { |key, value| [key, [self[key], value]] if value != self[key] }.compact.to_h
      end

      def to_arg_s
        if self[:op] == :key
          "#{self[:name]}: #{self[:value].inspect}"
        else
          "#{self[:name]} = #{self[:value].inspect}"
        end
      end
    end

    refine TracePoint do
      def arguments
        parameters.map { |op, name|
          { op: op, name: name, value: binding.local_variable_get(name) }
        }
      end

      def method_sig
        if defined_class.singleton_class?
          "#{defined_class.original_classname}.#{method_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        elsif defined_class == Object
          "#{callee_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        else
          "#{defined_class.original_classname}##{callee_id}(#{arguments.map(&:to_arg_s).join(", ")})"
        end
      end
    end
  }

  def trace_call_func(&block)
    # 各呼び出しのインスタンス変数を保持しておく
    ivar_table = {}
    indent_level = 0
    call_stack = [{}]

    trace = TracePoint.new(:line, :call, :return) do |tp|
      indent = "  " * indent_level
      ivar_table_key = "#{tp.self.object_id}#{tp.method_id}"

      case tp.event
      when :line
        call_stack.last[:called_lineno] = tp.lineno
        call_stack.last[:called_path] = tp.path
      when :call
        # メソッドが呼ばれた時にインスタンス変数の情報を保持しておく
        ivar_table[ivar_table_key] = tp.self.instance_variable_table

        call_stack << call_stack.last.dup
        called_lineno = call_stack.last[:called_lineno]
        called_path = call_stack.last[:called_path]
        puts "#{indent}#{tp.method_sig} # #{File.basename(called_path)}:#{called_lineno} {"
        indent_level += 1
      when :return
        call_stack.pop

        # メソッドを終了するタイミングで呼ばれたときのインスタンス変数との差分を表示する
        changes = ivar_table[ivar_table_key].difference tp.self.instance_variable_table
        if !changes.empty?
          puts "#{indent}# changes instance variables {"
          changes.each { |key, (prev, next_)|
            puts "#{"  " * (indent_level+2)}#{key} : #{prev.inspect} => #{next_.inspect}"
          }
          puts "#{indent}}"
        end

        indent_level -= 1
        puts "#{"  " * indent_level}} => #{tp.return_value.inspect}"
      end
    end
    trace.enable(&block)
  end

  def self.trace(**opt, &block)
    new(opt).trace_call_func(&block)
  end
end

# sample.rb
require_relative "./method_call_tracer.rb"

class User
  # ...省略...
end


MethodCallTracer.trace do
  user = User.create(name: "homu", age: 14)
  user.update(age: 15)
  puts user
end
__END__
output:
User.create(name = "homu", age = 14) # sample.rb:38 {
  User#initialize(name = "homu", age = 14) # sample.rb:13 {
    User#name=(name = "homu") # sample.rb:8 {
      # changes instance variables {
          @name : nil => "homu"
      }
    } => homu
    User#age=(age = 14) # sample.rb:9 {
      # changes instance variables {
          @age : nil => 14
      }
    } => 14
    # changes instance variables {
        @age : nil => 14
    }
  } => 14
} => name: homu, age: 14
User#update(name: "homu", age: 15) # sample.rb:39 {
  User#name=(name = "homu") # sample.rb:17 {
  } => homu
  User#age=(age = 15) # sample.rb:18 {
    # changes instance variables {
        @age : 14 => 15
    }
  } => 15
  # changes instance variables {
      @age : 14 => 15
  }
} => 15
User#to_s() # sample.rb:40 {
  User#name() # sample.rb:32 {
  } => homu
  User#age() # sample.rb:32 {
  } => 15
} => name: homu, age: 15
output: name: homu, age: 15

こんな感じで『変更されたインスタンス変数の差分』を表示するようにしてみました。
これでどのタイミングでインスタンス変数が変更されたのか完全理解できますね！！

まとめ

はい、という感じで簡単にメソッド呼び出しのトレースをやってみました。
いやーこれぐらいの実装でメソッド呼び出しをトレースできるなんて Ruby はなんて便利な言語なんだろうか。
TracePoint サイコー！
ただ、いろんな情報を表示するようにしたので見た目がごちゃごちゃしてしまってちょっと見づらいのが今後の課題ですねえ。
このあたりは単純に標準出力するだけではなくてもっと別の方法で情報を見やすくしたいところ。
これが解決できれば gem 化していきてえ。

兎にも角にもこの機能を使ってガンガンデバッグをやっていくぞい！
では、最後に Reline でキー入力を受け取ったときのメソッド呼び出しのトレース結果を見てみましょう。

Reline::LineEditor#rerender() # debug.rb:252 {
  Reline::LineEditor#whole_lines(index: 0, line: "aa") # line_editor.rb:440 {
    # local variables {
      temp_lines = ["aa"]
    }
  } => ["aa"]
  Reline::LineEditor#check_multiline_prompt(buffer = ["aa"], prompt = nil) # line_editor.rb:440 {
    Reline::LineEditor#simplified_rendering?() # line_editor.rb:106 {
      Reline::LineEditor#finished?() # line_editor.rb:67 {
      } => false
      Reline::LineEditor#finished?() # line_editor.rb:72 {
      } => false
    } => false
    Reline::LineEditor#check_mode_string() # line_editor.rb:129 {
      # local variables {
        mode_string = nil
      }
    } => nil
    Reline::LineEditor#calculate_width(str = "bbb\ncccc> ", allow_escape_code = true) # line_editor.rb:139 {
      Reline::Unicode.calculate_width(str = "cccc> ", allow_escape_code = true) # line_editor.rb:1936 {
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = ">") # unicode.rb:137 {
          # local variables {
            ord = 62
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = " ") # unicode.rb:137 {
          # local variables {
            ord = 32
            m = nil
          }
        } => 1
        # local variables {
          width = 6
          rest = "cccc> "
          in_zero_width = false
        }
      } => 6
    } => 6
    # local variables {
      mode_string = nil
      use_cached_prompt_list = false
      prompt_list = ["bbb\ncccc> "]
      prompt_width = 6
    }
    # changes instance variables {
      @prompt_cache_time : 1638277352.5684538 => 1638277353.403107
    }
  } => ["bbb\ncccc> ", 6, ["bbb\ncccc> "]]
  Reline::LineEditor#finished?() # line_editor.rb:446 {
  } => false
  Reline::LineEditor#calculate_width(str = "aa", allow_escape_code = false) # line_editor.rb:465 {
    Reline::Unicode.calculate_width(str = "aa", allow_escape_code = false) # line_editor.rb:1936 {
      Reline::Unicode.get_mbchar_width(mbchar = "a") # unicode.rb:144 {
        # local variables {
          ord = 97
          m = nil
        }
      } => 1
      Reline::Unicode.get_mbchar_width(mbchar = "a") # unicode.rb:144 {
        # local variables {
          ord = 97
          m = nil
        }
      } => 1
      # local variables {
        width = nil
        rest = nil
        in_zero_width = nil
      }
    } => 2
  } => 2
  Reline::LineEditor#calculate_height_by_width(width = 8) # line_editor.rb:465 {
  } => 2
  Reline::LineEditor#finished?() # line_editor.rb:488 {
  } => false
  Reline::LineEditor#whole_lines(index: 0, line: "aa") # line_editor.rb:505 {
    # local variables {
      temp_lines = ["aa"]
    }
  } => ["aa"]
  Reline::LineEditor#modify_lines(before = ["aa"]) # line_editor.rb:505 {
    Reline::LineEditor#simplified_rendering?() # line_editor.rb:1226 {
      Reline::LineEditor#finished?() # line_editor.rb:67 {
      } => false
      Reline::LineEditor#finished?() # line_editor.rb:72 {
      } => false
    } => false
    Reline::LineEditor#finished?() # line_editor.rb:1228 {
    } => false
          Reline::Unicode.escape_for_print(str = "aa") # color.rb:134 {
          } => "aa"
          Reline::Unicode.escape_for_print(str = "\n") # color.rb:134 {
          } => "\n"
    # local variables {
      after = "aa\n"
    }
  } => ["aa"]
  Reline::LineEditor#whole_lines(index: 0, line: "aa") # line_editor.rb:506 {
    # local variables {
      temp_lines = ["aa"]
    }
  } => ["aa"]
  Reline::LineEditor#check_multiline_prompt(buffer = ["aa"], prompt = "bbb\ncccc> ") # line_editor.rb:506 {
    Reline::LineEditor#simplified_rendering?() # line_editor.rb:106 {
      Reline::LineEditor#finished?() # line_editor.rb:67 {
      } => false
      Reline::LineEditor#finished?() # line_editor.rb:72 {
      } => false
    } => false
    Reline::LineEditor#check_mode_string() # line_editor.rb:129 {
      # local variables {
        mode_string = nil
      }
    } => nil
    Reline::LineEditor#calculate_width(str = "bbb\ncccc> ", allow_escape_code = true) # line_editor.rb:139 {
      Reline::Unicode.calculate_width(str = "cccc> ", allow_escape_code = true) # line_editor.rb:1936 {
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:137 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = ">") # unicode.rb:137 {
          # local variables {
            ord = 62
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = " ") # unicode.rb:137 {
          # local variables {
            ord = 32
            m = nil
          }
        } => 1
        # local variables {
          width = 6
          rest = "cccc> "
          in_zero_width = false
        }
      } => 6
    } => 6
    # local variables {
      mode_string = nil
      use_cached_prompt_list = true
      prompt_list = ["bbb\ncccc> "]
      prompt_width = 6
    }
  } => ["bbb\ncccc> ", 6, ["bbb\ncccc> "]]
  Reline::LineEditor#render_partial(prompt = "bbb\ncccc> ", prompt_width = 6, line_to_render = "aa", this_started_from = 0, with_control: true) # line_editor.rb:507 {
    Reline::LineEditor#split_by_width(str = "bbb\ncccc> aa", max_width = 145) # line_editor.rb:1129 {
      Reline::Unicode.split_by_width(str = "bbb\ncccc> aa", max_width = 145, encoding = #<Encoding:UTF-8>) # line_editor.rb:348 {
        Reline::Unicode.get_mbchar_width(mbchar = "b") # unicode.rb:169 {
          # local variables {
            ord = 98
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "b") # unicode.rb:169 {
          # local variables {
            ord = 98
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "b") # unicode.rb:169 {
          # local variables {
            ord = 98
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "\n") # unicode.rb:169 {
          # local variables {
            ord = 10
            m = nil
          }
        } => 2
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:169 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:169 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:169 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "c") # unicode.rb:169 {
          # local variables {
            ord = 99
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = ">") # unicode.rb:169 {
          # local variables {
            ord = 62
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = " ") # unicode.rb:169 {
          # local variables {
            ord = 32
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "a") # unicode.rb:169 {
          # local variables {
            ord = 97
            m = nil
          }
        } => 1
        Reline::Unicode.get_mbchar_width(mbchar = "a") # unicode.rb:169 {
          # local variables {
            ord = 97
            m = nil
          }
        } => 1
        # local variables {
          lines = ["bbb\ncccc> aa"]
          height = 2
          width = 13
          rest = "bbb\ncccc> aa"
          in_zero_width = false
        }
      } => [["bbb\ncccc> aa"], 2]
    } => [["bbb\ncccc> aa"], 2]
    Reline::LineEditor#move_cursor_up(val = 1) # line_editor.rb:1167 {
      Reline::ANSI.move_cursor_up(x = 1) # line_editor.rb:364 {
      } => 4
      # changes instance variables {
        @rest_height : 2 => 3
      }
    } => 3
    Reline::LineEditor#calculate_height_by_width(width = 8) # line_editor.rb:1168 {
    } => 2
    Reline::ANSI.move_cursor_column(x = 0) # line_editor.rb:1175 {
    } => 4
    Reline::ANSI.win?() # line_editor.rb:1197 {
    } => false
    Reline::ANSI.erase_after_cursor() # line_editor.rb:1208 {
    } => 3
    Reline::ANSI.move_cursor_column(x = 0) # line_editor.rb:1209 {
    } => 4
    Reline::LineEditor#finished?() # line_editor.rb:1213 {
    } => false
    Reline::LineEditor#move_cursor_up(val = 0) # line_editor.rb:1217 {
    } => nil
    Reline::ANSI.move_cursor_column(x = 8) # line_editor.rb:1219 {
    } => 4
    # local variables {
      visual_lines = ["bbb\ncccc> aa"]
      height = 2
      cursor_up_from_last_line = 0
      last_visual_line = nil
      last_screen_line = nil
      deleted_lines_before_screen = nil
      diff = nil
    }
    # changes instance variables {
      @rest_height : 2 => 3
    }
  } => 2
  Reline::LineEditor#render_dialog(cursor_column = 8) # line_editor.rb:509 {
    Reline::LineEditor#render_each_dialog(dialog = #<Reline::LineEditor::Dialog:0x00007fc5804702f0 @name=:autocomplete, @config=#<Reline::Config:0x00007, cursor_column = 8) # line_editor.rb:646 {
      Reline::LineEditor::Dialog#set_cursor_pos(col = 8, row = 1) # line_editor.rb:660 {
        Reline::LineEditor::DialogProcScope#set_cursor_pos(col = 8, row = 1) # line_editor.rb:605 {
        } => 1
      } => 1
      Reline::LineEditor::Dialog#call(key = #<struct Struct::Key char=97, combined_char=97, with_meta=false>) # line_editor.rb:661 {
        Reline::LineEditor::DialogProcScope#set_dialog(dialog = #<Reline::LineEditor::Dialog:0x00007fc5804702f0 @name=:autocomplete, @config=#<Reline::Config:0x00007) # line_editor.rb:620 {
        } => #<Reline::LineEditor::Dialog:0x00007fc5804702f0 @name=:autocomplete, @config=#<Reline::Config:0x00007
        Reline::LineEditor::DialogProcScope#set_key(key = #<struct Struct::Key char=97, combined_char=97, with_meta=false>) # line_editor.rb:621 {
        } => #<struct Struct::Key char=97, combined_char=97, with_meta=false>
        Reline::LineEditor::DialogProcScope#call() # line_editor.rb:622 {
          Reline::LineEditor::DialogProcScope#config() # reline.rb:207 {
          } => #<Reline::Config:0x00007fc580442990 @additional_key_bindings={:emacs=>{}, :vi_insert=>{}, :vi_command
          Reline::Config#autocompletion() # reline.rb:207 {
          } => false
        } => nil
        # local variables {
          dialog_render_info = nil
        }
      } => nil
      Reline::LineEditor#whole_lines(index: 0, line: "aa") # line_editor.rb:663 {
        # local variables {
          temp_lines = ["aa"]
        }
      } => ["aa"]
      Reline::LineEditor#modify_lines(before = ["aa"]) # line_editor.rb:663 {
        Reline::LineEditor#simplified_rendering?() # line_editor.rb:1226 {
          Reline::LineEditor#finished?() # line_editor.rb:67 {
          } => false
          Reline::LineEditor#finished?() # line_editor.rb:72 {
          } => false
        } => false
        Reline::LineEditor#finished?() # line_editor.rb:1228 {
        } => false
              Reline::Unicode.escape_for_print(str = "aa") # color.rb:134 {
              } => "aa"
              Reline::Unicode.escape_for_print(str = "\n") # color.rb:134 {
              } => "\n"
        # local variables {
          after = "aa\n"
        }
      } => ["aa"]
      Reline::LineEditor#clear_each_dialog(dialog = #<Reline::LineEditor::Dialog:0x00007fc5804702f0 @name=:autocomplete, @config=#<Reline::Config:0x00007) # line_editor.rb:670 {
        # local variables {
          prompt = nil
          prompt_width = nil
          prompt_list = nil
          visual_lines = nil
          visual_lines_under_dialog = nil
          visual_start = nil
          dialog_vertical_size = nil
        }
      } => nil
      Reline::LineEditor::Dialog#contents=(contents = nil) # line_editor.rb:671 {
      } => nil
      # local variables {
        dialog_render_info = nil
        old_dialog = nil
        pointer = nil
        height = nil
        bar_max_height = nil
        moving_distance = nil
        position_ratio = nil
        bar_height = nil
        upper_space = nil
        lower_space = nil
        diff = nil
      }
    } => nil
  } => [#<Reline::LineEditor::Dialog:0x00007fc5804702f0 @name=:autocomplete, @config=#<Reline::Config:0x0000
  # local variables {
    prompt = "bbb\ncccc> "
    prompt_width = 6
    prompt_list = ["bbb\ncccc> "]
    new_lines = nil
    new_highest_in_this = 2
    rendered = false
    line = "aa"
  }
  # changes instance variables {
    @prompt_cache_time : 1638277352.5684538 => 1638277353.403107
    @rest_height : 2 => 3
  }
} => nil

がんばってこ…。