Progessive slow down when inserting into a table with a clob

Thanks for the question, Erik.

Asked: May 04, 2002 - 8:44 pm UTC

Last updated: September 16, 2010 - 2:43 pm UTC

Version: 8.1.7

Viewed 10K+ times! This question is

You Asked

Tom,

I'm using PL/SQL to load a new table that is going to contain an XML document stored in a CLOB. I have to build the XML document from data in an existing table in the same database, basically each column gets its own tag. The rate that new rows are being inserted into the table keeps dropping and I haven't been able to figure out why. When the table was empty and we started the load, about 2200 rows an hour were being inserted. The rate kept dropping though until only 100 rows an hour were being inserted. I stopped to procedure and restarted it with the primary key on. It seemed to speed up initially. It took 5 minutes to do the first 100, but then 15 minutes to do the next 100, and progressively slower.

The tables look something like this (but with more columns):

create table src(
doc_id number,
a varchar2(20),
b varchar2(30),
c clob);

create table dest(
doc_id number,
doc clob);

CREATE OR REPLACE PROCEDURE load_docs
as
v_clob clob := empty_clob();
v_counter number := 0;
v_tmp varchar2(1000);
cursor my_cursor is
select doc_id, a, b, c from src;

begin

FOR my_rec
IN my_cursor
LOOP
insert into dest(doc_id, doc)
values (my_rec.doc_id, EMPTY_CLOB())
returning doc into v_clob;

v_tmp := '<DOCUMENT>';
dbms_lob.writeAppend(v_clob,length(v_tmp),v_tmp);

v_tmp := '<A_TAG>' || my_rec.a || '</A_TAG>';
dbms_lob.writeAppend(v_clob,length(v_tmp),v_tmp);

v_tmp := '<B_TAG>' || my_rec.b || '</B_TAG>';
dbms_lob.writeAppend(v_clob,length(v_tmp),v_tmp);

v_tmp := '<C_TAG>';
dbms_lob.writeAppend(v_clob,length(v_tmp),v_tmp);

dbms_lob.append(v_clob,my_rec.c);

v_tmp := '</C_TAG></DOCUMENT>';
dbms_lob.writeAppend(v_clob,length(v_tmp),v_tmp);

if v_counter = 100
then
commit;
v_counter = 0;
end if;
end loop;

commit;

end load_docs;
/

One thought we had was that the returning clause on the insert needed a PK to avoid doing a full table scan (which would explain the progressively slower behavior). We added a PK after we stopped the load and then restarted, but got the same behavior.

The disk the DB is on is raid 5, which accounts for some slowness on writes but I would think that that should be a constant.

I need to run this for about 2 million records, and with this speed it's going to take a LONG time.

Do you have any idea what could be accounting for this progressive slowdown? I would appreciate any thoughts you would have on what might be causing this. Is it the procedure or is something not tuned correctly?

Thanks,

Erik

and Tom said...

Well, you are seeing the effect on the raid 5 and buffering.

When you start (after you pause for example), there are lots of log buffers/data buffers just sitting their. Now, you start going full bore. The log buffers/data buffers start filling up, you run out of them and we have to flush them (you make the problem worse by committing frequently -- worst thing you can do -- ESPECIALLY since your load doesn't appear to be restartable at all -- you cannot restart this process, you would have to truncate and do it over).

Make SURE your logs are not on raid 5.

Use statspack and/or tkprof (if you have my book read chapter 10) to find out what your major waits are for (log file sync I'll guess).

Avoid the undue overhead you incurr by going back and forth and back and forth.

My suggestion is as follows:

IF the result of the string concatenation will be 4000 characters or less, use this approach:

ops$tkyte@ORA817DEV.US.ORACLE.COM> set timing on
ops$tkyte@ORA817DEV.US.ORACLE.COM>
ops$tkyte@ORA817DEV.US.ORACLE.COM> create table t ( x int, y clob );

Table created.

Elapsed: 00:00:00.10
ops$tkyte@ORA817DEV.US.ORACLE.COM>
ops$tkyte@ORA817DEV.US.ORACLE.COM> alter table t NOLOGGING;

Table altered.

Elapsed: 00:00:00.03
ops$tkyte@ORA817DEV.US.ORACLE.COM> insert /*+ APPEND */ into t
2 select object_id,
3 '<document><a_tag>' || object_id || '</a_tag>' ||
4 '<b_tag>' || object_name || '</b_tag>' ||
5 '<c_tag>' || object_type || '</c_tag>' ||
6 '<d_tag>' || owner || '<d_tag><document>' data
7 from all_objects;

22916 rows created.

Elapsed: 00:00:07.70
ops$tkyte@ORA817DEV.US.ORACLE.COM> alter table t logging;

Table altered.

Do it in a single, nologged SQL insert into statement using the direct path hint (append). This will be far far superior to all other methods. Fastest approach you can take.

If not, at least do as much as you can in SQL and if the XML document will be 32k or less use this approach:

ops$tkyte@ORA817DEV.US.ORACLE.COM> create or replace procedure load_docs
2 as
3 type array is table of varchar2(4000) index by binary_integer;
4
5 l_object_id array;
6 l_data array;
7 l_empty array;
8
9 l_string varchar2(31000);
10
11 cursor my_cursor is select object_id,
12 '<a_tag>' || object_id || '</a_tag>' ||
13 '<b_tag>' || object_name || '</b_tag>' ||
14 '<c_tag>' || object_type || '</c_tag>' ||
15 '<d_tag>' || owner || '<d_tag>' data
16 from all_objects;

use as many "data" columns as you need. put together as many columns as you can safely without exceeding 4000 characters/column. Later, when we assemble l_string, we'll do that final concatenation

17
18 begin
19 open my_cursor;
20 loop
21 fetch my_cursor BULK COLLECT into l_object_id, l_data LIMIT 500;
22

bulk collect the data, avoid single row processing...

23 for i in 1 .. l_object_id.count
24 loop
25 l_string := '<document>' || l_data(i) || '</document>';
26 insert into t (x,y) values ( l_object_id(i), l_string );
27 end loop;
28

unfortunately, we cannot bulk insert into a clob -- but we can at least cut way down on the round trips (dbms_lob.writeappends, returning clauses and such)

29 exit when MY_CURSOR%NOTFOUND;
30 l_object_id := l_empty;
31 end loop;
32 close my_cursor;
33 commit;

Please, commit when you are done -- not in the middle!!! frequent commits will achieve this for you:

o you will run slower
o you will generate more overall redo log
o you will generate more overall rollback

34 end;
35 /

Procedure created.

Elapsed: 00:00:00.24
ops$tkyte@ORA817DEV.US.ORACLE.COM>
ops$tkyte@ORA817DEV.US.ORACLE.COM> exec load_docs

PL/SQL procedure successfully completed.

Elapsed: 00:00:16.15
ops$tkyte@ORA817DEV.US.ORACLE.COM>

As you can see.... the insert in a single statement will be your preferred method. Followed by more optimized plsql. If you can go with the insert append in a single statement, you can massively reduce the amount of IO you will do. If not, you will need to TUNE your logs (i'll guess with 80% certainty that they are your bottleneck here -- the progressive slow down is indicative of this and over time you are starting to wait even on dbwr as the buffer cache is filled and you get buffer busy waits).

Use statspack to find out what the biggy waits are.

Rating

(40 ratings)

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

Comments

Really helpful, as usual

Heraldo, January 24, 2003 - 8:45 am UTC

But I still have a little doubt about this,
In your example above you wrote:
insert /*+ APPEND */ into t
select object_id,
'<document><a_tag>' || object_id|| '</a_tag>' ||
'<b_tag>' || object_name || '</b_tag>' ||
'<c_tag>' || object_type || '</c_tag>' ||
'<d_tag>' || owner || '<d_tag><document>' data
from all_objects;
with t ( x int, y clob );
Acording Oracle it's not possible to do an direct-load over a table with a LOB column. If I'm rigth, we only could make a nologging insert, but not a direct-load. Am I wrong in my conclusions? If yes, could you please tell me why?
Thanks in advance.
Heraldo

January 24, 2003 - 9:14 am UTC

you are right -- in 8i, the append didn't do anything: ops$tkyte@ORA817DEV> create table t ( x int, y clob ); Table created. ops$tkyte@ORA817DEV> ops$tkyte@ORA817DEV> alter table t nologging; Table altered. ops$tkyte@ORA817DEV> ops$tkyte@ORA817DEV> insert /*+ APPEND */ into t 2 select object_id, 3 '<document><a_tag>' || object_id || '</a_tag>' || 4 '<b_tag>' || object_name || '</b_tag>' || 5 '<c_tag>' || object_type || '</c_tag>' || 6 '<d_tag>' || owner || '<d_tag><document>' data 7 from all_objects 8 where rownum = 1; 1 row created. ops$tkyte@ORA817DEV> ops$tkyte@ORA817DEV> select * from t where rownum = 1; X Y ---------- -------------------------------------------------------------------------------- 30791 <document><a_tag>30791</a_tag><b_tag>/1001a851_ConstantDefImpl</b_tag><c_tag>JAV A CLASS</c_tag><d_tag>SYS<d_tag><document> In 9iR2 -- it will: ops$tkyte@ORA920> insert /*+ APPEND */ into t 2 select object_id, 3 '<document><a_tag>' || object_id || '</a_tag>' || 4 '<b_tag>' || object_name || '</b_tag>' || 5 '<c_tag>' || object_type || '</c_tag>' || 6 '<d_tag>' || owner || '<d_tag><document>' data 7 from all_objects 8 where rownum = 1; 1 row created. ops$tkyte@ORA920> ops$tkyte@ORA920> select * from t where rownum = 1; select * from t where rownum = 1 * ERROR at line 1: ORA-12838: cannot read/modify an object after modifying it in parallel <b>that last bit shows we did the direct path stuff</b> but you could use a nocache/nologging CLOB to force a direct write of the clob data if it exceeds 4k or is always stored out of line.

what to do when there is lots of 'direct path write (lob)' wait?

Winston, October 01, 2003 - 9:08 pm UTC

Hi Tom,

I adopted your strategy on 8.1.7.4.0.. alter table <> nologging; and then do insert /*+ append */ select from a table.

But I still see a lot of 'direct path write (lob)' events.

1 SELECT event, state, wait_time, p1, p2, p3
2 FROM v$session_wait
3 WHERE event= 'direct path write (lob)'
4* and sid=45

EVENT STATE WAIT_TIME P1 P2 P3
--------------- ---------- ---------- ---------- ---------- ----------
direct path wri WAITING 0 16 771984 1
te (lob)

1 SELECT segment_name, segment_type
2 FROM dba_extents
3 WHERE file_id =16
4* AND 771984 BETWEEN block_id AND block_id + blocks -1

SEGMENT_NAME SEGMENT_TYPE
------------------------------ --------------------
SYS_LOB0000030826C00006$$ LOB PARTITION

Thanks a lot!

October 02, 2003 - 7:37 am UTC

and you expected not to? not sure what your question would be here.

You appear to have a LOB (guess on my part, incomplete data)

a direct path insert into a nologging table would avoid redo/undo generation -- but why would you expect it to stop writing the LOB for you?

more information provided

Winston, October 02, 2003 - 12:41 pm UTC

I need to convert non-partitioned table1 to partitioned table2 for easy management.
Table1 and table2 have similar structure and they both contain CLOB field.
Table1 contains 1.2M rows. I created table2 and set it to nologging, then insert /*+ append */ into table2 select * from table1.
It took very long time to move data over (more than 15 hours now but still doing).

I used the above SQL statements to see what that session was waiting on and I found out it was 'direct path write (lob)'. I wonder if there is anything we can do to reduce the waits on 'direct path write (lob)'

October 02, 2003 - 4:45 pm UTC

how *big* is the table itself. 1.2 m rows could be anywhere between about 2meg and infinity. How much data are we talking about.

how good are your disks? the direct path write on the lob is simply the writing of the lob data to disk. you must be using non-cached lobs -- they are not hitting the buffer cache. You may find using a cached lob to be "faster" as DBWR will be doing the writes in the background.

Result of show_space after analyzing the table

Winston, October 02, 2003 - 5:58 pm UTC

winstonz@WZHG> exec show_space('TABLE1');
Free Blocks.............................11616
Total Blocks............................397440
Total Bytes.............................3255828480
Unused Blocks...........................6207
Unused Bytes............................50847744
Last Used Ext FileId....................19
Last Used Ext BlockId...................743561
Last Used Block.........................1985

PL/SQL procedure successfully completed.

winstonz@WZHG> SELECT (397440-11616-6207)*8/1024 FROM DUAL;

(397440-11616-6207)*8/1024
--------------------------
2965.75781

almost 3GB..

Please tell me how to measure 'how good the disks are' so that we can judge whether it should take so long time to move the data over?

October 02, 2003 - 6:53 pm UTC

thats 3gig of table data.

Now, hows about the LOB data which is probably stored OUT OF LINE in a lob segment :)

and the lob index, which is stored separately as well.

you bought the disks -- are they "good fast, and lots of them" or "big slow single disk that was cheap".

if you monitor IO at the OS level, are you hitting or getting near the throughput for your disks

This is getting more interesting

Winston, October 02, 2003 - 7:58 pm UTC

I am sure that most rows' LOB data were stored in line because most of them are smaller than 4K.
and I don't have any index on the partitioned target table (the table we're writing to), but I noticed Oracle create one for me. I don't know how to size this index since Oracle is still writing to using /*+ APPEND */
winstonz@WZHG> select index_name, partitioned,
2 num_rows, sample_size from user_indexes where table_name='TABLE2';

INDEX_NAME PAR NUM_ROWS SAMPLE_SIZE
------------------------------ --- ---------- -----------
SYS_IL0000030826C00006$$ YES

I ran the OS commands in doc id 1005636.6
and surprisingly I found out that my diskS are not busy at all...

sar -b 5 5

SunOS sedm1065p 5.8 Generic_108528-13 sun4u 10/02/03

23:16:56 bread/s lread/s %rcache bwrit/s lwrit/s %wcache pread/s pwrit/s
23:17:02 0 45 100 2 3 40 1 0
23:17:07 0 27 100 0 0 0 0 0
23:17:12 0 114 100 1 1 0 0 0
23:17:17 0 13 100 0 0 100 0 0
23:17:22 0 25 100 0 1 67 0 0

Average 0 45 100 1 1 38 0 0

iostat -d 5 5
sd6 sd15 sd52 sd53
kps tps serv kps tps serv kps tps serv kps tps serv
0 0 0 0 0 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0 0 0 0

sar -d 5 5 showed me that all the devices' busy% is lower than 5% (most of them are 0 )

My question is what can we check further to see why writing into a table containing CLOB is so slow?

Finally I got your new book, it's very well-written! but it didnt' cover the question above:)

