为什么我的 TKPROF 文件不显示我的 PL/SQL 块的提取计数？
Why my TKPROF file doesn't show the fetch counts of my PL/SQL block?
我正在尝试了解批量收集操作的性能影响。我执行了几个查询并获取了 TKPROF 输出。但是，这些 PL/SQL 块中的任何一个都没有获取计数以查看上下文切换计数。它们都是 0。我也无法从执行时间清楚地理解批量收集效果。
下面，我分享了我执行的查询的 TKPROF 输出。我使用了数据库的标准 SH 模式。
你能帮我解决这个问题吗？
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.
默认情况下，您应该在 tkprof 文件中写入 SELECT 查询。
首先将您的会话置于跟踪模式：
ALTER SESSION SET SQL_TRACE=TRUE
然后 运行 跟随 PL/SQL 块 例如：
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;
/
然后您可以从跟踪文件生成 tkprof 文件:
tkprof xe_ora_16120.trc sys=no
并且在生成的 tkprof 文件中，您应该看到 PL/SQL 块中的 SQL 查询的时间：
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
我正在尝试了解批量收集操作的性能影响。我执行了几个查询并获取了 TKPROF 输出。但是，这些 PL/SQL 块中的任何一个都没有获取计数以查看上下文切换计数。它们都是 0。我也无法从执行时间清楚地理解批量收集效果。
下面，我分享了我执行的查询的 TKPROF 输出。我使用了数据库的标准 SH 模式。 你能帮我解决这个问题吗？
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.
默认情况下，您应该在 tkprof 文件中写入 SELECT 查询。
首先将您的会话置于跟踪模式：
ALTER SESSION SET SQL_TRACE=TRUE
然后 运行 跟随 PL/SQL 块 例如：
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;
/
然后您可以从跟踪文件生成 tkprof 文件:
tkprof xe_ora_16120.trc sys=no
并且在生成的 tkprof 文件中，您应该看到 PL/SQL 块中的 SQL 查询的时间：
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