[実験室] RoboServer に過負荷をかけるとどうなる？エラーの種類と対応方法。

はじめに

BizRobo! はサーバ型のRPAと言われますが、その理由としては下図のように管理コンソール（MC）から起動されたロボットが、個別の端末ではなく中央に位置するロボット実行エンジン（RoboServer、以降 RS）によって集中処理されるアーキテクチャだからです。

ロボットの種類によっては RS 内で処理を完結するものもありますが、旧組み込みブラウザエンジンである WebKit を使ったロボットであれば kapowbrowser という子プロセスがロボットごとに派生し、一部の処理を請け負います。

また、DAS を使ったリモート端末の操作や、現在の組み込みブラウザエンジンである Chromium を使ったロボットの場合、kapowbrowser と並列して renderer等 のプロセスが更に生成され、それぞれのタスクを分担する構成です。

ただ、いずれにせよその中心にある RS は処理の肝であり、ロボット全体の実行に影響を与えてしまうので RS の安定稼働は何よりも重要です。

で、今回の企画としては、そんな重要な RS に過負荷をかけていじめたらどうなっちゃうの！！！という様子を見ていこうと思います。

MC と RS のコミュニケーションとログ

MC からの依頼を受けてロボットの実行を捌く RS ですが、そもそも MC と RS とはどんな関係なのでしょうか？まずはコミュニケーションと記録（ログ）の構成について見てみましょう。

1. RS は起動時に1度だけ¹ MC に通信し、自身を MC に登録する。（これにより、MC に RS が登録される）
   

2. RS は自身の状況について RoboServerメッセージ ログに記録する。（起動時のメッセージ記録）
   

3. MC は接続のあった RS に対してヘルスチェックを始める。接続が成立すると、ロボサーバのステータスを オンライン に更新。

4. MC は毎秒²登録された RS に対して疎通確認を行い、異常を検知した場合にはRoboServerメッセージ ログに記録する。
   
   MC から RS へ疎通が取れない場合、RoboServerメッセージ ログにその情報が記録されるほか、ロボサーバのステータスも オフライン に更新されます。
   運用監視の中で「あれ、ロボサーバが オフライン になっているけど、、」と気づいたときには RoboServerメッセージ を見てみることで、「いつからその状況が発生しているのか」を確認できます。

上の RoboServerメッセージ で RS 起動直後に MC から エラー のログが記録されていますが、これは問題のないログだとわかります。
単純に RS 起動後、MC との疎通→初期化処理（KCUの割り当てなど）が完了する前にタイミング悪く MC からの疎通確認が走った結果だと思われます。
起動と通信の仕組みが分かっていれば、エラーログを見ても焦ることはないでしょう。

RoboServer 耐久実験！

専門家の立場ではなく、BizRobo!のユーザー部門が実験をします。結果を参考にしていただいたとしても根拠とされるのはご遠慮ください。
JVM や CGの挙動についての専門的知識はありません。経験則に基づき観察した結果より導き出した見解の共有なので、記述の間違いや漏れなどあれば、是非ご指摘いただけると助かります。

実験の観点

本格的な試験であれば、ロボットを100台以上 様々なタイプを用意し、定常的に負荷のかかった状態を作り出したうえで、土俵際「何が決め手」になるのかを時間を掛けて検証していくと思いますが、今回は手っ取り早く結果を取りに行くのが目的です。

実際の運用においてどの程度起こり得るか！という点は全く無視して取り合えずどうやったらエラーになるのか？どんなエラーが出るのか？という観点で進めた結果です。実験に使ったロボットやファイルなどには特に触れません。

大きなファイルを読み込ませて一発で沈める。

「大きな Excel ファイルを読み込ませた結果 RS が Out of Memory でダウンした。」³という話を過去に聞いた記憶があります。参考に大きめのファイルを ベーシックエンジン ロボット で操作するロボットを作り、同時に10台程度並行稼働してみた結果が以下です。

ファイルの読み込み時に CPU の負荷がある程度上昇し、ヒープの消費量も急激に上昇するものの、毎回限界突破前にGCが走ってやり過ごされてしまう。

落ちませんね。。

