バッチ処理の一部で 30 分以上かかっていた処理を 14 秒で終わるようにした話

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 を使うとシステムの挙動をざっくり調べるときに便利です。