Thank you Tom for your time, I really appreciate it!

October 03, 2003 - 8:00 am UTC

do a 10046 level 12 trace -- do the insert append with just a couple thousand rows (where rownum < N)

also, do an exp of the "new" table with rows=n followed by an imp of that with show=y and post the DDL for the table you are adding to.

10046 trace

Winston, October 03, 2003 - 2:01 pm UTC

insert /*+ APPEND */ into table2
select MESSAGE_QUEUE_ID ,
MESSAGE_TIMESTAMP ,
RECORD_INSERT_TIME ,
nvl(SUCCESS_FLAG,:"SYS_B_0") as success_flag ,
RETRY ,
XML_MESSAGE from message_queue
where rownum<:"SYS_B_1"

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 38.48 78.77 1154 6405 3496 2999
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 38.48 78.77 1154 6405 3496 2999

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 55

Details in trace file
=====================
PARSING IN CURSOR #4 len=119 dep=1 uid=0 oct=6 lid=0 tim=3440971332 hv=1425443843 ad='a3fe25d8'
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9 wher
e obj#=:1
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3440971332
BINDS #4:
bind 0: dty=2 mxl=22(02) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=24 offset=0
bfp=101ecddd8 bln=24 avl=02 flg=05
value=50
bind 1: dty=2 mxl=22(02) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=24 offset=0
bfp=101ecdda8 bln=24 avl=02 flg=05
value=1
bind 2: dty=2 mxl=22(15) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=24 offset=0
bfp=101ecdd78 bln=24 avl=15 flg=05
value=999999999999999999999999999
bind 3: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=101ecdd48 bln=24 avl=01 flg=05
value=0
bind 4: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=101ecdd08 bln=24 avl=01 flg=05
value=0
bind 5: dty=2 mxl=22(02) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=24 offset=0
bfp=101ecdb48 bln=24 avl=02 flg=05
value=20
bind 6: dty=2 mxl=22(05) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=24 offset=0
bfp=101ecdb18 bln=24 avl=05 flg=05
value=7206151
bind 7: dty=1 mxl=32(32) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=32 offset=0
bfp=101ecdae0 bln=32 avl=32 flg=05
value="--------------------------------"
bind 8: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=101ecde08 bln=22 avl=03 flg=05
value=373
EXEC #4:c=0,e=0,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=4,tim=3440971332
STAT #4 id=1 cnt=1 pid=0 pos=0 obj=0 op='UPDATE SEQ$ '
STAT #4 id=2 cnt=1 pid=1 pos=1 obj=99 op='INDEX UNIQUE SCAN '
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40475 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40476 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40477 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40478 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40479 p3=16
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=6 p2=112616 p3=1
WAIT #3: nam='log buffer space' ela= 1 p1=0 p2=0 p3=0
WAIT #3: nam='direct path write (lob)' ela= 200 p1=16 p2=850779 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40495 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40496 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40497 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40498 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40499 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40500 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40501 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40502 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40503 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40504 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40505 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40506 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40507 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40508 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40511 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40509 p3=2
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40512 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40513 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40514 p3=2
WAIT #3: nam='direct path read (lob) ' ela= 1 p1=19 p2=265234 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 30 p1=6 p2=69911 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=216040 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=20 p2=270015 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=265217 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=265233 p3=1
WAIT #3: nam='direct path write (lob)' ela= 223 p1=6 p2=750596 p3=5
WAIT #3: nam='direct path write (lob)' ela= 0 p1=16 p2=850785 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40518 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=265232 p3=1
WAIT #3: nam='direct path write (lob)' ela= 124 p1=16 p2=850780 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40521 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40522 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40523 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40525 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40524 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40526 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40527 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40528 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40529 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40530 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40531 p3=16
WAIT #3: nam='latch free' ela= 2 p1=15032453248 p2=95 p3=0
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40547 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40548 p3=16
WAIT #3: nam='log buffer space' ela= 2 p1=0 p2=0 p3=0
WAIT #3: nam='db file sequential read' ela= 0 p1=19 p2=40564 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40565 p3=16
WAIT #3: nam='log buffer space' ela= 0 p1=0 p2=0 p3=0
WAIT #3: nam='log buffer space' ela= 0 p1=0 p2=0 p3=0
WAIT #3: nam='log buffer space' ela= 0 p1=0 p2=0 p3=0
WAIT #3: nam='db file scattered read' ela= 0 p1=19 p2=40581 p3=4
WAIT #3: nam='log buffer space' ela= 1 p1=0 p2=0 p3=0
WAIT #3: nam='db file sequential read' ela= 123 p1=20 p2=45065 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45066 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=20 p2=45067 p3=2
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45070 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=6 p2=112606 p3=1
WAIT #3: nam='direct path write (lob)' ela= 133 p1=16 p2=850781 p3=1
WAIT #3: nam='db file sequential read' ela= 16 p1=20 p2=45072 p3=1
WAIT #3: nam='log buffer space' ela= 1 p1=0 p2=0 p3=0
WAIT #3: nam='db file sequential read' ela= 1 p1=20 p2=45073 p3=1
WAIT #3: nam='log buffer space' ela= 1 p1=0 p2=0 p3=0
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45074 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45075 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45081 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45077 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45079 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45078 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45080 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45082 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45083 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45085 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45084 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45086 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45087 p3=1
WAIT #3: nam='log buffer space' ela= 0 p1=0 p2=0 p3=0
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=362422 p3=1
WAIT #3: nam='direct path write (lob)' ela= 131 p1=16 p2=850782 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=362474 p3=1
WAIT #3: nam='direct path write (lob)' ela= 141 p1=16 p2=850783 p3=1
WAIT #3: nam='db file sequential read' ela= 15 p1=20 p2=45091 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45090 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45093 p3=1
WAIT #3: nam='db file sequential read' ela= 1 p1=20 p2=45092 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45094 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45096 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45095 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45098 p3=1
WAIT #3: nam='log buffer space' ela= 0 p1=0 p2=0 p3=0
WAIT #3: nam='log buffer space' ela= 3 p1=0 p2=0 p3=0
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45099 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45097 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45100 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45101 p3=1
WAIT #3: nam='log buffer space' ela= 0 p1=0 p2=0 p3=0
WAIT #3: nam='db file sequential read' ela= 134 p1=20 p2=45105 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45104 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45107 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45106 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45108 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=20 p2=45109 p3=16
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45125 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 103 p1=6 p2=105494 p3=1
WAIT #3: nam='direct path write (lob)' ela= 116 p1=16 p2=850784 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 0 p1=19 p2=265224 p3=1
WAIT #3: nam='direct path write (lob)' ela= 125 p1=16 p2=850801 p3=1
WAIT #3: nam='db file sequential read' ela= 130 p1=20 p2=45129 p3=1
WAIT #3: nam='db file sequential read' ela= 2 p1=20 p2=45130 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850887 p3=1
WAIT #3: nam='db file scattered read' ela= 133 p1=20 p2=45131 p3=16
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850888 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850889 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850890 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850891 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850892 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850893 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850894 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850895 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850896 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850897 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850898 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850899 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850900 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850901 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850902 p3=1
WAIT #3: nam='db file sequential read' ela= 138 p1=20 p2=45148 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850903 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45147 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45149 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850904 p3=1
WAIT #3: nam='latch free' ela= 0 p1=15546021344 p2=106 p3=0
WAIT #3: nam='latch free' ela= 0 p1=15546021344 p2=106 p3=1
WAIT #3: nam='latch free' ela= 0 p1=15546021344 p2=106 p3=2
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45150 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850905 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850906 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850907 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45151 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850908 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45154 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850909 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=20 p2=45152 p3=2
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850910 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45156 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850911 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=20 p2=45155 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850912 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850913 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850914 p3=1
WAIT #3: nam='db file scattered read' ela= 0 p1=20 p2=45157 p3=11
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850915 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850916 p3=1
WAIT #3: nam='direct path read (lob) ' ela= 105 p1=6 p2=105485 p3=1
WAIT #3: nam='direct path write (lob)' ela= 121 p1=16 p2=850802 p3=1
WAIT #3: nam='db file sequential read' ela= 0 p1=16 p2=850917 p3=1
=====================
Summary:

