🥨

Ruby の inspect 結果の最初の n 文字だけ欲しい

2022/07/12に公開

最近ちょっと忙しくしながら Ruby のデバッガである debug.gem(ruby/debug: Debugging functionality for Ruby)の最新版(1.6.0)をリリースしました。なかなか便利じゃないかと思うので、良かったら使ってみてください。

それはともかく、debug.gem は、バックトレースを表示するとき、パラメータも一緒に表示します。

こんな感じ。この例では、bootsnap で Rails アプリをロードしてる最中に Ctrl-C で止めてバックトレースをのぞいているところです。

(rdbg) bt    # backtrace command
=>#0    [C] RubyVM::InstructionSequence.load_from_binary at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/compile_cache/iseq.rb:49
  #1    Bootsnap::CompileCache::ISeq.storage_to_output(binary="YARB\x03\x00\x00\x00\x01\x00\x00\x00|\x0..., _args=nil) at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/compile_cache/iseq.rb:49
  #2    [C] Bootsnap::CompileCache::Native.fetch at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/compile_cache/iseq.rb:60
  #3    Bootsnap::CompileCache::ISeq.fetch(path="/home/ko1/.rbenv/versions/3.1.2/lib/ruby..., cache_dir="/mnt/c/ko1/src/rb/ruby-debug/app/tapp/tm...) at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/compile_cache/iseq.rb:60
  #4    Bootsnap::CompileCache::ISeq::InstructionSequenceMixin#load_iseq(path="/home/ko1/.rbenv/versions/3.1.2/lib/ruby...) at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/compile_cache/iseq.rb:85
  #5    [C] Kernel#require at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #6    Kernel#require(path="active_storage/version") at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #7    <main> at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activestorage-7.0.3/lib/active_storage.rb:31
  #8    [C] Kernel#require at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #9    Kernel#require(path="active_storage") at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #10   <main> at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activestorage-7.0.3/lib/active_storage/engine.rb:8
  #11   [C] Kernel#require at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #12   Kernel#require(path="active_storage/engine") at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #13   block {|railtie="active_storage/engine"|} in <main> at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/railties-7.0.3/lib/rails/all.rb:20
  #14   [C] Array#each at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/railties-7.0.3/lib/rails/all.rb:18
  #15   <main> at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/railties-7.0.3/lib/rails/all.rb:18
  #16   [C] Kernel#require at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #17   Kernel#require(path="rails/all") at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #18   <main> at /mnt/c/ko1/src/rb/ruby-debug/app/tapp/config/application.rb:3
  #19   [C] Kernel#require at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
  #20   Kernel#require(path="/mnt/c/ko1/src/rb/ruby-debug/app/tapp/co...) at ~/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30
...

たとえば、#6 では、Kernel#require(path="active_storage/version") で path というパラメータが active_storage/versionなんだな、というのがわかります。ただ、あまり長くても邪魔なので、長すぎるのは #1 Bootsnap::CompileCache::ISeq.storage_to_output(binary="YARB\x03\x00\x00\x00\x01\x00\x00\x00|\x0..., _args=nil) こんな感じで、... で切ってしまいます。この記事は、この「切り方」の話。

このオブジェクトの概要表示は、#inspect を呼んだ結果なのですが、たかだか inspect だから時間もかからんだろ、と思っていたのですが、Rails 規模でバックトレースが長いと、inspect を大量に呼んでしまって遅い、という報告がありました(Slow backtraces due to inspect of large local variables · Issue #635 · ruby/debug )。そもそも inspect 自体の結果がでかくて、それがたくさんで遅いからなんとかならんか、と。

多くの場合、こういう情報はチラ見すれば十分なので(必要なら、さらに深堀すればよい)、最初の40字だけ欲しい、という問題にしましょう。

解きたい問題:inspectの最初の40文字を、できるだけ高速に欲しい。

今回は、次の C インスタンスを inspect する、という問題にしておきましょう。

# C インスタンスは複雑なので、inspect が十分遅い、というサンプル
class C
  def initialize
    @a = [:a] * 1_000
    @b = [:b] * 1_000
    @c = [:c] * 1_000
  end
end

何も考えない回答はこちら。

class Object
  def short_inspect1 max: 40
    str = self.inspect
    if str.length > max
      str[0..max] + '...'
    else
      str
    end
  end
end

時間をみてみましょう。

obj = C.new
N = 1_000

Benchmark.bm{|x|
  x.report('1.'){
    N.times{ obj.short_inspect1 }
  }
}

#=>
#         user     system      total        real
# 1.  0.891000   0.000000   0.891000 (  0.895000)

