IOCCC ネタバレ解説はじめました & IOCCC 2020 に入賞したよ

IOCCC の全作品のネタバレ解説を目指すサイトを作りました。

mame.github.io

いまのところ、最初の 4 年分まで書いてます(IOCCC 1984IOCCC 1987)。週ペースで書き足していくつもりなのでご笑覧ください。

IOCCC は、「現存する世界最古のプログラミングコンテスト」と言われることもあります。つまり、現在も開催されているということです。今年の正月に、昨年の IOCCC 2020 の入賞作品が公開されました。自分のプログラムが 3 つ入賞したので、デモ動画と簡単な紹介を書いておきます。

endoh1 - Most explosive

www.youtube.com

端末でのマインスイーパーですが、推論でわかるようなところは大体勝手に進めてくれます。 そういうダルくてミスしやすい作業はコンピュータにやらせて、マインスイーパーの本質(勘で適当に開くところ)に集中できます。

このプログラムは IOCCC 2019 用に作っていたのですが、時差で締め切りを勘違いして投稿しそこねたやつなので、1 年寝かしてました。そのわりにはひねりがあまりないですが、それでも今回の中では一番よい出来かなと思っています。 アニメキャラ形状のプログラムで有名な omoikane さんがマップを作ってくれたのがとても嬉しかったです。IOCCC を知ったきっかけが omoikane さんの作品なので感慨深い。

ちなみにこれは 2007 年頃に Java Web Start で作ってたネタの焼き直しです。

endoh2 - Best perspective

www.youtube.com

スター・ウォーズのオープニング風にメッセージを流す ROT13 デコーダ

フォントはベジエ曲線で表現したものをコード内に埋め込んでいます。monumental quine で作った経験を生かして一晩くらいで作りました。

スター・ウォーズのスクロールはずっとやりたいと思っていたネタでしたが、いまいち面白くする工夫を思いつかず、ずっと放置していました。結局 ROT13 を混ぜる程度になったけれど、気に入り度は普通。

endoh3 -- Most head-turning

www.youtube.com

散髪屋にある時計のように左右反転している時計を埋め込んだ Quine 。

本当に単純なプログラムなので、これが採択されたのはちょっと意外でした。まあ、「今年の Quine」みたいな扱いでしょうか。もっと頑張りたかったので、やや不満な出来。

審査員から「Unicode の文字を使ったもっと鏡文字っぽいバージョンが欲しい」と言われたので、prog.alt.c も作りました。動画のいちばん最後にデモしてるとおり、I ᨅ ℇ ᔨ ਟ ∂ ⎲ 8 ♇ OI II ᨅI を使ってます。これを作らせたくて採択されたのかも。

他の入賞作品

こちらからどうぞ。

www.ioccc.org

そのうち日本語での解説も書くのでお楽しみに。

Rubyと型についてのポエム

zenn.dev

matz はじめコミッターの型に対する姿勢にも疑問を持っています。

というご意見が自分に刺さった気がしたので、他の話題はともかくこの点に関してだけ、ポエムを書きます。

Rubyに型が欲しい」というのは、「もっと速い馬が欲しい」だと思っています。意味を知らない人は ヘンリー・フォード もっと速い馬が欲しい で検索してください。

これは批判でも皮肉でもありません。みんなが馬の乗り方を知っている世界では、誰も乗り方を知らない自動車より、速い馬のほうが確実で合理的です。まして、自動車が本当に実現できるかどうかわからない段階では。なので、他言語で型注釈を書くことによるプログラミング体験が良いと思った人が、それをRubyでも享受したいと思うのは自然だと思います。実際、Steep や Sorbet は Ruby でそういうプログラミング体験を提供することを目指していて、すでにある程度実現できています。

ただ、みんなが本当にほしいのは、「バグを早期発見できるRuby」「IDEで補完やドキュメント表示ができるRuby」だと思っています *1 。型注釈はこれらの利点を実現するためのひとつの手段にすぎません。

Ruby 3 は公式で型注釈を入れないという判断をしました。これに関して、「型注釈を書かないと上記の利点が実現できないことは歴史が証明している。Ruby は歴史に学ばない」というような意見を聞いたこともあります。しかしほんの 10 年前には、「言語に静的型付けを後から導入するのは無理。型は言語の設計段階から考慮しないと入れられない。歴史が証明している」などと言われていたことをご存知でしょうか。漸進的型付けが大成功した現代では、言う人がいなくなった言説です *2

TypeProf は型注釈なしで同等の利点を実現できないかに挑戦する試みです。TypeProf は完成しても、既存の静的型付けのプログラミング体験とは違う体験になると思われるので、まさに「自動車」を目指しています。残念ながら、TypeProf はまだ完成品の自動車というには程遠く、まだエンジンができたかどうかという段階です。正直に言うと、TypeProf がどんな自動車になるのか(何にもなれないのか)は、自分でもまだよくわかっていません。でも、本格的に作り始めた2年前から見ると、予想よりだいぶ動くものになったので驚いています(ひいき目は認めます)。

TypeProf 何も知らない人のために参考リンク↓

techlife.cookpad.com

「まともに使えるかどうかわからない自動車よりも、今すぐ使える速い馬が欲しい」というのは、完璧に正当な主張です。そういう人は、Steep や Sorbet をぜひトライしていただきたいです。まだいろんなライブラリに RBS が足らないので、RBS を書いて gem_rbs に pull request を送りまくってください。ライブラリの RBS が増えると Steep や Sorbet で解析できる範囲が増えますし、TypeProf の解析速度や精度も上がるので、とにかくありがたいです。

