Re: Excessive "latch: row cache objects" waits with simple INSERT statement

The fact that the EXEC lines show: " r=1" suggests that you are doing single row inserts. For array inserts I'd expect to see 'r={size of array}'.

If your code thinks it's doing array inserts and is actually doing single row maybe there are some features in play that block the array processing - e.g. would triggers have some effect of turning array processing into single row processing? If it's something to do with triggers is it possible that the intermittent sampling is something to do with trigger code that contains SQL for which SQL Directives have been created. What about VPD (RLS) ?

Regards
Jonathan Lewis

On Mon, 5 Oct 2020 at 07:13, Thomas Kellerer <thomas.kellerer_at_mgm-tp.com> wrote:

> Jonathan Lewis schrieb am 02.10.2020 um 14:47:
> > Have I said anything yet about creating a logon trigger (on one of
> > your schemas) to enable SQL tracing with waits events enabled for
> > just the SQL_ID of the critical statement - perhaps with a limited
> > lifetime so you only capture a few occurrences of the statement.
>
> I enabled SQL trace for that statement through ALTER SYSTEM and here is a
> part of the trace file of one of the sessions:
>
> ------------- snip ----------------
> *** 2020-10-05 08:00:44.936
> =====================
> PARSING IN CURSOR #140112424508552 len=66 dep=0 uid=115 oct=2 lid=115
> tim=103070917361722 hv=2215798297 ad='4fff64290' sqlid='dkv2b06214tht'
> insert into APP_USER.LOOKUP_TABLE (lookup_value) values (:1 )
> END OF STMT
> BINDS #140112424508552:
> Bind#0
> oacdty=01 mxl=128(112) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000010 frm=01 csi=873 siz=128 off=0
> kxsbbbfp=7f6e774b7010 bln=128 avl=28 flg=05
> value="****************************"
> EXEC
> #140112424508552:c=820,e=473,p=0,cr=1,cu=22,mis=0,r=1,dep=0,og=1,plh=0,tim=103070917362179
> STAT #140112424508552 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE
> CONVENTIONAL LOOKUP_TABLE (cr=1 pr=0 pw=0 time=367 us)'
> WAIT #140112424508552: nam='SQL*Net message to client' ela= 2 driver
> id=1413697536 #bytes=1 p3=0 obj#=-1 tim=103070917362338
> WAIT #140112424508552: nam='SQL*Net message from client' ela= 1284 driver
> id=1413697536 #bytes=1 p3=0 obj#=-1 tim=103070917363640
> CLOSE #140112424508552:c=0,e=4,dep=0,type=1,tim=103070917363708
> =====================
> PARSING IN CURSOR #140112424494776 len=66 dep=0 uid=115 oct=2 lid=115
> tim=103070917822795 hv=2215798297 ad='4fff64290' sqlid='dkv2b06214tht'
> insert into APP_USER.LOOKUP_TABLE (lookup_value) values (:1 )
> END OF STMT
> BINDS #140112424494776:
> Bind#0
> oacdty=01 mxl=128(112) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000010 frm=01 csi=873 siz=128 off=0
> kxsbbbfp=7f6e774b7010 bln=128 avl=28 flg=05
> value="****************************"
> WAIT #140112424494776: nam='latch: row cache objects' ela= 36924
> address=21728500976 number=411 tries=0 obj#=-1 tim=103070917859840
> WAIT #140112424494776: nam='latch: row cache objects' ela= 8
> address=21728500976 number=411 tries=0 obj#=-1 tim=103070917859907
> WAIT #140112424494776: nam='latch: row cache objects' ela= 4
> address=21728500976 number=411 tries=0 obj#=-1 tim=103070917859930
> WAIT #140112424494776: nam='latch: row cache objects' ela= 16
> address=21728500976 number=411 tries=0 obj#=-1 tim=103070917859960
> EXEC
> #140112424494776:c=0,e=37922,p=0,cr=1,cu=22,mis=0,r=1,dep=0,og=1,plh=0,tim=103070917860701
> STAT #140112424494776 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE
> CONVENTIONAL LOOKUP_TABLE (cr=1 pr=0 pw=0 time=37814 us)'
> WAIT #140112424494776: nam='SQL*Net message to client' ela= 2 driver
> id=1413697536 #bytes=1 p3=0 obj#=-1 tim=103070917860786
> WAIT #140112424494776: nam='SQL*Net message from client' ela= 849 driver
> id=1413697536 #bytes=1 p3=0 obj#=-1 tim=103070917861650
> CLOSE #140112424494776:c=0,e=7,dep=0,type=1,tim=103070917861696
> =====================
> PARSING IN CURSOR #140112424493680 len=66 dep=0 uid=115 oct=2 lid=115
> tim=103070918048079 hv=2215798297 ad='4fff64290' sqlid='dkv2b06214tht'
> insert into APP_USER.LOOKUP_TABLE (lookup_value) values (:1 )
> END OF STMT
> BINDS #140112424493680:
> Bind#0
> oacdty=01 mxl=128(112) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000010 frm=01 csi=873 siz=128 off=0
> kxsbbbfp=7f6e774bfed8 bln=128 avl=28 flg=05
> value="****************************"
> EXEC
> #140112424493680:c=0,e=831,p=0,cr=1,cu=23,mis=0,r=1,dep=0,og=1,plh=0,tim=103070918048885
> STAT #140112424493680 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE
> CONVENTIONAL LOOKUP_TABLE (cr=1 pr=0 pw=0 time=463 us)'
> WAIT #140112424493680: nam='SQL*Net message to client' ela= 3 driver
> id=1413697536 #bytes=1 p3=0 obj#=-1 tim=103070918049187
> WAIT #140112424493680: nam='SQL*Net message from client' ela= 2741 driver
> id=1413697536 #bytes=1 p3=0 obj#=-1 tim=103070918052062
> CLOSE #140112424493680:c=0,e=7,dep=0,type=1,tim=103070918052126
>
> ------------ snip ----------
>
> Does this mean the inserts aren't actually batched, but multiple single
> row inserts?
>
> The trace was enabled using:
>
> alter system set events 'sql_trace[sql: dkv2b06214tht] level=12';
>
> Thomas
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>

--
http://www.freelists.org/webpage/oracle-l