This is a blog note that started life in September 2001 (which was before I started blogging, I think), got drafted as a blog in January 2014 because of a question on the Oracle-L list server, and has finally got to publication following a question on the ODC database forum. (But the comments in the blog don’t look as if they are relevant to the question.)
The question on Oracle-l was: Why is the same CLOB datablock read multiple times?
The answer is basically: client programs tend to set a “sensible” fetch buffer size for LOBs and if the buffer size is less than the size of the LOB the block(s) the LOB is in have to be visited multiple times and for nocache LOBs that means the block(s) will be read multiple times.
This can be seen quite easily in SQL*Plus which has two helpful parameters (one dating back to at least v5):
set long N set longchunksize M
The “long” setting tells SQL*Plus how much of the LOB to display on screen, the “longchunksize” tells SQL*Plus how much of the LOB to fetch from the database on each call. The default value is 80 for both settings. So let’s set up some data and do a few simple demonstrations using nothing more subtle than autotrace.
rem
rem Script: lob_fetch_2.sql
rem Author: Jonathan Lewis
rem Dated: July 2012
rem Purpose:
rem
rem Last tested
rem 18.3.0.0
rem 12.1.0.2
rem 11.2.0.2
rem
create table t1 (
id number ,
v1 varchar2(60),
c1 clob,
c2 clob
)
lob(c1) store as (enable storage in row cache)
lob(c2) store as (enable storage in row cache)
;
begin
for i in 1..1000 loop
insert into t1 values(i, lpad(i,60), lpad(i,60), empty_clob());
end loop;
commit;
end;
/
execute dbms_stats.gather_table_stats(null,'t1')
I’ve got a table with two CLOB columns, both declared to enable storage in row and cache. I’ve also got a varchar2() column, and I’ve loaded one of the CLOB columns and the varchar2() column with a 60 character string, setting the other CLOB column explicitly to the empty_clob() value – which is not the same as setting it to NULL.
Now I’ll do 3 selects, fetching the id column and one other column, showing only the autotrace statistics:
set long 80 set longchunksize 80 set arraysize 5000 set autotrace traceonly statistics prompt ============== prompt Varchar2 fetch prompt ============== select id, v1 from t1; prompt ================ prompt Small CLOB fetch prompt ================ select id, c1 from t1; prompt ================ prompt Empty CLOB fetch prompt ================ select id, c2 from t1; set autotrace off
I’ve explicitly set long and longchunksize to 80 (the defaults) just to make it clear that that’s what they are for this test; and I’ve set the arraysize to 5000 so that I can get the 1,000 rows of data in the smallest number of fetches. Here are the three sets of autotrace statistics:
==============
Varchar2 fetch
==============
1000 rows selected.
Statistics
----------------------------------------------------------
11 recursive calls
11 db block gets
75 consistent gets
0 physical reads
2040 redo size
70545 bytes sent via SQL*Net to client
624 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1000 rows processed
================
Small CLOB fetch
================
1000 rows selected.
Statistics
----------------------------------------------------------
4 recursive calls
5 db block gets
2036 consistent gets
0 physical reads
992 redo size
707454 bytes sent via SQL*Net to client
296624 bytes received via SQL*Net from client
2002 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1000 rows processed
================
Enpty CLOB fetch
================
1000 rows selected.
Statistics
----------------------------------------------------------
3 recursive calls
5 db block gets
2036 consistent gets
0 physical reads
1048 redo size
585454 bytes sent via SQL*Net to client
296624 bytes received via SQL*Net from client
2002 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1000 rows processed
Key points to note (ignoring minor details like the recursive calls to parse the statements):
- The query for the the varchar2() column did two SQL*Net roundtrips and 75 consistent gets.
- The query for the small, inline, CLOB did 2,002 SQL*Net roundtrips and 2,036 consistent gets
- The query for the empty CLOB did exactly the same number of SQL*Net roundtrips and consistent gets as for the small CLOB
Because we were selecting a LOB column SQL*Plus switched from array fetches to single row fetches. In the first fetch of each pair of fetches it fetched the non-CLOB columns and the “LOB locator”; then in the second fetch of each pair it fetched the CLOB data – and it did this even when the LOB locator could (in principle) have told it that there was no data to fetch. (If you select both clob columns in the same query the number of SQL*Net roundtrips will go up to 3 per row in this test.)
Remember I said there was a difference between empty_clob() and NULL ? If you update the table to set c2 to null before running the query to select c2 you’ll see only 1,000 (and a few) SQL*Net roundtrips – you still get single row processing because you’re selecting a LOB column but when the NULL arrives at SQL*Plus the code will know that there is no LOB data to retrieve.
Now try this:
truncate table t1;
begin
for i in 1..1000 loop
insert into t1 values(i, lpad(i,60), lpad(i,180), empty_clob());
end loop;
commit;
end;
/
execute dbms_stats.gather_table_stats(null,'t1')
set long 170
select id, c1 from t1;
Pause for thought as you work out what the stats will look like
.
.
.
.
.
The longchunksize (still at the default of 80) is now too small to collect all the data that should be displayed in one SQL*Net roundtrip – it’s going to take 3 roundtrips to get 170 bytes, so we might expect to see about 4,000 SQL*Net roundtrips and a similar number of consistent gets. This is what the stats look like:
Statistics
----------------------------------------------------------
2 recursive calls
0 db block gets
4030 consistent gets
0 physical reads
0 redo size
1485454 bytes sent via SQL*Net to client
866624 bytes received via SQL*Net from client
4002 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1000 rows processed
Sure enough we do single row fetches, one SQL*Net roundtrip for each row with its LOB locator, then three more roundtrips for each LOB for a total of 4,000 round trips and (approximately) 4,000 consistent gets.
One last test – let’s change the c1 clob to nocache and disable storage in row then repeat the last experiment where the long setting is larger than the longchunksize setting.
alter table t1 move lob(c1) store as (disable storage in row nocache);
execute dbms_stats.gather_table_stats(null,'t1')
select id, c1 from t1;
Statistics
----------------------------------------------------------
2 recursive calls
0 db block gets
4001 consistent gets
6000 physical reads
0 redo size
1485454 bytes sent via SQL*Net to client
866624 bytes received via SQL*Net from client
4002 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1000 rows processed
Now there’s a surprise! I was expecting to see 3000 physical reads as each “out of row, nocache” LOB was accessed three times to pick up the three pieces of longchunksize using direct path reads. So why have I got 6,000 physical reads? Time to enable extended tracing (event 10046, level 8) and repeat.
Here’s a sample from the trace file – this trace is from 18.3, but the LOBREAD lines are a feature that appeared some time around 11.2.0.2.
FETCH #140355181475400:c=58,e=57,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3617692013,tim=5288719901 WAIT #140355181475400: nam='SQL*Net message from client' ela= 78 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288720015 WAIT #0: nam='direct path read' ela= 12 file number=2 first dba=2867 block cnt=1 obj#=132008 tim=5288720198 WAIT #0: nam='direct path read' ela= 8 file number=2 first dba=2867 block cnt=1 obj#=132008 tim=5288720288 WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288720326 LOBREAD: type=PERSISTENT LOB,bytes=80,c=247,e=246,p=2,cr=1,cu=0,tim=5288720350 WAIT #0: nam='SQL*Net message from client' ela= 82 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288720483 WAIT #0: nam='direct path read' ela= 12 file number=2 first dba=2867 block cnt=1 obj#=132008 tim=5288720733 WAIT #0: nam='direct path read' ela= 8 file number=2 first dba=2867 block cnt=1 obj#=132008 tim=5288720836 WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288720873 LOBREAD: type=PERSISTENT LOB,bytes=80,c=0,e=261,p=2,cr=1,cu=0,tim=5288720898 WAIT #0: nam='SQL*Net message from client' ela= 121 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288721071 WAIT #0: nam='direct path read' ela= 11 file number=2 first dba=2867 block cnt=1 obj#=132008 tim=5288721216 WAIT #0: nam='direct path read' ela= 8 file number=2 first dba=2867 block cnt=1 obj#=132008 tim=5288721300 WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288721335 LOBREAD: type=PERSISTENT LOB,bytes=20,c=0,e=236,p=2,cr=1,cu=0,tim=5288721359 WAIT #0: nam='SQL*Net message from client' ela= 73 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288721506 WAIT #140355181475400: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288721664 FETCH #140355181475400:c=51,e=51,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3617692013,tim=5288721695 WAIT #140355181475400: nam='SQL*Net message from client' ela= 74 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288721801 WAIT #0: nam='direct path read' ela= 12 file number=2 first dba=2868 block cnt=1 obj#=132008 tim=5288721939 WAIT #0: nam='direct path read' ela= 47 file number=2 first dba=2868 block cnt=1 obj#=132008 tim=5288722065 WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288722122 LOBREAD: type=PERSISTENT LOB,bytes=80,c=357,e=357,p=2,cr=1,cu=0,tim=5288722204 WAIT #0: nam='SQL*Net message from client' ela= 81 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288722351 WAIT #0: nam='direct path read' ela= 10 file number=2 first dba=2868 block cnt=1 obj#=132008 tim=5288722489 WAIT #0: nam='direct path read' ela= 11 file number=2 first dba=2868 block cnt=1 obj#=132008 tim=5288722671 WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288722720 LOBREAD: type=PERSISTENT LOB,bytes=80,c=0,e=349,p=2,cr=1,cu=0,tim=5288722746 WAIT #0: nam='SQL*Net message from client' ela= 76 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288722874 WAIT #0: nam='direct path read' ela= 11 file number=2 first dba=2868 block cnt=1 obj#=132008 tim=5288723013 WAIT #0: nam='direct path read' ela= 10 file number=2 first dba=2868 block cnt=1 obj#=132008 tim=5288723160 WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=132008 tim=5288723199 LOBREAD: type=PERSISTENT LOB,bytes=20,c=0,e=302,p=2,cr=1,cu=0,tim=5288723224
As you can see, the client seems to FETCH one row then do two direct path reads to read 80 bytes from a LOB, then another two direct path reads for the next 80 bytes, then another two direct path reads for the last 20 bytes. So the 6,000 reads is (strangely) doubling the 3,000 I was expecting to see and the trace file seems to say it’s really happening that way.
Unfortunately I decided to take snapshots of the session stats at this point – and that made things even worse (claiming, for example, 4,000 “consistent gets” but 7,000 “no work consistent gets”), the stats seem to be rather messed up and the whole thing looked very different when I ran this particular test on 12.1.0.2 (which claimed only one direct path read per CLOB rather than the three I was expecting).
Bottom line, though: notwithstanding any oddities of reporting, when your client progam is fetching LOBs from the database, you probably have to put up with:
single row fetches – that get the LOB locator then multiple fetches for each LOB, with the number of LOBREAD calls dependent on the buffer size the client allocates for pulling LOB data from the database.
So when handling LOBs make sure you know how the client can be configured to minimise SQL*Net roundtrips, and check a few simple examples looking at the the trace files, session stats and session events before you start loading data at production volumes.
Comments and related questions are welcome.