Tales From A Lazy Fat DBA

Tuning long PL/SQL programs is always a great pain but with the presence of DBMS_PROFILER this has become quite easy to monitor the performance of the PL/SQL programs and identifying the culprit statements consuming too much time while the run of the program.

$ cd $ORACLE_HOME/rdbms/admin
$ sqlplus / as sysdba

Execute profload.sql script and this will install the DBMS_PROFILER package.

SQL> @profload.sql

Package created.
Grant succeeded.
Synonym created.
Library created.
Package body created.

Testing for correct installation
SYS.DBMS_PROFILER successfully loaded.

PL/SQL procedure successfully completed.

/*Now create the user for a test of DBMS_PROFILER */

SQL> create user plsql_prof_test identified by test;
User created.

SQL> grant connect , resource to plsql_prof_test;
Grant succeeded.

SQL> conn plsql_prof_test/test
Connected.

/*Once connected run proftab.sql which will create related tables where profiler puts its results. */

SQL> @proftab.sql
drop table plsql_profiler_data cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist

drop table plsql_profiler_units cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist

drop table plsql_profiler_runs cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist

drop sequence plsql_profiler_runnumber
*
ERROR at line 1:
ORA-02289: sequence does not exist

Table created.
Comment created.
Table created.
Comment created.
Table created.
Comment created.
Sequence created.

Now we are all set to use the PROFILER to find areas of code causing issues.

09:00:07 SQL> execute dbms_profiler.start_profiler(‘archieve_test’);
PL/SQL procedure successfully completed.

Elapsed: 00:00:00.03

09:00:24 SQL> show user
USER is “ARADMIN”

09:00:26 SQL> exec ARCHIVING.archieve_test (‘Bdsss_asssas’,30,20, ‘Change MyDesk’, 1);
PL/SQL procedure successfully completed.

Elapsed: 00:10:24.63

09:17:41 SQL> execute dbms_profiler.STOP_PROFILER;
PL/SQL procedure successfully completed.

Now when profiling is completed its the time to use one of the view ‘plsql_profiler_runs’ which always created after you execute both the two initial sripts.
Below query will provide you
– RUN ID (Will help us to investigate further)
– RUN DETAILS (Run Timings)
– Total Time

set linesize 400 pagesize 400
col run_comment format a20
set lines 10000
column run_owner format a30
column run_comment format a20
select runid,run_owner, run_date,run_total_time/1000000000 run_total_time,run_comment from plsql_profiler_runs where run_comment like ‘%chieve%’ and RUN_DATE LIKE ‘%14-04-29%’;

RUNID RUN_OWNER                      RUN_DATE          RUN_TOTAL_TIME RUN_COMMENT
———- —————————— —————– ————– ——————–
63 ARAMAEK                       14-04-25 09:00:24        1078.98 archieve_test

Now when we have the RUN_ID we can collect and fragment query which is causing issues during the run time.
Below query will help us to divide the query (Procedure) with unit numbers and sometimes total time taken.

09:21:32 SQL> select runid,unit_number,unit_type,unit_owner, unit_name, unit_timestamp, total_time from plsql_profiler_units where runid=63;

RUNID UNIT_NUMBER UNIT_TYPE                        UNIT_OWNER                       UNIT_NAME                        UNIT_TIMESTAMP    TOTAL_TIME
———- ———– ——————————– ——————————– ——————————– —————– ———-
63           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                      00-00-00 01:01:01         .0
63           2 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                      00-00-00 01:01:01         .0
63           3 PACKAGE BODY                     ARADMIN                          ARCHIVING                        14-03-23 12:29:38         .0
63           4 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                      00-00-00 01:01:01         .0

Elapsed: 00:00:00.00

Below query will provide total number of occurences of UNIT SEGMENTS along with total time.

COLUMN runid FORMAT 99999
COLUMN unit_number FORMAT 99999
COLUMN unit_type FORMAT A20
column unit_name format a11
column TotalTime format a10
column MinTime format a10
SELECT u.runid,
u.unit_number,
u.unit_type,
u.unit_name,
d.line#,
to_char(d.total_occur) as TotalOccur,
to_char(d.total_time) as TotalTime,
to_char(d.min_time) as MinTime,
to_char(d.max_time) as max_time
FROM   plsql_profiler_units u
JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
WHERE  u.runid = 1
ORDER BY TotalOccur;

RUNID UNIT_NUMBER UNIT_TYPE            UNIT_NAME        LINE# TOTALOCCUR                               TOTALTIME  MINTIME    MAX_TIME
—— ———– ——————– ———– ———- —————————————- ———- ———- —————————————-