ということで、確実に仕留めるためにさらに大きなファイルを作成し、再度実行してみました。普通に Excel で開いても起動に少し時間がかかるサイズです。ファイルの大きさが原因であることを確定したかったので、ロボットは1つだけ実行してみます。

おっ！落ちた！！　というか、Wrapper プログラムにより再起動しました！

用意した環境にとっては大きすぎるファイルを処理するために Stop the world が連発しているのだろうか？

いずれにせよ、RS が無反応になってしまうと、定期的に MC から発信されている通信にもレスポンスができなくなるわけで、以下の様に RoboServerメッセージ ログへ MC からの「RSさん、オフライン になってるよ。」というメッセージが残されます。

今回は落とすことに集中しすぎてログの出力条件やタイミングについては後追いで確認したため、具体的なトリガーは分かっていませんが、参考情報として RoboServerメッセージ に表示される情報も載せてみました。

仮に、上記の様にサーバ過負荷に伴う stop the world を感知して RoboServerメッセージ に記録が残っているとするならば、サーバダウンの予防のために RoboServerメッセージ を監視しておくことは有効かもしれません。

さらに大きなファイルを読み込ませる。

ファイルのサイズをさらに大きくしたり、Full GC 中に更なる負荷を掛けたらどうなるかとロボットを同時実行した結果、以下のように即落ちするケースもありました。

Ping待ち 状態に入るまでもなく撃破！

プロセスごと撃破！

RS で内部エラーが発生した場合にはインストールフォルダ配下の Logs ディレクトリ内 yyyy-MM-dd HH_mi_ss RoboServer.log へエラーログが出力されるのが通常ですが、場合によっては上記の様に RoboServerメッセージ へログが記録されることもあります。

これは RS のメインプロセスは生きたまま 派生する kapowbrowser プロセスにエラーが発生した場合だけで、RS 自体が内部エラーでダウンしてしまった場合には対象外でしょう。

RS が落ちるぎりぎりを攻める

ここまでは、とりあえず RS をダウンさせることを目的に負荷をかけてきましたが、一方で「まだ大丈夫だけどこのままだと落ちる」という境界線が分かれば対策が取れるかもしれません。

ぎりぎり落ちそうで落ちないレベルの負荷をかけ続けた結果、以下のようなログが RoboServerメッセージ へ出力されることが分かりました。

High memory usage.

RoboServer is using 98 percent of the available memory and will queue all new robot executions. This normally happens if you run too many concurrent robots on the server. Try lowering the number of concurrent robots to avoid this problem. You will often find that lowering the number of concurrent robots will increase overall throughput. Another option is to increase the available memory. （RoboServer は使用可能なメモリの 98% を使用しており、すべての新しいロボットの実行をキューに入れます。 これは通常、サーバー上で同時に実行するロボットが多すぎる場合に発生します。 この問題を回避するには、同時実行ロボットの数を減らしてみてください。 多くの場合、同時実行ロボットの数を減らすと全体のスループットが向上することがわかります。 もう 1 つのオプションは、使用可能なメモリを増やすことです。）

オンラインマニュアルを調べてみると、以下の記述が見つかりました。

デフォルトでは非表示になっていますが、[管理] > [RoboServer] のページで表示させることができるので、「サーバに負荷がかかっているかな？」と思う場合には見てみるのもいいでしょう。

メモリの閾値超過

ちなみに、JVMのヒープはロボットが処理を終えたからと言ってすぐに解放されるわけではなく、新たにロボットが起動した際に領域が足りなかったらCGで開放するという仕組みっぽいので、一度80%を超えたヒープが長時間80%を割らないからと言って異常であるとは言えません。

特に多くのヒープを積んでいる環境であればなおさら、余裕は十分あるのに使用率は高いままということもあると思いますので、数値を気にしすぎるのもよくないです。

運用の要諦なのかもしれませんが、「通常と比較してどうか」ということを把握しておくことが重要かな。という気がしています。

ヒープがメモリ閾値内に戻った場合には、再度 RoboServerメッセージ へ以下のようなログが記録されます。

