Re: Tuning LOB: Where is all my time going?

The conclusion to this was that a CTAS took longer than a two step create and then insert /*+ append */. It seems that the direct I/O used by the CTAS (with a LOB present) highlights some machine hardware or configuration issue (Win2K, 4 CPU, RAID5). The lost time looks to be being used by some part of the machine and not being reported in perfmon - it looks like a lot of kernel CPU is being used during the CTAS. Thanks to everyone on this thread thread for providing some useful input.

Also thanks to Tom Kyte for the email exchange that help me get to this point (and an acceptable workaround whilst we investigate further).

Mat.

"Jonathan Lewis" <jonathan_at_jlcomp.demon.co.uk> wrote in message news:<ckhirl$8v9$1_at_sparta.btinternet.com>...
> There may be some issues with the way
> that Oracle is failing to record time against
> the direct path reads and writes.
>
> Take a look at the trace file and see if that
> gives you any clues - in particular with lines
> containing "tim=" timestamps, which will be
> microsecond timing.
>
> Other checks:
> Repeat the experiment doing rapid:
>
> select * from v$session_wait where sid =
> {sid of session doing the ctas}
>
> to see if there is something in v$session_wait
> that is not getting into the trace file.
>
>
> Take a couple of snapshots of v$system_event
> to see if the "lost time" is somehow being recorded
> against some other session (such as dbwr or I/O
> slaves).
>
>
>
> --
> Regards
>
> Jonathan Lewis
>
> http://www.jlcomp.demon.co.uk/faq/ind_faq.html
> The Co-operative Oracle Users' FAQ
>
> http://www.jlcomp.demon.co.uk/seminar.html
> Optimising Oracle Seminar - schedule updated Sept 19th
>
>
>
>
>
> "Matt Butler" <mathewbutler_at_yahoo.com> wrote in message
> news:19f48a45.0410112308.4af4065f_at_posting.google.com...
> > Oracle Standard 9.2.0.4 on WIN2K.
> >
> > I'm in the process of trying implement an archiving strategy for an
> > application. As part of this I have come across the following problem:
> >
> > Some of the application tables contain LOB's. The tables containing
> > LOBs are taking some time to slice. Below is a TKPROF report for one
> > CTAS that ran for approx. 5 min. It processed 100 out of 35000 blocks
> > (taken from v$session_longops). In this case the table
> > tst.bizdoccontent contained a few rows (2) and bizdoccontent contained
> > many (300,000 or so). Both tables are full scanned.
> >
> > My problem is that at this work rate, this query will take over a day
> > to complete. Looking at the discrepancy between cpu and elapsed time I
> > am obviously waiting for something, but that something is not on the
> > "waited for events list". At this point I am unsure how to proceed.
> >
> > Can anyone shed any light on what might be happening here? Below is
> > the output from user_lobs which descibes the LOB definition. Please
> > let me know if additional diagnostic info is required.
> >
> > Thanks in advance,
> >
> > Mat.
> >
> >
> > TABLE_NAME COLUMN_NAME SEGMENT_NAME INDEX_NAME CHUNK PCTVERSION RETENTION
> FREEPOOLS CACHE LOGGING IN_ROW
> > BIZDOCCONTENT CONTENTSYS_LOB0000026859C00005$$ SYS_IL0000026859C00005$$
> > 8192 10 10800 NO YES YES
> >
> > Here is the TKPROF.
> >
> >
> ****************************************************************************
> ****
> >
> > create table to_save_bizdoccontent
> > tablespace ebxml_med_data as
> > select * from bizdoccontent orig_bdc
> > where not exists ( select null from tst.bizdoccontent subset_bdc
> > where orig_bdc.docid = subset_bdc.docid
> > and orig_bdc.partname = subset_bdc.partname)
> >
> > call count cpu elapsed disk query current
> > rows
> > ------- ------ -------- ---------- ---------- ---------- ----------
> > ----------
> > Parse 1 0.00 0.00 0 0 0
> > 0
> > Execute 1 0.09 283.13 5165 32128 38154
> > 0
> > Fetch 0 0.00 0.00 0 0 0
> > 0
> > ------- ------ -------- ---------- ---------- ---------- ----------
> > ----------
> > total 2 0.09 283.13 5165 32128 38154
> > 0
> >
> > Misses in library cache during parse: 1
> > Optimizer goal: CHOOSE
> > Parsing user id: 42
> >
> > Elapsed times include waiting on following events:
> > Event waited on Times Max. Wait Total
> > Waited
> > ---------------------------------------- Waited ----------
> > ------------
> > control file sequential read 4 0.00
> > 0.00
> > db file scattered read 1 0.01
> > 0.01
> > direct path read (lob) 5161 0.02
> > 6.58
> > direct path write (lob) 4390 0.09
> > 1.37
> > direct path write 1 0.00
> > 0.00
> > log file sync 1 0.75
> > 0.75
> > SQL*Net break/reset to client 1 0.00
> > 0.00
> > SQL*Net message to client 1 0.00
> > 0.00
> > SQL*Net message from client 1 0.05
> > 0.05
> >
> ****************************************************************************
> ****
Received on Mon Oct 25 2004 - 20:25:57 CDT