4D v17 R5 では新規メソッドが追加されたほか、プロセスの個別トレースも可能になり、デバッグ・ログが改良されました。今回は 4D v17 R6 の BETAリリースとともに、プロセスの監視を助ける簡単なログ解析ツールを提供することになりました。このツールを使って、時間のかかるプロセスを確認したり、コール・チェーンとその処理時間を調べたりすることができます。
ここではサンプルシナリオとして、動的なWebページを提供するデータベースのレスポンスが遅い、という問題を調べることにします。
Webサイトが時々重いという指摘を複数のユーザーからもらいましたが、それ以上の詳細はわかりません。さっそく、何が問題なのか調査してみましょう。
デバッグ・ログの生成
問題を調査するにあたって、まずデバッグ・ログを生成します。この解析ツールは 4D v14 のデバッグ・ログ形式に基づいているため、ログ生成を有効にする際にオプションを指定する必要があります:
// デバッグ・ログをアクティブにし、3つのオプションを指定します。2:引数付き, 4:4D v14 形式 (タブ付き), 8:逐次記録
SET DATABASE PARAMETER (Debug log recording;2+4+8)
4D v17 R5 以降は個別プロセスのデバッグができるため、遅延の原因として疑われるプロセスがあれば、それをピンポイントで調査することもできます:
SET DATABASE PARAMETER (Current process debug log recording;2+4+8)
プロジェクト新規作成
この解析ツールでは、「プロジェクト」単位でデバッグ・ログ・ファイルを管理します。
解析ツールを起動すると、既存のプロジェクトが表示されます。「新規作成」ボタンで新しいプロジェクトを作成します。解析するログ・ファイルを、ファイルまたはフォルダーで選択し、プロジェクトの名称を指定します。
解析処理はプリエンプティブに実行されますが、解析するファイルの数やマシンの処理能力によって時間がかかる場合があります。
プロジェクトの分析
一覧からプロジェクトを選択すると、期間や行数などのログの基本情報が右に表示されます。右下のボタンをクリックして、プロジェクトのコール・チェーンや詳細を見ることができます。
コール・チェーン
この画面では、プロセスとその実行時間が一覧できます。リストの並び順は、もっとも時間を消費するプロセスが上にくるようになっています。
プロセスのコール・チェーンを展開していくと、各階層で一番時間がかかっている処理が確認できます。ALTキーを押しながら展開すると、一番処理の重いコール・チェーンを展開します。タスクやメソッドの行をダブルクリックすると、当該処理がコール・チェーン・エクスプローラーに表示されます。このリストの任意の階層をダブルクリックすると、それが単独で表示されます。コマンドを選択すると、そのコマンドのコール回数、総所要時間、平均所要時間が表示されます。
サンプルシナリオにおいて、一番時間のかかるプロセスとコマンドを探しました。RELATE MANY SELECTION コマンドの処理に1分以上かかることがあるのがわかりました。では、今度は詳細画面を開いて、このコマンドがどこでコールされたのか調べてみましょう。
詳細画面
- 範囲の選択
詳細画面では分刻みのアクティビティ・タイムラインが表示されます。範囲を指定してズームアイコンをクリックすると、拡大表示されます。これにより、対象を限定して調査していけるため、アクティビティが高い箇所を重点的に調べる方法がとれます。
範囲を変更するたびに解析が実行され、結果が下に表示されます。
- サマリー
「サマリー」タブには選択した範囲に関する処理の統計が表示されます。
- トップ
「トップ」タブには選択範囲あるいは選択プロセスに関わる、すべての処理のコール数と所要時間が表示されます。このリストはフィルターを使って、コマンドやメソッド、メンバーメソッドなどに絞り込むことができるため、処理タイプ別の調査に便利です。
サンプルシナリオの調査では範囲を限定したうえで、コマンドでフィルターをかけました。コール・チェーン画面でも確認したように、RELATE MANY SELECTION コマンドが複数回コールされており、処理時間もかかっているようです。
- オペレーション
「オペレーション」タブには、特定の1分に開始された処理の詳細が表示されます。このリストは任意の検索ワードで絞り込むか、ハイライト表示することができます。パフォーマンスの都合上、このタブの情報は1分の内容に限られています。任意の1分は紫のバーで変更できます。
処理されたすべてのコードが表示されているため、このリストはたいへん便利です。ヘッダーをクリックすることで並べ替えることもできます。
サンプルシナリオでは、すでにアタリを付けた RELATE MANY SELECTION コマンドで絞り込み検索し、所要時間の長い順に並べ替えました。一番時間のかかっている2回のコールは同じフィールドを引数として受け取っているようです。データベースのストラクチャーを確認したところ、原因がわかりました: このフィールドはインデックスされていませんでした。
おわりに
この解析ツールはコードの問題を発見し、データベースのパフォーマンスを改善する意図でデザインされています。ぜひツールをダウンロードして実際に使ってみてください！