Event Times Count Max. Total
waited on Waited Zero Time Wait Waited
--------------------------------------------- ------- --------- ------ ------
direct path write (lob)...................... 31 1 2.23 40.50
db file sequential read (single block scan).. 533 488 1.42 21.80
direct path read (lob) ...................... 35 26 1.36 6.17
log buffer space............................. 38 16 0.94 2.24
db file scattered read (multiblock full scan) 63 53 1.33 1.65
latch free (095 row cache objects)........... 5 0 0.02 0.07
file open.................................... 4 4 0.00 0.00
latch free (106 library cache)............... 6 6 0.00 0.00
SQL*Net message from client (idle)........... 1 0 0.03 0.03
SQL*Net message to client (idle)............. 1 1 0.00 0.00
--------------------------------------------- ----- --------- ------ ------
total........................................ 717 595 2.23 72.46
non-idle waits............................... 715 594 2.23 72.43
idle waits................................... 2 1 0.03 0.03

October 03, 2003 - 4:12 pm UTC

ok, since we do direct read/writes on out of line lobs -- I have a feeling your lobs are "bigger" then you think.

what is the output of:

select
avg( dbms_lob.getlength( XML_MESSAGE ) ),
min( dbms_lob.getlength( XML_MESSAGE ) ),
max( dbms_lob.getlength( XML_MESSAGE ) ),
count( case when dbms_log.getlength(xml_message) > 4000 then 1 else null end ),
count( xml_message )
from message_queue
where rownum< 3000;

you might consider "cache" on the lobs -- you can "uncache" them later.

did a small test with a 5000 byte lob, here is NOCACHE:

insert /*+ append */ into t2
select * from t

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 38.61 290.85 32768 100184 170857 32768
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 38.61 290.85 32768 100184 170857 32768

with biggest waits on direct path read (lob) direct path write (lob). with cache:

insert /*+ append */ into t2
select * from t

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 25.53 177.82 33044 100231 203544 32768
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 25.53 177.82 33044 100231 203544 32768

with no direct path write (lob) waits.

DDL

Winston, October 03, 2003 - 2:03 pm UTC

