Thanks for the question, Andrew.

Asked: December 07, 2020 - 12:00 pm UTC

Last updated: December 11, 2020 - 3:23 am UTC

Version: 19.3.0.0.0

Viewed 1000+ times

You Asked

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 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;

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 NOCACHE

However, 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

and Connor said...

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)

Rating

(1 rating)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Andrew Tindle, December 10, 2020 - 2:33 pm UTC

Thanks Connor.

Taking this exercise further, I'm now confused as to why I'm seeing different Caching behavior for this NOCACHE LOB when doing a direct SQL SELECT vs a SELECT in PL/SQL.

Test Setup

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

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

COMMIT;

Test1 : Direct SQL SELECT

SET FEEDBACK ONLY
ALTER SESSION SET EVENTS = '10046 trace name context forever, level 8';
SELECT json_data FROM clob_test_sf_nocache WHERE rownum <= 1000;

Running this repeatedly consistently gives:

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           0
Fetch     1001      0.07       0.08       4000       1005          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1003      0.07       0.08       4000       1005          0        1000

which is what I expect - Disk Reads=4000 - due to the LOB segment not being cached.

Test2 : PL/SQL Block

ALTER SESSION SET EVENTS = '10046 trace name context forever, level 8';
DECLARE
  TYPE t_json_data_tab IS TABLE OF clob_test_sf_nocache.json_data%TYPE INDEX BY PLS_INTEGER;
  json_data_tab t_json_data_tab;
BEGIN
  SELECT json_data BULK COLLECT INTO json_data_tab FROM clob_test_sf_nocache WHERE rownum <= 1000;
END;
/

Running this repeatedly consistently gives:

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           0
Fetch        1      0.00       0.00          0         12          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0         12          0        1000

for the SELECT statement within it.

This is not what I expect - does Disk Reads=0 not imply the LOB is now cached ?

Thanks
Andrew

December 11, 2020 - 3:23 am UTC

You are only picking up the locator there. PL/SQL didnt need the lob content until you actually *needed* it

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.

Breadcrumb

Question and Answer

You Asked

and Connor said...

Rating

Comments

More to Explore

Performance

Autotrace vs Oracle Trace: Showing different results for Disk Reads for LOB Segment with NOCACHE

Breadcrumb

Question and Answer

You Asked

and Connor said...

Rating

Comments

More to Explore

Performance