Bug #7356: ruby-2.0.0-preview1 で adlint-2.6.10 が性能劣化

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: 2.6
• ruby -v: ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux]
• Backport: 2.2: UNKNOWN, 2.3: UNKNOWN, 2.4: UNKNOWN

[yanoh (Yutaka Yanoh)]

== 現象

ruby-1.9.3-p327 と ruby-2.0.0-preview1 で adlint-2.6.10 の性能比較を行った結果、
ruby-2.0.0-preview1 の方が解析時間が 1.2 倍ほど長くかかりました。

== 再現手順

% gem install adlint
% tar xvjf adlint-benchmark-screen.tar.bz2 <- 添付ファイル
% cd adlint-benchmark-screen/adlint
% time make -j 2 2>/dev/null

== 性能測定結果

=== 測定環境

• Core 2 Duo E4500 2.20GHz / 3.4GB
• Fedora 14 / Linux 2.6.35.14-106.fc14.i686

=== 測定方法

• 下記バージョンの ruby を用いて、adlint-2.6.10 で screen-4.0.3 を解析
  ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux] built with gcc-4.5.1
  ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.5.1
  ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.7.2

• すべて configure オプションは --prefix のみ

• 解析は 2 コアを使い切れるよう make -j 2 を指定

• できるだけ IO による遅延を抑えるため標準エラーは /dev/null へリダイレクト
  ただし解析結果ファイルの出力は抑止できていません

=== 測定結果

• ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux] built with gcc-4.5.1
  make -j 2 2> /dev/null 1335.85s user 7.10s system 184% cpu 12:07.79 total
  make -j 2 2> /dev/null 1336.54s user 7.17s system 184% cpu 12:07.80 total
  make -j 2 2> /dev/null 1340.71s user 7.23s system 184% cpu 12:10.69 total

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.5.1
  make -j 2 2> /dev/null 1626.45s user 8.08s system 184% cpu 14:48.20 total
  make -j 2 2> /dev/null 1633.40s user 8.10s system 185% cpu 14:46.92 total
  make -j 2 2> /dev/null 1631.37s user 7.86s system 184% cpu 14:50.18 total

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.7.2
  make -j 2 2> /dev/null 1531.83s user 7.85s system 184% cpu 13:53.04 total
  make -j 2 2> /dev/null 1533.46s user 7.97s system 184% cpu 13:54.54 total
  make -j 2 2> /dev/null 1532.89s user 8.03s system 184% cpu 13:53.33 total

== 備考

adlint_sma コマンドは、最初のソースコード読み込み時と最後の解析結果書き出し時に
IO が走る以外は、オンメモリで計算のみを実行しています。
データ構造は木構造が多く、再帰処理を多用し、小さな一時オブジェクトを多く new し
ています。

[ko1 (Koichi Sasada)]

情報ありがとうございます．
簡単な再現手順はありませんかね．make じゃなくて，ruby 直接動かすようなも
のだとありがたいのですが...．

(2012/11/15 18:37), yanoh (Yutaka Yanoh) wrote:

Issue #7356 has been reported by yanoh (Yutaka Yanoh).

---

Bug #7356: ruby-2.0.0-preview1 で adlint-2.6.10 が性能劣化
https://bugs.ruby-lang.org/issues/7356

Author: yanoh (Yutaka Yanoh)
Status: Open
Priority: Normal
Assignee:
Category:
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux]

== 現象

ruby-1.9.3-p327 と ruby-2.0.0-preview1 で adlint-2.6.10 の性能比較を行った結果、
ruby-2.0.0-preview1 の方が解析時間が 1.2 倍ほど長くかかりました。

== 再現手順

% gem install adlint
% tar xvjf adlint-benchmark-screen.tar.bz2 <- 添付ファイル
% cd adlint-benchmark-screen/adlint
% time make -j 2 2>/dev/null

== 性能測定結果

=== 測定環境

• Core 2 Duo E4500 2.20GHz / 3.4GB
• Fedora 14 / Linux 2.6.35.14-106.fc14.i686

=== 測定方法

• 下記バージョンの ruby を用いて、adlint-2.6.10 で screen-4.0.3 を解析
  ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux] built with gcc-4.5.1
  ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.5.1
  ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.7.2

• すべて configure オプションは --prefix のみ

• 解析は 2 コアを使い切れるよう make -j 2 を指定