"CREATE TABLE "TABLE2" ("MESSAGE_QUEUE_ID" NUMBER(38, 0) NOT NULL ENAB"
"LE, "MESSAGE_TIMESTAMP" DATE, "RECORD_INSERT_TIME" DATE, "SUCCESS_FLAG" NUM"
"BER(3, 0), "RETRY" NUMBER(3, 0), "XML_MESSAGE" CLOB) PCTFREE 10 PCTUSED 40"
" INITRANS 1 MAXTRANS 255 NOLOGGING TABLESPACE "SWSPDA_01" LOB (XML_MESSAGE)"
" STORE AS (ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STORAGE"
"( BUFFER_POOL DEFAULT)) PARTITION BY RANGE ("SUCCESS_FLAG" ) (PARTITION "P"
"0" VALUES LESS THAN (1) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STOR"
"AGE(INITIAL 65536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE"
" AS (TABLESPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10"
" NOCACHE STORAGE(INITIAL 65536)), PARTITION "P1" VALUES LESS THAN (10) PC"
"TFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65536) TABLESPA"
"CE "SWSPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01"
"" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STORAGE(INITIAL 6"
"5536)), PARTITION "P2" VALUES LESS THAN (40) PCTFREE 10 PCTUSED 40 INITRAN"
"S 1 MAXTRANS 255 STORAGE(INITIAL 65536) TABLESPACE "SWSPDA_01" NOLOGGING LO"
"B (XML_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHU"
"NK 8192 PCTVERSION 10 NOCACHE STORAGE(INITIAL 65536)), PARTITION "P3" VALU"
"ES LESS THAN (70) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(IN"
"ITIAL 65536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS ("
"TABLESPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCAC"
"HE STORAGE(INITIAL 65536)), PARTITION "P4" VALUES LESS THAN (80) PCTFREE "
"10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65536) TABLESPACE "SW"
"SPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENAB"
"LE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STORAGE(INITIAL 65536))"
", PARTITION "P5" VALUES LESS THAN (90) PCTFREE 10 PCTUSED 40 INITRANS 1 MA"
"XTRANS 255 STORAGE(INITIAL 65536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML"
"_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 819"
"2 PCTVERSION 10 NOCACHE STORAGE(INITIAL 65536)), PARTITION "P6" VALUES LES"
"S THAN (100) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL"
" 65536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLE"
"SPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE S"
"TORAGE(INITIAL 65536)), PARTITION "P7" VALUES LESS THAN (110) PCTFREE 10 P"
"CTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65536) TABLESPACE "SWSPDA"
"_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABLE S"
"TORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STORAGE(INITIAL 65536)), PA"
"RTITION "P8" VALUES LESS THAN (120) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTR"
"ANS 255 STORAGE(INITIAL 65536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_ME"
"SSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 P"
"CTVERSION 10 NOCACHE STORAGE(INITIAL 65536)), PARTITION "P9" VALUES LESS T"
"HAN (130) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65"
"536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPA"
"CE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STOR"
"AGE(INITIAL 65536)), PARTITION "P10" VALUES LESS THAN (140) PCTFREE 10 PCT"
"USED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65536) TABLESPACE "SWSPDA_0"
"1" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABLE STO"
"RAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STORAGE(INITIAL 65536)), PART"
"ITION "P11" VALUES LESS THAN (150) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRA"
"NS 255 STORAGE(INITIAL 65536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_MES"
"SAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 PC"
"TVERSION 10 NOCACHE STORAGE(INITIAL 65536)), PARTITION "P12" VALUES LESS T"
"HAN (160) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65"
"536) TABLESPACE "SWSPDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPA"
"CE "SWSPDA_01" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STOR"
"AGE(INITIAL 65536)), PARTITION "P13" VALUES LESS THAN (MAXVALUE) PCTFREE 1"
"0 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE(INITIAL 65536) TABLESPACE "SWS"
"PDA_01" NOLOGGING LOB (XML_MESSAGE) STORE AS (TABLESPACE "SWSPDA_01" ENABL"
"E STORAGE IN ROW CHUNK 8192 PCTVERSION 10 NOCACHE STORAGE(INITIAL 65536)) "
")"

output of the query

Winston, October 03, 2003 - 5:08 pm UTC

winstonz@WZHG> select
2 avg( dbms_lob.getlength( XML_MESSAGE ) ) as avglength,
3 min( dbms_lob.getlength( XML_MESSAGE ) ) as minlength ,
4 max( dbms_lob.getlength( XML_MESSAGE ) ) as maxlength ,
5 count( case when dbms_lob.getlength(xml_message) > 4000 then 1 else null end ) as numlarger ,
6 count( xml_message ) as totalmsg
7 from message_queue
8 where rownum< 3000;
count( xml_message ) as totalmsg
*
ERROR at line 6:
ORA-00932: inconsistent datatypes

winstonz@WZHG> select
2 avg( dbms_lob.getlength( XML_MESSAGE ) ) as avglength,
3 min( dbms_lob.getlength( XML_MESSAGE ) ) as minlength ,
4 max( dbms_lob.getlength( XML_MESSAGE ) ) as maxlength ,
5 count( case when dbms_lob.getlength(xml_message) > 4000 then 1 else null end ) as numlarger ,
6 count( * ) as totalmsg
7 from message_queue
8 where rownum< 3000;

AVGLENGTH MINLENGTH MAXLENGTH NUMLARGER TOTALMSG
--------- --------- --------- --------- --------
1,878.13 1,343.00 ######### 30 2,999

winstonz@WZHG> column maxlength format 9,999,999,999
winstonz@WZHG> /

AVGLENGTH MINLENGTH MAXLENGTH NUMLARGER TOTALMSG
--------- --------- -------------- --------- --------
1,878.13 1,343.00 42,602 30 2,999

winstonz@WZHG> ed
Wrote file afiedt.buf

1 select
2 avg( dbms_lob.getlength( XML_MESSAGE ) ) as avglength,
3 min( dbms_lob.getlength( XML_MESSAGE ) ) as minlength ,
4 max( dbms_lob.getlength( XML_MESSAGE ) ) as maxlength ,
5 count( case when dbms_lob.getlength(xml_message) > 4000 then 1 else null end ) as numlarger ,
6 count( * ) as totalmsg
7 from message_queue
8* where rownum< 6000
winstonz@WZHG> /

AVGLENGTH MINLENGTH MAXLENGTH NUMLARGER TOTALMSG
--------- --------- -------------- --------- --------
1,864.09 1,163.00 42,602 65 5,999

winstonz@WZHG> ed
Wrote file afiedt.buf

1 select
2 avg( dbms_lob.getlength( XML_MESSAGE ) ) as avglength,
3 min( dbms_lob.getlength( XML_MESSAGE ) ) as minlength ,
4 max( dbms_lob.getlength( XML_MESSAGE ) ) as maxlength ,
5 count( case when dbms_lob.getlength(xml_message) > 4000 then 1 else null end ) as numlarger ,
6 count( * ) as totalmsg
7 from message_queue
8* where rownum< 12000
winstonz@WZHG> /

AVGLENGTH MINLENGTH MAXLENGTH NUMLARGER TOTALMSG
--------- --------- -------------- --------- --------
1,913.62 1,158.00 42,602 241 ######

winstonz@WZHG>
so only about 1~2% rows contain bigger LOB.

direct path write (lob) is totally gone

Winston, October 03, 2003 - 5:47 pm UTC

Thank you very much, Tom!

Now the tkprof changed to

insert /*+ APPEND */ into table3
select MESSAGE_QUEUE_ID ,
MESSAGE_TIMESTAMP ,
RECORD_INSERT_TIME ,
nvl(SUCCESS_FLAG,:"SYS_B_0") as success_flag ,
RETRY ,
XML_MESSAGE from message_queue
where rownum<:"SYS_B_1"

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.03 0.02 0 0 0 0
Execute 1 1.25 30.79 914 6389 5876 2999
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1.28 30.81 914 6389 5876 2999

and the top waits are on
db file sequential read (single block scan) --19.68
and direct path read (lob) --9.57

One thing I don't understand is why in your small test case you have biggest waits on 'direct path read (lob)' but mine is on 'db file sequential read'?

October 04, 2003 - 9:48 am UTC

I made 100% of my lobs incurr a direct path read.

you did not.

so, I had lots of them and you had fewer.

You book did mention about 'direct path write'

Winston, October 04, 2003 - 7:18 pm UTC

I read your book Chapter 2 again and I found out that you did mention uncached LOBs can cause the direct path write on page 151.

I wonder how you made 100% of your lobs incurr a direct path read? And in your test case there is huge difference between cpu and elapsed, how can you bring it down?

Thanks a lot!

October 04, 2003 - 7:26 pm UTC

... did a small test with a 5000 byte lob, here is NOCACHE: ....

5000 byte lobs will be stored OUT OF LINE, anything out of line in a nocache lob will be "direct path read"

to descrease the cpu/elapsed -- I would buy faster disks -- this was a simple, small desktop pc, not a "server" -- single ATA drive, nothing fancy.

Insert a clob errer

Yong, May 06, 2004 - 5:09 pm UTC

Tom,

I am doing a similar thing like your side to allow user to past text on a form and save to database. My problem is for small mount of text it works, for large text I got pl/sql numerical error. Here is my code

procedure add_form(v_task_id number) is
v_project_id number;
begin
select project_id into v_project_id from tasks where task_id=v_task_id and rownum=1;

htp.p('<link rel=stylesheet href="helper.css">
<title>Add Work Logs</title>
<script>
function FormSubmit(form) {
if ((form.v_content.value.length < 1) ) {
alert("Please enter content!");
form.v_content.focus();
return false;
}
form.submit();
return true;
}
</script>
<table><tr><td align=right>Project Name:</td><td>'||project.get_name(v_project_id)||'</td></tr>
<tr><td align=right>Taks Name:</td><td>'||task.get_name(v_task_id)||'</td></tr>
<tr><td align=right>Current User</td><td>'||security.get_userid||'</td><td>Current Date: '||to_char(sysdate,'mm/dd/yyyy hh24:mi:ss')||'</td></tr></table>
<form action=WORK_LOG.add_log method=post>
<input type=hidden name=v_task_id value="'||v_task_id||'">
<table border=0 cellspacing=1 cellpadding=1>
<tr><td valign=top align=right>Content:</td>
<td><textarea name=v_content cols=56 rows=24></textarea></td></tr>
<tr><td>&nbsp</td><td align=center><input type=button VALUE="Save" onClick="FormSubmit(this.form);">      
<input type=button value=Close OnClick=window.close();></td></tr>
</table></form>');
exception when others then
htp.p('Error in '||owa_util.get_procedure||': '||sqlerrm);
end;
/*=====*/
procedure add_log(v_task_id number,v_content clob) is
v_clob clob := empty_clob();
begin
insert into work_logs(log_id,task_id,created_by,content)
values(log_id_seq.nextval,v_task_id,security.get_userid,empty_clob())
returning content into v_clob;
dbms_lob.writeAppend(v_clob,length(v_content),v_content);
commit;
show(v_task_id);
end;

work_log has a clob column, content.

Please let me know if you find the problem.

thanks,

Yong

May 07, 2004 - 7:00 am UTC

v_content should be a long:

add_log(v_task_id number,v_content LONG )

it will be limited to 32k (with nothing to be done to change that limit, short of using FILE UPLOAD instead of a text area).

Yong, May 07, 2004 - 1:02 pm UTC

it is working now after setting Long as input parameter.

Thanks,

Yong

dbms_lob.getlength is slow

Vidya, June 29, 2004 - 3:28 pm UTC

Hi Tom,
I have a table with a blob column and when I do

select count(*) from <tablename>
where dbms_lob.getlength(<columnname>) = 0

it takes a considerable amount of time. Pls let me know how I can speed it up.
Thanks.

June 29, 2004 - 4:31 pm UTC

well, you are asking it to read each and every blob -- that is going to take some amount of time.

it has to hop from the table to the lob index, add them all up. lots of single block reads going on there.

to Vidya

A reader, June 29, 2004 - 4:56 pm UTC

May be you could retain the column as null instead
of empty_clob()? Then you could use
select count(*) from <tablename>
where <column_name> is null

which may be faster..

just a thought...

null blobs

Vidya, June 30, 2004 - 9:00 am UTC

Yeah, I want to make those columns as null but they are empty_blob() and I have about 16 million rows in that table. In that process I am facing this problem.

Thanks.

June 30, 2004 - 10:36 am UTC

you can use Do It Yourself (DIY) parallelism.

</code> http://asktom.oracle.com/pls/asktom/f?p=100:11:::::P11_QUESTION_ID:10498431232211 <code>

you have to hop from each and every row over to the lob index - there is no avoiding that. You can speed it up by breaking the problem up into bit sized chunks and running the process in parallel.

object no longer exists error

Vidya, July 01, 2004 - 11:33 am UTC

Hi Tom,

As per ur suggestion, I am trying to give the updates in parallel sessions. Now, assuming in my table, I have the desired empty_blob() at id 10003, I have start and stop ids as between 1 and 100, 101-200..etc. When i come to the range of 10000-10100, I am getting an error
ORA-08103: object no longer exists
ORA-06512: at "SYS.DBMS_LOB", line 535
at the line which has the statement dbms_lob.getlength(columnname).
what is the problem? Pls help.

Thanks.

July 01, 2004 - 7:42 pm UTC

use rowid ranges as suggested, since I cannot see your logic, I cannot really debug it.

rowid ranges will create non-overlapping ranges that cover the entire table.

Slow Blob writing?

Ian, January 11, 2005 - 5:52 am UTC

I am referring to the original question. I too have slow Blob writing issues. I have the following procedure which captures text data and converts it into a readable rich text format:

CREATE OR REPLACE PROCEDURE p_image (p_blob IN OUT BLOB, p_char IN VARCHAR2)
IS
v_raw RAW (4000);
v_varchar2 VARCHAR2 (4000);
BEGIN
v_raw := NULL;
v_varchar2 := '';

IF p_char IS NOT NULL
THEN
FOR i IN 1 .. LENGTH (p_char)
LOOP
v_varchar2 := v_varchar2 || TRIM (TO_CHAR (ASCII (SUBSTR (p_char, i, 1) ), 'xxxx') );
v_varchar2 := v_varchar2 || '00';
END LOOP;

v_raw := HEXTORAW (v_varchar2);
DBMS_LOB.writeappend (p_blob, LENGTH (v_raw) / 2, v_raw);
END IF;
EXCEPTION
WHEN OTHERS
THEN
RAISE;
END p_image;
/

The p_blob output is inserted/updated on a table containing a blob field.

Unfortunately it loops through the length of the text data inserting '00' between each byte.

1. I would like to avoid as much overhead as possible. Can the loop processing be re-written as SQL in some way?

2. Is there an efficient way of converting this data in parallel?

Please provide examples, thanks?

January 11, 2005 - 10:27 am UTC

well, not sure that this is a "blob is slow to write" problem or "substringing and converting chews cpu" if you have 10g: ops$tkyte@ORA10G> CREATE OR REPLACE PROCEDURE p_image1( p_char IN VARCHAR2) 2 IS 3 v_raw RAW (4000); 4 v_varchar2 VARCHAR2 (4000); 5 BEGIN 6 v_raw := NULL; 7 v_varchar2 := ''; 8 9 IF p_char IS NOT NULL 10 THEN 11 FOR i IN 1 .. LENGTH (p_char) 12 LOOP 13 v_varchar2 := v_varchar2 || TRIM (TO_CHAR (ASCII (SUBSTR (p_char, i, 1) ), 'xxxx') ); 14 v_varchar2 := v_varchar2 || '00'; 15 END LOOP; 16 end if; 17 END p_image1; 18 / Procedure created. ops$tkyte@ORA10G> CREATE OR REPLACE PROCEDURE p_image2( p_char IN VARCHAR2) 2 IS 3 l_output long; 4 BEGIN 5 l_output := utl_raw.cast_to_raw( regexp_replace( 'hello', '(.)', '\1'||chr(0) ) ); 6 end; 7 / Procedure created. ops$tkyte@ORA10G> ops$tkyte@ORA10G> exec runStats_pkg.rs_start; PL/SQL procedure successfully completed. ops$tkyte@ORA10G> exec for i in 1 .. 10000 loop p_image1( rpad( 'x', 200, 'x' ) ); end loop; PL/SQL procedure successfully completed. ops$tkyte@ORA10G> exec runStats_pkg.rs_middle; PL/SQL procedure successfully completed. ops$tkyte@ORA10G> exec for i in 1 .. 10000 loop p_image2( rpad( 'x', 200, 'x' ) ); end loop; PL/SQL procedure successfully completed. ops$tkyte@ORA10G> exec runStats_pkg.rs_stop(1000000); Run1 ran in 375 hsecs Run2 ran in 43 hsecs run 1 ran in 872.09% of the time the regexp_replace will be very useful. In 9i, you can still tune the algorithm greatly: ops$tkyte@ORA9IR2> CREATE OR REPLACE PROCEDURE p_image2( p_char IN VARCHAR2) 2 IS 3 l_temp long; 4 l_n number := length(p_char)-1; 5 l_output long; 6 BEGIN 7 l_temp := utl_raw.cast_to_raw( p_char ); 8 for i in 0 .. l_n 9 loop 10 l_output := l_output || substr( l_temp, 1+(i*2), 2 ) || '00'; 11 end loop; 12 end; 13 / Procedure created. ops$tkyte@ORA9IR2> ops$tkyte@ORA9IR2> exec runStats_pkg.rs_start; PL/SQL procedure successfully completed. ops$tkyte@ORA9IR2> exec for i in 1 .. 10000 loop p_image1( rpad( 'x', 200, 'x' ) ); end loop; PL/SQL procedure successfully completed. ops$tkyte@ORA9IR2> exec runStats_pkg.rs_middle; PL/SQL procedure successfully completed. ops$tkyte@ORA9IR2> exec for i in 1 .. 10000 loop p_image2( rpad( 'x', 200, 'x' ) ); end loop; PL/SQL procedure successfully completed. ops$tkyte@ORA9IR2> exec runStats_pkg.rs_stop(1000000); Run1 ran in 943 hsecs Run2 ran in 398 hsecs run 1 ran in 236.93% of the time <b>cool side note: this was done on the same box -- plsql in 10g is just that much faster - 943 hsecs in 9i, 375 in 10g -- so one way to tune is to upgrade. But then change the algorithm in 10g to incorporate the regexp and faster=even_more_so</b> As I don't know what your conversion process looks like, I cannot comment on parallelizing it -- i have to assume this is but a tiny piece of something much much larger.

Slow Blob writing: reply to followup

Ian, January 11, 2005 - 12:09 pm UTC

Thanks for your rapid reply. Yes you are right this is part of something larger. We are trying to insert 7 million rows into a table with one of the fields being a blob. The source data is varchar2 but we need to put the '00's to make it readable for a GUI app.

We are using 9iR2 and will not be upgrading to 10g yet (a shame). I implemented your 9i code and it speeded up performance by only 22%. This is because you missed out the step to writeappend the data to the blob field (p_blob - see my original post). You have used a LONG datatype for l_output. Is there a way to avoid using the DBMS_LOB.WRITEAPPEND proc and instead insert the contents of a LONG into a BLOB more efficiently/directly?

January 11, 2005 - 1:46 pm UTC

i didn't miss it, i skipped it :)

long is cool -- it is just a varchar2 subtype in plsql, I use it for "big strings"

is this the ENTIRE blob? or is this just part of a LARGER blob?

Slow Blob writing: reply to followup #2

Ian, January 12, 2005 - 4:18 am UTC

Yes, this will be the entire blob.

January 12, 2005 - 9:24 am UTC

since these are small, you could just: ops$tkyte@ORA9IR2> CREATE OR REPLACE FUNCTION convert_img( p_char IN VARCHAR2) return raw 2 IS 3 l_temp long; 4 l_n number := length(p_char)-1; 5 l_output long; 6 BEGIN 7 l_temp := utl_raw.cast_to_raw( p_char ); 8 for i in 0 .. l_n 9 loop 10 l_output := l_output || substr( l_temp, 1+(i*2), 2 ) || '00'; 11 end loop; 12 return hextoraw(l_output); 13 end; 14 / Function created. Elapsed: 00:00:00.04 ops$tkyte@ORA9IR2> drop table t; Table dropped. Elapsed: 00:00:00.62 ops$tkyte@ORA9IR2> create table t 2 as 3 select rpad( object_name, 999 ) || 'x' text, a.* 4 from all_objects a; Table created. Elapsed: 00:00:02.10 ops$tkyte@ORA9IR2> ops$tkyte@ORA9IR2> alter table t add rtf blob lob(rtf) store as ( tablespace users cache ); Table altered. Elapsed: 00:00:00.01 ops$tkyte@ORA9IR2> ops$tkyte@ORA9IR2> declare 2 dummy raw(4000); 3 begin 4 for x in ( select text from t ) 5 loop 6 dummy := convert_img(x.text); 7 end loop; 8 end; 9 / PL/SQL procedure successfully completed. Elapsed: 00:01:11.13 <b>there is just here to show you that the vast preponderance of time is not in the blob activity...</b> ops$tkyte@ORA9IR2> ops$tkyte@ORA9IR2> update t set rtf = convert_img(text); 27939 rows updated. Elapsed: 00:01:20.82 ops$tkyte@ORA9IR2> <b>if you have the CPU, and the table is in many extents (which is a good thing -- having many extents...) you can use:</b> set verify off define TNAME=&1 define CHUNKS=&2 select grp, dbms_rowid.rowid_create( 1, data_object_id, lo_fno, lo_block, 0 ) min_rid, dbms_rowid.rowid_create( 1, data_object_id, hi_fno, hi_block, 10000 ) max_rid from ( select distinct grp, first_value(relative_fno) over (partition by grp order by relative_fno, block_id rows between unbounded preceding and unbounded following) lo_fno, first_value(block_id ) over (partition by grp order by relative_fno, block_id rows between unbounded preceding and unbounded following) lo_block, last_value(relative_fno) over (partition by grp order by relative_fno, block_id rows between unbounded preceding and unbounded following) hi_fno, last_value(block_id+blocks-1) over (partition by grp order by relative_fno, block_id rows between unbounded preceding and unbounded following) hi_block, sum(blocks) over (partition by grp) sum_blocks from ( select relative_fno, block_id, blocks, trunc( (sum(blocks) over (order by relative_fno, block_id)-0.01) / (sum(blocks) over ()/&CHUNKS) ) grp from dba_extents where segment_name = upper('&TNAME') and owner = user order by block_id ) ), (select data_object_id from user_objects where object_name = upper('&TNAME') ) / <b>to split the table up into chunks -- this'll give you N rowid ranges, and you can fire up N sessions doing: update t set rtf = convert_img(text) where rowid BETWEEN :x and :y; If raw speed was the need -- for a one time conversion, and you have a C programmer, I might suggest: a) write a small proc app b) implment the convert_img in C (it'll be a bit faster) c) have that pro*c app take as inputs the rowid range (so you can parallelize it as well) d) have it array fetch 100 to 500 rows, convert them and array UPDATE the table back </b>

