マイクロサービスのサーキットブレーカーの動きをAPMで可視化してみる #Java

はじめに

最近マイクロサービスなお客様システムを手持ちのAPMツールで中身を可視化したのですが、非同期処理だの、HTTPリクエストが内部で何個も行ったり来たりして、従来のモニシリックなシステムよりも複雑だなぁと見てて思いました。
その中の一つ気になったのが、マイクロサービスのデザインパターンの一つのサーキットブレーカーパターンの部分です。
例えばこんな感じでサーキットブレーカーを使うことで、他のサービスへの依存度を減らすことができます。

このような図にするともちろんわかりやすいのですが、実際APMが拾ってくるトランザクショントレースのデータにはサーキットブレーカーが発動したかどうかという情報はないため、一見正常な処理だったのかどうかが判別できないというわけです。

そういうわけで、この記事ではサーキットブレーカーパターンのサンプルプログラムを使ってAPM（AppDynamics）を駆使してどこまでトレースして、中の動きを追えるかに挑戦したいと思います。

今回のサンプルプログラムは、最近学びたてで触ってみたかったRedHatのQuarkusフレームワークの中のJava MicroProfileのサーキットブレーカー機能が使われているの以下のサンプルを使わせていただいただきます。
https://quarkus.io/guides/microprofile-fault-tolerance

実際に利用するコードは上記ドキュメントからリンクされているこちらです。
https://github.com/quarkusio/quarkus-quickstarts/microprofile-fault-tolerance-quickstart

前提条件

今回の自分の環境は以下の通りでした。
- macOS Catalina バージョン 10.15.7
- OpenJDK 11.0.8
- AppDynamicsが利用可能な状態（こちらからSaaSフリートライアル申込可能です）
- AppDynamicsのJava Agent(ver20.11.0.31438)をMac上ディレクトリにunzip済み＜ー　ダウンロードはこちらから

サンプルアプリケーションの動作確認

まずサンプルプログラムを普通に動かしてみます。

git clone https://github.com/quarkusio/quarkus-quickstarts
cd quarkus-quickstarts/microprofile-fault-tolerance-quickstart
./mvnw package
java -jar target/microprofile-fault-tolerance-quickstart-1.0-SNAPSHOT-runner.jar

ドキュメントだと、./mvnw compile quarkus:devとして開発モードで起動していますが、今回は後でAPMのエージェントを起動するためにjarを作るための上記コマンドを実行してます。

そして、ここからドキュメントに記載の通り、以下の３つのURLをブラウザなどからアクセスして、レスポンスが表示されることを確認しました。

http://localhost:8080/coffee/2/recommendations
http://localhost:8080/coffee/2/availability
http://localhost:8080/coffee

APM (AppDynamics）でサンプルアプリケーションを監視

以下の例のように、-javaagentオプション及びAppDynamics SaaSに接続する際のその他プロパティを引数に与えて実行します。xxxはマスクした部分です。

java -javaagent:<xxx>/AppServerAgent-20.11.0.31438/javaagent.jar ¥
-Dappdynamics.controller.hostName=<xxx>.saas.appdynamics.com ¥
-Dappdynamics.controller.port=443 -Dappdynamics.agent.accountAccessKey=<xxx> ¥
-Dappdynamics.agent.accountName==<xxx> -Dappdynamics.controller.ssl.enabled=true ¥
-Dappdynamics.agent.applicationName=sekiya-quarkus-quickstarts ¥
-Dappdynamics.agent.tierName=microprofile-fault-tolerance-quickstart ¥
-Dappdynamics.agent.nodeName=microprofile-fault-tolerance-quickstart-01 ¥
-jar target/microprofile-fault-tolerance-quickstart-1.0-SNAPSHOT-runner.jar

下はAppDynamicsでアプリケーションの動きを可視化したアプリケーションフローマップです。今回のサンプルアプリは、一つのJavaプロセスの中で全ての処理が完結していて、特に外部へHTTPリクエストもDBアクセスないので、一つのJavaプロセスを表す○が表示されているだけのつまらない感じとなっています。

下はビジネストランザクション別の性能一覧です。（デフォルトだとURL 2セグメントでグルーピングされていますので、3セグメント表示されるようにAppDynamicsの画面から設定変更必要です。）

サーキットブレーカーのフォールバック処理が実行されたことをAppDynamicsで検知できるようにする

今回はこの3つリクエストの内の/coffee/2/recommendationsについてのソースコードを詳しく見ていきます。このメソッドの中で、randomDelay()によるランダムなThread.sleep処理が挟まれています。それが250msec以上の時は、 @Fallbackアノテーションによる、フォールバックメソッドが呼ばれるという動きになるわけです。

    @GET
    @Path("/{id}/recommendations")
    @Timeout(250)
    @Fallback(fallbackMethod = "fallbackRecommendations")
    public List<Coffee> recommendations(@PathParam int id) {
        long started = System.currentTimeMillis();
        final long invocationNumber = counter.getAndIncrement();

        try {
            randomDelay();
            LOGGER.infof("CoffeeResource#recommendations() invocation #%d returning successfully", invocationNumber);
            return coffeeRepository.getRecommendations(id);
        } catch (InterruptedException e) {
            LOGGER.errorf("CoffeeResource#recommendations() invocation #%d timed out after %d ms",
                    invocationNumber, System.currentTimeMillis() - started);
            return null;
        }
    }

    /**
     * A fallback method for recommendations.
     */
    public List<Coffee> fallbackRecommendations(int id) {
        LOGGER.info("Falling back to RecommendationResource#fallbackRecommendations()");
        // safe bet, return something that everybody likes
        return Collections.singletonList(coffeeRepository.getCoffeeById(1));
    }

こちらが、Fallbackが起きなかった時のレスポンス例です。

> curl -i http://localhost:8080/coffee/2/recommendations
HTTP/1.1 200 OK
Content-Length: 150
Content-Type: application/json

[{"id":1,"name":"Fernandez Espresso","countryOfOrigin":"Colombia","price":23},{"id":3,"name":"Dak Lak Filter","countryOfOrigin":"Vietnam","price":25}]

こちらが、逆にFallbackが起きた時のレスポンス例。レスポンスはどちらもHTTP 200なので、このままだとAppDynamicsの監視データ上ではFallbackが起きていたかは見た目判断できません。

> curl -i http://localhost:8080/coffee/2/recommendations
HTTP/1.1 200 OK
Content-Length: 78
Content-Type: application/json

[{"id":1,"name":"Fernandez Espresso","countryOfOrigin":"Colombia","price":23}]

このフォールバックメソッドが呼ばれたことをトレースできるように、AppDynamicsの画面からこのメソッドが呼ばれたことを検知できるCustom ExitPointを設定します。

設定の結果、こちらがFallbackがあった時のトレースデータです。DelayのThread.sleepが大きいかったため、Fallback処理が実行されたというわけです。さきほどのCustom ExitPoint設定のフォールバックメソッドが実行されたことがすぐに画面から判断できます。

下は同じリクエストの別の見方、Waterfallビューです。

下はこの時のコールスタックの状態です。内部のライブラリの動きが見えますね。

こちらがFallbackがなかった時のトレースデータです。DelayのThread.sleepが小さかったので、フォールバックは起きていないですね。

まとめ

今回はAppDynamicsの監視のカスタマイズ設定を使って、ブラックボックスになりがちなサーキットブレーカーの動きを補足することができたと思います。このように、AppDynamicsの設定をうまく使うことで、デフォルトでは見えなかったアプリケーションの動きを補足できるようになります。