Ubiregi Advent Calendar 2018 の18日目です。
ユビレジではたくさんのお客様の大量の POS データをお預かりしており、様々なバッチ処理も実行されています。今回は特定のケースでバッチ処理の一部が30分以上かかっていた処理を14秒で終わるようにした話について書きたいと思います。前回の Ruby 2.5 の SEGV と闘った話 - @watson1978 の日記 に引き続き DTrace を使った話になります。
はじめに
ユビレジでは CSV ファイルでお客様が特定のデータをダウンロードしたりアップロードできる機能があります。CSV ファイルにエクスポートしたり、CSV ファイルからDBに取り込む処理を Worker を起動してバッチ処理しています。 大量のデータを保有しているアカウントと同量のデータを用意して手元の環境で試したところ時間がかかることが発覚しました。Rails のログをながめていてもDBにアクセスしている雰囲気も無く、内部処理で何か詰まっているのかと現象を追いかけてみました。DTrace を有効にする
rbenv で Ruby をインストールする際に、以下の様にオプションを指定すると macOS 上で Ruby の DTrace 機能が有効になります。
$ CONFIGURE_OPTS="--enable-dtrace" rbenv install 2.5.3DTrace を使うと稼働中のシステムに手を加えること無く振る舞いを追跡することができとても便利です。
計測する
以下の DTrace のスクリプトで、バッチ処理中に各 Ruby メソッドを呼び出した回数と実行時間を計測しました。#!/usr/sbin/dtrace -s #pragma D option quiet ruby$target:::method-entry { @method_call_count[copyinstr(arg0), copyinstr(arg1)] = count(); self->method_starttime = walltimestamp / 1000; } ruby$target:::cmethod-entry { @method_call_count[copyinstr(arg0), copyinstr(arg1)] = count(); self->cmethod_starttime = walltimestamp / 1000; } ruby$target:::method-return { @invoked_time[copyinstr(arg0), copyinstr(arg1)] = sum((walltimestamp / 1000) - self->method_starttime); } ruby$target:::cmethod-return { @invoked_time[copyinstr(arg0), copyinstr(arg1)] = sum((walltimestamp / 1000) - self->cmethod_starttime); } END { printf("\n"); printf("%-30s %-15s %s\n", "CLASS", "METHOD", "COUNT"); printf("--------------------------------------------------------------------------------\n"); printa("%-30s %-15s %@d\n", @method_call_count); printf("\n"); printf("%-30s %-15s %s\n", "CLASS", "METHOD", "TOTAL TIME usec"); printf("--------------------------------------------------------------------------------\n"); printa("%-30s %-15s %@d\n", @invoked_time); }このスクリプトは DTrace で計測したいプロセスが終了するか、計測を
CTRL + Cで中断するまで計測し続けます。実行した結果が以下の様なログになります︵数分程度で中断しましたが︶。
$ sudo dtrace -q -s measure.d -p [Worker のプロセスID]
CLASS METHOD COUNT
--------------------------------------------------------------------------------
#<Class:0x00007fe014884108> lambda 424
#<Class:0x00007fe01db2a9d0> category 424
#<Class:0x00007fe01db2a9d0> name 424
#<Class:0x00007fe01db2a9d0> new 424
Array compact 424
Array include? 424
Array select 424
Array zip 424
BigDecimal initialize 424
BigDecimal new 424
Class new 424
Enumerable all? 424
Kernel method 424
Method to_proc 424
Regexp === 424
String gsub! 424
String rstrip! 424
String sub! 424
#<Class:0x00007fe01db2a9d0> group 425
#<Class:0x00007fe01db2a9d0> item_type 848
Integer === 848
#<Class:0x00007fe01db2a9d0> vat 1272
Array each 1272
Array map 1272
#<Class:0x00007fe01db2a9d0> price 1696
#<Class:0x00007fe01db2a9d0> sku 1696
Array first 1696
Kernel public_send 1696
Kernel respond_to? 1696
String strip 1696
Regexp match? 2120
Struct []= 4240
Symbol =~ 4240
CLASS METHOD TOTAL TIME usec
--------------------------------------------------------------------------------
Array compact 1617
String rstrip! 1727
Kernel method 2196
String gsub! 2790
Integer === 2829
BigDecimal initialize 2844
Array zip 2861
String sub! 3295
Regexp === 3980
Class new 4410
Array select 4515
Array first 5171
Kernel respond_to? 5820
BigDecimal new 6126
Enumerable all? 6158
String strip 6200
Array map 6604
Array each 8555
Regexp match? 11051
Kernel public_send 12027
Struct []= 13245
Symbol =~ 16732
#<Class:0x00007fe01db2a9d0> category 533850
#<Class:0x00007fe01db2a9d0> new 537748
#<Class:0x00007fe01db2a9d0> name 540244
#<Class:0x00007fe014884108> lambda 547411
Method to_proc 549701
#<Class:0x00007fe01db2a9d0> group 604678
#<Class:0x00007fe01db2a9d0> item_type 1076239
#<Class:0x00007fe01db2a9d0> vat 1599474
#<Class:0x00007fe01db2a9d0> sku 2143290
#<Class:0x00007fe01db2a9d0> price 2152747
Array include? 1544897529611642
このログから Array#include? を 424 回しか呼び出していないのに、桁違いに実行時間が長いことがわかりました。
Array#include? をどこで実行している？
ここで別のスクリプトを用意しました。Array#include? はC言語で実装されているので cmethod-entry というプローブで補足できます。以下のスクリプトでは Array#include? のときだけ cmethod-entry が実行されるようにしてあります。Array#include? が呼び出された際に、呼び出したファイル名と行番号を出力しています。
#!/usr/sbin/dtrace -s #pragma D option quiet // ruby:::cmethod-entry(classname, methodname, filename, lineno); ruby$target:::cmethod-entry / copyinstr(arg0) == "Array" && copyinstr(arg1) == "include?" / { printf("%s : %d\n", copyinstr(arg2), arg3); }実行すると以下の様に、どのファイルの何行目で呼び出されているかわかりました。
$ sudo dtrace -q -s trace.d -p [Worker のプロセスID]
/Users/watson/src/ubiregi-server/lib/menu_import/menu_reader.rb : 60
/Users/watson/src/ubiregi-server/lib/menu_import/menu_reader.rb : 60
/Users/watson/src/ubiregi-server/lib/menu_import/menu_reader.rb : 60
/Users/watson/src/ubiregi-server/lib/menu_import/menu_reader.rb : 60
...(略)...
ここまで Ruby のコードに一切手を加えずに原因箇所がわかりました。DTrace 便利(\( ⁰⊖⁰)/)
再現コードと修正後のコード
該当箇所を見たところ、処理したいデータがユニークな値になっていなかったら例外をあげるようになっていました。再現すると以下の様なコードになります。data = (1..200_000).to_a.map(&:to_s) array = [] data.each do |item| if array.include?(item) raise "item is not uniq" end array << item endチェックしたデータを配列で保持し、毎回
Array#include? で重複していないか確認していました。Array#include? では配列の各要素の文字列を一つずつ比較することになるので、要素が多くなれば当然遅くなります。
Hash を使えば簡単にデータの各要素がユニークかチェックできそうだったので以下の様にしました。
data = (1..200_000).to_a.map(&:to_s) hash = {} data.each do |item| if hash[item] raise "item is not uniq" end hash[item] = true end該当箇所の処理をちゃんと計測すると、修正前は
2091.88 sec かかっていたのですが修正後には 13.94 sec へ大幅に処理時間が減っていました。