Slow Blob writing: reply to followup #3

Ian, January 13, 2005 - 4:44 am UTC

Thanks for the suggestion. I used the convert_img function and now my test code runs 40% quicker than the original. I am already using diy parallelism but thanks for the suggestion. Your suggestions have been very helpful, cheers. :)

Progressive Slow down in Pl/SQL

KP, January 18, 2005 - 8:53 am UTC

Similar case, but without the CLOB.

We are currently working on a data migration project and have to use the vendors package (wrapped functions) to import the data to the system. The source table contains around 10 million records (accounting transactions) for about 200,000/- ledger accounts.

Each record in the source table gets inserted into 8 different tables as a debit posting and a credit posting (2 rows) and has referential integrities and a minimum of 3 indexes per table.

Currently I loop through each record in the source table and insert it into a PL/SQL table (with 2 records for debit and credit postings). This Pl/Sql table then calls the vendors function to insert the data.

Every 500 ledger accounts (25000 records) I pass a message to a dbms_pipe to store the statistics. When the process starts, the statistics display around 100 records processed every second. But after a couple of hours the process slows down and keeps slowing down.

If I leave it as a night job, the next morning it is processing only 15 records every second.

I used dbms_support.start_trace_in_session, and compared it at both times. The buffer gets, CPU time and elapsed time are the same. however the number of executes are very less in the morning than when it started.

To check wait events, I keep taking 15 minute statspacks during the start (when it is fast) and the morning run (when it is slow), the ratios and wait events (time waited) are also the same, however very less activity is happening.

The database is Oracle 9i running on RS/6000 with 4 CPU and 2GB RAM and all the tables were analyzed at the start of the migration run.

(a) What are the parameters that I need to check which makes it Progressively Slow.
(b) If it is because of the indexes etc, will it not get displayed in the TKPROF output somewhere. All my queries show the same amount of time taken for the number of executes. (Only that the number of executes is reduced).

For example,

The Instance Efficiency and the Buffer pool are given When it starts of....

$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
IAT2 611052525 iat2 1 9.2.0.4.0 NO opusprod

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 25 10-Jan-05 13:47:17 47 7.2
End Snap: 26 10-Jan-05 14:03:36 45 7.3
Elapsed: 16.32 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 48M Std Block Size: 8K
Shared Pool Size: 160M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 87,227.69 1,524,926.86
Logical reads: 2,342.91 40,959.04
Block changes: 824.89 14,420.79
Physical reads: 6.62 115.79
Physical writes: 8.92 155.91
User calls: 8.07 141.05
Parses: 50.84 888.80
Hard parses: 0.25 4.41
Sorts: 33.55 586.59
Logons: 0.31 5.45
Executes: 497.35 8,694.70
Transactions: 0.06

% Blocks changed per Read: 35.21 Recursive Call %: 98.98
Rollback per transaction %: 0.00 Rows per Sort: 114.41

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.72 In-memory Sort %: 100.00
Library Hit %: 99.95 Soft Parse %: 99.50
Execute to Parse %: 89.78 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 73.89 % Non-Parse CPU: 79.67

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.95 93.92
% SQL with executions>1: 73.89 71.40
% Memory for SQL w/exec>1: 56.68 55.11

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file parallel write 288 55 32.63
db file scattered read 335 31 18.08
control file parallel write 324 23 13.72
CPU time 22 13.04
log file parallel write 573 22 12.97
-------------------------------------------------------------------------------------

$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$

After the night run, in the morning,

$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
-------------------------------------------------------------------------------------
DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
IAT2 611052525 iat2 1 9.2.0.4.0 NO opusprod

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 18 10-Jan-05 09:38:31 34 6.9
End Snap: 19 10-Jan-05 09:55:25 38 7.2
Elapsed: 16.90 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 48M Std Block Size: 8K
Shared Pool Size: 160M Log Buffer: 512K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 22,693.54 38,674.37
Logical reads: 1,640.40 2,795.58
Block changes: 194.30 331.12
Physical reads: 69.23 117.98
Physical writes: 3.95 6.73
User calls: 4.20 7.16
Parses: 11.22 19.12
Hard parses: 0.02 0.04
Sorts: 10.16 17.32
Logons: 0.32 0.55
Executes: 107.46 183.13
Transactions: 0.59

% Blocks changed per Read: 11.84 Recursive Call %: 97.72
Rollback per transaction %: 0.00 Rows per Sort: 31.50

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 95.90 In-memory Sort %: 99.97
Library Hit %: 99.96 Soft Parse %: 99.82
Execute to Parse %: 89.56 Latch Hit %: 99.97
Parse CPU to Parse Elapsd %: 22.25 % Non-Parse CPU: 93.24

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.45 93.51
% SQL with executions>1: 78.70 78.52
% Memory for SQL w/exec>1: 61.64 63.98

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
latch free 1,446 31 29.24
db file parallel write 260 21 19.26
CPU time 16 14.70
db file scattered read 8,704 13 11.95
log file parallel write 848 11 9.96
-------------------------------------------------------------
$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
----------------------------------------------------------------------------------------

Even when I increased the PGA_AGGREGATE_TARGET and the buffer pool it is the same.
After some time, the performance becomes slow...;;

$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
----------------------------------------------------------------------------------------
STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
IAT2 611052525 iat2 1 9.2.0.4.0 NO opusprod

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 52 11-Jan-05 12:05:22 16 9.5
End Snap: 53 11-Jan-05 12:24:35 17 9.7
Elapsed: 19.22 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 192M Std Block Size: 8K
Shared Pool Size: 160M Log Buffer: 2,000K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 161,197.69 29,804.51
Logical reads: 4,916.46 909.03
Block changes: 1,466.32 271.11
Physical reads: 104.76 19.37
Physical writes: 97.27 17.99
User calls: 1.97 0.36
Parses: 195.82 36.21
Hard parses: 0.14 0.03
Sorts: 67.29 12.44
Logons: 0.00 0.00
Executes: 1,235.14 228.37
Transactions: 5.41

% Blocks changed per Read: 29.82 Recursive Call %: 99.90
Rollback per transaction %: 0.00 Rows per Sort: 25.84

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.98 In-memory Sort %: 100.00
Library Hit %: 99.96 Soft Parse %: 99.93
Execute to Parse %: 84.15 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 94.59 % Non-Parse CPU: -308.62

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 21.47 25.39
% SQL with executions>1: 60.34 61.91
% Memory for SQL w/exec>1: 50.88 55.65

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
db file parallel write 396 166 40.94
direct path write 4,862 68 16.81
db file scattered read 3,641 61 15.11
direct path read 8,232 41 10.16
control file parallel write 388 28 6.96
-------------------------------------------------------------
$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
$$$$$$$$$$$$$$$$$$$$$$$$$*************************************$$$$$$$$$$$$$$$$$$$
----------------------------------------------------------------------------------------

