Updated on 2024-06-03 GMT+08:00

DBE_PROFILER

The plprofiler provides an API for analyzing applications of stored procedures. It can collect, store, and delete data related to stored procedures.

Overview

Finding performance problems in PL/SQL functions and stored procedures may be difficult. The only query visible in the system or extended view is sent from the client. This is just the outermost stored procedure call. The plprofiler extension can be used to quickly identify the most time-consuming stored procedures and view the time consumption of a single statement.

You can use this tool to create a stored procedure and related table information in a session, call the plprofiler API to profiling the stored procedure, and then execute the stored procedure. In this case, the analysis data of the stored procedure is generated. You can query the system catalog to obtain data. Table 5 DBE_PROFILER.PL_PROFILING_FUNCTIONS lists the stored procedures involved in the profiling. Table 6 DBE_PROFILER.PL_PROFILING_DETAILS records details about the execution time of each statement in a stored procedure. Table 7 DBE_PROFILER.PL_PROFILING_CALLGRAPH records call stack information and the overall execution time of each stored procedure. Table 8 DBE_PROFILER.PL_PROFILING_TRACKINFO records the execution time of each phase of the stored procedure. You can call DBE_PROFILER.PL_CLEAR_PROFILING to delete one piece of data or all data stored in the system catalog after profiling.

After pl_start_profiling is executed, the dbe_profiler tool initializes the memory to prepare for data recording, stubs the stored procedures that are executed subsequently, records detailed information at key points, and records the information in the memory. Data in the memory is written to the four system catalogs only after the transaction is committed. When using the dbe_profiler tool in a transaction, note that data in the memory is not written to the system catalog because the transaction is not committed during transaction execution. Data is written to the system catalog only after the commit operation is executed. Similarly, after the rollback operation is executed, all data is deleted.

Permissions

Common users can access the DBE_PROFILER.PL_PROFILING_FUNCTIONS, DBE_PROFILER.PL_PROFILING_DETAILS, DBE_PROFILER.PL_PROFILING_CALLGRAPH and DBE_PROFILER.PL_PROFILING_TRACKINFO catalogs and have only the permission to query records.

APIs and System Catalogs

Table 1 DBE_PROFILER lists all APIs supported by the DBE_PROFILER advanced package.

Table 1 DBE_PROFILER

API

Description

DBE_PROFILER.PL_START_PLPROFILING

Allows users to perform profiling on target stored procedures.

DBE_PROFILER.PL_CLEAR_PROFILING

Deletes one piece of data or all data stored in system catalogs after profiling.

  • DBE_PROFILER.PL_START_PLPROFILING

    Allows users to perform profiling on target stored procedures. The function prototype of the DBE_PROFILER.PL_START_PLPROFILING function is as follows:

    1
    DBE_PROFILER.PL_START_PLPROFILING (run_id varchar2(64)) return void;
    
    Table 2 DBE_PROFILER.PL_START_PLPROFILING parameters

    Parameter

    Description

    run_id

    Execution ID of profiling. The system combines the session ID and execution ID into a character string in the format of sessionid_runid and writes the character string to the table as the unique ID of profiling.

  • DBE_PROFILER.PL_CLEAR_PROFILING

    Deletes one piece of data or all data stored in system catalogs after profiling. The function prototype of the DBE_PROFILER.PL_CLEAR_PROFILING function is as follows:

    1
    DBE_PROFILER.PL_CLEAR_PROFILING (run_id varchar2) return void;
    
    Table 3 DBE_PROFILER.PL_CLEAR_PROFILING parameters

    Parameter

    Description

    run_id

    If this parameter is not left empty, the unique ID of a profiling data record is deleted. If this parameter is left empty, all profiling data records are deleted.

