RE: Cursor Pin S and TKPROF anomaly?

I have experienced this in 10.2.0.2 and it is a bug with 10046 tracing that causes this wait and causes tracing to consume a ton more resources than on other versions. It is fixed on certain platforms in 10.2.0.3.

Ken

-----Original Message-----

From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Khemmanivanh, Somckit
Sent: Wednesday, May 23, 2007 12:13 PM
To: oracle-l_at_freelists.org
Subject: Cursor Pin S and TKPROF anomaly?

Hi,  

My Oracle version is 10gR2. The mystery occurs when we have many jobs executing concurrently. CPU usage spikes and jobs slow down considerably.

This just started occurring after an upgrade from 9i to 10gR2...it seems like the new mutex feature in 10gR2 is the culprit?  

Here's what looks to be the pattern from the trace file:

1. Acquire the pin S wait on X mutex to Parse the SQL Statement:

16158 WAIT #225: nam='cursor: pin S wait on X' ela= 15829 idn=688875006 value=3637837299712 where|

sleeps=12897830798 obj#=149934 tim=13839593792889

BINDS #225: kkscoacd

Bind#0

1oacdty=01 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00

oacflg=03 fl2=1000000 frm=01 csi=02 siz=96 off=0

kxsbbbfp=800003f78004a228 bln=32 avl=03 flg=05

value="100"

Bind#1

oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00

oacflg=03 fl2=1000000 frm=01 csi=02 siz=0 off=32

kxsbbbfp=800003f78004a248 bln=32 avl=10 flg=01

value="0011940619"

Bind#2

oacdty=01 mxl=32(04) mxlc=00 mal=00 scl=00 pre=00

oacflg=03 fl2=1000000 frm=01 csi=02 siz=0 off=64

kxsbbbfp=800003f78004a268 bln=32 avl=04 flg=01

value="0060"

2) Execute the SQL statement:

EXEC
#225:c=0,e=16717,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=13839593793270

3) Fetch the row:

FETCH
#225:c=0,e=85,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=13839593793395  

--Below is the TKPROF output (193 executes and fetches -- the CPU time
is 5 seconds and the ELAPSED time is 35 seconds for the *execute*)
--There are over 7000 waits for cursor pin S but total waited time is
near ZERO...where did all the time go?

call count cpu elapsed disk query current rows

• ------ -------- ---------- ---------- ---------- ----------

  ---

Parse 0 0.00 0.00 0 0 0 0

Execute 193 5.00 35.46 0 0 0 0

Fetch 193 0.08 9.28 0 2271 0 188

• ------ -------- ---------- ---------- ---------- ----------

  ---

total 386 5.08 44.74 0 2271 0 188

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 18

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

• Waited ---------- ------------

cursor: pin S 7374 0.00 0.00

SQL*Net message to client 193 0.00 0.00

SQL*Net message from client 193 1.09 3.20

latch: cache buffers chains 49 0.60 3.80

latch free 22 0.55 1.44

--Thanks for your help!

--

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

--

http://www.freelists.org/webpage/oracle-l Received on Wed May 23 2007 - 13:19:50 CDT