January 18, 2005 - 10:10 am UTC

these statspacks seem to be taken during "time of no processing"

I mean -- there are no significant waits, there is no real cpu time being used, the transactions/second are very low.

I see nothing that shows "progressive slowdown".

do you have your 3rd party vendor there with you -- as it is there code and they will be the only ones that can appreciably affect anything there.

KP, January 18, 2005 - 10:38 am UTC

The second set of statspack was taken after the night run in the morning or this happens when the process is running for 3 hours or more. When I check the check through the OEM or TOAD Session browser, I see the current statement waiting at my PL/SQL main program name:
begin accounting_migration.do_migration ; end ;
for a very long time, and then, after a while, it starts processing the records.

It is actually a readymade product and designed for OLTP with customisation allowed.

We were trying to look at possible reasons for this behaviour, so, first checked if there were any Memory contention, but the percentage of utilisation was only 25%. Then tried to check the I/O contention, but could not find any. CPU usage was also not maximum.
All the data files were initially in Raid-5, including the Redo log files, but moved the redo log files outside the raid-5 and still it was the same.

January 18, 2005 - 11:41 am UTC

you'll have to ask the vendor what they are doing -- look the statspack, there is nothing there. transactions/second -- nothing. cpu time -- nothing. waits nothing big there.

did the vendor instruement their code.

did the vendor make it possible for you to have a chance of success with their code?

I would turn on sql trace (using the 10046 level 12 trace event) and run their process for a while in sqlplus, exit out and see what you see

APPEND

IK, December 12, 2005 - 1:32 am UTC

Tom,

This thread was most useful.

I have a small question.

Pasting this from one of your followups.

>>>>>>>>>>>>>
In 9iR2 -- it will:

ops$tkyte@ORA920> insert /*+ APPEND */ into t
2 select object_id,
3 '<document><a_tag>' || object_id || '</a_tag>' ||
4 '<b_tag>' || object_name || '</b_tag>' ||
5 '<c_tag>' || object_type || '</c_tag>' ||
6 '<d_tag>' || owner || '<d_tag><document>' data
7 from all_objects
8 where rownum = 1;

1 row created.

ops$tkyte@ORA920>
ops$tkyte@ORA920> select * from t where rownum = 1;
select * from t where rownum = 1
*
ERROR at line 1:
ORA-12838: cannot read/modify an object after modifying it in parallel

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

Sorry for digressing here.

But, why would an APPEND hint modify the data in PARALLEL? If the DML has to be in parallel; i thought we need to explicitly say that.
Or is that the error you get after you do a direct-write and then attempt to read without commiting?

Please clarify.

Thank You,

December 12, 2005 - 7:57 am UTC

that error message really means "we did a parallel/direct path operation and you cannot read the object until we commit these changes"

Slowdown when inserting into table with blob

DanielD, January 31, 2006 - 6:35 pm UTC

Tom,

We are trying to consolidate webmethods tablespace residing in our database. We are running Oracle8i v 8.1.7.4. The original webmethods tablespace size was 40GB. We had removed data from the webmethods tablespace (by using webmethods job) so the tablespace should have only 14GB in size. To reclaim the space, we have created a new, locally managed webmethods tablespace with nologing. The script that creates tables in the new tablespace has syntax like this:

CREATE TABLE BIZDOCCONTENTARCHIVE_hold AS SELECT * FROM BIZDOCCONTENTARCHIVE WHERE rownum<1;

Here is bizdoctontentarchive table structure looks like:

CREATE TABLE "WEBMETHODS"."BIZDOCCONTENTARCHIVE"("DOCID" CHAR(
24) NOT NULL, "PARTNAME" VARCHAR2(100) NOT NULL, "MIMETYPE"
VARCHAR2(100), "CONTENTLENGTH" NUMBER, "CONTENT" BLOB,
"PARTINDEX" NUMBER, "STORAGETYPE" VARCHAR2(100), "STORAGEREF"
VARCHAR2(250),
CONSTRAINT "FK_BDCONTARC_DOCID_BIZDOCARC_1" FOREIGN KEY("DOCID")
REFERENCES "WEBMETHODS"."BIZDOCARCHIVE"("DOCID"),
CONSTRAINT "PK_BDCONTARC_DOCID_PARTNAME_1" PRIMARY KEY("DOCID",
"PARTNAME") USING
INDEX
TABLESPACE "WEBMETHODS"
STORAGE ( INITIAL 64K NEXT 0K MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1) PCTFREE 10 INITRANS
2 MAXTRANS 255)
TABLESPACE "WEBMETHODS" PCTFREE 10 PCTUSED 40 INITRANS 1
MAXTRANS 255
STORAGE ( INITIAL 64K NEXT 0K MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1)
LOGGING
LOB("CONTENT") STORE AS ( TABLESPACE "WEBMETHODS"
STORAGE ( INITIAL 64K NEXT 0K MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1)
ENABLE
STORAGE IN ROW
NOCACHE CHUNK 8192 PCTVERSION 10)

Then we were planning on using this insert to copy data from tables in old webmethods tablespace to corresponding table in new webmethods tablespace:

INSERT /*+ APPEND PARALLEL (BIZDOCCONTENTARCHIVE_hold,2) */ INTO BIZDOCCONTENTARCHIVE_hold SELECT /*+ PARALLEL (BIZDOCCONTENTARCHIVE,2) */ * FROM BIZDOCCONTENTARCHIVE;

The box has 4 CPUS. With tables without BLOB datatype, we had insert ratio about 40MB/minute. When insert started for the table with blob datatype, the speed decreased to 9MB/minute.

Due to the slowdown in insert speed ratio, the team lead has decided to abort the insert last week. New attempt is scheduled for this Friday. Could you please suggest how to speed up the insert process?

Thank you very much for your time.

February 01, 2006 - 2:45 am UTC

blobs have to maintain a rather complex data structure (an index, the lob segment).

if you have 4 cpus, parallel 8 (2x cpu count) would likely be more appropriate.

you'd be best off having a test machine to try out various approaches, otherwise - you won't really know what to expect. do you have something to test on

Slowdown when inserting into table with blob

DanielD, January 31, 2006 - 6:40 pm UTC

Thank you very much for your time.

I have forgotten to mention that the table has also been set to nologing:

ALTER TABLE BIZDOCCONTENTARCHIVE_hold NOLOGGING;

Thank you,

More tests with parallelism set to 2 and 4

DanielD, February 02, 2006 - 1:26 pm UTC

Tom,

Thank you for your advice. Ive thought that with parallel inserts, the parallelism should be set to the number of CPUs 1. We will try to use 8 instead of 2 for parallel.
We have tested the scenario on a test system with 8GB of webmethods data. It took 3 hours to do the inserts. It was 2 CPU box.
We need to do the same thing with 14GB of data in production.
We had done tests on 2 CPU box with parallelism set to 2 and then to 4. Here are our observations:

There is one table that contributes to 99% of the insert time. The table has 137590 rows (8 GB of data). With parallelism set to 2, it took 3 hours, 3 minutes and 3 seconds to do inserts (rows/second ratio: 12.52).
With parallelism set to 4, it took 2 hours, 34 minutes and 16 seconds to do inserts. (rows/second ratio: 14.86)

In prod, the same table has 226905 rows (14 GB of data), and with original parallelism, we had estimated that it could take about 5 hours to do the inserts. On 4 CPUs with parallelism set to 8 and with rows/second ratio of 17,2 it should take around 3 hours 39 minutes.

Thank you for your time.

February 02, 2006 - 2:29 pm UTC

with parallel, the starting point is 2*number of cpus.

Periodic slowness writing blob data to the database

Randy Strauss, February 17, 2006 - 1:43 am UTC

Our customer is seeing one of about 300 inserts into a particular table take 50 seconds every 50 seconds. The rest take no appreciable time.

We're using Oracle 9.2.0.4 and JDBC (Java 1.3.1) and the classes12.zip.

We have about 300 requests coming into the system every minute, and then into the database in a table like:
ID NOT NULL VARCHAR2(64)
THROTTLED NOT NULL CHAR(1)
CREATION_TIME NOT NULL NUMBER(38)
DATA BLOB
COMPLETECOUNT NUMBER(38)
MDA_ID NOT NULL VARCHAR2(8)
PRIORITY NUMBER(38)
START_TIME NOT NULL NUMBER(38)
There was some kind of oracle (or jdbc?) bug that was overwriting other columns if we insert more than 4k of blob data when we do the insert, so we insert with a fake, 1-byte blob, then select the row for update, update the blob field and commit.

The customer is seeing one of these inserts take 48-55 seconds approximately every 50 seconds. All the other request insertions take no noticable time. We can't reproduce it, but their system does, all the time.

The time is being spent in the blob's putBytes() call which sends the data to the database, or adding the blob to the prepared statement. We're using the oracle.sql.BLOB for this. We create the Blob by doing a results.getBlob(), coerce it to an Oracle BLOB, and then do the putBytes() and the prepStmt.setBlob().

I can find no other query that could be locking this (just inserter) row or table (which the other inserts are also accessing).

Is there anything in the database that can be causing this? Or is there a way I can monitor just an individual query that is taking a long time? I might be able to get a trace on the system (if I can convince the customer it'll be helpful)-- if I do, with 5 happening every second, will I be able to pinpoint both the start and end of the putBytes()? Any suggestions are welcome. Thanks.

February 17, 2006 - 1:44 pm UTC

you don't say whether the blob is cached or not cached, logged or not logged.

sounds suspiciously like "checkpoint not complete, cannot allocate new log"

I've never heard of a "overwrite bug" like that - that would be somewhat of a huge one - are you sure about that?

answers to questions

Randy Strauss, February 17, 2006 - 4:04 pm UTC

> cached or not, logged or not logged.

The defaults, which I guess are not-cached, and logged, if I read the docs correctly.

> sounds suspiciously like "checkpoint not complete, cannot allocate new log"

When I look at the article on this, it says, "during this time (when we cannot allocate a new log) processing is suspended in the database..."

We just see this thread pause for 50 seconds- lots of other things still happen.

> I've never heard of a "overwrite bug" like that...

Sorry, I got it wrong. If they inserted a large blob, all bytes after the first 4k were lost...

If it'd help, there's a statspack from the customer (temporarily) on: </code> http://randy.strauss.net/statspack.txt <code>

Thanks much, -r

February 17, 2006 - 5:25 pm UTC

in java, they would use streams of course for that.

statspack - not useful.

tkprof (10046 level 12 trace) of the affected thread - priceless.

PS:

Randy Strauss, February 17, 2006 - 4:09 pm UTC

I'm not sure how much the "waits" on db reads in the statspack tell us. We have some processes in multiple nodes that take turns by intentionally waiting to lock the the same table rows (I didn't write the code.)

