Re: catsearch and latch: cache buffers chains waits
From: Tanel Poder <tanel_at_poderc.com>
Date: Sat, 27 Feb 2010 00:08:31 +0800
Message-ID: <4602f23c1002260808u5b6c9cc7wdf533f4487cd4435_at_mail.gmail.com>
First I'd ask that how big % of your session's response time was wasted waiting for latches? Sometimes people troubleshoot the wrong symptom (like cases where 99% of response time was spent on CPU and 1% waiting for latches).
Date: Sat, 27 Feb 2010 00:08:31 +0800
Message-ID: <4602f23c1002260808u5b6c9cc7wdf533f4487cd4435_at_mail.gmail.com>
First I'd ask that how big % of your session's response time was wasted waiting for latches? Sometimes people troubleshoot the wrong symptom (like cases where 99% of response time was spent on CPU and 1% waiting for latches).
In addition to bad design, like running some PL/SQL lookup function for each row in SQL resultset, cache buffers chains latch contention often happens due an execution plan flip, where some SQL starts hammering a small set of data blocks due a wrongly ordered nested loop plan. Of course it always takes more than 1 process/session to have any kind of latch (or lock) contention, at least one holder of the lock and at least one waiter.
Btw, if you want to systematically troubleshoot any latch contention, then you can use my latchprofx script for drilling down to details:
-- Tanel Poder http://tech.e2sn.com http://blog.tanelpoder.com On Fri, Feb 26, 2010 at 10:23 PM, Dba DBA <oracledbaquestions_at_gmail.com>wrote:Received on Fri Feb 26 2010 - 10:08:31 CST
> I am trying to tune a query that uses the catsearch function and this
> appears to be the problem. I first looked at the event in v$session and
> noticed latch: cache buffers chains. This typically indicates excess
> parsing, but this is just 1 query?
>
> So I am running a 10046 trace and I am seeing something interesting. It
> appears that catsearch execute a query over and over again. Similiar to
> having a function in your query.
>
> I am also noticing that it executes for each row returned for each keyword.
> This is causing excess parsing.
>
> has anyone used catsearch before? This does not seem to be very efficient.
> It is using my ctxcat index. Here is a sample of one of the parses in the
> 10046 trace. This happens over and over again in my trace file.
>
>
> PARSING IN CURSOR #8 len=247 dep=1 uid=13686 oct=3 lid=13686
> tim=25146063685495 hv=2206871408 ad='c5437b70'
> select /*+ INDEX_ASC(i "DR$MYPOLICY$X") */ dr$rowid from
> "DR$MYPOLICY$I" i where dr$token = :token and dr$token_type = :ttype
> and DR$ROWID >= :r01 order by dr$token ASC, dr$token_type ASC, dr$rowid
> ASC
> END OF STMT
> PARSE #8:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=25146063685490
> BINDS #8:
> bind 0: dty=1 mxl=128(64) mal=00 scl=00 pre=00 oacflg=00 oacfl2=0000
> size=184 offset=0
> bfp=ffffffff7b991790 bln=128 avl=10 flg=05
> value="TOWNAME"
> bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=00 oacfl2=0000 size=0
> offset=128
> bfp=ffffffff7b991810 bln=22 avl=01 flg=01
> value=0
> bind 2: dty=1 mxl=32(18) mal=00 scl=00 pre=00 oacflg=00 oacfl2=0000 size=0
> offset=152
> ^C bfp=ffffffff7b991828 bln=32 avl=18 flg=01
> value="AAa8Q5ADYAAAAUQAAn"
> EXEC #8:c=0,e=156349,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=25146063956032
> FETCH #8:c=0,e=250,p=0,cr=3,cu=0,mis=0,r=215,dep=1,og=1,tim=25146064003460
> FETCH #8:c=0,e=241,p=0,cr=1,cu=0,mis=0,r=215,dep=1,og=1,tim=25146064022705
> STAT #8 id=1 cnt=0 pid=0 pos=1 obj=7062703 op='INDEX RANGE SCAN
> DR$MYPOLICY$X (cr=0 pr=0 pw=0 time=0 us)'
>
-- http://www.freelists.org/webpage/oracle-l