| Oracle® Database開発ガイド 12c リリース1 (12.1) B71295-06 |
|
 前 |
 次 |
PL/SQL階層プロファイラを使用すると、PL/SQLアプリケーションのボトルネックおよびパフォーマンスのチューニング機会を特定できます。
このプロファイラにより、ファンクション・コール別に編成されたPL/SQLプログラムの動的実行プロファイルがレポートされ、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プロファイラ出力から直接簡単なHTMLレポートを生成するには、plshprofコマンドライン・ユーティリティを使用できます。 |
PL/SQL階層プロファイラ用としてPL/SQLプログラムからプロファイル・データを収集する手順は、次のとおりです。
次の権限があることを確認します。
DBMS_HPROF.START_PROFILING PL/SQL APIを使用して、階層プロファイラのデータ・コレクションをセッションで開始します。
適切なコード・カバレッジを取得するために十分な時間PL/SQLプログラムを実行します。
経過時間を最大限正確に測定するために、PL/SQLプログラムが実行されているシステム上で関係のないアクティビティは実行しないようにしてください。
DBMS_HPROF.STOP_PROFILING PL/SQL APIを使用して、階層プロファイラのデータ・コレクションを終了します。
DBMS_HPROF.START_PROFILINGおよびDBMS_HPROF.STOP_PROFILINGの詳細は、『Oracle Database PL/SQLパッケージ・プロシージャおよびタイプ・リファレンス』を参照してください。
次の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;
/
例13-1のSQLスクリプトは、PL/SQLプロシージャtestの実行をプロファイリングしたものです。
例13-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;
/
|
注意: ディレクトリ・オブジェクトは、ファイル・システムのパス名の別名です。たとえば、データベースAS SYSDBAに接続している場合、次のCREATE DIRECTORY文では、ディレクトリ・オブジェクトPLSHPROF_DIRが作成され、これがファイル・システム・ディレクトリ/private/plshprof/resultsにマップされます。
CREATE DIRECTORY PLSHPROF_DIR as '/private/plshprof/results'; 例13-1のSQLスクリプトを実行するには、 GRANT READ, WRITE ON DIRECTORY PLSHPROF_DIR TO HR; ディレクトリ・オブジェクトの使用の詳細は、『Oracle Database SecureFilesおよびラージ・オブジェクト開発者ガイド』を参照してください。 |
RAWプロファイラ出力は、PL/SQL階層プロファイラのアナライザ・コンポーネントによって処理されることを目的としています。ただし、このように処理されなくても、プログラムの簡単な関数レベルのトレースは提供できます。ここでは、RAWプロファイラ出力について説明します。
|
注意: この章で示すRAWプロファイラの形式は、RAWプロファイラ出力の概念的な機能を示すことのみを目的としています。形式の詳細は、Oracle Databaseリリースごとに異なる可能性があります。 |
例13-1のSQLスクリプトでは、次のRAWプロファイラ出力がファイルtest.trcに書き込まれました。
P#V PLSHPROF Internal Version 1.0 P#! PL/SQL Timer Started P#C PLSQL."".""."__plsql_vm" P#X 1 P#C PLSQL."".""."__anonymous_block" P#X 66 P#C PLSQL."SYS"."DBMS_OUTPUT"::11."GET_LINES"#660bd56a1b1640db #180 P#X 5 P#R P#X 29 P#R P#X 2 P#R P#C PLSQL."".""."__plsql_vm" P#X 1 P#C PLSQL."".""."__anonymous_block" P#X 42 P#C PLSQL."HR"."TEST"::7."TEST"#980980e97e42f8ec #1 P#X 2 P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4 P#X 24 P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6 P#X 165 P#R P#X 13 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 P#X 75 P#R P#X 2 P#R P#X 2 P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4 P#X 2 P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6 P#X 73 P#R P#X 3 P#R P#X 1 P#R P#X 1 P#R P#X 1 P#R P#C PLSQL."".""."__plsql_vm" P#X 2 P#C PLSQL."".""."__anonymous_block" P#X 69 P#C PLSQL."SYS"."DBMS_OUTPUT"::11."GET_LINES"#660bd56a1b1640db #180 P#X 5 P#R P#X 35 P#R P#X 1 P#R P#C PLSQL."".""."__plsql_vm" P#X 1 P#C PLSQL."".""."__anonymous_block" P#X 58 P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #63 P#R P#R P#R P#! PL/SQL Timer Stopped
表13-1 RAWプロファイラ出力ファイルのインジケータ
| インジケータ | 意味 |
|---|---|
|
|
|
|
|
サブプログラムへのコール(コール・イベント) |
|
|
サブプログラムからの戻り値(戻りイベント) |
|
|
前のイベントと次のイベント間の経過時間 |
|
|
コメント |
コール・イベント(P#C)と戻りイベント(P#R)は、(一対のカッコのように)正しくネストされます。未処理の例外が原因でコール先のサブプログラムが終了しても、対応する戻りイベントはレポートされます。
RAWプロファイラ出力の各コール・イベント(P#C)のエントリには、次の情報が含まれます。
コール先のサブプログラムが属するネームスペース(13.3.1項を参照)
コール先のサブプログラムが定義されているPL/SQLモジュールの名前
コール先のサブプログラムが定義されているPL/SQLモジュールのタイプ
コール先のサブプログラムの名前
この名前は、13.3.2項の特別なファンクション名の1つである場合があります。
コール先のサブプログラムのシグネチャのMD5ハッシュを表す16進値
DBMS_HPROF.analyze PL/SQL API(13.4項を参照)により、ハッシュ値が階層プロファイラ表に格納されます。これにより、ユーザーとDBMS_HPROF.analyzeの両方が、オーバーロードされたサブプログラム(同じ名前を持つサブプログラム)を区別できるようになります。
コール先のサブプログラムがPL/SQLモジュールに定義されている行番号
PL/SQL階層プロファイラでは、モジュール内の個々の行で費やされた時間は測定されませんが、行番号を使用すると、(IDE/ツールのように)モジュール内のサブプログラムのソースの場所を特定し、オーバーロードされたサブプログラムを区別できるようになります。
たとえば、前述の例のRAWプロファイラ出力の次のエントリについて検討してみます。
P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4
前述のエントリの構成要素には、次のような意味があります。
| 構成要素 | 意味 |
|---|---|
PLSQL |
PLSQLは、コール先のサブプログラムが属するネームスペースです。 |
"HR"."TEST" |
HR.TESTは、コール先のサブプログラムが定義されているPL/SQLモジュールの名前です。 |
7 |
7は、HR.TESTのモジュール・タイプの内部列挙子です。モジュール・タイプの例としては、プロシージャ、パッケージおよびパッケージ本体があります。 |
"TEST.FOO" |
TEST.FOOは、コール先のサブプログラムの名前です。 |
#980980e97e42f8ec |
#980980e97e42f8ecは、TEST.FOOのシグネチャのMD5ハッシュを表す16進値です。 |
#4 |
4は、TEST.FOOが定義されているPL/SQLモジュールHR.TEST内の行番号です。 |
|
注意: サブプログラムがインラインされている場合、プロファイラ出力ではレポートされません。サブプログラムのインラインの詳細は、『Oracle Database PL/SQL言語リファレンス』を参照してください。
|
PL/SQL階層プロファイラが追跡するサブプログラムは、次のようにネームスペースPLSQLおよびSQLに分類されます。
ネームスペースPLSQLには、次が含まれます。
PL/SQLサブプログラム・コール
PL/SQLトリガー
無名PL/SQLブロック
リモート・サブプログラム・コール
パッケージ初期化ブロック
ネームスペースSQLには、問合せ、データ操作言語(DML)文、データ定義言語(DDL)文およびネイティブ動的SQL文など、PL/SQLから実行されるSQL文が含まれます。
PL/SQL階層プロファイラでは、特定の操作が表13-2に示す名前とネームスペースを持つ関数であるかのように追跡されます。
表13-2 PL/SQL階層プロファイラによって追跡される操作の関数名
| 追跡される操作 | 関数名 | ネームスペース |
|---|---|---|
|
PL/SQL Virtual Machineへのコール |
|
PL/SQL |
|
無名PL/SQLブロック |
|
PL/SQL |
|
パッケージ初期化ブロック |
|
PL/SQL |
|
行 |
|
SQL |
|
行 |
|
SQL |
|
行 |
|
SQL |
PL/SQL階層プロファイラのアナライザ・コンポーネントDBMS_HPROF.analyzeにより、RAWプロファイラ出力が処理され、表13-3に示す階層データベース表に結果が格納されます。
表13-3 PL/SQL階層プロファイラ・データベース表
| 表 | 説明 |
|---|---|
|
|
この |
|
|
この |
|
|
この |
内容は次のとおりです。
|
注意: アナライザを使用せずに、RAWプロファイラ出力から直接簡単なHTMLレポートを生成するには、plshprofコマンドライン・ユーティリティを使用できます。詳細は、13.5項を参照してください。 |
表13-3にある階層プロファイラ表と、プロファイル・データを永続的に格納するために必要な他のデータ構造を作成する手順は、次のとおりです。
スクリプトdbmshptab.sql(ディレクトリrdbms/adminにあります)を実行します。
このスクリプトにより、表13-3にある階層プロファイラ表と、プロファイル・データを永続的に格納するために必要な他のデータ構造の両方が作成されます。
|
注意: スクリプトdbmshptab.sqlを実行すると、以前に作成されたすべての階層プロファイラ表が削除されます。 |
次の権限があることを確認します。
DBMS_HPROFパッケージに対するEXECUTE権限
DBMS_HPROF.analyzeで指定されるディレクトリに対するREAD権限
PL/SQL API DBMS_HPROF.analyzeを使用して、単一のRAWプロファイラ出力ファイルを分析し、結果を階層プロファイラ表に格納します。
(RAWプロファイラ出力ファイルの例は、13.3項にあるtest.trcを参照してください。)
DBMS_HPROF.analyzeの詳細は、『Oracle Database PL/SQLパッケージ・プロシージャおよびタイプ・リファレンス』を参照してください。
階層プロファイラ表を使用して、カスタム・レポートを生成します。
例13-2の無名ブロックでは、次の処理を行います。
次の各項では、表13-3の階層プロファイラ表を使用する方法について説明します。
表13-4は、階層プロファイラ表DBMSHP_RUNSの列を示します。この表には、DBMS_HPROF.analyzeの実行時ごとに1行のトップレベル情報が含まれます。
階層プロファイラ表DBMSHP_RUNSの主キーはRUNIDです。
表13-4 DBMSHP_RUNS表の列
| 列名 | 列のデータ型 | 列の内容 |
|---|---|---|
|
|
|
|
|
|
|
この |
|
|
|
この |
|
|
|
この |
表13-5は、階層プロファイラ表DBMSHP_FUNCTION_INFOの列を示します。この表には、このDBMS_HPROF.analyzeの実行時にプロファイリングされたサブプログラムごとに1行の情報が含まれます。サブプログラムがオーバーロードされた場合、表13-5には、このサブシステムのバリエーションごとに1行が含まれます。各バリエーションには、独自のLINE#およびHASHがあります(13.4.2.2項「オーバーロードされたサブプログラムの区別」を参照)。
階層プロファイラ表DBMSHP_FUNCTION_INFOの主キーはRUNID, SYMBOLIDです。
表13-5 DBMSHP_FUNCTION_INFO表の列
| 列名 | 列のデータ型 | 列の内容 |
|---|---|---|
|
|
|
|
|
|
|
サブプログラムの記号識別子(この |
|
|
|
各サブプログラムが定義されているモジュールの所有者( |
|
|
|
サブプログラムが定義されているモジュール( |
|
|
|
サブプログラムが定義されているモジュールのタイプ( |
|
|
|
サブプログラムの名前(必ずしも関数であるとはかぎりません)( この名前は、13.3.2項の特別なファンクション名の1つである場合があります。 サブプログラム 関数 |
|
|
|
|
|
|
|
サブプログラムのシグネチャのハッシュ・コード(この |
|
|
|
サブプログラムのネームスペース。詳細は、13.3.1項を参照してください。 |
|
|
|
子サブプログラムで費やされた時間を含む、サブプログラムの経過時間(マイクロ秒単位)。 |
|
|
|
子サブプログラムで費やされた時間を除く、サブプログラムの経過時間(マイクロ秒単位)。 |
|
|
|
サブプログラムに対するコールの数。 |
表13-6は、階層プロファイラ表DBMSHP_PARENT_CHILD_INFOの列を示します。この表には、このDBMS_HPROF.analyzeの実行時にプロファイリングされた一意の親子サブプログラムの組合せごとに1行の親子情報が含まれます。
表13-6 DBMSHP_PARENT_CHILD_INFO表の列
| 列名 | 列のデータ型 | 列の内容 |
|---|---|---|
|
|
|
|
|
|
|
親記号ID。
|
|
|
|
子記号ID。
|
|
|
|
子サブプログラムで費やされた時間を含む、 |
|
|
|
子サブプログラムで費やされた時間を除く、 |
|
|
|
|
オーバーロードされたサブプログラムは、同じ名前を持つ異なるサブプログラムです(『Oracle Database PL/SQL言語リファレンス』を参照)。
プログラムによって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値は、パラメータ・リストを変更した場合など、関数のシグネチャが変更されたときのみ変更されます。
13.2項のPL/SQLプロシージャtestの階層プロファイラ表を例13-3から例13-5に示します。
例13-3 サンプルの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
例13-4 サンプルの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
例13-5 サンプルの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
DBMSHP_PARENT_CHILD_INFO表(例13-5)の第3行を検討してみます。RUNID列は、この行が3回目の実行時のものであることを示します。列PARENTSYMIDおよびCHILDSYMIDは、親(コール元)と子(コール先サブプログラム)の記号IDがそれぞれ2と1であることを示します。表DBMSHP_FUNCTION_INFO (例13-4)は、3回目の実行時については記号ID 2と1がそれぞれ、プロシージャ__plsql_vmと__anonymous_blockに対応することを示します。したがって、この行の情報は、プロシージャ__plsql_vmから、モジュールHR.TESTの__anonymous_block (__plsql_vm内で定義)へのコールに関するものです。この行には、プロシージャ__plsql_vmからコールされたとき、プロシージャ__anonymous_blockの関数時間が44マイクロ秒で、__anonymous_blockサブツリー(子孫を含む)で費やされた時間が121マイクロ秒であると表示されます。
オプションを使用しないDBMS_HPROF.analyzeのコール例は、例13-2を参照してください。
例13-6では、パッケージを作成し、パッケージ内のサブプログラムを起動するプロシージャを作成し、プロシージャをプロファイリングし、RAWプロファイラ出力ファイルの分析にDBMS_HRPROF.analyzeを使用します。RAWプロファイル出力ファイルは、PLSHPROF_DIRディレクトリ・オブジェクトに対応するディレクトリにあります。
例13-6 オプションを使用した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 Section 13.4.1).
-- 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コマンドライン・ユーティリティ(ディレクトリ$ORACLE_HOME/bin/にあります)により、1つまたは2つのRAWプロファイラ出力ファイルから簡単なHTMLレポートが生成されます。(RAWプロファイラ出力ファイルの例は、13.2項にあるtest.trcを参照してください。)
生成されたHTMLレポートは任意のブラウザで参照できます。ブラウザのナビゲーション機能と厳選したリンクを組み合せた効率的な手段により、大規模なアプリケーションのパフォーマンスを分析し、アプリケーションのパフォーマンスを向上させ、開発コストを削減できます。
内容は次のとおりです。
plshprofユーティリティを実行するコマンドは、次のとおりです。
plshprof [option...] profiler_output_filename_1 profiler_output_filename_2
optionは、次のいずれかを使用します。
| オプション | 説明 | デフォルト |
|---|---|---|
-skip count |
最初のcountコールをスキップします。-trace symbolとともにのみ使用します。 |
0 |
-collect count |
countコールに関する情報を収集します。-trace symbolとともにのみ使用します。 |
1 |
-output filename |
出力ファイルの名前を指定します。 | symbol.htmlまたはtracefile1.html |
-summary |
経過時間のみを出力します。 | なし |
-trace symbol |
ツリー・ルートの関数名を指定します。 | 適用なし |
RAWプロファイラ出力ファイルtest.trcが現行のディレクトリ内にあるとします。また、HTMLレポートを分析および生成し、HTMLレポートのルート・ファイルの名前をreport.htmlにするとします。次のコマンドを使用します(%はプロンプトです)。
% plshprof -output report test.trc
単一のRAWプロファイラ出力ファイルからPL/SQL階層プロファイラのHTMLレポートを生成するには、次のコマンドを使用します。
% cdtarget_directory% plshprof -outputhtml_root_filenameprofiler_output_filename
target_directoryは、HTMLファイルを作成するディレクトリです。
html_root_filenameは、作成するルートHTMLファイルの名前です。
profiler_output_filenameは、RAWプロファイラ出力ファイルの名前です。
前述のplshprofコマンドにより、一連のHTMLファイルが生成されます。html_root_filename.htmlからこれらの参照を開始します。
内容は次のとおりです。
単一のRAWプロファイラ出力ファイルから生成するHTMLレポートの最初のページには、サマリー情報やレポートの他のページへのハイパーリンクが含まれます。
最初のページのサンプル
PL/SQLの経過時間(マイクロ秒)の分析
2831マイクロ秒(経過時間)および12のファンクション・コール
PL/SQL階層プロファイラにより、様々な形式でプロファイラの出力ログから導出された情報が示されたレポートの集合が作成されます。一般的に、最初の参照レポートとしては次のレポートが最も役に立つことがわかっています。
サブツリーの合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
関数の合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
また、次のレポートも使用できます。
関数名別にソートした関数の経過時間(マイクロ秒)データ
子の合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
関数の合計コール件数別にソートした関数の経過時間(マイクロ秒)データ
サブツリーの平均経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
関数の平均経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
子の平均経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
関数の合計経過時間(マイクロ秒)別にソートしたモジュールの経過時間(マイクロ秒)データ
モジュール名別にソートしたモジュールの経過時間(マイクロ秒)データ
関数の合計コール件数別にソートしたモジュールの経過時間(マイクロ秒)データ
関数の合計経過時間(マイクロ秒)別にソートしたネームスペースの経過時間(マイクロ秒)データ
ネームスペース別にソートしたネームスペースの経過時間(マイクロ秒)データ
関数の合計コール件数別にソートしたネームスペースの経過時間(マイクロ秒)データ
親子の経過時間(マイクロ秒)データ
関数レベルのレポートは、プロファイル情報のフラット・ビューを提供します。関数レベルの各レポートには、関数ごとに次の情報が含まれます。
関数時間(関数自体で費やされた時間で、自己時間とも呼ばれます)
子の時間(関数の子で費やされた時間)
サブツリー時間(関数のサブツリーで費やされた時間: 関数時間と子の時間の合計)
関数に対するコールの数
関数名
関数名からは、関数の親子レポートへのハイパーリンクが作成されます。
関数レベルの各レポートは、関数時間またはサブツリー時間などの特定の属性によってソートされます。
次のサンプル・レポートは、関数のサブツリーの合計経過時間の降順でソートされています。「サブツリー」および「Ind%」列の情報が太字であるのはこのためです。
サンプル・レポート
サブツリーの合計経過時間(マイクロ秒)別にソートした関数の経過時間(マイクロ秒)データ
2831マイクロ秒(経過時間)および12のファンクション・コール
| サブツリー | Ind% | 関数 | 子 | Ind% | コール | Ind% | 関数名 |
|---|---|---|---|---|---|---|---|
| 2831 | 100% | 93 | 2738 | 96.7% | 2 | 16.7% | __plsq_vm |
| 2738 | 96.7% | 310 | 2428 | 85.8% | 2 | 16.7% | __anonymous_block |
| 2428 | 85.8% | 15 | 2413 | 85.2% | 1 | 8.3% | HR.TEST.TEST(1行目) |
| 2413 | 85.2% | 435 | 1978 | 69.9% | 3 | 25.0% | HR.TEST.TEST.FOO(3行目) |
| 1978 | 69.9% | 1978 | 0 | 0.0% | 3 | 25.0% | HR.TEST.__static_sql_exec_line5(5行目) |
| 0 | 0.0% | 0 | 0 | 0.0% | 1 | 8.3% | SYS.DBMS_HPROF.STOP_PROFILING(53行目) |
モジュール・レベルの各レポートには、モジュールごとに次の情報が含まれます(パッケージまたはタイプなど)。
モジュール時間(モジュールで費やされた時間: モジュール内のすべての関数の関数時間の合計)
モジュール内の関数に対するコールの数
モジュール・レベルの各レポートは、モジュール時間またはモジュール名などの特定の属性によってソートされます。
次のサンプル・レポートは、モジュール時間でソートされています。「モジュール」、「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 |
親子レポートは、プロファイラによって追跡される関数ごとに、親(コール元の関数)と子(コール先の関数)に関する情報を提供します。このレポートは、親ごとに、関数の実行プロファイル(サブツリー時間、関数時間、子の時間、コール数)を提供します。また、子ごとに、この関数からコールされたときの子の実行プロファイルを提供します(ただし、他の関数からコールされたときは除きます)。
ファンクションの実行プロファイルには、ファンクション・レベルのレポートで各ファンクションについて含まれる情報と同じ情報が含まれます(詳細は、13.5.2.2項「ファンクション・レベルのレポート」を参照)。
後述の「サンプル・レポート」は、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行目) |
2つのRAWプロファイラ出力ファイルからPL/SQL階層プロファイラのHTML差分レポートを生成するには、次のコマンドを使用します。
% cdtarget_directory% plshprof -outputhtml_root_filenameprofiler_output_filename_1profiler_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マイクロ秒(経過時間)
| 関数 | Rel% | Ind% | コール | Rel% | 関数名 |
|---|---|---|---|---|---|
| 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マイクロ秒(経過時間)
| 関数 | Rel% | Ind% | コール | Rel% | 関数名 |
|---|---|---|---|---|---|
| -467051 | -50.0% | 67.7% | -2 | -50.0% | HR.P.F(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
パフォーマンス回帰に関する関数の経過時間(マイクロ秒)データ
| サブツリー | 関数 | Rel% | Ind% | Cum% | 子 | コール | Rel% | 平均関数 | Rel% | 関数名 |
|---|---|---|---|---|---|---|---|---|---|---|
| 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
パフォーマンス向上に関する関数の経過時間(マイクロ秒)データ
| サブツリー | 関数 | Rel% | Ind% | Cum% | 子 | コール | Rel% | 平均関数 | Rel% | 関数名 |
|---|---|---|---|---|---|---|---|---|---|---|
| -1365827 | -467051 | -50.0% | 67.7% | 67.7% | -898776 | -2 | -50.0% | -32 | 0.0% | HR.P.F(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
関数の合計コール件数デルタ別にソートした関数の経過時間(マイクロ秒)データ
| サブツリー | 関数 | Rel% | Ind% | 子 | コール | Rel% | 平均関数 | Rel% | 関数名 |
|---|---|---|---|---|---|---|---|---|---|
| 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.F(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% | 差分 | Diff% |
|---|---|---|---|---|---|---|
| 関数の経過時間(マイクロ秒) | 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% |
