第8回　アプリケーションをシステム観点で監視する

前回は、業務観点でシステムをどう監視するかについて紹介しました。今回は、業務が動いているシステムの観点でどのように監視すればいいかを紹介します。

業務ロジックから処理の委譲までのシーケンスを押さえる

システムは、複数のサーバやサービスから成り立っています。システムのどこかに問題があると、その場所を特定するのは困難です。システム観点での情報をログに取るなど監視することで、システム基盤の問題箇所の特定や改善箇所の決定をするために重要な情報となります。

アプリケーションを処理するうえで、業務ロジックの中では処理の粒度はあるものの「データの取得・保存」や「APIの実行」など一部の処理をほかのサーバへ委譲することが多いです。処理の委譲先には、データベースサーバやリモートEJBサーバ、キューイング、ゲートウェイ経由でのAPIへのアクセスなどがあります。委譲する際の情報をログに取ることで、システム内のどの部分が正常でどの部分に問題が発生したかを判断できるようになります。

一般的に、業務ロジックから処理の委譲までのシーケンスは、以下のような流れで処理します。

業務データを委譲先の要求形式へ変換
委譲先へ処理を委譲
委譲先からの応答形式を業務データへ変換

たとえば、業務データを取得する処理をリレーショナルデータベースへ委譲する場合、以下の流れで処理します。

引数として与えられた業務データからSQLを作成し、値をバインド
SQLでリレーショナルデータベースへ問い合わせ
リレーショナルデータベースから返った結果セットを使用して、応答用の業務データやそのリストを作成

システム観点での監視は、「⁠何の」処理を、「⁠いつ」「⁠だれが」「⁠どこへ」「⁠どのように」処理を委譲し、委譲先から処理が返ってくるのに「どれくらい時間がかかったか」を情報としてログなどで取得します。

問題を局所化するためにチェックすべき8つのポイント

また、処理の委譲は必ずうまくいくとは限りません。委譲先が反応しなくなった場合には、タイムアウトやリトライが必要となりますので、それらも監視します。

「何の」処理をしたのか

まずはじめに重要なのは、システム観点の情報だけではなくどの業務を実行しているかを記録することです。これにより、どの業務ロジックからどの処理を委譲したのかをわかるようにします。例えば、引当処理や入荷処理などの業務から商品の在庫数を確認する処理を委譲するとします。商品の在庫数を確認する処理の中で在庫数が 0 の場合にログを出したときに、引当処理で発生したのか、入荷処理で発生したのかによって、在庫がないことが問題なのかどうかが判断できるようになります。

「いつ」処理したのか

この情報は、業務観点でも業務ロジックの処理時間として記録しています。そのため、システム観点では不要のように思われますが、シーケンスの1番の部分が遅いのか、委譲先の処理が遅いのか、外的要因による影響を受けたのかを切り分けられるようになります。例えば、ある処理が突然遅くなったときに、時間を使うことでどれくらい遅くなったかが分かります。また、遅くなった時間にシステム内で何か問題が起きていたかどうかも判断できるようになります。

「だれが」処理したのか

業務ロジックはたくさん実行され、たくさんの処理を委譲します。同時期に複数の業務ロジックが実行されると、どの業務ロジックによって委譲された処理なのかを追うことができなくなります。そこで、一連の処理には同一の固有番号を付与し、これを委譲先の処理でも引き継ぐことで、どの業務ロジックでの一連の処理なのかをわかるようにします。

「どこへ」処理を委譲したのか

委譲先のサーバは、スケールアウトや高可用性を実現するため、複数のハードウェア、プロセス、インスタンスによって実現していることが多いです。どのデータベースサーバやリモートEJBサーバ、サービスへアクセスしたのかを個別に特定できるようにします。

「どのように」処理を委譲したのか

処理の委譲の仕方は、委譲先のサーバによって異なります。たとえば、委譲先がリレーショナルデータベースの場合はSQLを使用して処理を委譲し、REST APIの場合はHTTPを使用して処理を委譲します。

データベースの場合は、以下を記録しましょう。

問い合わせたSQL
プレースホルダにバインドした値
SQLの結果セット

RESTサービスの場合は、以下を記録しましょう。

URL
HTTPメソッド（GET、PUT、POST、DELETEなど）
HTTPヘッダ　（⁠Content-Type、APIごとの独自ヘッダなど）
HTTPボディ
HTTPステータス

「どれくらい時間が」かかったか

委譲した処理にかかった時間は、問題箇所の切り分けで重要な情報になるため、できるだけ厳密に取得しましょう。厳密といっても、ナノ秒といった精度で取得するのではなく、できる限りシーケンスの2.のように委譲した処理だけを計測しましょう。

タイムアウトしたか

委譲先が過負荷だったり、ハングするほか、アプリが時間のかかる処理を委譲することで委譲先から応答がなくなることがあります。アプリはずっと待つこともできますが、一定時間を超えると委譲した処理をタイムアウトし、タイムアウトしたことを記録します。

何度目のリトライか

委譲した処理が失敗した場合、処理によって、もしくは失敗した理由によっては、再実行したいこともあるでしょう。再実行の実装次第ですが、サーバが複数台で構成されていると、再実行先が異なる可能性があります。再実行時には先述したすべての内容に加え、何度目の再実行であるかを記録します。

次のログは、これまでの内容をふまえて、引当処理の一部として、商品IDが5の商品の在庫数をRDBへ確認した場合のログです。

ログのサンプル

[引当][在庫確認][2017/06/23 18:19:46.138][ID3][1回目][RDB6]SELECT * FROM 在庫 WHERE 商品ID=?, 5
[引当][在庫確認][2017/06/23 18:19:56.138][ID3][1回目][RDB6]タイムアウト (10秒)
[引当][在庫確認][2017/06/23 18:19:56.246][ID3][1回目][RDB6]リトライ1回目
[引当][在庫確認][2017/06/23 18:19:56.387][ID3][2回目][RDB7]SELECT * FROM 在庫 WHERE 商品ID=?, 5
[引当][在庫確認][2017/06/23 18:19:56.395][ID3][2回目][8 ms] {商品ID:5, 数量:4}

1回目の問い合わせは一定時間経っても返答がなく、タイムアウトになったため、失敗しています。そして、リトライによる2回目の問い合わせは成功しています。

これらの情報を使用することで、この問題が引当業務や在庫確認処理だけで起きているかどうか、特定の時間だけ起きているか、特定のリクエストでだけ起きているか、特定のデータベースだけで起きているかなどを絞り込むことができます。

次回は、APサーバを使用する環境では何を監視すればいいのかを紹介します。