Ruby Issue Tracking System で見つけたチケットのバグを調べたときのあれこれをまとめたものです。
ちなみに、調べたチケットはこれ
簡単に言うとruby-profでコードの挙動を追うと意図したものと異なっているみたい
挙動が違う箇所
Ruby 2.6 でチケットにあるコードを実行すると以下のようなログがとれます。
require 'ruby-prof' str = "AABBCC" profile = RubyProf::Profile.profile do 5.times do str.unpack("c*") end end
21587600:115368.898844 line # bug.rb: 5 21587600:115368.898935 c-call Integer#times bug.rb: 5 21587600:115368.898946 line # bug.rb: 6 21587600:115368.898950 c-call String#unpack bug.rb: 6 21587600:115368.898957 c-return String#unpack bug.rb: 6 21587600:115368.898962 line # bug.rb: 6 21587600:115368.898965 c-call String#unpack bug.rb: 6 21587600:115368.898969 c-return String#unpack bug.rb: 6 21587600:115368.898972 line # bug.rb: 6 21587600:115368.898975 c-call String#unpack bug.rb: 6 21587600:115368.898978 c-return String#unpack bug.rb: 6 21587600:115368.898981 line # bug.rb: 6 21587600:115368.898984 c-call String#unpack bug.rb: 6 21587600:115368.898987 c-return String#unpack bug.rb: 6 21587600:115368.898990 line # bug.rb: 6 21587600:115368.898993 c-call String#unpack bug.rb: 6 21587600:115368.898996 c-return String#unpack bug.rb: 6 21587600:115368.898999 c-return Integer#times bug.rb: 5
Cの関数としてString#unpack
が呼び出され、その後c-return
でreturnされています。
しかし、Ruby 2.7では以下のようにログが変わります。
18616920:115460.887200 line # bug.rb: 5 18616920:115460.887364 c-call Integer#times bug.rb: 5 18616920:115460.887377 line # bug.rb: 6 18616920:115460.887383 call String#unpack <internal:pack>:256 18616920:115460.887388 line String#unpack <internal:pack>:257 18616920:115460.887399 line # bug.rb: 6 18616920:115460.887403 call String#unpack <internal:pack>:256 18616920:115460.887406 line String#unpack <internal:pack>:257 18616920:115460.887410 line # bug.rb: 6 18616920:115460.887413 call String#unpack <internal:pack>:256 18616920:115460.887417 line String#unpack <internal:pack>:257 18616920:115460.887421 line # bug.rb: 6 18616920:115460.887424 call String#unpack <internal:pack>:256 18616920:115460.887427 line String#unpack <internal:pack>:257 18616920:115460.887430 line # bug.rb: 6 18616920:115460.887433 call String#unpack <internal:pack>:256 18616920:115460.887437 line String#unpack <internal:pack>:257 18616920:115460.887440 c-return Integer#times bug.rb: 5
ログを見るとString#unpack
はRubyのメソッドとして呼び出されていますが、どうやらreturnされていないようです。
これが挙動が異なっている箇所のようです。
ちなみにruby 3.0.0dev (2020-09-03T21:41:58Z master d4585e7470) [x86_64-linux]
だと正しくreturnされていました。
47044487789240:115847.614876 line # bug.rb: 5 47044487789240:115847.614956 c-call Integer#times bug.rb: 5 47044487789240:115847.614966 line # bug.rb: 6 47044487789240:115847.614972 call String#unpack <internal:pack>:256 47044487789240:115847.614977 line String#unpack <internal:pack>:257 47044487789240:115847.614983 return String#unpack <internal:pack>:258 47044487789240:115847.614990 line # bug.rb: 6 47044487789240:115847.614993 call String#unpack <internal:pack>:256 47044487789240:115847.614996 line String#unpack <internal:pack>:257 47044487789240:115847.615000 return String#unpack <internal:pack>:258 47044487789240:115847.615004 line # bug.rb: 6 47044487789240:115847.615007 call String#unpack <internal:pack>:256 47044487789240:115847.615010 line String#unpack <internal:pack>:257 47044487789240:115847.615013 return String#unpack <internal:pack>:258 47044487789240:115847.615016 line # bug.rb: 6 47044487789240:115847.615018 call String#unpack <internal:pack>:256 47044487789240:115847.615021 line String#unpack <internal:pack>:257 47044487789240:115847.615024 return String#unpack <internal:pack>:258 47044487789240:115847.615027 line # bug.rb: 6 47044487789240:115847.615030 call String#unpack <internal:pack>:256 47044487789240:115847.615033 line String#unpack <internal:pack>:257 47044487789240:115847.615036 return String#unpack <internal:pack>:258 47044487789240:115847.615039 c-return Integer#times bug.rb: 5
修正箇所を探してみる
Ruby 2.7からはいくつかのメソッドはRuby(とC)で実装されています。今回のString#unpack
もRubyで実装されているメソッドです。
なので、RubyでRubyを実装している関連の部分で意図した処理が出来ていない可能性がありそうです。
現在のmasterでは修正されていることから関連しそうな箇所を洗ってみました。
builtin.c
やString#unpack
が実装されているpack.rb
などのコミットログを漁ってみましたが、それらしいのはなかったですね。
で、VM周りのコードでなにかしら変更がありそうだとアタリをつけてみたところ以下のコミットを見つけました。
追加されているテストを見る限りString#unpack
の挙動関連で修正されているようです。
今後
とりあえず、チケットのほうにはmasterでは修正済みと伝えておいた(チケット作った人の意図が僕の認識とあってればだけどね)
あと、バックポートした方が良いんじゃないかとは投げといた。だれもやらなさそうなら該当のコミットをcherry-pickするとかしてpull requestにするかな