a bit more

Randy Strauss, February 17, 2006 - 4:27 pm UTC

I was looking at the statspack, and see:
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file parallel write 59,493 58,870 32 1 0.2

My DBA suggests making some bigger redo logs.
Could this be causing this particular problem, esp the periodicity?

February 17, 2006 - 5:28 pm UTC

making the redo logs bigger won't make writing to them any faster.

however, enlarging the redo log buffer - if you have REALLY big transactions - so that while you are filling it, lgwr can write out.

but that would not cause a 50 second pause, of a single thread - it would pause pretty much everyone on "redo space" waits.

you have some log file syncs waits, they happen during "commit" (not during the generation of redo - during the commit). They (the log file sync waits) could be caused by log file parallel writes. But the 50 second pause - nope.

Now, that enqueue wait..... that's big.

Insert performance degrading

Hitesh, June 13, 2006 - 12:41 am UTC

Hi Tom,

Recently the performance of the sqlldr loading data in the database has considerably slowed down for the past one week.

The reason could attribute to increase in the IO wait time which has shooted up from 70% to 90% of the CPU cycles. Most of this has been contributed to 'db file sequential read' wait event.

The table is having a Primary Key Index, and a local partitioned index as the table is partitioned based on date using range partitioning.

We have n't altered any settings for the parameter file, and even then there is a huge dip. what could be the reasons for the dip.

The only thing which I could recollect is we have stopped gathering of stats. But does that hurt while inserting into the table?

Your thoughts on this would be appreciated.

June 13, 2006 - 12:09 pm UTC

insufficient details - you don't say whether you are using conventional path load, direct path load, and many other things.

How does IO "shoot up cpu cycles"? That doesn't compute.

Direct path INSERT with/without CLOB

Pedro, September 02, 2010 - 4:29 pm UTC

The database is 10.2.0.4.0.
1. Table with CLOB is being populated via a dblink from a remote database.
Here is the issue/question:
1.1. Table with CLOB conventional path - 20 minutes
1.2. Table with CLOB direct path /+ APPEND PARALLEL(T, 1)*/ - 20 minutes
1.3. Table with CLOB direct path with 8 hash partitions /+ PARALLEL(T, 8)*/ - 6 minutes
2. Table without CLOB is being populated via a dblink from a remote database.
2.1. Fastest (elapsed time)- table without CLOB direct path /+ APPEND PARALLEL(T, 1)*/
2.2. Slower (elapsed time)- table without CLOB conventional path
2.3. Slowest (elapsed time)- table without CLOB conventional path /+ APPEND PARALLEL(T, 8)*/
Does the above look normal to you? If yes, how could it be explained?
If needed I can provide the AUTOTRACE and tkprof files.
Thank you in advance,

Pedro

September 09, 2010 - 7:01 pm UTC

Is 1.3 versus 1.2/1.1 reproducible? over and over reproducible? I cannot think of any reason why 1.3 would be better than 1.1 or 1.2?

Direct path INSERT with/without CLOB

Pedro, September 14, 2010 - 12:24 pm UTC

Apologize for the delay.
The database is running with workarea_size_policy=AUTO, pga_aggregate_target=16106127360
Here is the CREATE TABLE:
CREATE TABLE UD_STW.ZZZ_PS_COMMUNICATION
(
COMMON_ID VARCHAR2(11) NOT NULL ENABLE,
SEQ_3C NUMBER (*,0) NOT NULL ENABLE,
SA_ID_TYPE VARCHAR2( 1) NOT NULL ENABLE,
COMM_DTTM DATE NOT NULL ENABLE,
INSTITUTION VARCHAR2( 5) NOT NULL ENABLE,
ADMIN_FUNCTION VARCHAR2( 4) NOT NULL ENABLE,
COMM_CATEGORY VARCHAR2( 6) NOT NULL ENABLE,
COMM_CONTEXT VARCHAR2( 6) NOT NULL ENABLE,
COMM_METHOD VARCHAR2( 1) NOT NULL ENABLE,
INCLUDE_ENCL VARCHAR2( 1) NOT NULL ENABLE,
DEPTID VARCHAR2(10) NOT NULL ENABLE,
COMM_ID VARCHAR2(11) NOT NULL ENABLE,
COMM_DT DATE,
COMM_BEGIN_TM DATE,
COMM_END_TM DATE,
COMPLETED_COMM VARCHAR2( 1) NOT NULL ENABLE,
COMPLETED_ID VARCHAR2(11) NOT NULL ENABLE,
COMPLETED_DT DATE,
COMM_DIRECTION VARCHAR2( 4) NOT NULL ENABLE,
UNSUCCESSFUL VARCHAR2( 1) NOT NULL ENABLE,
OUTCOME_REASON VARCHAR2( 1) NOT NULL ENABLE,
SCC_LETTER_CD VARCHAR2( 3) NOT NULL ENABLE,
LETTER_PRINTED_DT DATE,
LETTER_PRINTED_TM DATE,
CHECKLIST_SEQ_3C NUMBER (*,0) NOT NULL ENABLE,
CHECKLIST_SEQ NUMBER (*,0) NOT NULL ENABLE,
COMMENT_PRINT_FLAG VARCHAR2( 1) NOT NULL ENABLE,
ORG_CONTACT NUMBER (*,0) NOT NULL ENABLE,
ORG_DEPARTMENT NUMBER (*,0) NOT NULL ENABLE,
ORG_LOCATION NUMBER (*,0) NOT NULL ENABLE,
PROCESS_INSTANCE NUMBER (10, 0) NOT NULL ENABLE,
EXT_ORG_ID VARCHAR2(11) NOT NULL ENABLE,
VAR_DATA_SEQ NUMBER (*,0) NOT NULL ENABLE,
COMM_COMMENTS CLOB,
EMPLID_RELATED VARCHAR2(11) NOT NULL ENABLE,
JOINT_COMM VARCHAR2( 1) NOT NULL ENABLE,
SCC_COMM_LANG VARCHAR2( 3) NOT NULL ENABLE,
SCC_COMM_MTHD VARCHAR2( 1) NOT NULL ENABLE,
SCC_COMM_PROC VARCHAR2( 1) NOT NULL ENABLE
)
PCTFREE 0 PCTUSED 40 INITRANS 1 MAXTRANS 255 NOCOMPRESS NOLOGGING
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE DATA_SIZE_L_STW
LOB (COMM_COMMENTS)
STORE AS
(
TABLESPACE DATA_SIZE_L_STW ENABLE STORAGE IN ROW CHUNK 32768 PCTVERSION 10 NOCACHE LOGGING
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
)
PARALLEL 8
--PARTITION BY HASH(COMMON_ID, SEQ_3C)
--PARTITIONS 8
;
Here is the INSERT:
ALTER SESSION ENABLE PARALLEL DML;
INSERT /*+ APPEND PARALLEL(L,1) */ INTO UD_STW.ZZZ_PS_COMMUNICATION L
(
COMMON_ID ,
SEQ_3C ,
SA_ID_TYPE ,
COMM_DTTM ,
INSTITUTION ,
ADMIN_FUNCTION ,
COMM_CATEGORY ,
COMM_CONTEXT ,
COMM_METHOD ,
INCLUDE_ENCL ,
DEPTID ,
COMM_ID ,
COMM_DT ,
COMM_BEGIN_TM ,
COMM_END_TM ,
COMPLETED_COMM ,
COMPLETED_ID ,
COMPLETED_DT ,
COMM_DIRECTION ,
UNSUCCESSFUL ,
OUTCOME_REASON ,
SCC_LETTER_CD ,
LETTER_PRINTED_DT ,
LETTER_PRINTED_TM ,
CHECKLIST_SEQ_3C ,
CHECKLIST_SEQ ,
COMMENT_PRINT_FLAG ,
ORG_CONTACT ,
ORG_DEPARTMENT ,
ORG_LOCATION ,
PROCESS_INSTANCE ,
EXT_ORG_ID ,
VAR_DATA_SEQ ,
COMM_COMMENTS ,
EMPLID_RELATED ,
JOINT_COMM ,
SCC_COMM_LANG ,
SCC_COMM_MTHD ,
SCC_COMM_PROC
)
(
SELECT /*+ NO_PARALLEL(R) */
COMMON_ID ,
SEQ_3C ,
SA_ID_TYPE ,
COMM_DTTM ,
INSTITUTION ,
ADMIN_FUNCTION ,
COMM_CATEGORY ,
COMM_CONTEXT ,
COMM_METHOD ,
INCLUDE_ENCL ,
DEPTID ,
COMM_ID ,
COMM_DT ,
COMM_BEGIN_TM ,
COMM_END_TM ,
COMPLETED_COMM ,
COMPLETED_ID ,
COMPLETED_DT ,
COMM_DIRECTION ,
UNSUCCESSFUL ,
OUTCOME_REASON ,
SCC_LETTER_CD ,
LETTER_PRINTED_DT ,
LETTER_PRINTED_TM ,
CHECKLIST_SEQ_3C ,
CHECKLIST_SEQ ,
COMMENT_PRINT_FLAG ,
ORG_CONTACT ,
ORG_DEPARTMENT ,
ORG_LOCATION ,
PROCESS_INSTANCE ,
EXT_ORG_ID ,
VAR_DATA_SEQ ,
COMM_COMMENTS ,
EMPLID_RELATED ,
JOINT_COMM ,
SCC_COMM_LANG ,
SCC_COMM_MTHD ,
SCC_COMM_PROC
FROM UD_STW.ZZZ_PS_COMMUNICATION@DEVDATA.CSSD.PITT.EDU R
);
SELECT * FROM UD_STW.ZZZ_PS_COMMUNICATION WHERE ROWNUM = 1;
COMMIT;
ALTER SESSION DISABLE PARALLEL DML;
Here are the CLOB statistics:
SELECT
AVG(DBMS_LOB.GETLENGTH(&&vCOLUMN_NAME)),
MIN(DBMS_LOB.GETLENGTH(&&vCOLUMN_NAME)),
MAX(DBMS_LOB.GETLENGTH(&&vCOLUMN_NAME)),
COUNT(CASE WHEN DBMS_LOB.GETLENGTH(COMM_COMMENTS) > 4000 THEN 1 ELSE NULL END ),
COUNT(*)
FROM UD_STW.ZZZ_PS_COMMUNICATION
;
AVG MIN MAX COUNT COUNT(*)
------------- ---- ------- ------- ---------------
14.2310298 1 1396 0 3108718

1 row selected.

