Search My Oracle Blog

Custom Search

08 November, 2015

Trace Files -- 7 : SQL in PL/SQL

So far, all my examples of Tracing have been 'pure' SQL.  What does a Trace File show for SQL that is executed from within PL/SQL ?

I run this code  where I trace only the execution of the stored procedure :

SQL> drop table departmental_salary purge;

Table dropped.

SQL> drop procedure my_dept_salary_proc ;

Procedure dropped.

SQL> 
SQL> create table departmental_salary (department_id number, total_salary number);

Table created.

SQL> 
SQL> create or replace procedure my_dept_salary_proc as
  2  l_dept_id number(4);
  3  l_tot_salary number(10,2);
  4  cursor get_dept_id is select distinct department_id from employees;
  5  
  6  begin
  7  open get_dept_id;
  8  loop
  9  fetch get_dept_id into l_dept_id;
 10  exit when get_dept_id%notfound;
 11  
 12  -- get the sum(salary)
 13  select sum(salary) into l_tot_salary from employees where department_id = l_dept_id ;
 14  -- the developer mistakenly entered the same query twice in the procedure
 15  -- the second SELECT is textually different
 16  SELECT  SUM(SALARY) into l_tot_salary FROM    employees WHERE DEPARTMENT_ID = l_dept_id ;
 17  
 18  insert into departmental_salary values (l_dept_id, l_tot_salary);
 19  -- again, the developer mistakenly entered the same INSERT twice
 20  -- not exactly the same text
 21  INSERT into   DEPARTMENTAL_SALARY values (L_DEPT_ID, L_TOT_SALARY);
 22  
 23  end loop;
 24  
 25  commit;
 26  
 27  end;
 28  /

Procedure created.

SQL> 
SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> 
SQL> execute my_dept_salary_proc;

PL/SQL procedure successfully completed.

SQL> 
SQL> exec dbms_session.session_trace_disable;

PL/SQL procedure successfully completed.

SQL> 
SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3927.trc

SQL> 


Note the repetition of the SELECT and INSERT statements.  In "normal" SQL, the two SELECTs for SUM(SALARY) would have two different SQL_IDs because any SQL that differs by Case or blank characters is a different SQL_ID.  As also, the two INSERTs should have different SQL_IDs.

What does a tkprof show ?

[oracle@ora11204 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3927.trc \
> EXEC_MY_DEPT_SALARY_PROC.PRF sys=NO aggregate=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 8 23:23:42 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 ~]$ 



Note that I've set SYS=NO to exclude Parse Recursive SQLs.

Selectively reporting from the tkprof, I see :

SQL ID: 0wan8zwsb8000 Plan Hash: 0

BEGIN dbms_session.session_trace_enable(waits=>TRUE); END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43


SQL ID: a8p49fngpats5 Plan Hash: 0

BEGIN my_dept_salary_proc; END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43


SQL ID: 4xts9z878v4yb Plan Hash: 3042654289

SELECT DISTINCT DEPARTMENT_ID
FROM
 EMPLOYEES


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       13      0.00       0.00          0          6          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15      0.00       0.00          0          6          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
        12         12         12  HASH UNIQUE (cr=6 pr=0 pw=0 time=743 us cost=4 size=33 card=11)
       214        214        214   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=917 us cost=3 size=642 card=214)


SQL ID: bnr7u92kg18ak Plan Hash: 1756381138

SELECT SUM(SALARY)
FROM
 EMPLOYEES WHERE DEPARTMENT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12      0.00       0.00          0         66          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25      0.00       0.00          0         66          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=6 pr=0 pw=0 time=73 us)
        12         12         12   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=64 us cost=3 size=133 card=19)


SQL ID: bnr7u92kg18ak Plan Hash: 1756381138

SELECT SUM(SALARY)
FROM
 EMPLOYEES WHERE DEPARTMENT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12      0.00       0.00          0         66          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25      0.00       0.00          0         66          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=6 pr=0 pw=0 time=50 us)
        12         12         12   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=40 us cost=3 size=133 card=19)


SQL ID: b6yyghrcpvy4y Plan Hash: 0

INSERT INTO DEPARTMENTAL_SALARY
VALUES
 (:B2 , :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          4         55          12
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0          4         55          12

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=2 pr=0 pw=0 time=479 us)


SQL ID: b6yyghrcpvy4y Plan Hash: 0

INSERT INTO DEPARTMENTAL_SALARY
VALUES
 (:B2 , :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          1         14          12
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0          1         14          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=63 us)


SQL ID: 8ggw94h7mvxd7 Plan Hash: 0

COMMIT


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0

