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 :
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 ?
Note that I've set SYS=NO to exclude Parse Recursive SQLs.
Selectively reporting from the tkprof, I see :
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.
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 :
.
.
.
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:
Hemant, your posts and demonstrations are always instructive.
Foued
Post a Comment