Here are the times from 14-SEP-2010, yes I can reproduce the times over and over:
1.2. Table with CLOB direct path /+ APPEND PARALLEL(T, 1)*/ - 21 minutes (the newly created extents are being added as the table's extents)
1.3. Table with CLOB direct path with 8 hash partitions /+ PARALLEL(T, 8)*/ 5.5 minutes (the newly created extents are being added as temporary extents)
1.4. Table with CLOB commented out direct path /+ APPEND PARALLEL(T, 1)*/ - 3 minutes

Thank you very much,

Pedro

September 15, 2010 - 7:30 am UTC

I didn't ask for a table or anything, I cannot run your code.

Anyway - you seem to have changed the list here dramtically.

1.1. Table with CLOB conventional path - 20 minutes
1.2. Table with CLOB direct path /+ APPEND PARALLEL(T, 1)*/ - 20 minutes
1.3. Table with CLOB direct path with 8 hash partitions /+ PARALLEL(T, 8)*/ - 6 minutes

the numbering anyway - but in any case, you have just shown that parallel helps you quite a bit - so - what is the question again?

Direct path INSERT with/without CLOB

A reader, September 15, 2010 - 9:07 am UTC

Tom,

Thanks for the fast response.
The list has not change dramatically, I think the numbering misled you.
The issue is stated in your Followup September 9, 2010 - 7pm Central time zone: "Is 1.3 versus 1.2/1.1 reproducible? over and over reproducible? I cannot think of any reason why 1.3 would be better than 1.1 or 1.2?"
Version 1 of 1.2:
1.2. Table with CLOB direct path /*+ APPEND PARALLEL(T, 1)*/ - 20 minutes
Version 2 of 1.2:
1.2. Table with CLOB direct path /*+ APPEND PARALLEL(T, 1)*/ - 21 minutes (the newly created extents are being added as the table's extents)
Version 1 of 1.3:
1.3. Table with CLOB direct path with 8 hash partitions /*+ PARALLEL(T, 8)*/ - 6 minutes
Version 2 of 1.3:
1.3. Table with CLOB direct path with 8 hash partitions /*+ PARALLEL(T, 8)*/ 5.5 minutes (the newly created extents are being added as the temporary extents)
There is only one version of 1.4
1.4. Table with CLOB commented out direct path /*+ APPEND PARALLEL(T, 1)*/ - 3 minutes
And the questions are:
3. The target machine has 8 CPUs, for the non-CLOB tables the best times for direct INSERT from a remote database are obtained with /*+ APPEND PARALLEL(T, 1)*/ for the INSERT and /*+ NO_PARALLEL(R) */ for the SELECT. Do you think that is normal?
4. The CLOB non-HASH partitioned table is populated in 20 minutes with /*+ APPEND PARALLEL(T, 1)*/ for the INSERT, the CLOB HASH partitioned table is populated in 5-6 minutes with /*+ APPEND PARALLEL(T, 8)*/ for the INSERT. This behavior contradicts #3. The documentation states that parallel DML cannot be established for a non-partitioned table with a LOB. Still, parallel > 1 for a non-CLOB table slows down the performance, but parallel > 1 for a CLOB table speeds the performance.
Thanks again,

Pedro

September 15, 2010 - 9:39 am UTC

I misread the parallel 8/1 apparently. all you have shown us here is parallel 8 is better than parallel 1 in your case.

3) sure, in that case, parallel didn't help you. a serial direct path load was "best" for you.

4) why does it contradict - you are comparing apples to flying toaster ovens, you are doing two very different operations. A clob is a hugely complex structure (it is stored out of line, it has and index that needs to be maintained - none of which is happening without the clob).

Direct path INSERT with/without CLOB

Pedro, September 15, 2010 - 10:14 am UTC

Hello,

3. So there is a possibility that there is nothing wrong with the fact that parallel is slower than serial, maybe because the remote database cannot deliver data fast enough
4. I will give you the apples to flying toaster ovens (CLOB to non-CLOB table), but this does no explain part one of the question about the magic influence of HASH partitioning, how come:
4.1 CLOB non-HASH partitioned table is populated in 20 minutes with /*+ APPEND PARALLEL(T, 1)*/ for the INSERT - 20 minutes
4.2 CLOB HASH partitioned table is populated in 5-6 minutes with /*+ APPEND PARALLEL(T, 8)*/ - 5-6 minutes
If I can get 4 times faster executions, I will start hash partitioning everything.
5. Also, please have a look at the impact of an average 15 bytes per record CLOB maintenance the time goes from 3 minutes (#1.4) to 20 minutes (#1.2), both for a non HASH partitioned table.
Thanks for the lightning fast response.

Pedro

September 15, 2010 - 10:47 am UTC

... So there is a possibility that there is nothing wrong with the fact that
parallel is slower than serial, maybe because the remote database cannot
deliver data fast enough
...

absolutely. parallel is not fast=true.

4) but you already showed yourself that parallel is not always faster - I'm confused why you would say "If I can get 4 times faster executions, I will start hash partitioning everything." - you just gave an example yourself whereby serial trumped parallel????

5) huh? did not follow. you are comparing "no clob" to "clob"

Direct path INSERT with/without CLOB

Pedro, September 15, 2010 - 12:47 pm UTC

4.
I have a non-partitioned table with CLOB and populate it with /*+ APPEND PARALLEL(T, 1)*/ (since parallel cannot work for a non-partitioned table) => takes 20 minutes.
Then I have the same (only hash partitioned table) with the same CLOB and populate it with /*+ APPEND PARALLEL(T, 8)*/ (since parallel now works for a partitioned table) => takes 5 minutes
Since we already established that parallel does not equal true, it has to be the hash that dropped the time to 5 minutes, unless parallel=fast for tables with CLOB and parallel=slow for tables without CLOB.
5. The cost of transferring a 14 byte on the average CLOB per record is 17 minutes (700% compared to the rest of the table). There are 3108718 records in the table times 14 bytes for each CLOB equals around 40 MB, the table has around 500 MB, so to transfer 10% of the data I have to pay 700% time penalty. Something is not right here, or maybe I am missing something.
Thanks again,

Pedro

September 15, 2010 - 1:16 pm UTC

4) you are comparing:

no parallel and no partitioning

to

parallel and partitioning.

You changed two things, you cannot claim "one of them is the cause".

... unless parallel=fast for tables
with CLOB and parallel=slow for tables without CLOB.
...

that is patently false, you should know there are examples where parallel with a table without any clobs is faster than serial. Please...

5) I'm not following you at all, what is this 14 bytes about ???

if your clobs are only 14 bytes - why are you using a clob - which is an expensive data structure to use????

Direct path INSERT with/without CLOB

Pedro, September 15, 2010 - 2:25 pm UTC

4.
Someone on Follow up on September 9, 2010 - 7pm Central time zone and wrote:
"Is 1.3 versus 1.2/1.1 reproducible? over and over reproducible? I cannot think of any reason why 1.3 would be better than 1.1 or 1.2?"
the behavior can be reproduced at will, the person who answered wrote "I cannot think of any reason why 1.3 would be better than 1.1 or 1.2", today I am being written that everything is pretty much normal.
5.
Here are the CLOB statistics (posted September 14, 2010 - 12pm Central time zone):
SELECT
AVG(DBMS_LOB.GETLENGTH(&&vCOLUMN_NAME)),
MIN(DBMS_LOB.GETLENGTH(&&vCOLUMN_NAME)),
MAX(DBMS_LOB.GETLENGTH(&&vCOLUMN_NAME)),
COUNT(CASE WHEN DBMS_LOB.GETLENGTH(COMM_COMMENTS) > 4000 THEN 1 ELSE NULL END ),
COUNT(*)
FROM UD_STW.ZZZ_PS_COMMUNICATION
;
AVG MIN MAX COUNT COUNT(*)
---------- --- ---- ------- --------
14.2310298 1 1396 0 3108718

1 row selected.
and... by the way it is not I who uses CLOB it is the vendor of the source table who picked CLOB.
Thank you,

Pedro

September 15, 2010 - 2:37 pm UTC

then the vendor did a bad thing if they only store 1 to 2k of data in there. Not anything we can do about it really - they stuck you with an inappropriate datatype that simply takes longer to utilize then a varchar2 would.

Direct path INSERT with/without CLOB

Pedro, September 16, 2010 - 9:18 am UTC

How about any other options aside from HASH partitioning to speed up the INSERT?

September 16, 2010 - 10:11 am UTC

check out the attributes of the LOB - is it inline or out of line, is it cached or not cached, is it ....

use dbms_metadata.get_ddl to get the ddl and you'll see all of the storage options for the LOB - show us what they are (don't need ALL of the ddl if it is big, just the storage portion of the "store as" clause for the lob.)

Direct path INSERT with/without CLOB

Pedro, September 16, 2010 - 1:58 pm UTC

My update provided on "September 14, 2010 - 12pm Central time zone" contains CREATE TABLE that was obtained utilizing DBMS_METADATA.GET_DDL. This is the CREATE TABLE on the INSERT side of the operation.
Thanks for staying with me on this.

September 16, 2010 - 2:43 pm UTC

I don't read back and forth, I read the last bit only. So, I didn't look up to see if it was there. You could have sliced off what we needed to look at :)
LOB (COMM_COMMENTS) STORE AS ( TABLESPACE DATA_SIZE_L_STW ENABLE STORAGE IN ROW CHUNK 32768 PCTVERSION 10 NOCACHE LOGGING STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645 PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT) )

it allows storage in row - so the lob segment/lob index should not be touched here since your lobs are very small - nothing to be gained by changing that.

chunk 32k - if they are TINY as yours are - that doesn't really make sense. But it probably isn't affecting anything as you should never be going out of line anyway.

nocache and logging are not relevant either - since you are staying in line. The are cached always when "inline".

So, no, I don't see anything obvious to change

Direct path INSERT with/without CLOB

Pedro, September 16, 2010 - 4:09 pm UTC

You don't see anything obvious, I won't even try to look no more. Thanks for checking the LOB setup. I will go than with the magic of HASH PARTITIONING+PARALLEL, hoping that the CLOB restriction for non-partitioned tables gets lifted. One more thing, am I looking into any serious trouble by setting global indexes (basically leaving them the way they are) on my newly HASH PARTITIONED table?

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

CLOB/BLOB/etc

Complete documentation on Securefiles and Large Objects here

Progessive slow down when inserting into a table with a clob

Breadcrumb

Question and Answer

You Asked

and Tom said...

Rating

Comments

Really helpful, as usual

what to do when there is lots of 'direct path write (lob)' wait?

more information provided

Result of show_space after analyzing the table

This is getting more interesting

10046 trace

DDL

output of the query

direct path write (lob) is totally gone

You book did mention about 'direct path write'

Insert a clob errer

dbms_lob.getlength is slow

to Vidya

null blobs

object no longer exists error

Slow Blob writing?

Slow Blob writing: reply to followup

Slow Blob writing: reply to followup #2

Slow Blob writing: reply to followup #3

Progressive Slow down in Pl/SQL

APPEND

Slowdown when inserting into table with blob

Slowdown when inserting into table with blob

More tests with parallelism set to 2 and 4

Periodic slowness writing blob data to the database

answers to questions

PS:

a bit more

Insert performance degrading

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

Direct path INSERT with/without CLOB

More to Explore

CLOB/BLOB/etc