• できるだけ IO による遅延を抑えるため標準エラーは /dev/null へリダイレクト
  ただし解析結果ファイルの出力は抑止できていません

=== 測定結果

• ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux] built with gcc-4.5.1
  make -j 2 2> /dev/null 1335.85s user 7.10s system 184% cpu 12:07.79 total
  make -j 2 2> /dev/null 1336.54s user 7.17s system 184% cpu 12:07.80 total
  make -j 2 2> /dev/null 1340.71s user 7.23s system 184% cpu 12:10.69 total

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.5.1
  make -j 2 2> /dev/null 1626.45s user 8.08s system 184% cpu 14:48.20 total
  make -j 2 2> /dev/null 1633.40s user 8.10s system 185% cpu 14:46.92 total
  make -j 2 2> /dev/null 1631.37s user 7.86s system 184% cpu 14:50.18 total

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] built with gcc-4.7.2
  make -j 2 2> /dev/null 1531.83s user 7.85s system 184% cpu 13:53.04 total
  make -j 2 2> /dev/null 1533.46s user 7.97s system 184% cpu 13:54.54 total
  make -j 2 2> /dev/null 1532.89s user 8.03s system 184% cpu 13:53.33 total

== 備考

adlint_sma コマンドは、最初のソースコード読み込み時と最後の解析結果書き出し時に
IO が走る以外は、オンメモリで計算のみを実行しています。
データ構造は木構造が多く、再帰処理を多用し、小さな一時オブジェクトを多く new し
ています。

--
// SASADA Koichi at atdot dot net

[tarui (Masaya Tarui)]

windowsではあまり変わらないみたいです。
linuxだとどこが問題なんですかね。

== 測定環境
OS 名 Microsoft Windows 7 Home Premium
バージョン 6.1.7601 Service Pack 1 ビルド 7601
システムの種類 x64-ベース PC
プロセッサ Intel(R) Core(TM) i7-3770K CPU @ 3.50GHz、3501 Mhz、4 個のコア、8 個のロジカル プロセッサ
インストール済みの物理メモリ (RAM) 16.0 GB

== Measure-Command ｛make -J8 2> $nul } の結果

• ruby 2.0.0dev (2012-11-18 trunk 37704) [x64-mswin64_100]
  TotalSeconds : 308.6010451
  TotalSeconds : 306.6180463

• ruby 1.9.3p327 (2012-11-10 revision 37606) [x64-mswin64_100]
  TotalSeconds : 308.6779665
  TotalSeconds : 305.5603019

== xperf
全部は大変なのでprocess.cだけですが、下記でプロファイルを取った結果をおいておきます。
adlint_sma -t adlint_traits.yml -o . -p 1 ../screen-4.0.3/process.c 2>NUL:
結果:
https://docs.google.com/spreadsheet/ccc?key=0AoB-KHc4ekWzdFZsU19BOU9maTl2bWZmM1ZKam1uZmc

[mame (Yusuke Endoh)]

• Status changed from Open to Assigned
• Assignee set to ko1 (Koichi Sasada)

ささださん、preview2 後でいいのでがんばってみてください。
こういうので遅くなってたら「ささださんの仕事とは何だったのか」ということになりかねない。

他の方の追試も歓迎です。

--
Yusuke Endoh [e-mail]

[ko1 (Koichi Sasada)]

最悪「refinementのせい」「siphash のせい」ということで一つ．

いや，プロファイラ作れって話か．
簡単に試せそうなら，せっかく入った dtrace で見てみたいのですが，
yanoh さん，いかがでしょうか．

[yanoh (Yutaka Yanoh)]

反応が遅れてすみません。
まずは、ko1 さんからリクエストがあった ruby 単体で動くベンチマークを作ってみて、
その後 dtrace してみます。

[yanoh (Yutaka Yanoh)]

=begin
まずは ruby 単体で動くベンチマークプログラムを adlint-benchmark という gem で作成しました。

== 短時間で終了する版で測定

% gem install adlint-benchmark
% adlint_bm -p
user system total real
screen-4.0.3/process.c.small 16.040000 0.050000 16.090000 ( 16.228486)
16.430s user, 0.070s system, 00:00:16.50 total

== オリジナルの process.c 版で測定

% adlint_bm -t "screen-4.0.3/process.c" -p
user system total real
screen-4.0.3/process.c 213.220000 0.260000 213.480000 (215.310007)
213.620s user, 0.280s system, 00:03:33.90 total

