RE: Cursor Pin S and TKPROF anomaly?

  • From: "Khemmanivanh, Somckit" <somckit.khemmanivanh@xxxxxxxxxxxxxxxx>
  • To: "Ken Naim" <kennaim@xxxxxxxxx>, <oracle-l@xxxxxxxxxxxxx>
  • Date: Wed, 23 May 2007 11:34:05 -0700

Thanks, we turned of the mutexes and that fixed the issue.

In this situation (given that tracing skews the timing info) is there
another method to determine the response time and wait events

-----Original Message-----
From: Ken Naim [mailto:kennaim@xxxxxxxxx] 
Sent: Wednesday, May 23, 2007 11:20 AM
To: Khemmanivanh, Somckit; oracle-l@xxxxxxxxxxxxx
Subject: RE: Cursor Pin S and TKPROF anomaly?

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


-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx
On Behalf Of Khemmanivanh, Somckit
Sent: Wednesday, May 23, 2007 12:13 PM
To: oracle-l@xxxxxxxxxxxxx
Subject: Cursor Pin S and TKPROF anomaly?

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

This just started occurring after an upgrade from 9i to 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:



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



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



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


2) Execute the SQL statement:


3) Fetch the row:


--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!



Other related posts: