Ruby の inspect 結果の最初の n 文字だけ欲しい
最近ちょっと忙しくしながら 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 という、なんかいい感じに表示してくれる仕組みがあります。これを使うとどうでしょうか。厳密には pp と inspect の結果は違うんですが、まぁだいたい同じだろうと考えます。
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.pp を PP.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