The analysis data generated by the stored procedure is stored in the database system catalog. The catalog information is as follows:

  • Information about the DBE_PROFILER.PL_PROFILING_FUNCTIONS catalog is as follows:
    Table 5 DBE_PROFILER.PL_PROFILING_FUNCTIONS

    Column

    Type

    Description

    run_id

    VARCHAR2(80) NOT NULL

    Unique ID consisting of session ID and execution ID.

    funcoid

    BIGINT NOT NULL

    Stored procedure ID.

    schema

    TEXT NOT NULL

    Schema name.

    funcname

    TEXT NOT NULL

    Stored procedure name.

    total_occur

    BIGINT

    Total number of stored procedure execution times.

    total_time

    BIGINT

    Total execution time of a stored procedure.

  • Information about the DBE_PROFILER.PL_PROFILING_DETAILS catalog is as follows:
    Table 6 DBE_PROFILER.PL_PROFILING_DETAILS

    Column

    Type

    Description

    run_id

    VARCHAR2(80) NOT NULL

    Unique ID consisting of session ID and execution ID.

    funcoid

    BIGINT NOT NULL

    Stored procedure ID.

    line#

    INTEGER NOT NULL

    Line number.

    source

    TEXT

    Stored procedure execution statement.

    cmd_type

    TEXT

    Statement type.

    total_occur

    BIGINT

    Number of statement execution times.

    total_time

    BIGINT

    Total execution time of a statement.

    min_time

    BIGINT

    Minimum execution time of a statement.

    max_time

    BIGINT

    Maximum execution time of a statement.

  • Information about the DBE_PROFILER.PL_PROFILING_CALLGRAPH catalog is as follows:
    Table 7 DBE_PROFILER.PL_PROFILING_CALLGRAPH

    Column

    Type

    Description

    run_id

    varchar2(80) NOT NULL

    Unique ID consisting of session ID and execution ID.

    stack

    text[] NOT NULL

    Call stack.

    self_time

    bigint

    Stored procedure execution time.

  • Information about the DBE_PROFILER.PL_PROFILING_TRACKINFO catalog is as follows:
    Table 8 DBE_PROFILER.PL_PROFILING_TRACKINFO

    Column

    Type

    Description

    run_id

    VARCHAR2(80) NOT NULL

    Unique ID consisting of session ID and execution ID.

    funcoid

    BIGINT NOT NULL

    Stored procedure ID.

    step_name

    TEXT NOT NULL

    Execution phase name.

    loops_count

    INTEGER

    Total number of execution times of the execution phase.

    max_time

    BIGINT

    Maximum execution time of the execution phase.

    min_time

    BIGINT

    Minimum execution time of the execution phase.

    avg_time

    BIGINT

    Average execution time of the execution phase.

    total_time

    BIGINT

    Total execution time of the execution phase.

Constraints

  • The dbe_profiler.pl_start_profiling cannot be used in a stored procedure. Calling it in a stored procedure does not take effect.
  • The dbe_profiler.pl_start_profiling does not support the function of recording transaction failure statistics to the system catalog.
  • The length of the input parameter runid of dbe_profiler.pl_start_profiling is limited to 64 characters. If the length exceeds 64 characters, an error is reported.
  • If the input parameter of dbe_profiler.pl_start_profiling is the same as the value of runid in the profiler system catalog, an error is reported.
  • The plprofiler does not support anonymous block statements, PACKAGE initialization statements, and statements in nested subprograms.
  • Committing and rolling back an autonomous transaction does not affect the data that has been committed by the primary transaction. Therefore, the plprofiler cannot record information about stored procedures that contain autonomous transactions.

Examples

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
-- Step 1 Create tables and stored procedures.
gaussdb=# DROP TABLE IF EXISTS t1;
gaussdb=# CREATE TABLE t1 (i int);
gaussdb=# CREATE OR REPLACE PROCEDURE p1() AS
	sql_stmt varchar2(200);
	result number;
BEGIN
    for i in 1..1000 loop
      insert into t1 values(1);
    end loop;
    sql_stmt := 'select count(*) from t1';
    EXECUTE IMMEDIATE sql_stmt into result;
END;
/
gaussdb=# CREATE OR REPLACE PROCEDURE p2() AS
BEGIN
   p1();
END;
/
gaussdb=# CREATE OR REPLACE PROCEDURE p3() AS
BEGIN
    p2();
END;
/

-- Step 2 Call the plprofiler API to profile the stored procedures.
gaussdb=# SELECT dbe_profiler.pl_start_profiling('123');
gaussdb=# CALL p3();

-- Step 3 Query profiling information.
-- Query the dbe_profiler.pl_profiling_functions catalog to check the stored procedures involved in profiling.
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions ORDER BY run_id, funcoid;
       run_id        | funcoid | schema | funcname | total_occur | total_time 
---------------------+---------+--------+----------+-------------+------------
 140300887521024_123 |   16770 | public | p1()     |           1 |      54217
 140300887521024_123 |   16771 | public | p2()     |           1 |      54941
 140300887521024_123 |   16772 | public | p3()     |           1 |      55758