ということでポエムでした。こういうポエムは、ちゃんと自動車が作れてから言えたらカッコよかったんですけどね。なんか書きたくなった。なお、これは Ruby コミッタの総意などではなく、ぼくの個人的な意見です。

*1:型注釈を書くことの他の利点には、インターフェイス言語化することで設計を整理したり共同開発しやすくしたりすることがあると思います。Ruby 3 では型を表現するための記法 RBS が公式に導入されるので、(理論上は)この利点はそのまま享受できると思います。

*2:言った人に罪はないです。言語に静的型付けを後から導入する試みは 1990 年ごろから模索されていたテーマですが、ずーっと成功事例がなく、30 年してようやく実用化したものなので。

設定情報をエレガントに管理する方法(解決なし)

アプリケーションにはいろいろ設定があるものです。一般的な例では、production / development のようなモードや、ログレベルなど。プログラムを書くとき、こういうデータをどのように管理しますか?

大きく 2 種類の書き方があると思います。

  1. グローバル変数(やそれに類するもの)に入れる
  2. クラス生成時にコンストラクタに引き回す

どちらも一長一短があると思っています。

1. グローバル変数に入れる

たとえば、$config = { mode: :development } などとするだけ。

Rubyの場合、グローバル変数だけでなく、定数に入れたり、クラスメソッドにしたり、singletonライブラリを使ったり、スレッドローカルストレージを使ったりするのもこの分類に含めます。

長所

  • 記述がとても簡潔
  • 設定の追加が簡単

短所

  • グローバル変数を使うことに罪悪感がある
  • 1 つのプロセスで唯一の設定しか持てない

解説

とにかく簡単な方法。設定情報が必要なときはグローバル変数を読み出すだけなので、プログラムの記述は非常に簡潔。また、設定を追加したくなったときも自明。名前の衝突が気になるなら、$MyApp_configのように、アプリケーション名をprefixすると良さそう(ただし長くなるので、記述性は若干下がる)。

この方法を選びたくない最大の理由は、気持ちの問題だと思う。教育されたプログラマは「グローバル変数はダメ」と心に刷り込まれている。しかし設定情報をグローバル変数に入れることは、そこまで問題ではない気もする。グローバル変数がダメなのは、実行中にグローバル変数を書き換えることでモジュール間に暗黙的な依存が発生してしまうためだけれど、設定情報はアプリ初期化時以外に代入されることはないはずなので、意図しない依存は発生しないはず。

この方法の実用上の問題は、設定情報をプロセス内で1つしか持てないこと。つまり、同一プロセス内で異なる設定のアプリケーションインスタンスを複数作ることができない。大して問題ないと思うかもしれないが、テスト時などに様々な設定でのアプリケーションインスタンスを作りたくなったり、アプリケーションをライブラリとして使いたくなったりしたときに困る。

なお、定数やクラスメソッドなども本質的にはグローバル変数と変わらないので、プロセスの問題は解決しない *1 。スレッドローカルストレージを使っても、本質的な問題は変わらない *2

2. クラス生成時にコンストラクタに引き回す

たとえば次のように、クラスごとにインスタンス変数@configなどで保持する。設定情報が必要なクラスには必ず設定情報を渡す。

class MyApp::Foo
  def initialize(config, ...)
    @config = config
    ...
    @bar = Bar.new(@config, ...)
    ...
  end
end

長所

短所

  • 記述が極めて冗長(ほとんどすべてのクラスに設定情報をたらい回しする必要がある)
  • インスタンスを大量に生成する場合、速度やメモリ使用量がやや気になる(多くの場合は無視できるとは思う)

解説

教科書的に正しそうな方法。グローバル変数の類が一切ないので罪悪感がない。また、異なる設定のアプリケーションインスタンスを作ることもできる。

しかし、記述性は明らかにグローバル変数の方法より劣る。initializeは必ず@configを受け取る必要があり、newには必ず@configを渡す必要がある。

また、ASTのノードのクラスのように、インスタンスが大量生成される可能性があるクラスに毎回@configをもたせるのは、無駄が気にならなくもない。ほとんどの場合、すべての@configには同じオブジェクトへの参照が入るだけなので。(ただし、実際に問題になる可能性は高くないと思う)

近い将来にアプリケーションインスタンスを複数作る必要がない場合、この方法を選ぶメリットはないと思う。しかし、必要になってから書き換えるには、変更量は非常に多くてつらい。しかし、だからといって防衛的にこっちの方法を選んで記述性や実行効率を下げるのは、生産性を下げていると感じてしまう……。

なお、この方法のバリアントとして、「すべての設定情報を渡すのではなく、そのクラスが必要としている情報だけを渡す」というのがある。これはより「正しい」感じがするが、生産性はより最悪になる *3

どうなれば幸せか

上の 2 つはどちらを選んでも何か間違っているような気分になり、いつもモヤモヤしています。なにか言語機能が不足しているのではないかと思うのですが、どういう機能があれば綺麗に解決するのかもよくわかりません。

  • 動的スコープな変数があればよいのでは?と思っていた時期もあったのですが、複数のアプリケーションインスタンスを相互に実行するような場合にはイマイチ使えなさそう。
  • オブジェクトをグループ化する機能があればよさそうな気がしますが、記述性を下げずに所属グループを指定する方法を思いつかない。Ractor が近そうだけれど、Ractor はやはり別物なので多分転用はむずかしい(シェアされたオブジェクトの中で設定を参照すると曖昧とか)。