たかだか1,000回に1秒かかってしまいました。

どうにかできないでしょうか。inspect に「ここまで文字列が伸びたらおしまい」という引数を指定できればいいんですが、さすがに今からそれを入れるのは互換性的に無理です。

Ruby には pp という、なんかいい感じに表示してくれる仕組みがあります。これを使うとどうでしょうか。厳密には ppinspect の結果は違うんですが、まぁだいたい同じだろうと考えます。

class Object
  def short_inspect_pp max: 40
    str = PP.pp(self, String.new)
    if str.length > max
      str[0..max] + '...'
    else
      str
    end
  end
end

obj = C.new
N = 1_000

Benchmark.bm(10){|x|
  x.report('1. inspect'){
    N.times{ obj.short_inspect1 }
  }
  x.report('2. pp'){
    N.times{ obj.short_inspect1 }
  }
}
##=>
#                 user     system      total        real
#1. inspect   0.890000   0.000000   0.890000 (  0.894466)
#2. pp       23.641000   0.359000  24.000000 ( 24.174404)

むっちゃ遅くなりましたね。pp はいい感じに出力するための Ruby によるフレームワークで、イイ感じに出力するためにいろんな計算するので、あんまり速くないのですね。

今回の問題については、pp 中に、ある程度(40文字程度)文字がたまったら、もう処理を中断する、というものです。

さて、PP.pp(self, String.new) という呼び出しで、イイ感じの出力を得られるのですが、第2引数は、出力先になります( https://docs.ruby-lang.org/ja/latest/class/PP.html#S_PP )。つまり、ppメソッドは、この第二引数に << で出力を足しこんでいくことで結果を作ります。そのため、例えば $stderr を指定すれば、結果が標準エラー出力されます。

となると、<< で文字列をくっつけていって、長さが一定になったら打ち切り、とするような出力先を作れば良さそうです。

class Object
  class LimitedPP
    def self.pp(obj, max=80)
      out = self.new(max)
      catch out do
        PP.pp(obj, out)
      end
      out.buf
    end

    attr_reader :buf

    def initialize max
      @max = max
      @buf = String.new
    end

    def <<(other)
      @buf << other

      if @buf.size >= @max
        @buf = @buf[0..@max] + '...'
        throw self
      end
    end
  end

  def short_inspect_limitedpp max: 40
    LimitedPP.pp(self, max)
  end
end

<<メソッドで、既定の長さになったら throw で抜ける、というものです。
例外のある Ruby では、throw catch ってあんまり使わない気がしますね。

obj = C.new
N = 1_000

Benchmark.bm(10){|x|
  x.report('1. inspect'){
    N.times{ obj.short_inspect }
  }
  x.report('2. PP'){
    N.times{ obj.short_inspect_pp }
  }
  x.report('3. LimitedPP'){
    N.times{ obj.short_inspect_pp }
  }
}

#                     user     system      total        real
#1. inspect       0.844000   0.000000   0.844000 (  0.841211)
#2. PP           21.625000   0.203000  21.828000 ( 21.881416)
#3. LimitedPP     0.359000   0.359000   0.718000 (  0.721188)

お、だいぶ速くなりましたね。でも、inpsect と同じ程度。もう少し何とかならないでしょうか。

ところで、PP.pp は、イイ感じに改行を入れてくれるのですが、今回の実装では、改行は邪魔です。実は改行を入れない PP.singleline_ppというのがあります。

というわけで、上記コードの PP.ppPP.singleline_pp に置き換えます。

...
  class LimitedPP
    def self.pp(obj, max=80)
      out = self.new(max)
      catch out do
        PP.singleline_pp(obj, out) # PP.pp から変更
      end
      out.buf
    end
...

#                     user     system      total        real
#1. inspect       0.844000   0.000000   0.844000 (  0.841211)
#2. PP           21.625000   0.203000  21.828000 ( 21.881416)
#3. LimitedPP     0.359000   0.359000   0.718000 (  0.721188) # PP.pp 版
#3. LimitedPP     0.046000   0.000000   0.046000 (  0.054492) # PP.singleline_pp 版

inspect より10倍くらい速くなりましたね!

というわけで、

解きたい問題:inspectの最初の40文字を、できるだけ高速に欲しい。

に対する私の答えは、

PP.singleline_pp に途中で中断するようなバッファを第2引数に渡す。

でした。新しい debug.gem では、まさにこんなふうに作っています。たかだかオブジェクトの状態表示(inspect)ですが、こう考えるとなかなか難しいですね。

Discussion