15 PL/SQL階層プロファイラの使用
PL/SQL階層プロファイラを使用すると、PL/SQLアプリケーションのボトルネックおよびパフォーマンスのチューニング機会を特定できます。
このプロファイラにより、ファンクション・コール別に編成されたPL/SQLプログラムの動的実行プロファイルがレポートされ、SQL実行時間とPL/SQL実行時間が個別に明確になります。特別なソースやコンパイル時間の準備は必要なく、あらゆるPL/SQLプログラムをプロファイリングできます。
この章では、PL/SQL階層プロファイラについて説明するとともに、これを使用してPL/SQLプログラムのプロファイル・データを収集して分析する方法を示します。
トピック:
PL/SQL階層プロファイラの概要
非階層(フラット)プロファイラにより、プログラムによって各サブプログラム内で費やされた時間(サブプログラムの関数時間または自己時間)が記録されます。関数時間は役に立ちますが、たいていこれでは十分ではありません。たとえば、サブプログラムINSERT_ORDER
でプログラム全体の40%が費やされたことがわかれば参考になりますが、INSERT_ORDER
を頻繁にコールするプログラムや、INSERT_ORDER
の下(子サブプログラムを含む)で費やされた合計時間がわかればさらに便利です。階層プロファイラは、このような情報を提供します。
PL/SQL階層プロファイラには、次の機能があります。
-
サブプログラム・コール別に編成されたPL/SQLプログラムの動的実行プロファイルのレポート
-
SQL実行時間およびPL/SQL実行時間の個別の説明
-
特殊なソースやコンパイル時間の準備が不要
-
カスタム・レポートを生成するために統合開発環境(IDE)ツール(SQL Developerやサード・パーティ・ツールなど)によって処理された結果のデータベース表(階層プロファイラ表)への格納
-
次のような、サブプログラム・レベルの実行サマリー情報の提供
-
サブプログラムへのコール回数
-
サブプログラム自体で費やされた時間(関数時間または自己時間)
-
サブプログラム自体およびその子サブプログラムで費やされた時間(サブツリー時間)
-
次のような、詳細な親子情報
-
特定のサブプログラムのすべてのコール元(親)
-
特定のサブプログラムによってコールされたすべてのサブプログラム(子)
-
サブプログラムxがyからコールされたときに費やされた時間
-
サブプログラムxがyからコールされた回数
-
-
PL/SQL階層プロファイラは、DBMS_HPROF
パッケージによって実装され、次の2つのコンポーネントを持ちます。
-
データ収集
データ・コレクション・コンポーネントは、PL/SQL Virtual Machine固有のパーツです。
DBMS_HPROF
パッケージには、階層プロファイリングのオンとオフを切り替えるAPIが用意されています。RAWプロファイラ出力はファイルまたはRAWプロファイラ・データ表に書き込まれます。 -
アナライザ
アナライザ・コンポーネントにより、RAWプロファイラ出力が処理され、分析の結果が生成されます。アナライザ・コンポーネントによって次が分析されます。-
RAWプロファイラ・データ・ファイルおよびHTML CLOBレポートへのRAWプロファイラ・データ表に存在するRAWプロファイラ・データ、分析されたレポート・ファイル、および階層プロファイラ分析表。
注意:
アナライザを使用せずに、RAWプロファイラ出力から直接簡単なHTMLレポートを生成するには、
plshprof
コマンドライン・ユーティリティを使用できます。 -
プロファイル・データの収集
PL/SQL階層プロファイラ用としてPL/SQLプログラムからプロファイル・データを収集するステップは、次のとおりです。
例15-1 PL/SQLプロシージャのプロファイリング
BEGIN /* Start profiling. Write raw profiler output to file test.trc in a directory that is mapped to directory object PLSHPROF_DIR (see note after example). */ DBMS_HPROF.START_PROFILING('PLSHPROF_DIR', 'test.trc'); END; / -- Run procedure to be profiled BEGIN test; END; / BEGIN -- Stop profiling DBMS_HPROF.STOP_PROFILING; END; /
例15-2 RAWプロファイラ・データ表でのプロファイル
DECLARE analyze_runid number; trace_id number; BEGIN -- create raw profiler data and analysis tables -- call create_tables with force_it =>FALSE ( default) when -- raw profiler data and analysis tables do not exist already DBMS_HPROF . CREATE_TABLES ; -- Start profiling . -- Write raw profiler data in raw profiler data table trace_id := DBMS_HPROF . START_PROFILING ; -- Run procedure to be profiled test ; -- Stop profiling DBMS_HPROF . STOP_PROFILING ; -- analyzes trace_id entry in raw profiler data table and writes -- hierarchical profiler information in hprof ’s analysis tables. analyze_runid := DBMS_HPROF . ANALYZE(trace_id ); END; /
次のPL/SQLプロシージャtest
について検討してみます。
CREATE OR REPLACE PROCEDURE test AUTHID DEFINER IS n NUMBER; PROCEDURE foo IS BEGIN SELECT COUNT(*) INTO n FROM EMPLOYEES; END foo; BEGIN -- test FOR i IN 1..3 LOOP foo; END LOOP; END test; /
RAWプロファイラ・データ表を分析し、HTML CLOBレポートを生成するPL/SQLプロシージャについて検討してみます
declare reportclob clob ; trace_id number; begin -- create raw profiler data and analysis tables -- force_it =>TRUE will dropped the tables if table existed DBMS_HPROF . CREATE_TABLES (force_it =>TRUE ); -- Start profiling . -- Write raw profiler data in raw profiler data table trace_id := DBMS_HPROF . START_PROFILING ; -- Run procedure to be profiled test ; -- Stop profiling DBMS_HPROF . STOP_PROFILING ; -- analyzes trace_id entry in raw profiler data table and produce -- analyzed HTML report in reportclob . DBMS_HPROF .ANALYZE (trace_id , reportclob ); end; /
例15-1のSQLスクリプトは、PL/SQLプロシージャtest
の実行をプロファイリングしたものです。
注意:
ディレクトリ・オブジェクトは、ファイル・システムのパス名の別名です。たとえば、データベースAS
SYSDBA
に接続している場合、次のCREATE
DIRECTORY
文では、ディレクトリ・オブジェクトPLSHPROF_DIR
が作成され、これがファイル・システム・ディレクトリ/private
/plshprof
/results
にマップされます。
CREATE DIRECTORY PLSHPROF_DIR as '/private/plshprof/results';
例15-1のSQLスクリプトを実行するには、PLSHPROF_DIR
とマップ先のディレクトリの両方に対するREAD
およびWRITE
権限が必要です。データベースにAS
SYSDBA
で接続している場合、次のGRANT
文では、PLSHPROF_DIR
に対するREAD
およびWRITE
権限がHR
に付与されます。
GRANT READ, WRITE ON DIRECTORY PLSHPROF_DIR TO HR;
関連項目:
-
ディレクトリ・オブジェクトの使用の詳細は、『Oracle Database SecureFilesおよびラージ・オブジェクト開発者ガイド』を参照してください。
-
DBMS_HPROF
.START_PROFILING
およびDBMS_HPROF
.STOP_PROFILING
の詳細は、『Oracle Database PL/SQLパッケージおよびタイプ・リファレンス』を参照してください。
RAWプロファイラ出力の理解
RAWプロファイラ出力は、PL/SQL階層プロファイラのアナライザ・コンポーネントによって処理されることを目的としています。ただし、このように処理されなくても、プログラムの簡単な関数レベルのトレースは提供できます。ここでは、RAWプロファイラ出力について説明します。
注意:
この章で示すRAWプロファイラの形式は、RAWプロファイラ出力の概念的な機能を示すことのみを目的としています。形式の詳細は、Oracle Databaseリリースごとに異なる可能性があります。
例15-1のSQLスクリプトでは、次のRAWプロファイラ出力がファイルtest
.trc
に書き込まれました。
P#V PLSHPROF Internal Version 1.0 P#! PL/SQL Timer Started P#C PLSQL."".""."__plsql_vm" P#X 4 P#C PLSQL."".""."__anonymous_block" P#X 77 P#C PLSQL."HR"."TEST"::7."TEST"#980980e97e42f8ec #1 P#X 4 P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4 P#X 47 P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6."3r6qf2qhr3cm1" P#! SELECT COUNT(*) FROM EMPLOYEES P#X 279 P#R P#X 58 P#R P#X 3 P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4 P#X 4 P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6."3r6qf2qhr3cm1" P#! SELECT COUNT(*) FROM EMPLOYEES P#X 121 P#R P#X 5 P#R P#X 2 P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4 P#X 3 P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6."3r6qf2qhr3cm1" P#! SELECT COUNT(*) FROM EMPLOYEES P#X 117 P#R P#X 4 P#R P#X 2 P#R P#X 2 P#R P#X 3 P#R P#C PLSQL."".""."__plsql_vm" P#X 3 P#C PLSQL."".""."__anonymous_block" P#X 86 P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #453 P#R P#R P#R P#! PL/SQL Timer Stopped
表15-1 RAWプロファイラ出力ファイルのインジケータ
インジケータ | 意味 |
---|---|
|
|
|
サブプログラムへのコール(コール・イベント) |
|
サブプログラムからの戻り値(戻りイベント) |
|
前のイベントと次のイベント間の経過時間 |
|
コメント |
コール・イベント(P#C
)と戻りイベント(P#R
)は、(一対のカッコのように)正しくネストされます。未処理の例外が原因でコール先のサブプログラムが終了しても、対応する戻りイベントはレポートされます。
RAWプロファイラ出力の各コール・イベント(P#C
)のエントリには、次の情報が含まれます。
-
コール先のサブプログラムが属するネームスペース
-
コール先のサブプログラムが定義されているPL/SQLモジュールの名前
-
コール先のサブプログラムが定義されているPL/SQLモジュールのタイプ
-
コール先のサブプログラムの名前
この名前は、「特別なファンクション名」の特別なファンクション名の1つである場合があります。
-
コール先のサブプログラムのシグネチャのMD5ハッシュを表す16進値
DBMS_HPROF
.analyze
PL/SQL APIにより、ハッシュ値が階層プロファイラ表に格納されます。これにより、ユーザーとDBMS_HPROF
.analyze
の両方が、オーバーロードされたサブプログラム(同じ名前を持つサブプログラム)を区別できるようになります。 -
コール先のサブプログラムがPL/SQLモジュールに定義されている行番号
PL/SQL階層プロファイラでは、モジュール内の個々の行で費やされた時間は測定されませんが、行番号を使用すると、(IDE/ツールのように)モジュール内のサブプログラムのソースの場所を特定し、オーバーロードされたサブプログラムを区別できるようになります。
たとえば、前述の例のRAWプロファイラ出力の次のエントリについて検討してみます。
P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4
前述のエントリの構成要素には、次のような意味があります。
コンポーネント | 意味 |
---|---|
|
|
|
|
|
7は、 |
|
|
|
|
|
4は、 |
注意:
サブプログラムがインラインされている場合、プロファイラ出力ではレポートされません。
DETERMINISTIC
ファンクションのコールが最適化されている場合、プロファイラ出力ではレポートされません。
関連項目:
-
analyze
PL/SQL APIの詳細は、「プロファイル・データの分析」を参照してください。 -
サブプログラムのインライン記述の詳細は、『Oracle Database PL/SQL言語リファレンス』を参照してください。
-
DETERMINISTIC
関数の詳細は、『Oracle Database PL/SQL言語リファレンス』を参照してください。
追跡されるサブプログラムのネームスペース
PL/SQL階層プロファイラが追跡するサブプログラムは、次のようにネームスペースPLSQLおよびSQLに分類されます。
-
ネームスペースPLSQLには、次が含まれます。
-
PL/SQLサブプログラム・コール
-
PL/SQLトリガー
-
無名PL/SQLブロック
-
リモート・サブプログラム・コール
-
パッケージ初期化ブロック
-
-
ネームスペースSQLには、問合せ、データ操作言語(DML)文、データ定義言語(DDL)文およびネイティブ動的SQL文など、PL/SQLから実行されるSQL文が含まれます。
特別な関数名
PL/SQL階層プロファイラでは、特定の操作が表15-2に示す名前とネームスペースを持つ関数であるかのように追跡されます。
表15-2 PL/SQL階層プロファイラによって追跡される操作の関数名
追跡される操作 | 関数名 | ネームスペース |
---|---|---|
PL/SQL Virtual Machineへのコール |
|
PL/SQL |
無名PL/SQLブロック |
|
PL/SQL |
パッケージ初期化ブロック |
|
PL/SQL |
行 |
|
SQL |
行 |
|
SQL |
行 |
|
SQL |
プロファイル・データの分析
PL/SQL階層プロファイラのアナライザ・コンポーネントDBMS_HPROF
.analyze
により、RAWプロファイラ出力が処理され、表15-3に示す階層データベース表に結果が格納されます。
トピック:
注意:
アナライザを使用せずに、RAWプロファイラ出力から直接簡単なHTMLレポートを生成するには、plshprof
コマンドライン・ユーティリティを使用できます。詳細は、「plshprofユーティリティ」を参照してください。
階層プロファイラ表の作成
次のステップでは、表15-3にある階層プロファイラ表と、プロファイル・データを永続的に格納するために必要な他のデータ構造を作成する方法、DBMS_HPROF
パッケージの実行に必要な権限、カスタム・レポートの生成について説明します。
例15-3 DBMS_HPROF.analyzeの起動
DECLARE runid NUMBER; BEGIN runid := DBMS_HPROF.analyze(LOCATION=>'PLSHPROF_DIR', FILENAME=>'test.trc'); DBMS_OUTPUT.PUT_LINE('runid = ' || runid); END; /
例15-3の無名ブロックでは、次の処理を行います。
-
DBMS_HPROF
.analyze
機能の起動により、次が実行されます。-
ディレクトリ・オブジェクト
PLSHPROF_DIR
にマップされたディレクトリにあるRAWプロファイラ出力ファイルtest
.trc
(「RAWプロファイラ出力の理解」を参照)のプロファイル・データを分析し、データを表15-3の階層プロファイラ表に格納します。 -
表15-3の階層プロファイラ表に問い合せるために使用できる一意の識別子を戻します。(これらの階層プロファイラ表に問い合せることにより、カスタマイズ・レポートを作成できます。)
-
-
一意の識別子を、出力のための変数
runid
に保存します。
階層プロファイラ表の理解
次の各項では、表15-3の階層プロファイラ表を使用する方法について説明します。
階層プロファイラ・データベース表の列
表15-4は、階層プロファイラ表DBMSHP_RUNS
の列を示します。この表には、DBMS_HPROF
.analyze
の実行時ごとに1行のトップレベル情報が含まれます。
階層プロファイラ表DBMSHP_RUNS
の主キーはRUNID
です。
表15-4 DBMSHP_RUNS表の列
列名 | 列データ型 | 列の内容 |
---|---|---|
|
|
|
|
|
この |
|
|
この |
|
|
この |
表15-5は、階層プロファイラ表DBMSHP_FUNCTION_INFO
の列を示します。この表には、このDBMS_HPROF
.analyze
の実行時にプロファイリングされたサブプログラムごとに1行の情報が含まれます。サブプログラムがオーバーロードされた場合、表15-5には、このサブシステムのバリエーションごとに1行が含まれます。各バリエーションには、独自のLINE#
およびHASH
があります(「オーバーロードされたサブプログラムの区別」を参照)。
階層プロファイラ表DBMSHP_FUNCTION_INFO
の主キーはRUNID, SYMBOLID
です。
表15-5 DBMSHP_FUNCTION_INFO表の列
列名 | 列データ型 | 列の内容 |
---|---|---|
|
|
|
|
|
サブプログラムの記号識別子(この |
|
|
各サブプログラムが定義されているモジュールの所有者( |
|
|
サブプログラムが定義されているモジュール( |
|
|
サブプログラムが定義されているモジュールのタイプ( |
|
|
サブプログラムの名前(必ずしも関数であるとはかぎりません)( この名前は、「特別なファンクション名」の特別なファンクション名の1つである場合があります。 サブプログラム 関数 |
|
|
|
|
|
サブプログラムのシグネチャのハッシュ・コード(この |
|
|
サブプログラムのネームスペース。詳細は、「追跡されるサブプログラムのネームスペース」を参照してください。 |
|
|
子サブプログラムで費やされた時間を含む、サブプログラムの経過時間(マイクロ秒単位)。 |
|
|
子サブプログラムで費やされた時間を除く、サブプログラムの経過時間(マイクロ秒単位)。 |
|
|
サブプログラムに対するコールの数。 |
|
|
SQL文のSQL識別子。 |
|
|
SQL文の最初の50文字。 |
表15-6は、階層プロファイラ表DBMSHP_PARENT_CHILD_INFO
の列を示します。この表には、このDBMS_HPROF
.analyze
の実行時にプロファイリングされた一意の親子サブプログラムの組合せごとに1行の親子情報が含まれます。
表15-6 DBMSHP_PARENT_CHILD_INFO表の列
列名 | 列データ型 | 列の内容 |
---|---|---|
|
|
|
|
|
親記号ID。
|
|
|
子記号ID。
|
|
|
子サブプログラムで費やされた時間を含む、 |
|
|
子サブプログラムで費やされた時間を除く、 |
|
|
|
オーバーロードされたサブプログラムの区別
オーバーロードされたサブプログラムとは、同じ名前を持つ異なるサブプログラムです。
プログラムによってcompute
という名前の3つのサブプログラム(1番目は50行目、2番目は76行目、3番目は100行目)が宣言されるとします。DBMSHP_FUNCTION_INFO
表では、これらのサブプログラムごとにFUNCTION
列にcompute
があります。これらの3つのサブプログラムを区別するには、LINE#
列(1番目のサブプログラムは50、2番目は76、3番目は100)またはHASH
列(サブプログラムごとに一意の値)を使用します。
2回の異なる実行時のプロファイル・データでは、関数のLINE#
およびHASH
値が異なる可能性があります。関数のLINE#
値は、関数定義の前で行を挿入または削除したときに変更されます。HASH
値は、パラメータ・リストを変更した場合など、関数のシグネチャが変更されたときのみ変更されます。
関連項目:
オーバーロードされたサブプログラムの詳細は、『Oracle Database PL/SQL言語リファレンス』を参照してください。
サンプルのPL/SQLプロシージャの階層プロファイラ表
「プロファイル・データの収集」のPL/SQLプロシージャtest
の階層プロファイラ表を例15-4から例15-6に示します。
DBMSHP_PARENT_CHILD_INFO
表(例15-6)の第3行を検討してみます。RUNID
列は、この行が3回目の実行時のものであることを示します。列PARENTSYMID
およびCHILDSYMID
は、親(コール元)と子(コール先サブプログラム)の記号IDがそれぞれ2
と1
であることを示します。表DBMSHP_FUNCTION_INFO
(例15-5)は、3回目の実行時については記号ID 2
と1
がそれぞれ、プロシージャ__plsql_vm
と__anonymous_block
に対応することを示します。したがって、この行の情報は、プロシージャ__plsql_vm
から、モジュールHR
.TEST
の__anonymous_block
(__plsql_vm
内で定義)へのコールに関するものです。この行には、プロシージャ__plsql_vm
からコールされたとき、プロシージャ__anonymous_block
の関数時間が44マイクロ秒で、__anonymous_block
サブツリー(子孫を含む)で費やされた時間が121マイクロ秒であると表示されます。
例15-4 サンプルのPL/SQLプロシージャのDBMSHP_RUNS表
RUNID RUN_TIMESTAMP TOTAL_ELAPSED_TIME RUN_COMMENT ---------- ------------------------------ ------------------ ----------- 1 20-DEC-12 11.37.26.688381 AM 7 2 20-DEC-12 11.37.26.700523 AM 9 3 20-DEC-12 11.37.26.706824 AM 123
例15-5 サンプルのPL/SQLプロシージャのDBMSHP_FUNCTION_INFO表
RUNID SYMBOLID OWNER MODULE TYPE FUNCTION ---------- ----------- ------- ------------ --------------- ------------------------- 1 1 HR PKG PACKAGE BODY MYPROC 2 1 HR PKG PACKAGE BODY MYFUNC 2 2 HR PKG PACKAGE BODY MYPROC 3 1 __anonymous_block 3 2 __plsql_vm 3 3 HR PKG PACKAGE BODY MYFUNC 3 4 HR PKG PACKAGE BODY MYPROC 3 5 HR TEST2 PROCEDURE TEST2 LINE# CALLS HASH NAMESPACE ----- ------ ---------------------------------------------------------------- ----------- 2 1 9689BA467A19CD19 PLSQL 7 1 28DC3402BAEB2B0D PLSQL 2 1 9689BA467A19CD19 PLSQL 0 1 PLSQL 0 1 PLSQL 7 1 28DC3402BAEB2B0D PLSQL 2 2 9689BA467A19CD19 PLSQL 1 1 980980E97E42F8EC PLSQL NAMESPACE SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME ----------- ----------------------- ------------------------ PLSQL 7 7 PLSQL 9 8 PLSQL 1 1 PLSQL 121 44 PLSQL 123 2 PLSQL 9 8 PLSQL 8 8 PLSQL 77 61
例15-6 サンプルのPL/SQLプロシージャのDBMSHP_PARENT_CHILD_INFO表
RUNID PARENTSYMID CHILDSYMID SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME CALLS
---------- ----------- ---------- ----------------------- ------------------------ ------
2 1 2 1 1 1
3 1 5 77 61 1
3 2 1 121 44 1
3 3 4 1 1 1
3 5 3 9 8 1
3 5 4 7 7 1
オプションを使用したDBMS_HPROF.analyzeのコール例
オプションを使用しないDBMS_HPROF
.analyze
のコール例は、例15-3を参照してください。
例15-7では、パッケージを作成し、パッケージ内のサブプログラムを起動するプロシージャを作成し、プロシージャをプロファイリングし、RAWプロファイラ出力ファイルの分析にDBMS_HRPROF
.analyze
を使用します。RAWプロファイル出力ファイルは、PLSHPROF_DIR
ディレクトリ・オブジェクトに対応するディレクトリにあります。
例15-7 オプションを使用したDBMS_HPROF.analyzeの起動
-- Create package CREATE OR REPLACE PACKAGE pkg AUTHID DEFINER IS PROCEDURE myproc (n IN out NUMBER); FUNCTION myfunc (v VARCHAR2) RETURN VARCHAR2; FUNCTION myfunc (n PLS_INTEGER) RETURN PLS_INTEGER; END pkg; / CREATE OR REPLACE PACKAGE BODY pkg IS PROCEDURE myproc (n IN OUT NUMBER) IS BEGIN n := n + 5; END; FUNCTION myfunc (v VARCHAR2) RETURN VARCHAR2 IS n NUMBER; BEGIN n := LENGTH(v); myproc(n); IF n > 20 THEN RETURN SUBSTR(v, 1, 20); ELSE RETURN v || '...'; END IF; END; FUNCTION myfunc (n PLS_INTEGER) RETURN PLS_INTEGER IS i PLS_INTEGER; PROCEDURE myproc (n IN out PLS_INTEGER) IS BEGIN n := n + 1; END; BEGIN i := n; myproc(i); RETURN i; END; END pkg; / -- Create procedure that invokes package subprograms CREATE OR REPLACE PROCEDURE test2 AUTHID DEFINER IS x NUMBER := 5; y VARCHAR2(32767); BEGIN pkg.myproc(x); y := pkg.myfunc('hello'); END; -- Profile test2 BEGIN DBMS_HPROF.START_PROFILING('PLSHPROF_DIR', 'test2.trc'); END; / BEGIN test2; END; / BEGIN DBMS_HPROF.STOP_PROFILING; END; / -- If not done, create hierarchical profiler tables (see Creating Hierarchical Profiler Tables). -- Call DBMS_HPROF.analyze with options DECLARE runid NUMBER; BEGIN -- Analyze only subtrees rooted at trace entry "HR"."PKG"."MYPROC" runid := DBMS_HPROF.analyze('PLSHPROF_DIR', 'test2.trc', trace => '"HR"."PKG"."MYPROC"'); -- Analyze up to 20 calls to subtrees rooted at trace entry -- "HR"."PKG"."MYFUNC". Because "HR"."PKG"."MYFUNC" is overloaded, -- both overloads are considered for analysis. runid := DBMS_HPROF.analyze('PLSHPROF_DIR', 'test2.trc', collect => 20, trace => '"HR"."PKG"."MYFUNC"'); -- Analyze second call to PL/SQL virtual machine runid := DBMS_HPROF.analyze('PLSHPROF_DIR', 'test2.trc', skip => 1, collect => 1, trace => '""."".""__plsql_vm"'); END; /
plshprofユーティリティ
plshprof
コマンドライン・ユーティリティ(ディレクトリ$ORACLE_HOME/bin/
にあります)により、1つまたは2つのRAWプロファイラ出力ファイルから簡単なHTMLレポートが生成されます。(RAWプロファイラ出力ファイルの例は、「プロファイル・データの収集」にあるtest
.trc
を参照してください。)
生成されたHTMLレポートは任意のブラウザで参照できます。ブラウザのナビゲーション機能と厳選したリンクを組み合せた効率的な手段により、大規模なアプリケーションのパフォーマンスを分析し、アプリケーションのパフォーマンスを向上させ、開発コストを削減できます。
トピック:
plshprofのオプション
plshprof
ユーティリティを実行するコマンドは、次のとおりです。
plshprof [option...] profiler_output_filename_1 profiler_output_filename_2
option
は、次のいずれかを使用します。
オプション | 説明: | デフォルト |
---|---|---|
|
最初の |
0 |
|
|
1 |
|
出力ファイルの名前を指定します。 |
|
|
経過時間のみを出力します。 |
なし |
|
ツリー・ルートの関数名を指定します。 |
該当なし |
RAWプロファイラ出力ファイルtest
.trc
が現行のディレクトリ内にあるとします。また、HTMLレポートを分析および生成し、HTMLレポートのルート・ファイルの名前をreport
.html
にするとします。次のコマンドを使用します(%
はプロンプトです)。
% plshprof -output report test.trc
単一のRAWプロファイラ出力ファイルから生成するHTMLレポート
単一のRAWプロファイラ出力ファイルからPL/SQL階層プロファイラのHTMLレポートを生成するには、次のコマンドを使用します。
% cdtarget_directory
% plshprof -outputhtml_root_filename
profiler_output_filename
target_directory
は、HTMLファイルを作成するディレクトリです。
html_root_filename
は、作成するルートHTMLファイルの名前です。
profiler_output_filename
は、RAWプロファイラ出力ファイルの名前です。
前述のplshprof
コマンドにより、一連のHTMLファイルが生成されます。html_root_filename
.html
からこれらの参照を開始します。
トピック:
レポートの最初のページ
単一のRAWプロファイラ出力ファイルから生成するHTMLレポートの最初のページには、サマリー情報やレポートの他のページへのハイパーリンクが含まれます。
最初のページのサンプル
PL/SQLの経過時間(マイクロ秒)の分析
824マイクロ秒(経過時間)および12のファンクション・コール
PL/SQL階層プロファイラにより、様々な形式でプロファイラの出力ログから導出された情報が示されたレポートの集合が作成されます。一般的に、最初の参照レポートとしては次のレポートが最も役に立つことがわかっています。
-
サブツリーの合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
-
関数の合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
-
SQL ID(マイクロ秒)別にソートしたSQL IDの経過時間(マイクロ秒)データ
また、次のレポートも使用できます。
-
関数名別にソートした関数の経過時間(マイクロ秒)データ
-
子の合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
-
関数の合計コール件数別にソートした関数の経過時間(マイクロ秒)データ
-
サブツリーの平均経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
-
関数の平均経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
-
子の平均経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
-
関数の合計経過時間(マイクロ秒)別にソートしたモジュールの経過時間(マイクロ秒)データ
-
モジュール名別にソートしたモジュールの経過時間(マイクロ秒)データ
-
関数の合計コール件数別にソートしたモジュールの経過時間(マイクロ秒)データ
-
関数の合計経過時間(マイクロ秒)別にソートしたネームスペースの経過時間(マイクロ秒)データ
-
ネームスペース別にソートしたネームスペースの経過時間(マイクロ秒)データ
-
関数の合計コール件数別にソートしたネームスペースの経過時間(マイクロ秒)データ
-
親子の経過時間(マイクロ秒)データ
関数レベルのレポート
関数レベルのレポートは、プロファイル情報のフラット・ビューを提供します。関数レベルの各レポートには、関数ごとに次の情報が含まれます。
-
関数時間(関数自体で費やされた時間で、自己時間とも呼ばれます)
-
子の時間(関数の子で費やされた時間)
-
サブツリー時間(関数のサブツリーで費やされた時間: 関数時間と子の時間の合計)
-
関数に対するコールの数
-
関数名
関数名からは、関数の親子レポートへのハイパーリンクが作成されます。
-
SQL ID
-
SQLテキスト(SQLテキストの最初の50文字)。
関数レベルの各レポートは、関数時間またはサブツリー時間などの特定の属性によってソートされます。
次のサンプル・レポートは、関数のサブツリーの合計経過時間の降順でソートされています。「サブツリー」および「Ind%」列の情報が太字であるのはこのためです。
サンプル・レポート
サブツリーの合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
824マイクロ秒(経過時間)および12のファンクション・コール
サブツリー | Ind% | 関数 | 子 | Ind% | コール | Ind% | 関数名 | SQL ID | SQL TEXT |
---|---|---|---|---|---|---|---|---|---|
824 |
100% |
10 |
814 |
98.8% |
2 |
16.7% |
__plsq_vm |
||
814 |
98.8% |
165 |
649 |
78.8% |
2 |
16.7% |
__anonymous_block |
||
649 |
78.8% |
11 |
638 |
77.4% |
1 |
8.3% |
HR.TEST.TEST (1行目) |
||
638 |
77.4% |
121 |
517 |
62.7% |
3 |
25.0% |
HR.TEST.TEST.FOO (4行目) |
||
517 |
62.7% |
517 |
0 |
0.0% |
3 |
25.0% |
HR.TEST.__static_sql_exec_line5(6行目) |
3r6qf2qhr3cm1 |
SELECT COUNT(*) FROM EMPLOYEES |
0 |
0.0% |
0 |
0 |
0.0% |
1 |
8.3% |
SYS.DBMS_HPROF.STOP_PROFILING(453行目) |
モジュール・レベルのレポート
モジュール・レベルの各レポートには、モジュールごとに次の情報が含まれます(パッケージまたはタイプなど)。
-
モジュール時間(モジュールで費やされた時間: モジュール内のすべての関数の関数時間の合計)
-
モジュール内の関数に対するコールの数
モジュール・レベルの各レポートは、モジュール時間またはモジュール名などの特定の属性によってソートされます。
次のサンプル・レポートは、モジュール時間でソートされています。「モジュール」、「Ind%」および「Cum%」列の情報が太字であるのはこのためです。
サンプル・レポート
関数の合計経過時間(マイクロ秒)別にソートしたモジュールの経過時間(マイクロ秒)データ
166878マイクロ秒(経過時間)および1099のファンクション・コール
モジュール | Ind% | Cum% | コール | Ind% | モジュール名 |
---|---|---|---|---|---|
84932 |
50.9% |
50.9% |
6 |
0.5% |
HR.P |
67749 |
40.6% |
91.5% |
216 |
19.7% |
SYS.DBMS_LOB |
13340 |
8.0% |
99.5% |
660 |
60.1% |
SYS.UTL_FILE |
839 |
0.5% |
100% |
214 |
19.5% |
SYS.UTL_RAW |
18 |
0.0% |
100% |
2 |
0.2% |
HR.UTILS |
0 |
0.0% |
100% |
1 |
0.1% |
SYS.DBMS_HPROF |
ネームスペース・レベルのレポート
ネームスペース・レベルの各レポートには、ネームスペースごとに次の情報が含まれます。
-
ネームスペース時間(ネームスペースで費やされた時間: ネームスペース内のすべての関数の関数時間の合計)
-
ネームスペース内の関数に対するコールの数
ネームスペース・レベルの各レポートは、ネームスペース時間またはネームスペース内の関数に対するコールの数などの、特定の属性によってソートされます。
次のサンプル・レポートは、関数時間でソートされています。「関数」、「Ind%」および「Cum%」列の情報が太字であるのはこのためです。
サンプル・レポート
関数の合計経過時間(マイクロ秒)別にソートしたネームスペースの経過時間(マイクロ秒)データ
166878マイクロ秒(経過時間)および1099のファンクション・コール
関数 | Ind% | Cum% | コール | Ind% | ネームスペース |
---|---|---|---|---|---|
93659 |
56.1% |
56.1% |
1095 |
99.6% |
PLSQL |
73219 |
43.9% |
100% |
4 |
0.4% |
SQL |
関数の親子レポート
親子レポートは、プロファイラによって追跡される関数ごとに、親(コール元の関数)と子(コール先の関数)に関する情報を提供します。このレポートは、親ごとに、関数の実行プロファイル(サブツリー時間、関数時間、子の時間、コール数)を提供します。また、子ごとに、この関数からコールされたときの子の実行プロファイルを提供します(ただし、他の関数からコールされたときは除きます)。
関数の実行プロファイルには、関数レベルのレポートで各関数について含まれる情報と同じ情報が含まれます。
後述の「サンプル・レポート」は、HR
.P
.UPLOAD
という名前の関数に対応する親子レポートの断片です。最初の行には、次のサマリー情報があります。
-
関数
HR
.P
.UPLOAD
に対するコールは2つあります。 -
関数の合計サブツリー時間は166,860マイクロ秒で、そのうち11,713マイクロ秒(7.0%)は関数自体、155,147マイクロ秒(93.0%)は子の時間です。
行「親」の後には、HR
.P
.UPLOAD
の2つの親の実行プロファイル行であるHR
.UTILS
.COPY_IMAGE
とHR
.UTILS
.COPY_FILE
があります。
HR
.UTILS
.COPY_IMAGE
の最初の親実行プロファイル行は、次を示しています。
-
HR
.UTILS
.COPY_IMAGE
はHR
.P
.UPLOAD
を1回コールしており、これはHR
.P
.UPLOAD
に対するコールの50%を占めます。 -
HR
.UTILS
.COPY_IMAGE
からコールされたときのHR
.P
.UPLOAD
のサブツリー時間は106,325マイクロ秒で、これはHR
.P
.UPLOAD
の合計サブツリー時間の63.7%を占めます。 -
HR
.UTILS
.COPY_IMAGE
からコールされたときのHR
.P
.UPLOAD
の関数時間は6,434マイクロ秒で、これはHR
.P
.UPLOAD
の合計関数時間の54.9%を占めます。
行「子」の後には、HR
.P
.UPLOAD
からコールされたときのHR
.P
.UPLOAD
の子の実行プロファイル行があります。
SYS
.UTL_FILE
.GET_RAW
に対応する3番目の子の実行プロファイル行は、次を示しています。
-
HR
.P
.UPLOAD
は、SYS
.UTL_FILE
.GET_RAW
を216回コールしています。 -
HR
.P
.UPLOAD
からコールされたときのSYS
.UTL_FILE
.GET_RAW
のサブツリー時間、関数時間および子の時間はそれぞれ12,487マイクロ秒、3,969マイクロ秒および8,518マイクロ秒です。 -
HR
.P
.UPLOAD
の子の合計時間(155,147マイクロ秒)のうち、子SYS
.UTL_FILE
.GET_RAW
は12,487マイクロ秒(8.0%)を占めます。
サンプル・レポート
HR.P.UPLOAD (3行目)
サブツリー | Ind% | 関数 | Ind% | 子 | Ind% | コール | Ind% | 関数名 |
---|---|---|---|---|---|---|---|---|
166860 |
100% |
11713 |
7.0% |
155147 |
93.0% |
2 |
0.2% |
HR.P.UPLOAD (3行目) |
親: |
||||||||
106325 |
63.7% |
6434 |
54.9% |
99891 |
64.4% |
1 |
50.0% |
HR.UTILS.COPY_IMAGE (3行目) |
60535 |
36.3% |
5279 |
45.1% |
55256 |
35.6% |
1 |
50.0% |
HR.UTILS.COPY_FILE (8行目) |
子: |
||||||||
71818 |
46.3% |
71818 |
100% |
0 |
N/A |
2 |
100% |
HR.P.__static_sql_exec_line38(38行目) |
67649 |
43.6% |
67649 |
100% |
0 |
N/A |
214 |
100% |
SYS.DBMS_LOB.WRITEAPPEND (926行目) |
12487 |
8.0% |
3969 |
100% |
8518 |
100% |
216 |
100% |
SYS.UTL_FILE.GET_RAW(1089行目) |
1401 |
0.9% |
1401 |
100% |
0 |
N/A |
2 |
100% |
HR.P.__static_sql_exec_line39(39行目) |
839 |
0.5% |
839 |
100% |
0 |
N/A |
214 |
100% |
SYS.UTL_FILE.GET_RAW(246行目) |
740 |
0.5% |
73 |
100% |
667 |
100% |
2 |
100% |
SYS.UTL_FILE.FOPEN (422行目) |
113 |
0.1% |
11 |
100% |
102 |
100% |
2 |
100% |
SYS.UTL_FILE.FCLOSE (585行目) |
100 |
0.1% |
100 |
100% |
0 |
N/A |
2 |
100% |
SYS.DBMS_LOB.CREATETEMPORARY (536行目) |
関連項目:
PL/SQL階層プロファイラのSQLレベルのレポートの理解
DBMS_HPROF.ANALYZEのSQLレベルのレポートについて理解します。
PL/SQL階層プロファイラSQLレベル・レポートは、プロファイリング中に収集されたすべてのSQLのリストと略記されたSQLテキストおよびSQL IDでソートされた経過時間(マイクロ秒)を提供します。SQL IDは他のSQL統計を他の表で取得する必要がある場合(たとえば、SQLチューニング目的)に便利です。レポートには、SQLテキストの最初の50文字が含まれます。SQLがコールされる場所の周囲の詳細および必要に応じてソース・コード内の場所を取得するには、ファンクション・レベルのレポートを使用できます。
サンプル・レポート
SQL ID(マイクロ秒)別にソートしたSQL IDの経過時間(マイクロ秒)データ
824マイクロ秒(経過時間)および12のファンクション・コール
SQL ID | SQL TEXT | 関数 | Ind% | コール | Ind% |
---|---|---|---|---|---|
3r6qf2qhr3cm1 | SELECT COUNT(*) FROM EMPLOYEES | 679 | 82.4% | 3 | 25.0% |
2つのRAWプロファイラ出力ファイルから生成するHTML差分レポート
2つのRAWプロファイラ出力ファイルからPL/SQL階層プロファイラのHTML差分レポートを生成するには、次のコマンドを使用します。
% cdtarget_directory
% plshprof -outputhtml_root_filename
profiler_output_filename_1
profiler_output_filename_2
target_directory
は、HTMLファイルを作成するディレクトリです。
html_root_filename
は、作成するルートHTMLファイルの名前です。
profiler_output_filename_1
およびprofiler_output_filename_2
は、RAWプロファイラ出力ファイルの名前です。
前述のplshprof
コマンドにより、一連のHTMLファイルが生成されます。html_root_filename
.html
からこれらの参照を開始します。
トピック:
差分レポートの表記規則
差分レポートでは、次の表記規則が使用されます。
-
レポート・タイトルでは、デルタは差分または変更を意味します。
-
正数は、初回実行時から2回目の実行時にかけて数値が増加(低下)したことを示します。
-
差分の負数は、初回実行時から2回目の実行時にかけて数値が減少(向上)したことを示します。
-
関数名の後ろの記号
#
は、関数が1回の実行のみでコールされたことを意味します。
差分レポートの最初のページ
2つのRAWプロファイラ出力ファイルから生成するHTML差分レポートの最初のページには、サマリー情報およびレポートの他のページへのハイパーリンクが含まれます。
最初のページのサンプル
PL/SQLの経過時間(マイクロ秒)の分析 - サマリー・ページ
この分析により、正味2709589マイクロ秒(経過時間)または80%(3393719対6103308)の回帰が判明します。これは、最も重要な7つの個別関数の回帰および向上状況をまとめたものです。
回帰: 3399382マイクロ秒(経過時間)
関数 | 相対% | Ind% | コール | 相対% | 関数名 |
---|---|---|---|---|---|
2075627 |
+941% |
61.1% |
0 |
HR.P.G (35行目) |
|
1101384 |
+54.6% |
32.4% |
5 |
+55.6% |
HR.P.H (18行目) |
222371 |
6.5% |
1 |
HR.P.J (10行目) |
向上: 689793マイクロ秒(経過時間)
関数 | 相対% | Ind% | コール | 相対% | 関数名 |
---|---|---|---|---|---|
-467051 |
-50.0% |
67.7% |
-2 |
-50.0% |
HR.P.I (25行目) |
-222737 |
32.3% |
-1 |
HR.P.I (2行目)# |
||
-5 |
-21.7% |
0.0% |
0 |
HR.P.TEST (46行目) |
PL/SQLタイミング・アナライザにより、様々な形式でプロファイラの出力ログから導出された情報が示されたレポートの集合が作成されます。一般的に、最初の参照レポートとしては次のレポートが最も役に立つことがわかっています。
-
パフォーマンス回帰に関する関数の経過時間(マイクロ秒)データ
-
パフォーマンス向上に関する関数の経過時間(マイクロ秒)データ
また、次のレポートも使用できます。
-
関数名別にソートした関数の経過時間(マイクロ秒)データ
-
サブツリーの合計経過時間(マイクロ秒)デルタ別にソートした関数の経過時間(マイクロ秒)データ
-
関数の合計経過時間(マイクロ秒)デルタ別にソートした関数の経過時間(マイクロ秒)データ
-
子の合計経過時間(マイクロ秒)デルタ別にソートした関数の経過時間(マイクロ秒)データ
-
関数の合計コール件数デルタ別にソートした関数の経過時間(マイクロ秒)データ
-
モジュール名別にソートしたモジュールの経過時間(マイクロ秒)データ
-
関数の合計経過時間(マイクロ秒)デルタ別にソートしたモジュールの経過時間(マイクロ秒)データ
-
関数の合計コール件数デルタ別にソートしたモジュールの経過時間(マイクロ秒)データ
-
ネームスペース別にソートしたネームスペースの経過時間(マイクロ秒)データ
-
関数の合計経過時間(マイクロ秒)別にソートしたネームスペースの経過時間(マイクロ秒)データ
-
関数の合計コール件数別にソートしたネームスペースの経過時間(マイクロ秒)データ
-
親子のファイル経過時間(マイクロ秒)データ比較
関数レベルの差分レポート
関数レベルの各差分レポートには、各関数の、初回実行時から2回目の実行時にかけての次の値の変更が含まれます。
-
関数時間(関数自体で費やされた時間で、自己時間とも呼ばれます)
-
子の時間(関数の子で費やされた時間)
-
サブツリー時間(関数のサブツリーで費やされた時間: 関数時間と子の時間の合計)
-
関数に対するコールの数
-
平均関数時間
平均関数時間は、関数時間を関数へのコール数で割った値です。
-
関数名
関数名からは、関数の親子差分レポートへのハイパーリンクが作成されます。
「サンプル・レポート1」のレポートは、2回目の実行時より初回実行時の方がパフォーマンスがよかったすべての関数に関する差分情報を示します。次の点に注意してください。
-
HR
.P
.G
の場合、関数時間は2,075,627マイクロ秒(941%)増加し、これはすべての回帰の61.1%を占めます。 -
HR
.P
.H
の場合、関数時間およびコール数はそれぞれ1,101,384マイクロ秒(54.6%)および5(55.6%)増加しましたが、平均関数時間は-1,346マイクロ秒(-0.6%)向上しました。 -
HR
.P
.J
は、1回の実行でのみコールされました。
サンプル・レポート 1
パフォーマンス回帰に関する関数の経過時間(マイクロ秒)データ
サブツリー | 関数 | 相対% | Ind% | Cum% | 子 | コール | 相対% | 平均関数 | 相対% | 関数名 |
---|---|---|---|---|---|---|---|---|---|---|
4075787 |
2075627 |
+941% |
61.1% |
61.1% |
2000160 |
0 |
2075627 |
+941% |
HR.P.G (35行目) |
|
1101384 |
1101384 |
+54.6% |
32.4% |
93.5% |
0 |
5 |
+55.6% |
-1346 |
-0.6% |
HR.P.H (18行目) |
222371 |
222371 |
6.5% |
100% |
0 |
1 |
HR.P.J (10行目)# |
「サンプル・レポート2」のレポートは、初回実行時より2回目の実行時の方がパフォーマンスがよかったすべての関数に関する差分情報を示します。
サンプル・レポート 2
パフォーマンス向上に関する関数の経過時間(マイクロ秒)データ
サブツリー | 関数 | 相対% | Ind% | Cum% | 子 | コール | 相対% | 平均関数 | 相対% | 関数名 |
---|---|---|---|---|---|---|---|---|---|---|
-1365827 |
-467051 |
-50.0% |
67.7% |
67.7% |
-898776 |
-2 |
-50.0% |
-32 |
0.0% |
HR.P.I (25行目) |
-222737 |
-222737 |
32.3% |
100% |
0 |
-1 |
HR.P.I (2行目) |
||||
2709589 |
-5 |
-21.7% |
0.0% |
100% |
2709594 |
0 |
-5 |
-20.8 |
HR.P.TEST (46行目)# |
「サンプル・レポート3」のレポートには、すべての関数の差分情報をまとめます。
サンプル・レポート 3
関数の合計コール件数デルタ別にソートした関数の経過時間(マイクロ秒)データ
サブツリー | 関数 | 相対% | Ind% | 子 | コール | 相対% | 平均関数 | 相対% | 関数名 |
---|---|---|---|---|---|---|---|---|---|
1101384 |
1101384 |
+54.6% |
32.4% |
0 |
5 |
+55.6% |
-1346 |
-0.6% |
HR.P.H (18行目) |
-1365827 |
-467051 |
+50.0% |
67.7% |
-898776 |
-2 |
-50.0% |
-32 |
-0.0% |
HR.P.I (25行目) |
-222377 |
-222377 |
32.3% |
0 |
-1 |
HR.P.I (2行目)# |
||||
222371 |
222371 |
6.5% |
0 |
1 |
HR.P.J (10行目)# |
||||
4075787 |
2075627 |
+941% |
61.1% |
2000160 |
0 |
2075627 |
+941% |
HR.P.G (35行目) |
|
2709589 |
-5 |
-21.7% |
0.0% |
2709594 |
0 |
-5 |
-20.8% |
HR.P.TEST (46行目) |
|
0 |
0 |
0 |
0 |
SYS.DBMS_HPROF.STOP_PROFILING(53行目) |
モジュール・レベルの差分レポート
モジュール・レベルの各レポートには、各モジュールの、初回実行時から2回目の実行時にかけての次の値の変更が含まれます。
-
モジュール時間(モジュールで費やされた時間: モジュール内のすべての関数の関数時間の合計)
-
モジュール内の関数に対するコールの数
サンプル・レポート
関数の合計経過時間(マイクロ秒)デルタ別にソートしたモジュールの経過時間(マイクロ秒)データ
モジュール | コール | モジュール名 |
---|---|---|
2709589 |
3 |
HR.P |
0 |
0 |
SYS.DBMS_HPROF |
ネームスペース・レベルの差分レポート
ネームスペース・レベルの各レポートには、各ネームスペースの、初回実行時から2回目の実行時にかけての次の値の変更が含まれます。
-
ネームスペース時間(ネームスペースで費やされた時間: ネームスペース内のすべての関数の関数時間の合計)
-
ネームスペース内の関数に対するコールの数
サンプル・レポート
ネームスペース別にソートしたネームスペースの経過時間(マイクロ秒)データ
関数 | コール | ネームスペース |
---|---|---|
2709589 |
3 |
PLSQL |
関数の親子差分レポート
関数の親子差分レポートは、初回実行時から2回目の実行時にかけての次の実行プロファイルの変更を示します。
-
親(関数のコール元の関数)
-
子(関数のコール先の関数)
子の実行プロファイルには、他の関数によってこれらがコールされたときではなく、この関数によってこれらがコールされたときの情報のみが含まれます。
関数の実行プロファイルには、次の情報が含まれます。
-
関数時間(関数自体で費やされた時間で、自己時間とも呼ばれます)
-
子の時間(関数の子で費やされた時間)
-
サブツリー時間(関数のサブツリーで費やされた時間: 関数時間と子の時間の合計)
-
関数に対するコールの数
-
関数名
サンプル・レポートは、HR
.P
.X
という名前の関数に対応する親子差分レポートの断片です。
初回実行時と2回目の実行時の差分のサマリーである最初の行は、回帰を示します。関数時間は1,094,099マイクロ秒増加しています(おそらく、関数が5回余計にコールされたことが原因です)。
「親」行は、HR
.P
.G
によってHR
.P
.X
が初回実行時より2回目の実行時の方が9回多くコールされたが、HR
.P
.F
によっては4回少なくコールされたことを示しています。
「子」行は、HR
.P
.X
によって各子が初回実行時より2回目の実行時の方が5回多くコールされたことを示しています。
サンプル・レポート
HR.P.X (11行目)
サブツリー | 関数 | 子 | コール | 関数名 |
---|---|---|---|---|
3322196 |
1094099 |
2228097 |
5 |
HR.P.X (11行目) |
親: |
||||
6037490 |
1993169 |
4044321 |
9 |
HR.P.G (38行目) |
-2715294 |
-899070 |
-1816224 |
-4 |
HR.P.F (28行目) |
子: |
||||
1125489 |
1125489 |
0 |
5 |
HR.P.J (10行目) |
1102608 |
1102608 |
0 |
5 |
HR.P.I (2行目) |
関数の親子差分レポートには、関数比較レポートが付随しています。このレポートは、関数の初回実行時と2回目の実行時およびこれらの差分に関する実行プロファイルを示します。次の例は、関数HR
.P
.X
の関数比較レポートです。
サンプル・レポート
HR.P.X(11行目)の経過時間(マイクロ秒)(回帰合計の20.1%)
HR.P.X (11行目) | 初回トレース | Ind% | 2回目のトレース | Ind% | 差分 | 差分% |
---|---|---|---|---|---|---|
関数の経過時間(マイクロ秒) |
1999509 |
26.9% |
3093608 |
24.9% |
1094099 |
+54.7% |
子の経過時間(マイクロ秒) |
4095943 |
55.1% |
6324040 |
50.9% |
2228097 |
+54.4% |
サブツリーの経過時間(マイクロ秒) |
6095452 |
81.9% |
9417648 |
75.7% |
3322196 |
+54.5% |
関数のコール |
9 |
25.0% |
14 |
28.6% |
5 |
+55.6% |
関数の平均経過時間(マイクロ秒) |
222167.7 |
220972.0 |
-1195.7 |
-0.5% |
||
子の平均経過時間(マイクロ秒) |
455104.8 |
451717.1 |
-3387.6 |
-0.7% |
||
サブツリーの平均経過時間(マイクロ秒) |
677272.4 |
672689.1 |
-4583.3 |
-0.7% |