長らくロボットを動かしていない間も高止まりを続け、次に新しいロボットを実行したところ、CGにより一部のメモリが解放され、閾値80%を下回りました。

メモリの閾値超過への対応

ただしマニュアルにあるように「閾値に到達した場合、RoboServer はロボットを起動する代わりに、キューに登録します。」の通り、スケジュール実行したはずのロボットがキューに登録されたまま「処理待ち」でスタックしてしまっている場合には、強制的に GC を実行してメモリを解放することも必要かもしれません。（実際にそのようなケースに遭遇したことはないですが）

ただ、上の実験結果でも見ていただいている通り、98%ヒープを使用している状態からスケジュール実行してロボットが動いていますので、「キューに登録されてしまう」のは他のロボットが動いている状態で閾値を超えた場合の一時的な挙動と考えるのが妥当でしょう。

仮にタスクの状態が「処理待ち」のままで、実行中のロボットが終了した後でもロボットが実行開始されないようであれば、一度 RS 自体を再起動することをお勧めします。
何らかの理由により RS に内部エラーが発生してゾンビ化している場合、MC との間で正常な通信ができていない可能性もあります。MC 上全てのタスクが「処理待ち」になっていれば RS を再起動してもエラーとならず再起動後に実行開始してくれるので、即再起動をするのが確実かもしれません。

まとめ

これまで RS はメモリの容量が足りていれば CPU については低速でも稼働に影響しない。 というのがよく言われていた常識で、私もそう思っていました。

実際にKCUがボトルネックになってCPUの性能を出し切れない場合が多いのですが、今回の実験を通して「CPU 性能を上げれば Ping待ちタイムアウトによりサーバがダウンすることは回避できるのでは？」と思い Bard に聞いてみました。

Q. JVMのFullGCにかかる処理時間に影響するのは以下項目の内どれが一番大きいですか？また、その程度と理由についても教えてください。（以下条件に関わらず、設定しているヒープの値は同じものとする）

1．搭載物理メモリ容量
2．CPUのクロック数
3．CPUのキャッシュサイズ
4．ハードディスクの速度

A.
JVMのFullGCにかかる処理時間に影響するのは、以下の項目の内、搭載物理メモリ容量です。その程度は、メモリ容量が大きいほど、FullGCにかかる処理時間は短くなります。理由は、メモリ容量が大きいほど、GCが処理する必要があるメモリ領域が少なくなるためです。

CPUのクロック数、CPUのキャッシュサイズ、ハードディスクの速度は、FullGCにかかる処理時間に影響しますが、その程度は、搭載物理メモリ容量ほど大きくありません。CPUのクロック数は、GCの処理速度に影響しますが、GCの処理時間の大部分は、メモリ領域の移動に費やされるため、CPUのクロック数の影響は小さいです。CPUのキャッシュサイズは、GCが処理する必要があるメモリ領域をキャッシュに保存することで、GCの処理時間を短縮することができますが、その効果は、メモリ容量が小さい場合ほど大きくなります。ハードディスクの速度は、GCで生成されるログファイルの書き込み速度に影響しますが、その影響は、GCの処理時間の全体に占める割合が小さいため、それほど大きくありません。

したがって、JVMのFullGCにかかる処理時間を短縮するには、搭載物理メモリ容量を増やすことが最も効果的です。

Bing にも聞いてみましたが、同じような回答でした。あまり関係ないみたいです。

1. BizRobo! のv11.4では起動時の1回だけではなく、起動後も MC との接続が切断されると起動時と同様に RS から MC へ接続処理を実行します。 ↩

2. 正確な仕様は聞いていないのでわかりませんが、ユーザーとして計測した範囲では毎秒ヘルスチェックが行われていました。 ↩

3. ExcelファイルをExcelファイルとして処理したい場合には DA でExcelアプリケーションを直接操作するか、Built-in-ExcelによりAPI経由でExcelファイルの操作をしましょう。ベーシックエンジン ロボット に内蔵されている POI は、Excelがインストールされていなくても扱える時点でExcelではないですし、そもそもの目的が Excelアプリを扱うものではなく、スプレッドシートのデータ（簡易表データの読み取り）を扱うためのにもともと作成されたものです。 ↩