まとまらないまとめ

わかりやすそうなので「設定情報」で話しましたが、アプリケーション全体の管理を行う(半グローバルな)インスタンスも同様にすべての関係インスタンスに参照もたせたい気持ちになります。

この問題をエレガントに解決している言語の事例とか言語機能の論文とかあれば、教えてください。

*1:グローバル変数」という言葉は避けられるので、気持ちは落ち着くかもしれない。実際、実行中にうっかり書き換えてしまうリスクは減るので、多少改善はしてそう。

*2:「スレッド内で 1 つ」に緩和できるものの、アプリケーションインスタンスを複数同居させられない問題自体は変わらない。あと記述も長くなりがち。

*3:「クラスが必要としている情報」はなかなか予測できないし、そのクラス自身が必要としなくても、そのクラスの中で別のクラスをインスタンス化する際に必要になるということもありうる。

rubygems を 1.5 倍に高速化した方法(stackprof --d3-flamegraph の使い方)

タイトルは釣りです。明日 ISUCON 10の予選があると小耳に挟んだので、Ruby で参加する人が絶対に抑えておくべき? Ruby 高速化の tips をひとつ。stackprof --d3-flamegraph のご紹介です。

例題

ちょうど今日、gem install aws-sdk にかかる時間を 37 秒から 24 秒ほどに高速化しました。

変更前:

$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed
real    0m37.104s
user    0m36.952s
sys     0m0.333s

変更後:

$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed
real    0m23.905s
user    0m23.740s
sys     0m0.365s

stackprof --d3-flamegraph ってやつを使ったら 2 時間くらいでできました。

stackprof の使い方

このあたりはみんな知ってると思うのでざっくりと。

対象である gem コマンドに StackProf.run(...) do ... end を挟み込みます。rack だったら use StackProf::Middleware でしょうか。

diff --git a/bin/gem b/bin/gem
index baf607308..6a508e989 100755
--- a/bin/gem
+++ b/bin/gem
@@ -11,8 +11,13 @@

 args = ARGV.clone

+require 'stackprof'
+StackProf.run(mode: :cpu, out: 'stackprof.dump', raw: true) do
+
 begin
   Gem::GemRunner.new.run args
 rescue Gem::SystemExitException => e
-  exit e.exit_code
+  e.exit_code
+end
+
 end

raw: true というのが最重要ポイントです。あと、exit すると stackprof.dump が出力されないようなので、少しだけいじっています。

実行する。

$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed

real    0m36.562s
user    0m36.418s
sys     0m0.313s

stackprof.dump ができていると思うので、stackprof コマンドで結果を見ます。

