Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Re: 10046 trace: 'latch free' then 'db file seq. read' waits

Re: 10046 trace: 'latch free' then 'db file seq. read' waits

From: hpuxrac <johnbhurley_at_sbcglobal.net>
Date: 15 Jun 2006 10:23:24 -0700
Message-ID: <1150392204.576391.110410@p79g2000cwp.googlegroups.com>

Spendius wrote:
> sjaffarhussain_at_gmail.com a écrit:
> > cache buffer chain generally comes when a block accessed in the buffer,
> > i.e. logical read. Since the wait event is 'db file sequential read', I
> > guess this could be index root block hot block issues.
> > Can you give us the explain plan and information about the tabels
> > involved in the query and its statistical information and also index
> > information.
> > What is the size of buffer cache in the database?
> > Jaffar
> >
> Thanks for the replies. Here are the infos.
>
> SQL> sta param k_buffers
>
> NAME TYPE VALUE
> ------------------------------------ ----------- -----------
> db_block_buffers integer 400000
> SQL> sta param lru
>
> NAME TYPE VALUE
> ------------------------------------ ----------- -----------
> db_block_lru_latches integer 8
>
> SQL> sta param cpu_c
>
> NAME TYPE VALUE
> ------------------------------------ ----------- -----------
> cpu_count integer 8
> SQL> show sga
>
> Total System Global Area 3875663548 bytes
> Fixed Size 102076 bytes
> Variable Size 597696512 bytes
> Database Buffers 3276800000 bytes
> Redo Buffers 1064960 bytes
>
> Block size is 8192.
>
> I have to add we're not experiencing latch problems at the instance
> level, but we're hitting a very puzzling and unusual behaviour in a
> query that gets blocked *just a few records before the end of its
> result set*: thanks to the FIRST_ROWS hint this stmt immediately
> starts to display its result, until it's reached 98 or 99% of what it
> must display, then it hangs for about 2 minutes. When I check the
> waits once it's started to hang, I see 'latch free' and 'db file seq.
> read' waits alternating (with most of the waits on 'db file...'). This
> *systematically* happens, every day, at any hour: a few lines
> before showing the oldest records (you'll see below
> the sort is descending on a date), the display in SQL*Plus hangs,
> then it suddenly completes (the whole result is about 900 records,
> it stops at the 890th or 892nd row, hangs, and ends up displaying
> the 10 or 8 last rows). In fact we used to put this query inside
> a sub-query with a ROWNUM < 700, we've removed this "SELECT
> * FROM (sub-query shown below) WHERE ROWNUM < 700" stuff
> and since then we've noticed it blocks for a few mn before ending.
> Very peculiar.
>
> The SELECT is as follows:
> select:
> SELECT /*+ first_rows */
> d.tab_id tab_id,
> TO_CHAR (di.time_oper, 'DD/MM/YYYY') time_oper,
> ...
> FROM tab TAB, <= accessed thru TAB_PK
> tab_inf di, <= accessed thru TAIN_IDX_NI5
> tab_pnrers dpe, <= accessed thru TNPE_PK
> tab_pay TAB_PAY <= accessed thru TPMT_TAB_FK_I
> WHERE di.operation = 'CREATE'
> AND di.distrib_code = 'BS'
> AND di.tab_id = TAB.tab_id
> AND TAB_PAY.tab_id = TAB.tab_id
> AND TAB_PAY.TIME_OF_PAY > SYSDATE-1
> AND dpe.tab_id(+) = TAB.tab_id
> ORDER BY di.time_oper DESC
>
> on TAB_INF.TIME_OPER we have a non-unique index: TAIN_IDX_NI5
> that appears much too many times from the moment I start to
> trace the session executing this stmt. These tables are pretty
> voluminous (millions of records each except for tab_pnrers).
>
> Execution Plan
> ----------------------------------------------------------
> 0 SELECT STATEMENT Optimizer=HINT: FIRST_ROWS (Cost=237543 Card=1
> Bytes=393)
> 1 0 VIEW (Cost=237543 Card=1 Bytes=393)
> 2 1 NESTED LOOPS (OUTER) (Cost=237543 Card=1 Bytes=135)
> 3 2 NESTED LOOPS (Cost=237540 Card=1 Bytes=122)
> 4 3 NESTED LOOPS (Cost=237537 Card=1 Bytes=66)
> 5 4 TABLE ACCESS (BY INDEX ROWID) OF 'TAB_INF' (Cost=237535
> Card=1 Bytes=24)
> 6 5 INDEX (FULL SCAN DESCENDING) OF 'TAIN_IDX_NI5'
> (NON-UNIQUE) (Cost=35791 Card=1)
> 7 4 TABLE ACCESS (BY INDEX ROWID) OF 'TAB' (Cost=2
> Card=823017 Bytes=34566714)
> 8 7 INDEX (UNIQUE SCAN) OF 'TAB_PK' (UNIQUE) (Cost=1
> Card=823017)
> 9 3 TABLE ACCESS (BY INDEX ROWID) OF 'TAB_PAY' (Cost=3
> Card=49551 Bytes=2774856)
> 10 9 INDEX (RANGE SCAN) OF 'TPMT_TAB_FK_I' (NON-UNIQUE)
> (Cost=2 Card=49551)
> 11 2 INDEX (RANGE SCAN) OF 'TNPE_PK' (UNIQUE) (Cost=3
> Card=1181995 Bytes=15365935)
>
> I have a script that returns lines looking like a 10046 trace, that I
> run
> from the moment my displays starts to hang for these +/- 2 minutes
> (I loop very quickly on a SELECT FROM V$SESSION_WAIT -forget the
> "ela=" value as it's erroneous-) and I get things like the following:
> SQL> sta pseudo10046 <sid#>
> nam='latch free' ela=2 p1=18420778536 p2=66 p3=0
> nam='latch free' ela=2 p1=18420778536 p2=66 p3=0
> nam='db file sequential read' ela=-1 p1=12 p2=4342 p3=1
> nam='db file sequential read' ela=-1 p1=12 p2=4342 p3=1
> nam='db file sequential read' ela=-1 p1=12 p2=4342 p3=1
> [... continued over thousands of lines until my first session
> finishes to display my result set, I get then:]
> nam='SQL*Net message from client' ela=0 p1=675562835 p2=1 p3=0
> and do a <CTL-C>.
>
> Then I put all p1=file# p2=block# when nam='db file seq. read'
> in a script 'hotblocks.sql' that contains a call to another script
> that reads
> SQL: select owner||'.'||segment_name segment, segment_type,
> tablespace_name
> SQL: from sys.dba_extents
> SQL: where file_id = &&1
> SQL: and &&2 between block_id and (block_id+(blocks-1))
> it returns me the segments as follows (I've replaced "INDEX"
> with "**index**" so it's more legible here):
>
> SQL> sta hotblocks
> TNPE_PK **index** TAB1_DI1
> TAB_PAY TABLE TAB1_DD1
> <128 times...>
> TAB_PAY TABLE TAB1_DD1
> TAIN_IDX_NI5 **index** TAB1_DI2
> TAIN_IDX_NI5 **index** TAB1_DI2
> TAIN_IDX_NI5 **index** TAB1_DI2
> TAB_PAY TABLE TAB1_DD1
> TAIN_IDX_NI5 **index** TAB1_DI2
> TAIN_IDX_NI5 **index** TAB1_DI2
> TAB_PAY TABLE TAB1_DD1
> [... over thousands of lines]
>
> Most of the lines here show reads on blocks from
> o this index quoted above (TAIN_IDX_NI5) or
> o from the table TAB_PAY,
> it varied during my tests (but I don't know depending on
> what !). Just to display the verly last records, Oracle then
> carries out thousands of reads either against this index, or
> against the TAB_PAY table (the 4rth in the FROM list).
>
> What I CAN'T understand is why Oracle starts to display
> very quickly, then stays blocked for about 2 mn only to
> finish displaying the 10 last rows... (when i say I get the
> same behaviour everyday that means every day -and
> even every 5 minutes- the result set differs and gets
> bigger every hour as these tables incur many inserts/updates
> all the time)
>
> Thanks.

First instead of your simulated trace ( don't quite understand that ) why not do a real 10046 trace at level 12? You can setup a logon database trigger if needed to get the trace started at the beginning of the activity ... prior to the SQL statement being executed.

You do understand ( I hope ) that FIRST_ROWS hint tells the optimizer to create if it can an execution plan that favors getting some of the information back quickly but may not be a good choice for an execution plan if you really need all the data.

At some point it sounds like someone had this SQL changed so that it didn't get all the data ( only first 700 rows right ).

You or someone needs to look at the business case. Do you need all the data or not?

If you do need all the data, then FIRST_ROWS may not be a good choice to see the last rows.

I would recommend understanding the application and the SQL first before making other changes. Received on Thu Jun 15 2006 - 12:23:24 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US