I'm trying to learn the performance effects of a bulk collect operation. I executed a couple of queries and took the TKPROF output. However, there is no fetch count for any of these PL/SQL blocks to see the context switch count. They are all 0. And I couldn't understand the bulk collect effects clearly, from the execution times as well.
Below, I shared the TKPROF output of the queries I executed. And I used the standard SH schema of the database. Could you please help me for this?
TKPROF: Release 12.2.0.1.0 - Development on Thu Apr 11 08:51:44 2019
Copyright (c) 1982, 2017, Oracle and/or its affiliates. All rights reserved.
Trace file: orcl_ora_15104_TUNY.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: 3bza4q71t1k45 Plan Hash: 0
BEGIN dbms_session.session_trace_enable(waits=>true, binds => true); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.03 0.03 2 377 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.03 0.03 2 377 0 1
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 230
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 4.06 4.06
********************************************************************************
declare
cursor c1 is select cust_id, cust_email FROM customers order by cust_id;
type r_type is table of c1%rowtype;
r1 r_type := r_type();
idx pls_integer := 0;
BEGIN
OPEN c1;
LOOP
idx:=idx+1;
r1.extend;
FETCH c1 INTO r1(idx);
EXIT WHEN c1%notfound;
END LOOP;
CLOSE c1;
dbms_output.put_line(r1(idx-1).cust_id);
END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 2.06 2.05 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 2.06 2.05 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 230
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 171 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.02 0.02
********************************************************************************
declare
cursor c1 is select cust_id, cust_email FROM customers order by cust_id;
type r_type is table of c1%rowtype;
r1 r_type := r_type();
BEGIN
OPEN c1;
FETCH c1 BULK COLLECT INTO r1;
CLOSE c1;
dbms_output.put_line(r1(r1.last).cust_id);
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: 230
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.07 0.07
********************************************************************************
declare
cursor c1 is select cust_id, cust_email FROM customers order by cust_id;
type r_type is table of c1%rowtype;
r1 r_type := r_type();
BEGIN
OPEN c1;
FETCH c1 BULK COLLECT INTO r1 LIMIT 100;
CLOSE c1;
dbms_output.put_line(r1(r1.last).cust_id);
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: 230
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.07 0.07
********************************************************************************
declare
cursor c1 is select cust_id, cust_email FROM customers order by cust_id;
type r_type is table of c1%rowtype;
r1 r_type := r_type();
BEGIN
OPEN c1;
FETCH c1 BULK COLLECT INTO r1 LIMIT 1000;
CLOSE c1;
dbms_output.put_line(r1(r1.last).cust_id);
END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 230
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 14.66 14.66
********************************************************************************
declare
cursor c1 is select cust_id, cust_email FROM customers order by cust_id;
type r_type is table of c1%rowtype;
r1 r_type := r_type();
BEGIN
OPEN c1;
FETCH c1 BULK COLLECT INTO r1 LIMIT 100000;
CLOSE c1;
dbms_output.put_line(r1(r1.last).cust_id);
END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.03 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.03 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 230
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 11.04 11.04
********************************************************************************
SQL ID: bz2z37aj1gkkw 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: 1
Optimizer mode: ALL_ROWS
Parsing user id: 230
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6 0.00 0.00 0 0 0 0
Execute 7 2.10 2.13 2 377 0 7
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13 2.10 2.13 2 377 0 7
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 6 14.66 29.95
PGA memory operation 175 0.00 0.01
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PGA memory operation 478 0.00 0.00
7 user SQL statements in session.
0 internal SQL statements in session.
7 SQL statements in session.
********************************************************************************
Trace file: orcl_ora_15104_TUNY.trc
Trace file compatibility: 12.2.0.0
Sort options: default
1 session in tracefile.
7 user SQL statements in trace file.
0 internal SQL statements in trace file.
7 SQL statements in trace file.
7 unique SQL statements in trace file.
56323 lines in trace file.
32 elapsed seconds in trace file.
By default, you should have the SELECT query writen in your tkprof file.
First put your session in trace mode :
ALTER SESSION SET SQL_TRACE=TRUE
Then run following PL/SQL block for example :
declare
cursor c1 is select username
FROM all_users order by username;
type r_type is table of c1%rowtype; r1 r_type := r_type();
idx pls_integer := 0;
BEGIN
OPEN c1;
LOOP
idx:=idx+1;
r1.extend;
FETCH c1 INTO r1(idx);
EXIT WHEN c1%notfound;
END LOOP;
CLOSE c1;
dbms_output.put_line(r1(idx-1).username);
END;
/
Then you can generate the tkprof file from the trace file :
tkprof xe_ora_16120.trc sys=no
and in the generated tkprof file you should see the timing for the SQL Queries that were in the PL/SQL block :
SQL ID: cccjz73g9uyba Plan Hash: 1902255816
SELECT USERNAME
FROM
ALL_USERS ORDER BY USERNAME
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.03 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 31 0.00 0.00 0 55 0 30
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 33 0.03 0.01 0 55 0 30