Misses in library cache during parse: 0
Parsing user id: 43     (recursive depth: 1)


SQL ID: 4pzfk82288xrc Plan Hash: 0

BEGIN dbms_session.session_trace_disable; END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43


********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.01          0          0          0           3

Misses in library cache during parse: 1



OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       15      0.00       0.00          0          0          0           0
Execute     59      0.00       0.00          0         17         77          28
Fetch       40      0.00       0.00          0        148          0          37
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      114      0.01       0.01          0        165         77          65

Misses in library cache during parse: 1
Misses in library cache during execute: 1





Note 1 : The first query for DISTINCT DEPARTMENT_IDs returned 12 rows (12 distinct Department_IDs).  Therefore, each of the SELECT and INSERT statements was executed 12 times.
There are some very interesting observations to be made.

Note 2 : The Rows (1st), (avg), (max) statistics for the SELECT SUM(SALARY) are not accurate as the trace file has not captured Row Source Statistics individually for each execution of the query.  Different DEPARTMENT_IDs actually have different Row Counts.  You have to be careful when interpreting these statistics.  Check the trace file to see if Row Source Statistics (indicated by "STAT" lines) are captured.


Firstly : The SQLs called from the PLSQL procedure are not accounted under "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS". This can be surmised by looking at the "Execute" and "Fetch" count statistics. The SQLs called from the PLSQL procedure are reported under "OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS".  That is why it can sometimes be very important to *not* ignore the "Recursive Statements" statistics.  Here, all the effort is in what are identified by tkprof as "Recursive Statements".  Some of the 59 Executions under "Recursive Statements" are NOT Parse overheads but actual User SQLs (called from the PLSQL procedure) !
I can also see from the raw trace file that my SELECT and INSERT statements appear with "dep=1" (and not "dep=0").  So, they are tracked as Recursive Depth SQLs, not Parent level SQLs.

PARSING IN CURSOR #139685522349264 len=44 dep=1 uid=43 oct=3 lid=43 tim=1446996115239966 hv=244159435 ad='70eaa1c0' sqlid='4xts9z878v4yb'
SELECT DISTINCT DEPARTMENT_ID FROM EMPLOYEES
END OF STMT

PARSING IN CURSOR #139685521574368 len=60 dep=1 uid=43 oct=3 lid=43 tim=1446996115241015 hv=2767233362 ad='70f496b0' sqlid='bnr7u92kg18ak'
SELECT SUM(SALARY) FROM EMPLOYEES WHERE DEPARTMENT_ID = :B1
END OF STMT

PARSING IN CURSOR #139685521624960 len=51 dep=1 uid=43 oct=2 lid=43 tim=1446996115241988 hv=3646814366 ad='6e08dea0' sqlid='b6yyghrcpvy4y'
INSERT INTO DEPARTMENTAL_SALARY VALUES (:B2 , :B1 )
END OF STMT


Secondly : those CASE-Sensitive SQL statements that I had in the procedure which should have generated different SQL_IDs are all transformed to ALL-UPPERCASE SQL statements with the additional blank spaces stripped out.  Thus, although we have two different sets of SELECT statements for the SUM(SALARY), they appear exactly the same (transformed to ALL-UPPERCASE) with the *same* SQL_ID in the raw trace.  Similarly, the two different INSERT statements appear exactly the same ALL-UPPERCASE statements.
This is in optimization that Oracle applies to SQL statements inside PLSQL.  They effectively become case-insensitive and similar.  Also, you can see that Oracle automatically assigns Bind Variables (:B1, :B2) in place of the placeholders I used (l_dept_id, l_tot_salary).


Note  :  SELECT statement statistics (consistent gets, disk reads,  rows etc are accounted under FETCH, while DML (e.g. INSERT) statement statistics are accounted under EXECUTE.


I can verify that the INSERTs were executed twice for each DEPARTMENT_ID :

SQL> select department_id, total_salary from departmental_salary order by 1;

DEPARTMENT_ID TOTAL_SALARY
------------- ------------
    10       8800
    10       8800
    20      38000
    20      38000
    30      49800
    30      49800
    40      13000
    40      13000
    50     312800
    50     312800
    60      57600
    60      57600
    70      20000
    70      20000
    80     609000
    80     609000
    90     116000
    90     116000
   100     103216
   100     103216
   110      40616
   110      40616



24 rows selected.

SQL> 


.
.
.

1 comment:

Foued said...

Hemant, your posts and demonstrations are always instructive.
Foued

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com

Top 50 Oracle SQL Blogs 2016

Top 50 Oracle SQL Blogs 2016
Top 50 Oracle SQL Blogs 2016