自动跟踪vs Oracle跟踪: 显示带有NOCACHE的LOB段的磁盘读取的不同结果

嗨，

当测试安全文件LOB段的NOCACHE选项并使用自动跟踪vs跟踪/TKPROF分析选择性能时，我看到了不同的结果。

Test Setup

CREATE TABLE js_poc.clob_test_sf_nocache (
  id         NUMBER,
  json_data  CLOB   CHECK(json_data IS JSON)
) 
LOB(json_data) STORE AS SECUREFILE(NOCACHE);
复制

INSERT INTO js_poc.clob_test_sf_nocache
SELECT level,'{"key":"This is a long string of text, repeat"}'
FROM dual
CONNECT BY level <= 1000;
复制

Test 1: Select 500 rows with SET AUTOTRACE TRACEONLY

sqlplus js_poc
SET AUTOTRACE TRACEONLY
SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;
复制

输出:

Statistics
----------------------------------------------------------
         31  recursive calls
          7  db block gets
       1014  consistent gets
       1005  physical reads
       1004  redo size
     371998  bytes sent via SQL*Net to client
     148424  bytes received via SQL*Net from client
       1002  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        500  rows processed
复制

SELECT的后续运行显示类似的输出:

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       1003  consistent gets
       1000  physical reads
          0  redo size
     371998  bytes sent via SQL*Net to client
     148424  bytes received via SQL*Net from client
       1002  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        500  rows processed
复制

每个SELECT 显示1000 physical reads对于每次运行，这是我在配置LOB时所期望的NOCACHE

但是，当我执行相同的SELECT语句并跟踪它/tkprof时，即

ALTER SESSION SET SQL_TRACE = TRUE;
SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;
ALTER SESSION SET SQL_TRACE = FALSE;
复制

TKPROF文件始终为磁盘读取显示0，例如

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      501      0.01       0.01          0        503          0         500
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      503      0.01       0.01          0        505          0         500
复制

如果您可以解释为什么会发生这种情况，或者我对Autotrace/SQL Trace的2个指标的误解是什么，那就太好了。

谢谢
安德鲁

这只是每个工具报告I/O的方式的细微差异。

当您查询LOB (足够大，不能与行内联存储) 时，“基” 查询将获取lob定位器 (只是一个指针)，然后当您从表中获取行时，然后使用定位器执行额外的I/O以获取实际的lob数据。

set autotrace并不真正知道这一点-它只是在做一个增量，即

a-我的会话完成了多少个I/o？
b-运行我的查询
c-我的会话完成了多少个I/o？
d-报告差异

因此，它 “看到” 作为获取的一部分完成的I/O。所以让我们进一步探索一下。

SQL> CREATE TABLE clob_test_sf_nocache (
  2    id         NUMBER,
  3    json_data  CLOB   CHECK(json_data IS JSON)
  4  )
  5  LOB(json_data) STORE AS SECUREFILE(NOCACHE);

Table created.

SQL>
SQL> INSERT INTO clob_test_sf_nocache
  2  SELECT level,'{"key":"This is a long string of text, repeat"}'
  3  FROM dual
  4  CONNECT BY level <= 1000;

1000 rows created.

SQL>
SQL> commit;

Commit complete.

SQL>
SQL> set autotrace traceonly stat
SQL> SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;

500 rows selected.


Statistics
----------------------------------------------------------
         29  recursive calls
          7  db block gets
       1038  consistent gets
          1  physical reads
        996  redo size
     204998  bytes sent via SQL*Net to client
     148424  bytes received via SQL*Net from client
        502  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        500  rows processed

SQL> set autotrace off
复制

没有LOB物理读取，因为它足够小，可以与行内联存储。

SQL> CREATE TABLE clob_test_sf_nocache (
  2    id         NUMBER,
  3    json_data  CLOB   CHECK(json_data IS JSON)
  4  )
  5  LOB(json_data) STORE AS SECUREFILE(NOCACHE);

Table created.

SQL> INSERT INTO clob_test_sf_nocache
  2  SELECT level,'{"key":"'||rpad('x',16000,'x')||'"}'
  3  FROM dual
  4  CONNECT BY level <= 1000;

1000 rows created.

SQL> commit;

Commit complete.

SQL> set autotrace traceonly stat
SQL> SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;

500 rows selected.


Statistics
----------------------------------------------------------
         25  recursive calls
          7  db block gets
       1030  consistent gets
       1001  physical reads
        996  redo size
     237998  bytes sent via SQL*Net to client
     148424  bytes received via SQL*Net from client
        502  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        500  rows processed

SQL> set autotrace off

复制

现在LOB是离线存储的，我们做了物理IO来获取每个lob

我添加了一个跟踪，通过

SQL> alter session set events = '10046 trace name context forever, level 8';

Session altered.

SQL> set feedback only
SQL> SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;

500 rows selected.
复制

它以不同的方式代表活动...

SELECT json_data 
FROM
 clob_test_sf_nocache WHERE rownum <= 500


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          4          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      501      0.13       0.14       2000        502          0         500
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      503      0.13       0.15       2000        506          0         500

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 107  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       500        500        500  COUNT STOPKEY (cr=502 pr=0 pw=0 time=2021 us starts=1)
       500        500        500   TABLE ACCESS FULL CLOB_TEST_SF_NOCACHE (cr=502 pr=0 pw=0 time=2019 us starts=1 cost=4 size=67000 card=500)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     502        0.00          0.00
  SQL*Net message from client                   502        0.00          0.03
  direct path read                              502        0.00          0.04
  SQL*Net more data to client                  1501        0.00          0.03
复制

您可以看到 “pr = 0” 数字-读取 * table * 不需要花费任何费用，但是在获取时，我们会报告 “disk” 计数2000年。但是，如果您低头查看等待事件，我们有500直接路径读取。如果我们对跟踪文件的详细信息进行了处理，则每次直接读取都会看到以下内容

WAIT #2345311765584: nam='direct path read' ela= 181 file number=64 first dba=61502 block cnt=4 obj#=123271 tim=2274769349559
WAIT #2345311765584: nam='direct path read' ela= 199 file number=64 first dba=61494 block cnt=4 obj#=123271 tim=2274769348517
WAIT #2345311765584: nam='direct path read' ela= 214 file number=64 first dba=61498 block cnt=4 obj#=123271 tim=2274769349045
WAIT #2345311765584: nam='direct path read' ela= 232 file number=64 first dba=61506 block cnt=4 obj#=123271 tim=2274769350116
WAIT #2345311765584: nam='direct path read' ela= 251 file number=64 first dba=61490 block cnt=4 obj#=123271 tim=2274769348005
WAIT #2345311765584: nam='direct path read' ela= 259 file number=64 first dba=61486 block cnt=4 obj#=123271 tim=2274769347431
...
...
...
复制

因此，每个直接读取是针对4个块，因此给出了500*4 = 2000的总磁盘读取。

(这些测试都在19.8上完成)