$ stackprof stackprof.dump
==================================
  Mode: cpu(1000)
  Samples: 3543 (0.06% miss rate)
  GC: 340 (9.60%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       567  (16.0%)         374  (10.6%)     Gem::Version#<=>
       446  (12.6%)         349   (9.9%)     Gem::Requirement.parse
       287   (8.1%)         287   (8.1%)     (sweeping)
       498  (14.1%)         257   (7.3%)     URI::Generic#hash
       227   (6.4%)         227   (6.4%)     Gem::Version#canonical_segments
      1145  (32.3%)         198   (5.6%)     Gem::Resolver::APISpecification#initialize
       630  (17.8%)         184   (5.2%)     Gem::Requirement#initialize
       172   (4.9%)         172   (4.9%)     Gem::Version.new
       241   (6.8%)         136   (3.8%)     URI::Generic#component_ary
       842  (23.8%)         128   (3.6%)     Gem::Dependency#initialize
       131   (3.7%)         106   (3.0%)     Gem::Platform#=~
       714  (20.2%)          84   (2.4%)     Gem::Requirement.create
        81   (2.3%)          76   (2.1%)     URI::Generic#component
       156   (4.4%)          75   (2.1%)     Gem::Version#hash
      3070  (86.6%)          70   (2.0%)     Gem::Resolver#search_for
        52   (1.5%)          52   (1.5%)     Gem::Platform.local
       412  (11.6%)          51   (1.4%)     Gem::Requirement#satisfied_by?
        47   (1.3%)          47   (1.3%)     Gem::Version#_version
        46   (1.3%)          45   (1.3%)     Gem::Requirement#none?
       564  (15.9%)          44   (1.2%)     Gem::Dependency#match?
        44   (1.2%)          44   (1.2%)     Gem::Resolver::Specification#initialize
        42   (1.2%)          42   (1.2%)     (marking)
        42   (1.2%)          42   (1.2%)     Gem::Platform.new
        33   (0.9%)          33   (0.9%)     Gem::Resolver::DependencyRequest#name
        33   (0.9%)          30   (0.8%)     Gem::StubSpecification#data
        30   (0.8%)          30   (0.8%)     Gem::Resolver::ActivationRequest#initialize
        28   (0.8%)          28   (0.8%)     Gem::Version#prerelease?
        26   (0.7%)          26   (0.7%)     Gem::Dependency#requirement
        24   (0.7%)          24   (0.7%)     URI::Generic#userinfo
      1765  (49.8%)          22   (0.6%)     Gem::Resolver::APISet#find_all

なるほど、Gem::Version#<=>ボトルネックなんですね。じゃあこれを高速化しましょう!Gem::Version#<=> のコードを見て……という前に考えるとよいことがあります。

このメソッドはバージョン番号の比較をする演算なので、それ自体がすごく遅いとは考えにくいです。そういうのを速くしようとすると、近視眼的で hacky な最適化になりがちです。どの当たりに時間がかかっているのか、もうすこし大局的に眺めてみましょう。

stackprof --d3-flamegraph の使い方

そこで、flamegraph を使ってみます。次のように実行します。

$ stackprof --d3-flamegraph stackprof.dump > stackprof.html

このとき、

.../lib/stackprof/report.rb:197:in `print_d3_flamegraph': profile does not include raw samples (add `raw: true` to collecting StackProf.run) (RuntimeError)

のようなエラーが出たら、上述の raw: true を付け忘れているので、直して再プロファイルしてください。

この html を開くと、フレーム(炎)というか山のような図が出てきます。

f:id:ku-ma-me:20200911223800p:plain
stackprof --d3-flamegraph の出力(html)

これは、スタックフレームを表現しています。下から 2 番目が起動スクリプトの bin/gem があり、そこから呼び出されているメソッドが上に積み重なっています。

勘違いしやすいですが、このグラフは時系列とは一切関係ありません。左から右に時間が進んでいる図ではありません。実行中のスタックフレームを定期的に観測し、そのスタックフレームを辞書順にソートして並べたものになっています。

見方にコツがあります。例でいうと、下から 6 番目の Gem::GemRunner#run とその上の Gem::CommandManager#run は、横幅がほとんど同じです。これは、Gem::GemRunner#runGem::CommandManager#run を呼び出しており、前者の実行時間は後者の実行時間とほとんど同じ、という意味です。よって、Gem::GemRunner#run のコードを最適化しようと思ったときに考えるべきなのは、「Gem::CommandManager#run の呼び出し回数を減らせないか」ということです。しかしコードを見ると、前者は後者を 1 回呼び出しているだけでした。つまり、GemRunner#run を何年眺めても何の高速化もできそうにないということになります。

実際の --d3-flamegraph の結果を置いておきます。

rubygems-stackprof-d3-flamegraph.netlify.app

高速化できそうなところを探す

ここからは結局、気合(デバッグプリント)です。

このグラフはわりと横幅が同じところが多く、上の方には Gem::Resolver クラスのメソッドがいっぱい並んでいます。aws-sdk は大量の依存を持つので、依存関係の解決に時間がかかっているのは直感にあいますね。一番横幅が長そうな子供を選んでたどっていくと、find_all というメソッドがいくつか並んだあとで、Gem::Resolver::APISpecification#initialize が 26.347% も占めていることがわかります。

f:id:ku-ma-me:20200911224103p:plain
Gem::Resolver::APISpecification#initialize を発見したところ

呼び出し元の Gem::Resolver::APISet#find_all と合わせてみると、Gem::Resolver::APISpecification というのは、rubygems.org のサーバから送られてきたデータをオブジェクト化したもののように見えます。いくつかデバッグ出力を挟んで実行してログを観察すると、中身がまったく同じ Gem::Resolver::APISpecification インスタンスを何回も作ってる気配を感じました。この手のオブジェクトは中身を破壊的に変更することはなさそうなので、生成したオブジェクトを使い回せるのでは?と考えて、オブジェクト生成をメモ化する魔法の 7 行を書いてみます。

  @@cache = {}
  def self.new(set, api_data)
    cache_key = [set, api_data]
    cache = @@cache[cache_key]
    return cache if cache
    @@cache[cache_key] = super
  end

再実行。

$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed

real    0m25.387s
user    0m24.436s
sys     0m0.354s

やったね。破壊的操作がないことを確かめるため、各フィールドを freeze してもテストが通ることを確認。まあ大丈夫じゃないかな……ということで PR を送って無事マージされました(もしどこかで破壊してて動かなくなってたらごめんね!)。

github.com

修正後の flamegraph

修正後の flamegraph も置いておきます。

rubygems-stackprof-d3-flamegraph.netlify.app

Gem::Resolver::APISpecification#initializeの代わりにGem::Resolver::APISpecification.newが来るようになりました。割合も 15.249% に減っています。 ここからsuperでたまにGem::Resolver::APISpecification#initializeを呼んでいるはずなのですが、定期的な観測にひっかからないほどレアになったということでしょう(たぶん)。

なお、デバッグプリントからの推測ですが、gem install は、公開されているすべてのバージョンのメタ情報(依存関係情報)をフェッチしてきて、すべてオブジェクト化してから依存関係を解決するようです。これは公開バージョンが増えるほど遅くなりそうなので、まだまだ改善の余地がありそうです。

まとめ

stackprof --d3-flamegraph のご紹介でした。実はこの機能を作ったのは自分なので、自慢です *1 。でも役に立つと思います。

Ruby で ISUCON に参加する人たち、ぜひがんばってください。

*1:--d3-flamegraph の前から flamegraph を生成する方法はあったのですが、いまいち素直に使えなかったので。

カロリーメイトリキッドのQuineを書きました

縁あって、カロリーメイトリキッドのプロモーション用にちょっとした Ruby プログラムを書かせてもらいました。

www.otsuka.co.jp

↑のリンクを開いて、cd .Quine したところにある CML_quine.rb がそれです。 cat CML_quine.rb とすると中身が見えます。ruby CML_quine.rb すると動きます。

f:id:ku-ma-me:20200803184915p:plain
CalorieMate-Liquid-Quine

実行してみましたか?サイト上で気楽に実行できるので、ぜひ試してみてください。

これがどういうプログラムなのか、簡単に解説しておきます *1

ローカルでの遊び方

サイト上で ruby CML_quine.rb をするだけでも楽しめますが、自分のパソコンに保存するとより楽しめます。

まず、cat CML_quine.rb した中身をまるごとコピーしてください。 n=2;で始まる行の頭から、'CalorieMate-Liquid-Quine' で始まる行の終わりまでです。 それをペーストして、CML_quine.rb というファイル名でローカルに保存してください。

そして、Ruby をインストールして、ターミナル(端末)で ruby CML_quine.rb で実行してください。 Windows Terminal で動作確認しています。

Quine

Quine とは、実行すると自分のソースコードを出力するプログラムのことです。 といっても、ソースコードをファイル読み込みして出力するわけではありません。 ちょっとしたパズルのようなコードを書くことで、ファイル読み込みせずに自分を出力できます。 詳しくはWIkipediaの記事や拙著『あなたの知らない超絶技巧プログラミングの世界』をご覧ください。

そして、このプログラムはQuineみたいなもので、実行するとまずソースコードを出力し、それからアニメーションをします。

「みたいなもの」と言ったのは、1回実行しただけではちょっとだけ違う結果になるからです。 サイトのreadme.mdにも書いてありますが、次のように3回実行を繰り返すと元に戻るようになっています。

$ ruby CML_quine.rb  > CML_quine2.rb

$ ruby CML_quine2.rb > CML_quine3.rb

$ ruby CML_quine3.rb > CML_quine4.rb

$ diff -s CML_quine.rb CML_quine4.rb
ファイル CML_quine.rb と CML_quine4.rb は同一です

ターミナル上でのアニメーション

各プログラムの違いは、『フレーバー』です。 CML_quine.rb と CML_quine2.rb と CML_quine3.rb をそれぞれ単体で実行すると、いずれも同じアニメーションをしますが、最終的に出来上がるフレーバーが変わるようになってます。 次のように実行してみてください。

$ ruby CML_quine.rb

$ ruby CML_quine2.rb

$ ruby CML_quine3.rb

このアニメーションは、エスケープシーケンスを使って色付き文字のモードにしたり、カーソルを移動したりすることで行っています。

ロゴを描くためのカーソルの動きのデータは、すべてコード中に埋め込まれています。 そのままだと巨大になってしまうので、バイトペア符号化によって圧縮しています。

流体シミュレーション

最後。缶に黄色い液体が注ぎ込まれるアニメーションですが、これは決まった動きをハードコーディングしているわけではなく、流体シミュレーションを使って実行時に計算しています。 流体力学の原理であるナビエ-ストークス方程式Smoothed Particle Hydrodynamicsと言われる方法で数値的・近似的に解きます。 簡単に言えば、液体を表現する粒子同士がお互いに押し合ったり(圧力)、粘ついたり(粘性)、重力に引っ張られたり(外力)するのをシミュレーションしています。

実はここは、以前C言語で書いたコードの移植です *2 。こちら。

www.youtube.com

ただ、今回はシミュレーションの精度を上げるために粒子の数を増やしたこともあって実行速度が遅くなってしまったので、空間分割法を実装して高速化しました。

おまけ

「プログラムを表示した後、アニメーションで上書きしちゃったら Quine にならないじゃないじゃん!」と思う人がいるかもしれません。 しかし、背景色と文字色が同じになってて読めないだけで、実は文字はちゃんと表示されています。 次の動画のように端末からコピペすれば実行できます。

「出力にエスケープシーケンスを混ぜたらプログラムとして実行できない!」と思う人がいるかもしれません。 しかし、エスケープシーケンスはコメント内に出すようになっているので、実はちゃんと動きます。 次のように実行すれば、エスケープシーケンス入りの CML_quine2.rb がちゃんとプログラムとして動くことがわかります。

$ script -q -c "ruby CML_quine.rb" /dev/null | tee CML_quine2.rb
$ ruby CML_quine2.rb
$ vim CML_quine2.rb

ということで

このコードはカロリーメイトリキッドを 3 種類ぜんぶ飲みながら実装しました。

以上の処理はどこか見えないところに隠されているわけではなく、cat CML_quine.rb で見ることができる 22 行のプログラムの中にすべて詰め込まれています。 プログラミング言語 Ruby の簡潔さ・強力な言語機能・柔軟性を悪用するとこんなこともできるんですよ。他の言語ではなかなかむずかしい。

ということで、腕に覚えのある人はぜひ解読してみてください! 他にもここで解説しなかった工夫がいくつか仕込まれています *3

なお、Quine に興味がある人は、拙著『あなたの知らない超絶技巧プログラミングの世界』に詳しいやり方からたくさんの実例までむちゃくちゃ詳しく書いてあるので、ぜひ読んでみてください。(宣伝)

*1:念のために書いておくと、このブログを書くことは関係者の方に了承を得ております。

*2:余談ですが、元のソースコードを失っていたので、難読化コードを読み解いた。

*3:流体シミュレーションをさらに高速化するためのチート(上げ底)や、缶の形状を実行時に生成する式、isatty を使っているところ、謎のイニシャル :-)などなど

CPU律速なRuby/Pythonコードはデフォルト設定のdocker上で遅くなる

English version

要約

dockerはデフォルトでセキュリティ機構(Spectre脆弱性の対策)を有効にします。この影響で、RubyPythonのようなインタプリタは速度が劣化します。特にCPU律速なプログラムで顕著に遅くなります(実行時間が倍くらいになることがあります)。

現象

Rubyで1億回ループするコードを、直接ホスト上で実行する場合と、docker上で実行する場合で実行時間を比較してみます。

直接ホスト上で実行した場合:

$ ruby -ve 't = Time.now; i=0;while i<100_000_000;i+=1;end; puts "#{ Time.now - t } sec"'
ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]
1.321703922 sec

docker上で実行した場合:

$ docker run -it --rm ruby:2.7 ruby -ve 't = Time.now; i=0;while i<100_000_000;i+=1;end; puts "#{ Time.now - t } sec"'
ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]
2.452876383 sec

dockerを使うと実行時間がおよそ倍になっています(1.3秒→2.5秒)。

docker runに--security-opt seccomp=unconfinedというオプションを与えて実行すると、ホストと同等程度の速度になります。

$ docker run --security-opt seccomp=unconfined -it --rm ruby:2.7 ruby -ve 't = Time.now; i=0;while i<100_000_000;i+=1;end; puts "#{ Time.now - t } sec"'
ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]
1.333669449 sec

Ruby特有ではなく、Pythonでも同じ現象が起きます(i=0 / while i<100000000: i+=1 という2行のコードで7.0秒→11秒)。

なお、カーネルの設定次第では、この現象が再現しないこともあります(後述)。

原因

LinuxカーネルにはSpectre脆弱性の対策がいくつか実装されています。

この対策の中に間接分岐予測を抑制するもの(STIBPと呼ばれる)があり、CPU律速なコードが50%ほど速度低下するということで、Linuxカーネルのデフォルトではオフになっています(参考)。 一方、dockerはデフォルトで、Spectre脆弱性の対策を有効にしてコンテナを実行します。*1

これはほぼすべてのプログラムの速度を低下させます*2が、RubyPythonのようなインタプリタは間接分岐(switch/caseやdirect threadingなど)を多用しているので、特に強く影響を受けます。dockerの外では対策がオフなので高速に実行され、dockerの中ではオンなので速度劣化が起きます。

証拠として、上記のベンチマークプログラムのperf statを見てみると、branch-missesが圧倒的に増えていることが観察できました(522,663回→199,260,442回)。 https://www.phoronix.com/scan.php?page=article&item=linux-420-stibp&num=2 --security-opt seccomp=unconfined あり(Spectre対策なし)

 Performance counter stats for process id '153095':
          1,235.67 msec task-clock                #    0.618 CPUs utilized          
                 8      context-switches          #    0.006 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
                 2      page-faults               #    0.002 K/sec                  
     4,284,307,990      cycles                    #    3.467 GHz                    
    13,903,977,890      instructions              #    3.25  insn per cycle         
     1,700,742,230      branches                  # 1376.378 M/sec                  
           522,663      branch-misses             #    0.03% of all branches        
       2.000223507 seconds time elapsed

--security-opt seccomp=unconfined なし(Spectre対策あり)

 Performance counter stats for process id '152556':
          3,300.42 msec task-clock                #    0.550 CPUs utilized          
                16      context-switches          #    0.005 K/sec                  
                 2      cpu-migrations            #    0.001 K/sec                  
                 2      page-faults               #    0.001 K/sec                  
    11,912,594,779      cycles                    #    3.609 GHz                    
    13,906,818,105      instructions              #    1.17  insn per cycle         
     1,701,237,677      branches                  #  515.460 M/sec                  
       199,260,442      branch-misses             #   11.71% of all branches        
       6.000985834 seconds time elapsed

なおこの問題は、STIBPがconditional(デフォルトはオフだがseccompで有効にできる)のときだけ起きます。STIBPがdisabled(常にオフ)またはforced(常にオン)の環境では、dockerだけ遅いという現象は起きません。disabledの場合ホストもdockerも速い(そして脆弱)、forcedの場合はホストもdockerも遅い、ということになります。*3

ちなみに、STIBP以外にも、投機的ストアバイアスのサイドチャネル攻撃の対策(spec_store_bypass_disable)もかなり速度劣化を起こすようです。笹田耕一さんの調査によると spectre_v2_user=off spec_store_bypass_disable=off というカーネルオプションを用いることで、--security-opt seccomp=unconfinedなしのDocker上でも速度劣化がなくなったということでした。

対策

残念ながら、あまりオススメできる対策はありません。--security-opt seccomp=unconfined をつければ速くなりますが、Spectre攻撃に対して脆弱になるのでやめたほうがいいでしょう(ちなみに--privilegedでも速くなります)。

ただし、これはCPU律速なコードでしか問題にならないと思います。Ruby on Railsを使ったWebアプリは多くの場合IOやGC律速になっているので、Spectre対策を止めても観測できるほどの速度向上はしないでしょう(たぶん)。なので当面気にしないことをおすすめします。

長期的には、CPU側でSpectre対策がなされればこの問題は解決すると思います(ただし10年スパンで考える必要はある)。もしくは、笹田耕一さんがRubyKaigi 2019で発表していた実行方式(context threading)は間接分岐を多用しないので、これが取り込まれれば解決するかもしれません(数年スパンで考える必要はある)。

謝辞

  • 相談ツイートに反応してくださったみなさん(特に@ryotaraiさんのリツイート
  • ruby-jp Slackの #container チャンネルのみなさん(特に件のオプションが効く理由を調査してくれた笹田耕一さん)
  • Rubyコミッタのみなさん

余談

Ruby 3の速度目標ベンチマークになってるoptcarrotがこの影響をとても受けて、ホストだと33 fpsなのがdockerだと14 fpsになるので困ってました。原因と(一応の)対策がわかったので、これでベンチマークが取れる。

蛇足(2020/05/23 12:00)

  • 律速とは、速度を決定する要因、つまりボトルネックのことです :-)

  • dockerが遅いと言えば、ふつうはdockerが仮想化しているファイルシステムやネットワーク関係を疑うところですが、メイン部で一切syscallをしないCPU律速なコードでも遅くなることがある、というのが意外なところでした。

  • Ruby/Pythonコードは」というタイトルにしてしまいましたが、本文に書いた通りだいたいどんなプログラムでも遅くなります(脚注に書いたように、実際Javamemcachedなども遅くなるらしい)。最初に気づいたのがRubyで、Rubyにはちょっと詳しいので限定して書いてしまった。他のプログラムよりRuby/Pythonのようなインタプリタは重症度がひどい可能性はあると思ってますが、特に比較はしていないし、ワークロードに強く依存するので比較は難しそうです。

  • この問題は「誰かが悪い」ということではないです :-) 用途を考えると、dockerがSpectre対策をデフォルトで有効にするのは理解できます(意識してやってるのか、たまたまそうなってるのかは不明ですが)。

*1:笹田注:より正確には、Linuxの起動時の設定が、「通常実行では脆弱性対策を有効にしない(脆弱なまま)だが、seccompなどを利用すると有効にする」となってるときにこの現象が起きるようです。手元の Ubuntu 18.04 がそういう設定でした。最近の Docker は、デフォルトでseccompを有効にするため、何もしないとこれらの対策が入り、速度劣化が観察できる、というようです。Linux Kernel の起動オプションで色々選べるようです。具体的な設定は Spectre Side Channels — The Linux Kernel documentation をご覧下さい。Docker起動時にseccompの設定で制御できるのかはわかりませんでした(出来ても良さそうですが)。

*2:この記事によると、STIBPはJava、Node.js、memcachedPHPなどのベンチマークで速度劣化が確認されたようです。

*3:どういう設定になっているかは /sys/devices/system/cpu/vulnerabilities/spectre_v2 というファイルを見ればわかります。

Rubyのテストのややこしい失敗を直した話

Ruby の CI 維持業というのはこんな感じという事例紹介。

CIを観察する

RubyのCIがときどき次のように失敗していました。

  1) Error:
TestM17N#test_object_inspect_external:
Encoding::CompatibilityError: incompatible character encodings: UTF-8 and UTF-16BE
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:311:in `encode'
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:311:in `inspect'
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:313:in `inspect'
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:313:in `test_object_inspect_external'

http://ci.rvm.jp/logfiles/brlog.trunk-test-random.20200322-221411

なんか例外が発生しています。必ず再現するわけではなく、手元で再現もできないのですが、日に数回程度失敗し続けていて鬱陶しいテストでした。このログだけ見て問題箇所を特定できたらエスパーです。

問題を切り分ける

まず、ボトムアップトップダウンの両面から観察を試みます。

ボトムアップ観察、つまり例外発生箇所から観察します。エラーメッセージの "incompatible character encodings" で検索すると、5箇所ほどrb_raiseしている箇所がありました。しかし、どれで発動しているのかよくわかりませんでした。

トップダウン観察は、失敗しているテストを見ることです。

def test_object_inspect_external
...
  Encoding.default_external = Encoding::UTF_16BE
...
  def o.inspect
    "abc".encode(Encoding.default_external)
  end

  assert_equal '[abc]', [o].inspect
...
end

問題を切り分けるために、inspect が無関係であることを確かめたいのですが、このテストだけ切り出しても問題が再現しないので、確かめることができません。そこで、"abc".encode(Encoding.default_external) だけで例外が出るかどうか、それらのエンコーディングが妙なことになっていないかなどをデバッグ出力させるコードをテストに突っ込んで、しばらくCIを観察することにしました。

デバッグ情報を集める

翌朝CIを見ると、めでたく失敗が起きていましたデバッグ出力を見ると、"abc".encode(Encoding.default_external) 単体で例外が起きることが確認できました。また、それらのエンコーディングも期待通り。意外性はなかった。

ということで問題はほぼ特定できたのですが、しかし、ちょっと考えてもどういう経緯でこの例外が投げられるかはわかりませんでした。そこで、例外発生時の C のスタックトレースを採取することを試みます。次のようなデバッグコードをテストコードにコミットしました。

TracePoint.new(:raise) do |tp|
  Process.kill(:SEGV, $$)
end.enable { "abc".encode(Encoding.default_external) }

TracePoint ってこういう風につかうものなんですよね。

問題を分析する

また翌朝、CIが失敗していて無事Cのスタックトレースが取れました

String#encode が呼ばれてから raise が起きるまでのトレース。

/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_raise+0x94) [0x7fc6c5e4cf74] /tmp/ruby/v2/src/trunk-test-random/error.c:2689
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(enc_compatible_p+0x0) [0x7fc6c5e32d80] /tmp/ruby/v2/src/trunk-test-random/encoding.c:915
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_enc_check) (null):0
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_file_expand_path_internal+0x109) [0x7fc6c5e61cf9] /tmp/ruby/v2/src/trunk-test-random/file.c:3640
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_file_expand_path_internal+0x847) [0x7fc6c5e62437] /tmp/ruby/v2/src/trunk-test-random/file.c:3746
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_find_file_ext+0x3fb) [0x7fc6c5e62f3b] /tmp/ruby/v2/src/trunk-test-random/file.c:6330
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(require_internal+0x2dc) [0x7fc6c5eb044c] /tmp/ruby/v2/src/trunk-test-random/load.c:909
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_require_string+0x23) [0x7fc6c5eb2173] /tmp/ruby/v2/src/trunk-test-random/load.c:1111
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(load_transcoder_entry+0xa8) [0x7fc6c5fe7908] /tmp/ruby/v2/src/trunk-test-random/transcode.c:386
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(load_transcoder_entry+0x14) [0x7fc6c5feb5d0] /tmp/ruby/v2/src/trunk-test-random/transcode.c:372
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_econv_open) /tmp/ruby/v2/src/trunk-test-random/transcode.c:943
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(str_transcode0+0x268) [0x7fc6c5feed28] /tmp/ruby/v2/src/trunk-test-random/transcode.c:2275
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(str_encode+0x64) [0x7fc6c5fef3f4] /tmp/ruby/v2/src/trunk-test-random/transcode.c:2763

問題を分析するのに十分な情報が取れました。これをもとに、各C関数の実装を解読していきます。1時間くらいがんばる。結果として、

  • Encoding.default_external = Encoding::UTF_16BE とすることで、ファイルシステムエンコーディングが UTF-16BE とみなされるようになる
  • そのあと String#encode によって Encoding::UTF_16BE の実体がロードされようとする
  • このロードの際、LOAD_PATHの文字列(UTF-8)が相対パスのとき、カレントディレクトリ(UTF-16BE)と結合しようとして件の例外が投げられる

という現象であると仮説が立てられました。

この現象自体がバグかどうかは判断が難しい。ファイルシステムが UTF-16BE ならば LOAD_PATH に UTF-8 文字列を入れるのがおかしいわけで、この例外自体は正当かもしれない。でも現実問題として、いまの Rubyファイルシステムが ASCII-compatible でないエンコーディングの場合をサポートしてない気がするので、ちょっと微妙。

仮説を検証する

この仮説をもとに、再現コードを作ります。デバッグ出力をはさみつつ30分ほどがんばると、次のコードで件の例外が観測できました。

$LOAD_PATH << "no_existing_dir"
Encoding.default_external = Encoding::UTF_16BE
load "dummy.rb" #=> incompatible character encodings: UTF-8 and UTF-16BE

存在するディレクトリへの相対パスを $LOAD_PATH に追加すると内部的に絶対パスに変換されるので、問題は発現しません。存在しないディレクトリを加えるところが再現のポイントでした。

ということで、この問題は、「何かのテストが存在しないディレクトリを $LOAD_PATH に追加している」「その後、件のテストを実行すると例外が投げられる」という現象である可能性が高まりました。

問題のテストを探す

テストの中で $LOAD_PATH をいじっているコードを全部見ていきます。たくさんあったので面倒でしたが、ほとんどの箇所は絶対パスを入れているので、丁寧に見ていけば見つけられました。

case ENV['JSON']
when 'pure'
  $:.unshift 'lib'
  require 'json/pure'
when 'ext'
  $:.unshift 'ext', 'lib'
  require 'json/ext'
else
  $:.unshift 'ext', 'lib'
  require 'json'
end

https://github.com/ruby/ruby/blob/13e9551b97d6bb9fcd09283692f6090f4c418059/test/json/test_helper.rb

まさか JSON のテストが原因とは、最初の問題からは想像できないですね。

ちなみに、これは JSON を gem として開発するときのハックのようです(JSONはpure Ruby実装とC実装の2つを持っていて、環境変数によってテスト対象を制御できるようにしている)。しかし Ruby にバンドルされた状況下では常にC実装を使うので、このハックは無意味です。

手元で再現させる

これが原因であることを確認するためには、json と件のテストだけを実行すればいいです。

$ make test-all TESTS="json ruby/m17n -n test_object_inspect_external"
Run options: 
  --seed=94886
  "--ruby=./miniruby -I../ruby.src/lib -I. -I.ext/common  ../ruby.src/tool/runruby.rb --extout=.ext  -- --disable-gems"
  --excludes-dir=../ruby.src/test/excludes
  --name=!/memory_leak/
  -n
  test_object_inspect_external

# Running tests:

[1/1] TestM17N#test_object_inspect_external/home/mame/work/ruby.src/test/ruby/test_m17n.rb:319: [BUG] Segmentation fault at 0x000003e80000751d
...

無事問題が再現しました。ということで、これが原因ということで間違いなさそうです(ひょっとしたら他にもあるかもしれないけど)。

しれっと再現したと書いていますが、2つポイントがあります。

  • in-place build では再現しません(カレントディレクトリにたまたま ext も lib も存在するので発動条件を満たさない)。out-of-place のときは lib が存在しないので発動します。(問題のCIを管理しているささださんが out-of-place build 派だという知識があると有利。)
  • -n test_object_inspect_external によって、件のテストだけを実行することが必要です。なぜなら、他の M17N のテストを先に実行すると UTF_16BE のオートロードが先に行われてしまい、問題のテストでファイルロードが行われなくなって再現しなくなる。

修正する

ここで相対パスを入れなければ大丈夫なので、雑に絶対パスにしてやりました。これで手元では問題が再現されなくなりました。コミットして CI 観察継続中。

まとめ

Ruby の CI がときどき失敗する現象の調査と修正の事例紹介でした。JSON のテストが M17N のテストを失敗させるとかなかなか難しいですね。今回はテストの修正だけで済みましたが、本体側の修正が必要になる場合ももちろんあります。また、これはRubyの知識で完結している問題でしたが、システムプログラミングの知識が要求されるようなことも多いです。Rubyの品質をたもつのは総合格闘技