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.3
DTrace を使うと稼働中のシステムに手を加えること無く振る舞いを追跡することができとても便利です。
計測する
以下の 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 へ大幅に処理時間が減っていました。
まとめ
DTrace を使うとシステムの挙動をざっくり調べるときに便利です。
