RubyをFlightRecoderを使ってブラックボックス分析する

はじめに

性能分析や障害分析で詳細なログ情報が取得たいときは良くあります。

私は普段はRuby製のバッチやWebアプリを本番で動かさないのであまり気にした事が無かったのですが、パッと思い付かなかったのでJFR(JDK Flight Recorder)をRubyに適用出来るかを試してみました。

JFRというブラックボックス分析向けのJVMの仕組みで低遅延のプロファイラを常時本番環境のアプリに適用してCPUやメモリ、GCログはもちろんスレッドダンプやI/O、カスタムイベントを１ファイルに集約保存する仕組みです。
これによって、障害時の原因の特定をスピーディーに実施できます。

今回はTruffleRubyを使う事でJFRを有効にしてみました。

TruffleRubyのインストール

まずはインストールです。rbenvとかで入れたくなるのですが、その場合JVM版が入らないのでGraalVMからインストールを行います。

こちらからCommunity版をインストールするか、SDKMANを使ってインストールします。下記はSDKMANのケースです。

# GraalVMのインストール
$ sdk install java 19.3.0.r11-grl  
$ java -version 
openjdk version "13.0.1-BellSoft" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1-BellSoft+9)
OpenJDK 64-Bit Server VM (build 13.0.1-BellSoft+9, mixed mode, sharing)

続いてTruffle Rubyのインストールです。ここからの手順はGraalVMのインストール方法に依存せず共通です。

$ gu install ruby  
$ ruby --jvm --version
truffleruby 19.3.0, like ruby 2.6.2, GraalVM CE JVM [x86_64-darwin]

インストールはこれで完了です。

検証アプリを作成

動作テスト用のアプリをSinatraで作成します。

$ bundler init
$ echo 'gem "sinatra"' >> Gemfile 
$ bundler install 

下記のようにapp.rbを書きます。

require 'sinatra'

get '/' do
  'Hello world!'
end⏎

JFRの取得

アプリを起動させてJFRを取得します。以下のようなJVMオプションをRubyに渡します。--vm.XX:...のようにする事でJVMオプションを指定できます。

$ ruby --jvm --vm.XX:StartFlightRecording=settings=profile,filename=myapp.jfr app.rb

下記のメッセージが出ればJFRが有効になっています。

Started recording 1. No limit specified, using maxsize=250MB as default.
Use jcmd 53009 JFR.dump name=1 to copy recording data to file.

プロセス終了時にmyapp.jfrという名前で作成されます。

VisualVMで見てみる

JFRはバイナリなのでJDK Mission Controlをインストールして解析したり、jfrコマンドでJSONに変換したりして分析します。
GraalVMにはjvisualvmが同梱されているのでこちらを利用することも可能です。VisualVMでJFRを開くと以下のような情報が取得できます。

他にもGCログとかヒストグラムとかスレッドロックとか色々見れますが割愛。VisualVMのJFRサポートはまだ絶賛開発中なので、本格的に見るならJMCの方がUIもこなれていてオススメです。

カスタムイベントの追加

Flight Recorderにはカスタムタグと言って任意のイベントを追加する仕組みがあります。これを使うことでログを吐くのと同じ感覚でJFRファイルの中に情報を組み込めます。

以下のようにjdk.jfr.Eventクラスを継承したコードをJavaで書きます。

java/src/profile/HttpRequestEvent.java

package profile;

import jdk.jfr.Category;
import jdk.jfr.Event;
import jdk.jfr.Label;

/**
 *
 * @author koduki
 */
@Category({ "Application Profile" })
@Label("HTTP Request")
public class HttpRequestEvent extends Event {

    @Label("Method")
    public String method;

    @Label("URL")
    public String url;
}

続いてRubyでJavaコードを呼び出します。

require 'sinatra'
Java.import 'profile.HttpRequestEvent'

get '/' do
  event = HttpRequestEvent.new
  event.begin
  r = 'Hello world!'
  event.end

  event.setUrl("/")
  event.setMethod("get")
  event.commit

  r
end

Java.importでJavaのコードをrequireします。JRubyとTruffleRubyで構文が少し違うのでご注意ください。
begin/endで囲んだ範囲の処理をdurationとして自動で記録します。その後、先ほどJavaのクラスで指定した任意のプロパティに値を入れる事ができます。

続いて以下のコマンドで実行します。

$ javac java/src/profile/HttpRequestEvent.java -d java/classes
$ ruby --jvm --vm.classpath=./java/classes/ --vm.XX:StartFlightRecording=settings=profile,disk=true,filename=myapp.jfr app.rb

新しいオプションとして--vm.classpathを足しています。こちらで作ったJavaのカスタムイベントをクラスパスに通します。

準備はできたのでabコマンドで適当にリクエストを投げてみます。

$ ab -n 5000 -c 10 "http://localhost:4567/" 

こちらrubyのプロセスを終了してmyapp.jfrを見てみると以下のようにカスタムイベントが表示されます。

今回は単純にリクエストを入れましたが障害時に便利な情報を入れておくと良いでしょう。ちなみに閾値の設定とかもできます。

ちなみにJMC以外で例えばMetabaseとかで分析したい場合は2019-12-09
JFRをBigQuery/Metabaseのオレオレダッシュボードで可視化するをご参照ください。

まとめ

Rubyの本番時の障害分析はおそらくNewRelicなどのAPMを中心に行われてるのでは無いかと思われます。

ただスレッドロックとか細かい情報も見たいことは本番運用してたらありそうなので、JFRはAPMよりも障害分析に特化した機能が多くRubyでも使おうと思えば使えるのは助かります。

今回はビジネスロジックの中に直書きしましたが、Rubyなのでメソッド呼び出しをフックして自動で書き込むとかFW側にJFRのロジックを入れれば、グッと使いやすくなると思います。

TruffleRubyはパフォーマンスが注目されがちですが、こうしたJavaのエコシステムと連携できるのも魅力の一つかと考えています。

ただ、スタックトレースがRuby側まで追いきれないようなので、この辺はやはりRubyネイティブのものがあると良いですね。

それではHappy Hacking!

参考

• Truffle Ruby - Polyglot Programming
• Migration from JRuby to TruffleRuby