1           3 PACKAGE BODY         ARCHIVING         8741 5                                        5000       1000       1000
1           3 PACKAGE BODY         ARCHIVING         8904 5                                        136732000  25889000   29557000
1           3 PACKAGE BODY         ARCHIVING         8908 5                                        15000      3000       3000
1           3 PACKAGE BODY         ARCHIVING         8930 5                                        54969000   145000     54211000
1           3 PACKAGE BODY         ARCHIVING         8934 5                                        3000       1000       1000
1           3 PACKAGE BODY         ARCHIVING         8958 5                                        15445000   383000     13588000
1           3 PACKAGE BODY         ARCHIVING         8962 5                                        2000       1000       1000
1           3 PACKAGE BODY         ARCHIVING         8964 5                                        59000      1000       40000
1           3 PACKAGE BODY         ARCHIVING         8967 5                                        328000     38000      123000
1           3 PACKAGE BODY         ARCHIVING         8969 5                                        6000       1000       2000
1           3 PACKAGE BODY         ARCHIVING         7780 6                                        140969000  29000      140716000
1           3 PACKAGE BODY         ARCHIVING         7782 6                                        7000       1000       2000
1           3 PACKAGE BODY         ARCHIVING         8702 6                                        5000       1000       1000
1           3 PACKAGE BODY         ARCHIVING         1463 972                                      524000     1000       12000

Almost similar query above but this time sorted based on Total Time basis.

09:27:29 SQL> select runid,unit_number,  line#,total_occur, to_char(total_time), to_char(min_time), to_char(max_time) from plsql_profiler_data where runid=63
09:27:37   2  and total_time !=0 and min_time !=0 and max_time !=0 order by TOTAL_TIME DESC, MIN_TIME  DESC, MAX_TIME DESC, total_occur;

RUNID UNIT_NUMBER      LINE# TOTAL_OCCUR TO_CHAR(TOTAL_TIME)                      TO_CHAR(MIN_TIME)                        TO_CHAR(MAX_TIME)
—— ———– ———- ———– —————————————- —————————————- —————————————-
63           3       5090         220 226072292804                             34994                                    17049666731
63           3       5240          20 181066607554                             3979107078                               103125720715
63           3       4926          20 141296980613                             6541296441                               7361430883
63           3       5195          40 67123652951                              256962                                   3455214090
63           3       5093         200 2777416725                               3649463                                  130042883
63           3       5141          20 1573445706                               999                                      85397446
63           3       5040          26 1123533842                               6529040                                  260607691
63           3       4920          20 538701811                                1999706                                  116417886
63           3       5144           7 538252877                                96985                                    183333050
63           3       4903          20 511259845                                18179327                                 76123809
63           3        941         371 295843511                                527922                                   5997118
63           3       4900          20 243442214                                8460756                                  40755009
63           3       5198          20 223308174                                6913983                                  62818765
63           3       5154           4 197841917                                3578473                                  186799540
63           3       5147           4 173199539                                4495339                                  159311581
63           3       5037          46 111132663                                85987                                    18228320
63           3       5046          26 104860585                                315953                                   49972654
63           3        942         371 101599065                                101985                                   3873430
63           3       5103         200 69940718                                 111983                                   23141598
63           3       5156           4 67220118                                 3353507                                  35764742
63           3        956        2547 52771242                                 9998                                     2742596

TO FIND THE ORIGINAL TEXT OF THE OBJECT FROM ALL_SOURCE VIEW.
SELECT line || ‘ : ‘ || text FROM all_source WHERE owner = ‘ARAMAEK ‘ AND type= ‘PACKAGE BODY’ AND name  = ‘ARCHIVING_TEST’;

* In this case this has resulted in a 11014 lines of PACKAGE BODY named ‘ARCHIEVING_TEST’.

09:29:55 SQL> select OWNER#, OBJ#, NAME, NAMESPACE, TYPE#,STATUS from obj$  where name =’ARCHIVING_TEST’;

OWNER#       OBJ# NAME                            NAMESPACE      TYPE#     STATUS
———- ———- —————————— ———- ———- ———-
58      85332 ARCHIVING_TEST                               1          9          1
58      85334 ARCHIVING_TEST                               2         11          1

Now you can locate those lines from the package body which is causing issues.

select source from source$ where obj#=85334 and line=5090;
FETCH aSH INTO aStateHistoryID;

select source from source$ where obj#=85334 and line=5240;
FETCH aTR INTO aTicketRelationID;

select source from source$ where obj#=85334 and line between 5239 and 5242 /* Problem Line 5240 */;

—————————————————————————————————————————————-
OPEN aTR FOR ‘SELECT ‘ || getTableColumnName(trFormName, Request_MAST) ||’ FROM ‘ ||t_tr_table||’ WHERE ‘|| getTableColumnName(trFormName, Parent_Request_OID) || ‘ = ‘ || db_request_oid ; LOOP
FETCH aTR INTO aRecordRelationID;
EXIT WHEN aTR%NOTFOUND;
dynInsert := ‘INSERT INTO ‘||t_astr_table||’ (‘||t_tr_tableCol||’) SELECT ‘||t_tr_tableCol||’ from ‘||t_tr_table||’ where C1 = :bind_var’;

Now when we are zeroed to only few line of codes out of 11014 line of codes we can investiate the issue.
Result: After small analysis we found there is few issues with the variable TYPE declaration and issue is fixed after same has been fixed.

Thanks
Prashant Dixit