(3 rows)
-- Query the dbe_profiler.pl_profiling_details catalog to check the execution time details of each statement in a stored procedure.
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_details WHERE funcoid = 16770 ORDER BY run_id, funcoid, line#;
       run_id        | funcoid | line# |                   source                    |  cmd_type  | total_occur | total_time | max_time | min_time 
---------------------+---------+-------+---------------------------------------------+------------+-------------+------------+----------+----------
 140300887521024_123 |   16770 |     1 |  DECLARE                                    |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     2 | sql_stmt varchar2(200);                     |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     3 | result number;                              |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     4 | begin                                       |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     5 |     for i in 1..1000 loop                   | FORI       |           1 |      52496 |    52496 |    52496
 140300887521024_123 |   16770 |     6 |       insert into t1 values(1);             | EXECSQL    |        1000 |      51970 |     2115 |       47
 140300887521024_123 |   16770 |     7 |     end loop;                               |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     8 |     sql_stmt := 'select count(*) from t1';  | ASSIGN     |           1 |        446 |      446 |      446
 140300887521024_123 |   16770 |     9 |     EXECUTE IMMEDIATE sql_stmt into result; | DYNEXECUTE |           1 |       1271 |     1271 |     1271
 140300887521024_123 |   16770 |    10 | end                                         |            |           0 |          0 |        0 |        0
(10 rows)
-- Query the dbe_profiler.pl_profiling_callgraph catalog to check the call stack information and the overall execution time of each stored procedure (total_time and self_time correspond to the total execution time of the stored procedure at the top of the call stack and the execution time of the stored procedure).
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_callgraph ORDER BY run_id, stack;
       run_id        |                                   stack                                   | self_time 
---------------------+---------------------------------------------------------------------------+-----------
 140300887521024_123 | {"public.p3() oid=16772"}                                                 |       817
 140300887521024_123 | {"public.p3() oid=16772","public.p2() oid=16771"}                         |       724
 140300887521024_123 | {"public.p3() oid=16772","public.p2() oid=16771","public.p1() oid=16770"} |     54217
(3 rows)
-- Query the dbe_profiler.pl_profiling_trackinfo catalog to check the execution time of each phase of the stored procedure.
gaussdb=# SELECT step_name, loops_count FROM dbe_profiler.pl_profiling_trackinfo WHERE funcoid=16770;
  step_name   | loops_count 
--------------+-------------
 init         |           1
 package      |           1
 spictx       |           1
 compile      |           1
 exec_context |           1
 execute      |           1
 exec_cursor  |           1
 cleanup      |           1
 finsh        |           1
(9 rows)

-- Step 4 Delete data from the system catalog.
gaussdb=# SELECT dbe_profiler.pl_clear_profiling('');
gaussdb=# SELECT step_name, loops_count FROM dbe_profiler.pl_profiling_trackinfo WHERE funcoid=16770;
 step_name | loops_count 
-----------+-------------
(0 rows)
gaussdb=# DROP TABLE t1;

-- Step 5 Profile the stored procedure that contains an autonomous transaction.
-- Create a table.
gaussdb=# CREATE TABLE t2(a int, b int);
-- Create a stored procedure that contains an autonomous transaction.
gaussdb=# CREATE OR REPLACE PROCEDURE autonomous(a int, b int)  AS 
DECLARE 
	num3 int := a;
	num4 int := b;
	PRAGMA AUTONOMOUS_TRANSACTION;
BEGIN
	insert into t2 values(num3, num4); 
	dbe_output.print_line('just use call.');
END;
/
-- Create a common stored procedure that calls an autonomous transaction stored procedure.
gaussdb=# CREATE OR REPLACE PROCEDURE autonomous_1(a int, b int)  AS 
DECLARE 
BEGIN
	dbe_output.print_line('just no use call.');
	insert into t2 values(666, 666);
	autonomous(a,b);
END;
/
gaussdb=# SELECT dbe_profiler.pl_start_profiling ('100');
gaussdb=# CALL autonomous(11,22);
-- Query table information.
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions ORDER BY run_id, funcoid;
 run_id | funcoid | schema | funcname | total_occur | total_time 
