Hi,
I am seeing different outcomes when testing the NOCACHE option of SECUREFILE LOB Segments and analysing SELECT performance using Autotrace vs Trace/TKPROF.
Test SetupCREATE 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 TRACEONLYsqlplus js_poc
SET AUTOTRACE TRACEONLY
SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;
Output:
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
and subsequent runs of the SELECT show similar output:
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
each
SELECT showing
1000 physical reads for every run, which is what I expect when the LOB is configured for
NOCACHEHowever, when I execute the same SELECT statement and trace it/tkprof it, i.e.
ALTER SESSION SET SQL_TRACE = TRUE;
SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 500;
ALTER SESSION SET SQL_TRACE = FALSE;
the TKPROF file always shows 0 for Disk Reads, e.g.
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
If you could explain why this is happening or what my misunderstanding is for the 2 metrics from Autotrace/SQL Trace, that would be great.
Thank you
Andrew
It is just a subtle difference in the way each tool is reporting the I/O.
When you query a LOB (that is large enough not to be stored inline with the row), the "base" query gets the lob locator (just a pointer), and then as you fetch rows from the table, the locator is then used to perform additional I/O to get the actual lob data.
set autotrace doesn't really know this - it is simply doing a delta, namely
a- how many I/Os has my session done?
b- run my query
c- how many I/Os has my session done?
d- report the difference
hence it "sees" the I/O done as part of the fetching. So lets explore a little further.
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
No LOB physical reads because its small enough to be stored inline with the row....So now we bump it up
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
Now that the LOB is stored out of line, we did the physical IO to get each lob
I added a trace pick up an execution via
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.
and it represents the activity differently...
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
You can see the "pr=0" figure - it cost us nothing to read the *table*, but on fetching we report 'disk' count of 2000. But if you look down at the wait events, we had 500 direct path reads. If we did into the detail of the trace file, you'll see the following for each direct read
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
...
...
...
So each direct read was for 4 blocks, thus giving out total disk reads of 500*4 = 2000.
(These tests all done on 19.8)