== ベンチマークドライバのサンプル

AdLint::Benchmark.run を自前のドライバから呼び出して測定することも可能です。

require "adlint/benchmark"
AdLint::Benchmark.run("screen-4.0.3/process.c.small", true)
=end

[wanabe (_ wanabe)]

• File r37410-adapted37582-partially.patch r37410-adapted37582-partially.patch added
• File r37410-revert34948-partially.patch r37410-revert34948-partially.patch added
• Status changed from Assigned to Feedback

横からすみません。adlint-benchmark 使わせていただきました。
git bisect で調べてみたのですが、r34948 で rb_ary_push_m() が
rb_ary_cat() を呼び出すように変更されているのが性能劣化の原因ではないでしょうか。
また、r37582 でその rb_ary_cat() の内容が変更されたため、再度性能が回復しているように見えます。
実験的に r34948 の関連する部分を revert するパッチと、r37582 の関連する部分を適用する二つのパッチを書きました。
r34948 ～ r37581 の間で、どちらのパッチを用いても速度が改善されると思われます。
チケット起票時に使われた r37410 （でいいのでしょうか？ r37411 は見つかりませんでした）を使って確認しました。
yanoh さん、よろしければご確認いただけますでしょうか。
最後に実験結果を示します。参考にしていただければ幸いです
長々と書きましたが、r37582 以降 trunk で性能劣化はないのではないか、と思います。
（本題から逸れるので調べませんでしたが、むしろ r37410 ～ r37581 の間でも
　何らかの性能改善があったように見受けられます。）

• ruby 1.9.3p327 (2012-11-10 revision 37605)
  user system total real
  screen-4.0.3/process.c.small 26.880000 0.100000 26.980000 ( 27.002153)
  27.470s user, 0.130s system, 00:00:27.59 total

• trunk r34947
  user system total real
  screen-4.0.3/process.c.small 27.500000 0.120000 27.620000 ( 27.645960)
  28.120s user, 0.180s system, 00:00:28.30 total

• trunk r34948
  user system total real
  screen-4.0.3/process.c.small 33.080000 0.190000 33.270000 ( 33.382366)
  33.730s user, 0.220s system, 00:00:33.94 total

• trunk r37581
  user system total real
  screen-4.0.3/process.c.small 25.910000 0.140000 26.050000 ( 26.057930)
  26.550s user, 0.190s system, 00:00:26.74 total

• trunk r37582
  user system total real
  screen-4.0.3/process.c.small 21.480000 0.130000 21.610000 ( 21.608838)
  22.090s user, 0.190s system, 00:00:22.28 total

• trunk r37410
  user system total real
  screen-4.0.3/process.c.small 33.690000 0.100000 33.790000 ( 33.858404)
  34.360s user, 0.140s system, 00:00:34.50 total

• trunk r37410 with r37410-revert34948-partially.patch
  user system total real
  screen-4.0.3/process.c.small 26.710000 0.120000 26.830000 ( 26.879693)
  27.390s user, 0.160s system, 00:00:27.55 total

• trunk r37410 with r37410-adapted37582.patch
  user system total real
  screen-4.0.3/process.c.small 26.830000 0.100000 26.930000 ( 27.078610)
  27.490s user, 0.140s system, 00:00:27.62 total

[yanoh (Yutaka Yanoh)]

wanabe さん、情報ありがとうございます。

下記のバージョンで再測定してみました。

• ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux]
• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] <- 2.0.0-preview1
• ruby 2.0.0dev (2012-11-29 trunk 37962) [i686-linux] <- trunk 最新

== 結論

• adlint_bm (screen-4.0.3/process.c.small) では、trunk 最新 (r37962) が一番高速
• adlint_bm (screen-4.0.3/process.c) では、ruby-1.9.3p327 が一番高速

2.0.0-preview1 (r37411) よりは trunk 最新 (r37962) の方がかなり性能回復していま
すが、それでも条件によっては ruby-1.9.3p327 より遅い場合があるようです。

adlint_bm のターゲット screen-4.0.3/process.c.small は、ベンチマーク時間を短縮
するためオリジナルの screen-4.0.3/process.c の大部分を削除したものです。
それぞれのターゲットで、ベンチマーク時の測定内容がかなり異なるようです。

== 測定条件

