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
accurately?
Thanks!
-----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 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@xxxxxxxxxxxxx
[mailto: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?
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!
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
