SAP SQL Anywhere Tips – 要求ロギングの使用方法

前書き

今回はパフォーマンス問題の分析手法についてのブログとなります。

今回は基本指針とSAP SQL Anywhere全てのバージョンで使用できるログの取得方法について解説したいと思います。

問題の切り分け

問題分析の対応指針をまとめてみました。

注）これは1例としてお考えください。

これはこの順番で対応するとよいと考えられるものですが、実際には早く解決すべく、同時並行的に進めることが多いと思います。この場合はエンドユーザー様にもお手数をおかけすることがあります。それを少なくするためにどのようにすれば全体として手数が減るかを考えるべきです。

データベースをそのまま、SQL AnywhereでいうとInteractive SQLを使用してSQLを直接実行しているという使い方でない限り、パフォーマンスの問題は殆どの場合アプリケーションのパフォーマンスの問題としてエンドユーザーから報告されるでしょう。

この報告はアプリケーション全体を指すものと特定の処理の2種に分けられます。*①

但し、エンドユーザーの報告をそのまま捉えるのではなく、それが本当に正しいのかは確認や分析が必要です。*②

これにはより詳細なヒアリングであったり、実際にアプリケーションの処理時間を計測するなどが必要となります。この作業自体は後のパフォーマンス改善の報告の際の「改善前」の項目で使用することになりますので無駄な作業ではないでしょう。本当に全体的な問題なのか、一部分の問題なのか切り分けることが重要です。

全体的に遅いという場合はそもそもハードウェアやネットワークのリソースが不足していたり、アプリケーション構成・データベース構造に問題があるということになります。特定の処理が遅いと言う場合はその処理を更に切り分けします。*③

エンドユーザーから見える処理というのはあくまでアプリケーション上の処理です。例えばあるボタンを押して検索結果を表示するという処理であれば、アプリケーションの内部的にはボタンを押されたことに対するハンドラ→SQL文の実行→結果の受け取り→結果の表示という処理が流れることになります。その他にも「DBの接続切断」「アプリ内での他の処理」なども流れるかもしれません。その中でどの処理にどのくらいの時間がかかっているかを調査する必要があります。これが簡単にできるようにアプリ側で例えば時刻も含めたログを出力できるモードも用意しておくべきです。アプリ開発環境のデバッガを使用する方法もありますが、あまり現実的ではないでしょう。

アプリ側にログの出力機能がない場合は、その処理で実行したSQLを抜き出してInteractive SQLで実行して処理時間を計測してみてください。正確性には欠けますがおおよその目安となります。

Interactive SQLでの処理時間は結果をフェッチのような逐次処理で出力している場合の判別に役立つかもしれません。

SAConnection conn = new SAConnection(
    "Data Source=SQL Anywhere 17 Demo;Password="+pwd);
conn.Open();
SACommand cmd = new SACommand("SELECT Surname FROM Employees", conn);
SADataReader reader = cmd.ExecuteReader();
while (reader.Read())
{
    //何かの処理
}
reader.Close();
conn.Close();

このコードの場合、reader.Read()は「SELECT Surname FROM Employees」の結果を1行ずつデータベースから取得し、次の行にカーソルを移動します。whileループが終了するのは結果行の最後に達したときです。

このようなコードの場合、コメントアウトした「何かの処理」の部分が重要です。

Interactive SQLのでの計測結果と実際のコード上での処理速度があまりに違う場合、この結果の処理部分を疑うべきです。また、全行読まないで、ある特定の行が出現したらそこで読み込みを終了させるという場合もあるでしょうから、ロジックにより非常に判別が難しくなります。やはり開発時点から

SAConnection conn = new SAConnection(
    "Data Source=SQL Anywhere 17 Demo;Password="+pwd);
