为什么我的 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