1. データベース開発ガイド
  2. アプリケーション開発者用のPL/SQL
  3. PL/SQL階層プロファイラの使用

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プログラムからプロファイル・データを収集するステップは、次のとおりです。

  1. 次の権限があることを確認します。

    • DBMS_HPROFパッケージに対するEXECUTE権限

    • DBMS_HPROF.START_PROFILINGをコールするときに指定するディレクトリに対するWRITE権限

  2. DBMS_HPROF.START_PROFILING PL/SQL APIを使用して、階層プロファイラのデータ・コレクションをセッションで開始します。
  3. 十分な範囲のコードを取得できるまでPL/SQLプログラムを実行します。

    経過時間を最大限正確に測定するために、PL/SQLプログラムが実行されているシステム上で関係のないアクティビティは実行しないようにしてください。

  4. DBMS_HPROF.STOP_PROFILING PL/SQL APIを使用して、階層プロファイラのデータ・コレクションを終了します。

例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;

関連項目:

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#V

PLSHPROFバナーとバージョン番号

P#C

サブプログラムへのコール(コール・イベント)

P#R

サブプログラムからの戻り値(戻りイベント)

P#X

前のイベントと次のイベント間の経過時間

P#!

コメント

コール・イベント(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

前述のエントリの構成要素には、次のような意味があります。

コンポーネント 意味

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内の行番号です。

注意:

サブプログラムがインラインされている場合、プロファイラ出力ではレポートされません。

DETERMINISTICファンクションのコールが最適化されている場合、プロファイラ出力ではレポートされません。

関連項目:

追跡されるサブプログラムのネームスペース

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へのコール

__plsql_vm

PL/SQL

無名PL/SQLブロック

__anonymous_block

PL/SQL

パッケージ初期化ブロック

__pkg_init

PL/SQL

行line#の静的SQL文

__static_sql_exec_lineline#

SQL

行line#の動的SQL文

__dyn_sql_exec_lineline#

SQL

行line#のSQL FETCH文

__sql_fetch_lineline#

SQL

プロファイル・データの分析

PL/SQL階層プロファイラのアナライザ・コンポーネントDBMS_HPROF.analyzeにより、RAWプロファイラ出力が処理され、表15-3に示す階層データベース表に結果が格納されます。

表15-3 PL/SQL階層プロファイラ・データベース表

表 説明:

DBMSHP_RUNS

このDBMS_HPROF.analyzeの実行時のトップレベル情報。列の詳細は、表15-4を参照してください。

DBMSHP_FUNCTION_INFO

このDBMS_HPROF.analyzeの実行時にプロファイリングされる各サブプログラムの情報。列の詳細は、表15-5を参照してください。

DBMSHP_PARENT_CHILD_INFO

このDBMS_HPROF.analyzeの実行時にプロファイリングされる各サブプログラムの親子情報。列の詳細は、表15-6を参照してください。

トピック:

注意:

アナライザを使用せずに、RAWプロファイラ出力から直接簡単なHTMLレポートを生成するには、plshprofコマンドライン・ユーティリティを使用できます。詳細は、「plshprofユーティリティ」を参照してください。

階層プロファイラ表の作成

次のステップでは、表15-3にある階層プロファイラ表と、プロファイル・データを永続的に格納するために必要な他のデータ構造を作成する方法、DBMS_HPROFパッケージの実行に必要な権限、カスタム・レポートの生成について説明します。

  1. 表15-3にある階層プロファイラ表と、プロファイル・データを永続的に格納するために必要な他のデータ構造は、次の方法で作成できます。
    1. DBMS_HPROF.CREATE_TABLESプロシージャをコールします。
    2. スクリプトdbmshptab.sql(ディレクトリrdbms/adminにあります)を実行します。

      注意:

      スクリプトdbmshptab.sqlを実行すると、以前に作成されたすべての階層プロファイラ表が削除されます。

      注意:

      dbmshptab.sql(ディレクトリrdbms/admin内)は非推奨になりました。このスクリプトには、表および順序を削除する文および非推奨の注意事項が含まれています。

  2. 次の権限があることを確認します。

    • DBMS_HPROFパッケージに対するEXECUTE権限

    • DBMS_HPROF.analyzeで指定されるディレクトリに対するREAD権限

  3. PL/SQL API DBMS_HPROF.analyzeを使用して、単一のRAWプロファイラ出力ファイルを分析し、結果を階層プロファイラ表に格納します。

    (RAWプロファイラ出力ファイルの例は、「RAWプロファイラ出力の理解」にあるtest.trcを参照してください。)

    DBMS_HPROF.analyzeの詳細は、『Oracle Database PL/SQLパッケージ・プロシージャおよびタイプ・リファレンス』を参照してください。

  4. 階層プロファイラ表を使用して、カスタム・レポートを生成します。

例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表の列

列名 列データ型 列の内容

RUNID

NUMBER

DBMSHP_RUNNUMBER順序から生成された、このDBMS_HPROF.analyzeの実行時の一意の識別子。

RUN_TIMESTAMP

TIMESTAMP(6)

このDBMS_HPROF.analyzeの実行時のタイムスタンプ。

RUN_COMMENT

VARCHAR2(2047)

このDBMS_HPROF.analyzeの実行時に指定したコメント。

TOTAL_ELAPSED_TIME

NUMBER(38)

このDBMS_HPROF.analyzeの実行時の合計経過時間。

表15-5は、階層プロファイラ表DBMSHP_FUNCTION_INFOの列を示します。この表には、このDBMS_HPROF.analyzeの実行時にプロファイリングされたサブプログラムごとに1行の情報が含まれます。サブプログラムがオーバーロードされた場合、表15-5には、このサブシステムのバリエーションごとに1行が含まれます。各バリエーションには、独自のLINE#およびHASHがあります(「オーバーロードされたサブプログラムの区別」を参照)。

階層プロファイラ表DBMSHP_FUNCTION_INFOの主キーはRUNID, SYMBOLIDです。

表15-5 DBMSHP_FUNCTION_INFO表の列

列名 列データ型 列の内容

RUNID

NUMBER

DBMSHP_RUNS表のRUNID列を参照します。この列の詳細は、表15-4を参照してください。

SYMBOLID

NUMBER

サブプログラムの記号識別子(このDBMS_HPROF.analyzeの実行時に固有)。

OWNER

VARCHAR2(128)

各サブプログラムが定義されているモジュールの所有者(SYSまたはHRなど)。

MODULE

VARCHAR2(128)

サブプログラムが定義されているモジュール(DBMS_LOB、UTL_HTTPまたはMY_PACKAGEなど)。

TYPE

VARCHAR2(32)

サブプログラムが定義されているモジュールのタイプ(PACKAGE、PACKAGE_BODYまたはPROCEDUREなど)。

FUNCTION

VARCHAR2(4000)

サブプログラムの名前(必ずしも関数であるとはかぎりません)(INSERT_ORDER、PROCESS_ITEMSまたはTESTなど)。

この名前は、「特別なファンクション名」の特別なファンクション名の1つである場合があります。

サブプログラムA内で定義されているサブプログラムBの場合、この名前はA.Bになります。

関数Xに対する再帰的コールはX@nとして表されます。nは再帰の深さです。たとえば、X@1は、Xに対する第1再帰的コールです。

LINE#

NUMBER

FUNCTIONが定義されているOWNER.MODULE内の行番号。

HASH

RAW(32)

サブプログラムのシグネチャのハッシュ・コード(このDBMS_HPROF.analyzeの実行時に固有)。

NAMESPACE

VARCHAR2(32)

サブプログラムのネームスペース。詳細は、「追跡されるサブプログラムのネームスペース」を参照してください。

SUBTREE_ELAPSED_TIME

NUMBER(38)

子サブプログラムで費やされた時間を含む、サブプログラムの経過時間(マイクロ秒単位)。

FUNCTION_ELAPSED_TIME

NUMBER(38)

子サブプログラムで費やされた時間を除く、サブプログラムの経過時間(マイクロ秒単位)。

CALLS

NUMBER(38)

サブプログラムに対するコールの数。

SQL_ID

VARCHAR2(13)

SQL文のSQL識別子。

SQL_TEXT

VARCHAR2(4000)

SQL文の最初の50文字。

表15-6は、階層プロファイラ表DBMSHP_PARENT_CHILD_INFOの列を示します。この表には、このDBMS_HPROF.analyzeの実行時にプロファイリングされた一意の親子サブプログラムの組合せごとに1行の親子情報が含まれます。

表15-6 DBMSHP_PARENT_CHILD_INFO表の列

列名 列データ型 列の内容

RUNID

NUMBER

DBMSHP_FUNCTION_INFO表のRUNID列を参照します。この列の詳細は、表15-5を参照してください。

PARENTSYMID

NUMBER

親記号ID。

RUNID、PARENTSYMIDは、DBMSHP_FUNCTION_INFO(RUNID、SYMBOLID)を参照します。

CHILDSYMID

NUMBER

子記号ID。

RUNID、CHILDSYMIDは、DBMSHP_FUNCTION_INFO(RUNID、SYMBOLID)を参照します。

SUBTREE_ELAPSED_TIME

NUMBER(38)

子サブプログラムで費やされた時間を含む、RUNID、PARENTSYMIDからコールされたときのRUNID、CHILDSYMIDの経過時間(マイクロ秒単位)。

FUNCTION_ELAPSED_TIME

NUMBER(38)

子サブプログラムで費やされた時間を除く、RUNID、PARENTSYMIDからコールされたときのRUNID、CHILDSYMIDの経過時間(マイクロ秒単位)。

CALLS

NUMBER(38)

RUNID、PARENTSYMIDからRUNID、CHILDSYMIDへのコールの数。

オーバーロードされたサブプログラムの区別

オーバーロードされたサブプログラムとは、同じ名前を持つ異なるサブプログラムです。

プログラムによって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は、次のいずれかを使用します。

オプション 説明: デフォルト

-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プロファイラ出力ファイルから生成するHTMLレポート

単一のRAWプロファイラ出力ファイルからPL/SQL階層プロファイラのHTMLレポートを生成するには、次のコマンドを使用します。

% cd target_directory
% plshprof -output html_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差分レポートを生成するには、次のコマンドを使用します。

% cd target_directory
% plshprof -output html_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%