conn.Open();
SACommand cmd = new SACommand("SELECT Surname FROM Employees", conn);
//時刻取得1
Logfile.WriteLine(DateTime.Now.ToString()+":reader実行前);

SADataReader reader = cmd.ExecuteReader();

//時刻取得2
Logfile.WriteLine(DateTime.Now.ToString()+":reader実行完了);

while (reader.Read())
{
    //何かの処理
}
reader.Close();

//時刻取得3
Logfile.WriteLine(DateTime.Now.ToString()+":フェッチ完了);

conn.Close();

のようにログを取得する機構を入れておくことがベストです。

SAP SQL Anywhere側でもこの問題の判別をしやすくする機構を用意していますが、アプリのコードとの照らし合わせはその処理だけを単独で行わないと判別が難しいです。

このようにして、問題がアプリなのかデータベース側にあるのかを判別して対応にあたることになります。データベースを使用したアプリケーションにおいては処理速度はアプリケーション側処理とデータベース側処理の合算です。

そうそう、上で「現実的ではないでしょう」で終わらせてしまいましたが、前回のブログで解説したとおり、SQL Anywhereの特徴としてデータベースファイルはコピーするだけで他のマシン上でも使用できます。お客様のデータベースファイル（のコピー）を入手することができればそのデータベースファイルを利用しての問題解析が可能となります。開発環境でも動作させることができるようになりますのでデバッガも使用することができるでしょう。

要求ロギング

全てのバージョンで使用できるSAP SQL Anywhere側の処理のロギング方法としては「要求ロギング」があります。どのようなSQLが実行されるかをテキストファイルに逐次記録する方法です。

要求ロギングを使用するにはSAP SQL Anywhere起動時のオプションとして設定する方法と sa_server_optionシステムプロシージャで起動中のデータベースサーバに対して設定する方法の2種があります。

起動時のオプションの場合は以下のように使用します。これはVer.17のネットワークエンジン(dbsrv)での例ですが、パーソナルエンジン(dbeng)でも動作しますし17の部分を変えることで他のバージョンでも動作します。

この-zrと-zoは今現在使用している他のオプションの後に付け加える形で追加してください。

必須ではありませんが、使用する際は-zoでログの出力先を設定することを推奨します。これを指定していない場合-oで出力先を指定しているメッセージログに要求ログを出力してしまいます。また、拡張子を「.log」とするのはデータベースファイルのログファイルと混同し、トラブルの元になるのであまりおすすめしません。

-zrはどのログを取得するかです。一般的なアプリケーションであれば「SQL,PROCEDURES,TRIGGERS」で良いかと思います。NONEはログを取得しない設定ですが、-zrで設定することは無いでしょう。（-zrを付けないのと等価です）

sa_server_optionシステムプロシージャで設定する場合は上記の場合ですと以下になります。

これはInteractive SQLなどでデータベースに接続して実行することになります。

上の文が-zoに相当し、-zrが下の文に設定することになります。

順番は上記のようにRequestLogFileを先に設定するべきです。これはプロシジャの扱いですのでSQL文のルールと同じく、Windowsを御使用の場合はパスを示す\(円マーク）を\\のように2重にすることに注意してください。

なお、起動時の-zrオプション指定で開始し、CALL sa_server_option( ‘RequestLogging’ , ‘NONE’ );で止めるということも可能です。（データベースを動作させながら要求ロギングのみ停止するにはこの方法しかありません。）

出力されるログは以下のようなものになります。

正直よくわかりませんよね。でもよく見ていただければ実行されたSQLがSELECT文も含めて出力されているのがわかるかと思います。一応この時点での重要なポイントとして

• SELECT文も出力されます
• ファイルの先頭から後方に処理されたということですので前後関係は取得されます。
• アプリケーションが明示的に実行していないSQL Anywhere、Interactive SQL、SQL Central(Sybase Central)やドライバ類が内部的に実行しているSQLも記録されます。

が挙げられます。

この出力されたログは実行されたSQL文を取得するだけならこのまま見ても良いですが、分析用のシステムプロシジャが用意されていますのでそれを介して見るのが良いでしょう。

要求ログの分析

Interactive SQLを起動して適当なデータベースに接続してください。サンプルのdemo.dbでも良いです。（もちろんログを取得したデータベースでも良いです）
そして（上記で取得したログの場合なら）以下のSQL文を実行します。

これはsa_get_request_profileシステムプロシジャで取得した要求ログを分析し、結果をテンポラリテーブルのSATMP_request_timeとSATMP_request_profileに出力します。（それをSELECT文で閲覧します。）

私の場合はこの3つの文をセットで実行してしまうことが多いです。そして最も重要視するカラムを降順になるようにORDER BYを追加しています。これは私の場合ですのでORDER BYはなくても結構です。

実行すると以下のように結果セットが2つ返ります。（画面下部のタブに注目してください。）

結果セット1がSATMP_request_timeのSELECTの結果です。つまりは要求ログが分析された結果です。
結果で重要なのは

stmt：実行したSQL文
millisecs：stmtカラムで実行されたSQLの実行時間（ミリ秒）

となります。この2つのカラムを見ればどのSQLにどのくらいの処理時間を要しているか見ることが出来ます。（ORDER BYで実行時間が長い順でソートさせたことになります。）
なお、処理の前後関係を追うのであればreq_id、接続単位で見るのであればconn_id/conn_handleを利用します。

結果セット2がSATMP_request_profileのSELECTの結果です。これは結果セット1の結果を更に集約したもので、
uses: そのSQL文が実行された回数
total_ms:合計実行時間（ミリ秒)
avg_ms:平均実行時間（ミリ秒、total_ms/uses）
max_ms:最大実行時間（ミリ秒）
を表します。（ORDER BYでusesで降順ソートしたことになります。）

この２つから例えば

・あるSQLの合計実行時間は大半を最大実行時間のものが占めている
→　SATMP_request_time（結果セット1）でその最大実行時間はどのような時に発生したかを確認
→　不定期に発生する
→　キャッシュが不足してキャッシュアウトした時に実行したものが遅いのではないか？
→　キャッシュを増やしてみよう

・アプリ上で遅い処理で実行しているSQLは遅くはない
→　アプリのロジックの問題？

等の考察を得ることが出来ます。

以上古いSQL Anywhereでも最新のSQL Anywhereでも使用できる一番ベーシックな機能・手法について解説しました。

次回はこれから発展したVer.17での新機能を利用した方法について解説します。