トレースでパフォーマンスのボトルネックを特定してみた

テクニカルブログ

2026.04.12

アプリケーションの動きがなんか遅いなと感じたとき、みなさんはどのように調査をしていますか？
今回はパフォーマンスのボトルネックの特定と改善の方法についてご紹介いたします！
なお、 PowerBuilder 2022 R3 環境で動作確認を行っております。

トレースとは

解析のためには何といってもログ情報を集めて、それを解析するのがセオリーです。
アプリケーションから DB 接続および SQL 文の実行結果のログを「データベーストレースログ」。
アプリケーションのプログラムのログを「トレースファイル」と呼びます。
今回下記のログファイルを出力し、解析に利用したいと思います。

・データベースのトレースログ（デフォルトでは dbtrace.log）
・アプリケーションのトレースファイル（.pbp ファイル形式）

サンプルアプリケーション

サンプル用にアプリケーションを作成しました。画面イメージは下記のとおりです。

部署名での従業員検索処理と、データウィンドウに表示された検索結果を PDF に出力する機能を持つアプリケーションとなります。
このアプリケーションのパフォーマンスが全体的に悪いため、原因の特定とパフォーマンスの改善を目指します。

データベーストレースログ出力方法

さっそくデータベース接続や SQL のパフォーマンスを解析していきたいと思います。
まずデータベーストレースログを出力するには、接続情報の記載を下記のように変更します。
なお、筆者は PostgreSQL を ODBC 経由で接続し動作確認をいたしました。

// 修正前
// SQLCA.DBMS = "ODBC"
// 修正後
SQLCA.DBMS = "TRACE ODBC"

SQLCA.DBMS の値の先頭に TRACE をつけるだけで済むので簡単ですね！
アプリケーションを実行すると、ログファイルの出力先を尋ねられるので任意のディレクトリを指定してください。

トレースログの解析

データベースの接続から切断までの、アプリケーションから接続中のデータベースに対して実行される内部コマンドの記録が出力されます。
ログファイルから、実行した SQL や実行にかかった時間を解析します。
下記の通りトレースログの一部を抜粋いたします。

(00B7C068): PREPARE: (0.000 MS / 90.382 MS)
(00B7C068): BEGIN TRANSACTION: (0.006 MS / 90.388 MS)
(00B7C068): PREPARE WITH BIND VARIABLES:
(00B7C068): SELECT departments.dept_name, employees.emp_name FROM departments, employees WHERE ( departments.dept_id = employees.dept_id ) and ( ( departments.dept_name LIKE '%' || ? || '%' OR ? = '') ) 
(00B7C068): VCHAR Length=3 ID=:as_dept_name *開発部*
(00B7C068): VCHAR Length=3 ID=:as_dept_name *開発部* (1.411 MS / 91.799 MS)
(00B7C068): BIND SELECT OUTPUT BUFFER (DataWindow): (0.021 MS / 91.820 MS)
(00B7C068): ,len=101,type=CHAR,pbt=1,dbt=0,ct=0,prec=0,scale=0
(00B7C068): ,len=101,type=CHAR,pbt=1,dbt=0,ct=0,prec=0,scale=0
(00B7C068): EXECUTE: (2.598 MS / 94.418 MS)
(00B7C068): FETCH NEXT: (0.016 MS / 94.434 MS)
(00B7C068): 	COLUMN=開発部	COLUMN=田中 太郎
(00B7C068): FETCH NEXT: (0.000 MS / 94.434 MS)
(00B7C068): 	COLUMN=開発部	COLUMN=佐藤 花子
(00B7C068): FETCH NEXT: (0.197 MS / 94.631 MS)
(00B7C068): *** DBI_FETCHEND *** (rc 100)
(00B7C068): COMMIT: (0.307 MS / 94.938 MS)

もし特定の SQL 実行（EXECUTE,FETCH）に時間がかかっていれば、パフォーマンス低下は SQL 起因といえますが、
今回は短時間で実行できているので、パフォーマンスの低下の原因は他の箇所にありそうですね。

アプリケーションのトレースファイルの出力方法

続いて、アプリケーションのトレースファイルを見ていきましょう。
アプリケーションのトレースファイルを出力するには、 [ ツール ] ＞ [ システムオプション ] ＞ [ プロファイル ] にて下記の設定をしてください。

・「トレースを有効にする」のチェックボックスを ON 
・「トレースファイル名」を .pbw ファイルと同じ場所を指定する（.pbp ファイル形式）

「トレースを有効にする」を ON にすると、 IDE からの実行時に「トレースファイル名」で指定したパスにトレースファイルが作成されます。
トレースファイルの解析は、後述するプロファイルツールにて当該ファイルを参照して行います。

プロファイルツールを使ったトレースファイルの解析

ただし先述した方法で出力したトレースファイルをテキストエディタで直接開くことはできません。
プログラム（TraceFile オブジェクト）による解析も可能ですが、今回はプロファイルツールで解析する方法をご紹介します。

プロファイルツールには、「プロファイルクラスビュー」、「プロファイルルーチンビュー」、「プロファイルトレースビュー」の 3 種類があります。
[ ファイル ] ＞ [ 新規作成 ] ＞ [ ツール ] から開くことができます。

・プロファイルクラス ビュー
　　アプリケーションで使用されたクラス（ウィンドウ、ユーザーオブジェクトなど）単位で、処理時間と実行回数を表示します。
・プロファイルルーチン ビュー
　　実行されたすべてのルーチンの処理時間、実行回数を関数・イベント単位で表示します。
・プロファイルトレース ビュー
　　プログラムが実行された順番通りにログを表示します。

プロファイルツールを使ったトレースファイルの解析

プロファイルトレース　ビュー

さっそくプロファイルツールを使ってトレースファイルを解析してみましょう。
まずは時系列順に処理を追うため、[ プロファイルトレースビュー ] でログを見ます。

どのオブジェクトの、どのイベントから、どのような処理が行われたかが上から順に表示されています。
画面で「検索」や「出力」ボタンをクリックしたことにより、cb_search.clicked() や cb_output.clicked() が実行されていることが確認できます。
また、イベント内での関数呼び出しや DB 操作についても記録されます。例えば Retrieve() の処理時間が長ければ SQL が原因なのでは？といった風に推測ができます。
今回は cb_search.clicked() から呼び出している、ユーザーオブジェクトの関数「uo_dummy.delayed() 」の実行にやや時間がかかっているように見えます。

uo_dummy.delayed() がどのような処理でどこから呼び出されているのか。これを解析するために次は「プロファイルルーチンビュー」を開きます。

プロファイルルーチン　ビュー

そのルーチンの呼び出し元と、呼び出し先のルーチンそれぞれの処理時間とソースコード表示されています。
やはり uo_dummy.delayed() の処理に時間がかかっていますね。
「検索」ボタン押下時（cb.search.clicked()）から uo_dummy.delayed() が呼び出されているので、次は呼び出し先のルーチンを見てみましょう。

「呼出元」を見ると、 uo_dummy.delayed() がいくつかのルーチンから呼び出されているようです。
uo_dummy.delayed() の呼び出しをやめるか、もしくは当該ソースを修正することでパフォーマンス改善が見込めそうですね。
uo_dummy.delayed() でどのような処理をしているか見てみましょう。