trunk の最新で adlint-2.6.10 を実行したところ、ブロック無しの Enumerator.new を
使用していたため、大量の warning が出力されました。
これが測定結果に影響を与えるかもしれないと思い、Object#to_enum に変更したものを
adlint-2.6.12 としてリリースし、このバージョンで測定しました。

また、adlint_bm についても -c NUM で測定回数を指定可能にして
adlint-benchmark-1.1.0 としてリリースし、このバージョンを使用しました。

== 測定結果

=== "screen-4.0.3/process.c.small" ターゲット

測定コマンド : adlint_bm -p

• ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux]
  user system total real
  screen-4.0.3/process.c.small #1 16.250000 0.050000 16.300000 ( 16.434142)
  total 16.250000 0.050000 16.300000 ( 16.434142)

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] <- 2.0.0-preview1
  user system total real
  screen-4.0.3/process.c.small #1 21.540000 0.080000 21.620000 ( 21.800759)
  total 21.540000 0.080000 21.620000 ( 21.800759)

• ruby 2.0.0dev (2012-11-29 trunk 37962) [i686-linux] <- trunk 最新
  user system total real
  screen-4.0.3/process.c.small #1 15.220000 0.050000 15.270000 ( 15.392969)
  total 15.220000 0.050000 15.270000 ( 15.392969)

=== "screen-4.0.3/process.c" ターゲット

測定コマンド : adlint_bm -t "screen-4.0.3/process.c" -p

• ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux]
  user system total real
  screen-4.0.3/process.c #1 214.060000 0.470000 214.530000 (216.548791)
  total 214.060000 0.470000 214.530000 (216.548791)

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] <- 2.0.0-preview1
  user system total real
  screen-4.0.3/process.c #1 244.090000 0.520000 244.610000 (246.698421)
  total 244.090000 0.520000 244.610000 (246.698421)

• ruby 2.0.0dev (2012-11-29 trunk 37962) [i686-linux] <- trunk 最新
  user system total real
  screen-4.0.3/process.c #1 227.260000 0.310000 227.570000 (229.420830)
  total 227.260000 0.310000 227.570000 (229.420830)

== さらに測定

"screen-4.0.3/process.c" ターゲットについて、-c NUM オプションで測定を繰り返し
て見たところ、1.9.3 と 2.0.0 で動作特性が異なる傾向を持つことが分かりました。

2.0.0 では初回のみ遅くなっているようです。やはりプロファイラによる詳細な分析が
必要でしょうか。

測定コマンド : adlint_bm -t "screen-4.0.3/process.c" -c 3 -p

• ruby 1.9.3p327 (2012-11-10 revision 37606) [i686-linux]
  user system total real
  screen-4.0.3/process.c #1 217.300000 0.100000 217.400000 (218.929445)
  screen-4.0.3/process.c #2 217.790000 0.070000 217.860000 (219.410483)
  screen-4.0.3/process.c #3 216.250000 0.300000 216.550000 (218.345587)
  total 651.340000 0.470000 651.810000 (656.685515)

• ruby 2.0.0dev (2012-11-01 trunk 37411) [i686-linux] <- 2.0.0-preview1
  user system total real
  screen-4.0.3/process.c #1 241.460000 0.180000 241.640000 (243.313287)
  screen-4.0.3/process.c #2 213.320000 0.120000 213.440000 (214.921192)
  screen-4.0.3/process.c #3 201.570000 0.050000 201.620000 (203.014434)
  total 656.350000 0.350000 656.700000 (661.248912)

• ruby 2.0.0dev (2012-11-29 trunk 37962) [i686-linux] <- trunk 最新
  user system total real
  screen-4.0.3/process.c #1 227.050000 0.100000 227.150000 (228.728632)
  screen-4.0.3/process.c #2 220.260000 0.080000 220.340000 (221.945992)
  screen-4.0.3/process.c #3 223.870000 0.420000 224.290000 (226.271632)
  total 671.180000 0.600000 671.780000 (676.946256)

[ko1 (Koichi Sasada)]

• Target version changed from 2.0.0 to 2.6

放っておいてすみません。
もうちょっと見ないとわからんですねぇ。

というわけで、次のバージョンで頑張りましょう。

[ko1 (Koichi Sasada)]

• Status changed from Feedback to Closed

がんばれなかった...

もし、どなたかがんばってくれるなら...。