--------+---------+--------+----------+-------------+------------
(0 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_details ORDER BY run_id, funcoid, line#;
 run_id | funcoid | line# | source | cmd_type | total_occur | total_time | max_time | min_time 
--------+---------+-------+--------+----------+-------------+------------+----------+----------
(0 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_callgraph ORDER BY run_id, stack;
 run_id | stack | self_time 
--------+-------+-----------
(0 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_trackinfo ORDER BY run_id, funcoid;
 run_id | funcoid | step_name | loops_count | max_time | min_time | avg_time | total_time 
--------+---------+-----------+-------------+----------+----------+----------+------------
(0 rows)

gaussdb=# SELECT dbe_profiler.pl_start_profiling ('101');
gaussdb=# CALL autonomous_1(11,22);
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions ORDER BY run_id, funcoid;
       run_id        | funcoid |   schema   |    funcname    | total_occur | total_time 
---------------------+---------+------------+----------------+-------------+------------
 140421237831424_101 |   10422 | dbe_output | print_line()   |           1 |        758
 140421237831424_101 |   16771 | public     | autonomous_1() |           1 |      23855
(2 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_details ORDER BY run_id, funcoid, line#;
       run_id        | funcoid | line# |                   source                    | cmd_type | total_occur | total_time | max_time | min_time 
---------------------+---------+-------+---------------------------------------------+----------+-------------+------------+----------+----------
 140421237831424_101 |   10422 |     1 |                                             |          |           0 |          0 |        0 |        0
 140421237831424_101 |   10422 |     2 | BEGIN                                       |          |           0 |          0 |        0 |        0
 140421237831424_101 |   10422 |     3 |     PKG_UTIL.io_print(format, true);        | PERFORM  |           1 |        754 |      754 |      754
 140421237831424_101 |   10422 |     4 | END;                                        |          |           0 |          0 |        0 |        0
 140421237831424_101 |   10422 |     5 |                                             |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     1 |                                             |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     2 | DECLARE                                     |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     3 | BEGIN                                       |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     4 | dbe_output.print_line('just no use call.'); | PERFORM  |           1 |       2435 |     2435 |     2435
 140421237831424_101 |   16771 |     5 | insert into t2 values(666, 666);            | EXECSQL  |           1 |        602 |      602 |      602
 140421237831424_101 |   16771 |     6 | autonomous(a,b);                            | PERFORM  |           1 |      20813 |    20813 |    20813
 140421237831424_101 |   16771 |     7 | END                                         |          |           0 |          0 |        0 |        0
(12 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_callgraph ORDER BY run_id, stack;
       run_id        |                                  stack                                  | self_time 
---------------------+-------------------------------------------------------------------------+-----------
 140421237831424_101 | {"public.autonomous_1() oid=16771"}                                     |     23097
 140421237831424_101 | {"public.autonomous_1() oid=16771","dbe_output.print_line() oid=10422"} |       758
(2 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_trackinfo ORDER BY run_id, funcoid;
       run_id        | funcoid |  step_name   | loops_count | max_time | min_time | avg_time | total_time 
---------------------+---------+--------------+-------------+----------+----------+----------+------------
 140421237831424_101 |   10422 | init         |           1 |        0 |        0 |        0 |          0
 140421237831424_101 |   10422 | package      |           1 |        9 |        9 |        9 |          9
 140421237831424_101 |   10422 | spictx       |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   10422 | compile      |           1 |      383 |      383 |      383 |        383
 140421237831424_101 |   10422 | exec_context |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   10422 | execute      |           1 |     1301 |     1301 |     1301 |       1301
 140421237831424_101 |   10422 | exec_cursor  |           1 |        3 |        3 |        3 |          3
 140421237831424_101 |   10422 | cleanup      |           1 |       11 |       11 |       11 |         11
 140421237831424_101 |   10422 | finsh        |           1 |        0 |        0 |        0 |          0
 140421237831424_101 |   16771 | init         |           1 |        0 |        0 |        0 |          0
 140421237831424_101 |   16771 | package      |           1 |      103 |      103 |      103 |        103
 140421237831424_101 |   16771 | spictx       |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   16771 | compile      |           1 |     1869 |     1869 |     1869 |       1869
 140421237831424_101 |   16771 | exec_context |           1 |        3 |        3 |        3 |          3
 140421237831424_101 |   16771 | execute      |           1 |    24011 |    24011 |    24011 |      24011
 140421237831424_101 |   16771 | exec_cursor  |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   16771 | cleanup      |           1 |       16 |       16 |       16 |         16
 140421237831424_101 |   16771 | finsh        |           1 |        1 |        1 |        1 |          1
(18 rows)

gaussdb=# SELECT dbe_profiler.pl_clear_profiling('');
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions;
 run_id | funcoid | schema | funcname | total_occur | total_time 
--------+---------+--------+----------+-------------+------------
(0 rows)

gaussdb=# DROP TABLE t2;