Using DBMS Profiler

What is DBMS_PROFILER and how it helps in identifying long running SQLs?

Simply inspecting the code can bring out the bottlenecks eating up your processing time. Using explain plan to fine tune the SQL statements resolves issues most of the time. However, sometimes it may not be that simple. The profiler gathers the following information about each line of PL/SQL code:

•       Total elapsed time in execution

•       Total number of times each line was executed. 

•       Time spent executing each line. This includes SQL statements.

•       Minimum and maximum duration spent on a specific line of code. 

•       Code that is actually being executed for a given scenario.

For DBMS_PROFILER Installation-Please Click here.

DBMS_PROFILER

We have two procedures. One of them uses literals in the queries and the other uses bind variables. We noticed that the program using literals taking too much time. We will then use DBMS_PROFILER to pin point the statement consuming most of the time.

Create table that will be used in our PL/SQL code that we will investigate through DBMS_PROFILER package.

SQL> Create Table T1 (col1 varchar2(30), col2 varchar2(30));

Table created.

Create two different procedures one using literals in the queries and other using bind variables.

SQL> Create or Replace Procedure Literals
  2       IS
  3       vNumber Number;
  4       Begin
  5       For i in 1..100000 Loop
  6         vNumber := Dbms_Random.Random;
  7         Execute Immediate 'Insert Into T1 Values ('||vNumber||','||vNumber||')';
  8       End Loop;
  9      End;
 10  /

Procedure created.

SQL> Create or Replace Procedure Binds
  2       IS
  3       vNumber number;
  4      Begin
  5       For i in 1..100000 Loop
  6         vNumber := Dbms_Random.Random;
  7         Insert Into T1 Values (vNumber,vNumber);
  8       End Loop;
  9      End;
 10  /

Procedure created.

DBMS_PROFILER package provides us following 3 important procedures:   

·       DBMS_PROFILER.START_PROFILER: Start the monitoring process.

·       DBMS_PROFILER.STOP_PROFILER: Stop the monitoring process

·       DBMS_PROFILER.FLUSH_DATA: Save profiler stats in tables and flush the memory.

DBMS_PROFILER.START_PROFILER 
The DBMS_PROFILER.START_PROFILER tells Oracle to start the monitoring process. An identifier needs to be provided with each run that is used later to retrieve the statistics. Starts the profiler before the execution of the PL/SQL program.

DBMS_PROFILER.STOP_PROFILER 
The DBMS_PROFILER.STOP_PROFILER tells Oracle to stop the monitoring. Stops the profiler once the program finishes executing.

First run the procedure with the queries that contain literals.

SQL> Execute Dbms_Profiler.Start_Profiler('Literals');

PL/SQL procedure successfully completed.

SQL> Exec Literals;

PL/SQL procedure successfully completed.

SQL> Execute Dbms_Profiler.Stop_Profiler;

PL/SQL procedure successfully completed.

The literals run is finished now run the program which contains queries with bind variables.

SQL> Execute Dbms_Profiler.Start_Profiler('Binds');

PL/SQL procedure successfully completed.

SQL> Exec Binds;

PL/SQL procedure successfully completed.

SQL> Execute Dbms_Profiler.Stop_Profiler;

PL/SQL procedure successfully completed.

As binds run is complete now we can see the result of these runs captured by DBMS_PROFILER.

SQL> Set Lines 10000
SQL> Column Run_Owner Format a30
SQL> Column Run_Comment Format a10
SQL> Select Runid, Run_Owner, Run_Date,Run_Total_Time/1000000000 Run_Total_Time,Run_comment
  2      From Plsql_Profiler_Runs;

     RUNID RUN_OWNER                      RUN_DATE  RUN_TOTAL_TIME RUN_COMMEN
---------- ------------------------------ --------- -------------- ----------
         2 MYUSER                         15-JAN-17        107.362 Literals
         3 MYUSER                         15-JAN-17         35.683 Binds

 /* Plsql_Profiler_Runs has summary of all Dbms_Profiler Runs */

SQL> Column Text Format a55
SQL> Column Total_Time Format 99.9
SQL> Column Min_time Format 99.9
SQL> Column Max_time Format 99.9

SQL> Select S.Text , P.Total_Occur , P.Total_Time/1000000000 Total_Time, P.Min_Time/1000000000 Min_Time, P.Max_Time/1000000000 Max_Time
  2  From Plsql_Profiler_Data P, User_Source S, Plsql_Profiler_Runs R
  3  Where P.Line# = S.Line And P.Runid = R.Runid And   R.Run_Comment = 'Literals' And  S.Name ='LITERALS';

TEXT                                                    TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
------------------------------------------------------- ----------- ---------- -------- --------
Procedure Literals                                                2         .0       .0       .0
Procedure Literals                                                0         .0       .0       .0
Procedure Literals                                                3         .0       .0       .0
Procedure Literals                                                1         .0       .0       .0
     For i in 1..100000 Loop                                 100001         .0       .0       .0
       vNumber := Dbms_Random.Random;                        100000         .2       .0       .0
       Execute Immediate 'Insert Into T1 Values ('||vNu      100000       47.3       .0      4.1
mber||','||vNumber||')';

    End;                                                          1         .0       .0       .0

8 rows selected.

SQL> Select S.Text , P.Total_Occur , P.Total_Time/1000000000 Total_Time, P.Min_Time/1000000000 Min_Time, P.Max_Time/1000000000 Max_Time  
From Plsql_Profiler_Data P, User_Source S, Plsql_Profiler_Runs R
Where P.Line# = S.Line And P.Runid = R.Runid And   R.Run_Comment = 'Binds' And  S.Name ='BINDS';


TEXT                           TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
------------------------------ ----------- ---------- -------- --------
Procedure Binds                          1         .0       .0       .0
Procedure Binds                          3         .0       .0       .0
Procedure Binds                          0         .0       .0       .0
For i in 1..100000 Loop             100001         .0       .0       .0
vNumber := Dbms_Random.Random;      100000         .2       .0       .0
Insert Into T1 Values (vNumber      100000        7.9       .0       1.0
,vNumber);               
End;                                     1         .0       .0       .0
Procedure Binds                          2         .0       .0       .0

8 rows selected.

As it can clearly be seen that all the time was being consumed by the INSERT statement that was using literals. Rest of the lines in the code are doing just fine.

The test that we ran is also an evidence of using bind variables is better than using literals in most cases. The statement that was using literals consumed 47.3 seconds and the statement using bind variables consumed only 7.9 seconds. And this difference will be even more when multiple sessions are running this program because they will then cause contention on shared pool latches as they all will be parsing same statement again and again.

Conclusion
DBMS_PROFILER is a very powerful tool and the first of its kind to identify performance issues on the PL/SQL front. This utility can be best used in the development stages to fine tune code based on various applicable scenarios. It can also be used to fine tune routines that are already in production and are taking noticeable time to execute. Overall, this utility gives statistics for each line of code that will help us in evaluating and tuning at a finer level. Just as SQL statements are checked for performance, PL/SQL code should not be ignored but should be tuned for optimal results as well

Get involved and leave your Comments in the Box Below. The more people get involved, the more we all benefit. So, leave your thoughts before you leave the page.