Skip to Main Content
Forums

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Interested in getting your voice heard by members of the Developer Marketing team at Oracle? Check out this post for AppDev or this post for AI focus group information.

Performance problem - event : cursor: pin S wait on X

YoavMar 25 2010 — edited Apr 24 2010
Hi,

Bellow is 17 min awr report , of oracle PeopleSoft DB on 10204 instance on HPUX machine.
During this time the customers complained on poor performance.
There were 4,104.23 execution per second and 3,784.95 parses
which mean that almost any statment was parsed. since the Soft Parse %= 99.77
its seems that most of the parses are soft parse.

During those 17 min , the DB Time = 721.74 min and the "Top 5 Timed Events"
shows : "cursor: pin S wait on X" at the top of the Timed Events
Attached some details for the awr report

Could you please suggest where to focus ?

Thanks
WORKLOAD REPOSITORY report for

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
xxxx          2993006132 xxxx                1 10.2.0.4.0  NO  xxxx

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     18085 25-Mar-10 10:30:41       286      14.9
  End Snap:     18086 25-Mar-10 10:48:39       301      15.1
   Elapsed:               17.96 (mins)
   DB Time:              721.74 (mins)

Cache Sizes
~~~~~~~~~~~                       Begin        End
                             ---------- ----------
               Buffer Cache:     4,448M     4,368M  Std Block Size:         8K
           Shared Pool Size:     2,736M     2,816M      Log Buffer:     2,080K

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:          3,831,000.13            271,096.84
              Logical reads:            164,733.47             11,657.20
              Block changes:             17,757.42              1,256.59
             Physical reads:                885.19                 62.64
            Physical writes:                504.92                 35.73
                 User calls:              5,775.09                408.67
                     Parses:              3,784.95                267.84
                Hard parses:                  8.55                  0.60
                      Sorts:                212.37                 15.03
                     Logons:                  0.77                  0.05
                   Executes:              4,104.23                290.43
               Transactions:                 14.13

  % Blocks changed per Read:   10.78    Recursive Call %:    24.14
 Rollback per transaction %:    0.18       Rows per Sort:    57.86

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.98       Redo NoWait %:   99.97
            Buffer  Hit   %:   99.47    In-memory Sort %:  100.00
            Library Hit   %:   99.73        Soft Parse %:   99.77
         Execute to Parse %:    7.78         Latch Hit %:   99.77
Parse CPU to Parse Elapsd %:    3.06     % Non-Parse CPU:   89.23

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   34.44   34.78
    % SQL with executions>1:   76.52   60.40
  % Memory for SQL w/exec>1:   73.75   99.18

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
cursor: pin S wait on X           1,378,354      13,462     10   31.1 Concurrenc
db file sequential read             878,684       8,779     10   20.3   User I/O
CPU time                                          4,998          11.5
local write wait                      2,692       2,442    907    5.6   User I/O
cursor: pin S                     1,932,830       2,270      1    5.2      Other
          -------------------------------------------------------------
Time Model Statistics                  DB/Inst: xxxx/xxxx  Snaps: 18085-18086

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                             21,690.6         50.1
parse time elapsed                                   17,504.9         40.4
DB CPU                                                4,998.0         11.5
hard parse elapsed time                                 372.1           .9
connection management call elapsed time                 183.9           .4
sequence load elapsed time                              125.8           .3
PL/SQL execution elapsed time                            89.2           .2
PL/SQL compilation elapsed time                           9.2           .0
inbound PL/SQL rpc elapsed time                           5.5           .0
hard parse (sharing criteria) elapsed time                5.5           .0
hard parse (bind mismatch) elapsed time                   0.5           .0
failed parse elapsed time                                 0.1           .0
repeated bind elapsed time                                0.0           .0
DB time                                              43,304.1          N/A
background elapsed time                               3,742.3          N/A
background cpu time                                     114.8          N/A
          -------------------------------------------------------------
                                                                  Avg
                                       %Time       Total Wait    wait     Waits
Wait Class                      Waits  -outs         Time (s)    (ms)      /txn
-------------------- ---------------- ------ ---------------- ------- ---------
Concurrency                 1,413,633   97.5           14,283      10      92.8
User I/O                      925,010     .3           11,485      12      60.7
Other                       1,984,969     .2            2,858       1     130.3
Application                     1,342   46.4            1,873    1396       0.1
Configuration                  12,116   63.6            1,857     153       0.8
System I/O                    582,094     .0            1,444       2      38.2
Commit                         17,253     .6            1,057      61       1.1
Network                     6,180,701     .0               68       0     405.9
          -------------------------------------------------------------

Wait Events                            DB/Inst: xxxx/xxxx  Snaps: 18085-18086

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
cursor: pin S wait on X           1,378,354  100.0      13,462      10      90.5
db file sequential read             878,684     .0       8,779      10      57.7
local write wait                      2,692   91.2       2,442     907       0.2
cursor: pin S                     1,932,830     .0       2,270       1     126.9
log file switch (checkpoint           2,669   49.1       1,510     566       0.2
enq: RO - fast object reuse             542   86.5       1,398    2580       0.0
log file sync                        17,253     .6       1,057      61       1.1
control file sequential read        450,043     .0         579       1      29.6
log file parallel write              17,903     .0         558      31       1.2
enq: TX - row lock contentio            295   52.2         475    1610       0.0
buffer busy waits                     7,338    4.4         348      47       0.5
buffer exterminate                      322   92.5         302     938       0.0
read by other session                24,694     .0         183       7       1.6
library cache lock                       59   94.9         167    2825       0.0
log file sequential read            109,494     .0         161       1       7.2
latch: cache buffers chains          18,662     .0         149       8       1.2
log buffer space                      2,493     .0         139      56       0.2
Log archive I/O                       3,592     .0         131      37       0.2
free buffer waits                     6,420   99.1         130      20       0.4
latch free                           42,812     .0         121       3       2.8
Streams capture: waiting for            845    6.0         106     125       0.1
latch: library cache                  2,074     .0          96      46       0.1
db file scattered read               12,437     .0          80       6       0.8
enq: SQ - contention                    150   14.0          71     471       0.0
SQL*Net more data from clien        331,961     .0          41       0      21.8
latch: shared pool                      320     .0          32     100       0.0
LGWR wait for redo copy               5,307   49.1          29       5       0.3
SQL*Net more data to client         254,217     .0          17       0      16.7
control file parallel write           1,038     .0          15      14       0.1
latch: library cache lock               477     .4          14      29       0.0
latch: row cache objects              6,013     .0          10       2       0.4
SQL*Net message to client         5,587,878     .0          10       0     366.9
latch: redo allocation                1,274     .0           9       7       0.1
log file switch completion               62     .0           6      92       0.0
Streams AQ: qmn coordinator               1  100.0           5    4882       0.0
latch: cache buffers lru cha            434     .0           4       9       0.0
block change tracking buffer            111     .0           4      35       0.0
wait list latch free                    135     .0           3      21       0.0
enq: TX - index contention              132     .0           2      17       0.0
latch: session allocation               139     .0           2      14       0.0
latch: object queue header o            379     .0           2       4       0.0
row cache lock                           15     .0           2     107       0.0
latch: redo copy                         56     .0           1      17       0.0
latch: library cache pin                184     .0           1       5       0.0
write complete waits                     14   28.6           1      51       0.0
latch: redo writing                     251     .0           1       3       0.0
enq: MN - contention                      3     .0           1     206       0.0
enq: CF - contention                     16     .0           0      23       0.0
log file single write                    24     .0           0      13       0.0
os thread startup                         3     .0           0     102       0.0
reliable message                         66     .0           0       4       0.0
enq: JS - queue lock                      2     .0           0     136       0.0
latch: cache buffer handles              46     .0           0       5       0.0
buffer deadlock                          65  100.0           0       4       0.0
latch: undo global data                  73     .0           0       3       0.0
change tracking file synchro             24     .0           0       6       0.0
change tracking file synchro             30     .0           0       3       0.0
kksfbc child completion                   2  100.0           0      52       0.0
SQL*Net break/reset to clien            505     .0           0       0       0.0
db file parallel read                     3     .0           0      30       0.0

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
SQL*Net more data from dblin            127     .0           0       0       0.0
SQL*Net more data to dblink             319     .0           0       0       0.0
latch: enqueue hash chains               20     .0           0       2       0.0
latch: checkpoint queue latc              5     .0           0       5       0.0
SQL*Net message to dblink             6,199     .0           0       0       0.4
enq: TX - allocate ITL entry              1     .0           0      22       0.0
direct path read                      5,316     .0           0       0       0.3
latch: messages                          24     .0           0       1       0.0
enq: US - contention                      3     .0           0       4       0.0
direct path write                     1,178     .0           0       0       0.1
rdbms ipc reply                           1     .0           0       1       0.0
library cache load lock                   2     .0           0       0       0.0
direct path write temp                    3     .0           0       0       0.0
direct path read temp                     3     .0           0       0       0.0
SQL*Net message from client       5,587,890     .0     135,002      24     366.9
wait for unread message on b          7,809   21.8       3,139     402       0.5
LogMiner: client waiting for        262,604     .1       3,021      12      17.2
LogMiner: wakeup event for b      1,405,104    2.4       2,917       2      92.3
Streams AQ: qmn slave idle w            489     .0       2,650    5420       0.0
LogMiner: wakeup event for p        123,723   32.1       2,453      20       8.1
Streams AQ: waiting for time              9   55.6       1,790  198928       0.0
LogMiner: reader waiting for         45,193   51.3       1,526      34       3.0
Streams AQ: waiting for mess            297   99.3       1,052    3542       0.0
Streams AQ: qmn coordinator             470   33.8       1,050    2233       0.0
Streams AQ: delete acknowled            405   32.3       1,049    2591       0.0
jobq slave wait                         379   77.8         958    2529       0.0
LogMiner: wakeup event for r         16,591   10.6         125       8       1.1
SGA: MMAN sleep for componen          3,928   99.3          35       9       0.3
SQL*Net message from dblink           6,199     .0          31       5       0.4
single-task message                     108     .0           8      74       0.0
class slave wait                          3     .0           0       0       0.0
          -------------------------------------------------------------

Background Wait Events                 DB/Inst: xxxx/xxxx  Snaps: 18085-18086
-> ordered by wait time desc, waits desc (idle events last)

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file parallel write              17,916     .0         558      31       1.2
Log archive I/O                       3,592     .0         131      37       0.2
log file sequential read              3,636     .0          47      13       0.2
events in waitclass Other             6,149   42.4          40       7       0.4
log file switch (checkpoint              30   53.3          19     619       0.0
control file parallel write           1,038     .0          15      14       0.1
db file sequential read               1,166     .0           6       5       0.1
control file sequential read          2,986     .0           6       2       0.2
latch: shared pool                        4     .0           4     917       0.0
latch: library cache                      5     .0           3     646       0.0
free buffer waits                       160   98.8           2      10       0.0
buffer busy waits                         2     .0           1     404       0.0
latch: redo writing                      19     .0           0      23       0.0
log file single write                    24     .0           0      13       0.0
os thread startup                         3     .0           0     102       0.0
log buffer space                          7     .0           0      35       0.0
latch: cache buffers chains              16     .0           0       8       0.0
log file switch completion                1     .0           0      71       0.0
latch: library cache lock                 3   66.7           0      11       0.0
latch: redo copy                          1     .0           0      20       0.0
direct path read                      5,316     .0           0       0       0.3
latch: row cache objects                  3     .0           0       1       0.0
direct path write                     1,174     .0           0       0       0.1
latch: library cache pin                  3     .0           0       0       0.0
rdbms ipc message                    20,401   24.2      11,112     545       1.3
Streams AQ: qmn slave idle w            489     .0       2,650    5420       0.0
Streams AQ: waiting for time              9   55.6       1,790  198928       0.0
pmon timer                              379   94.5       1,050    2771       0.0
Streams AQ: delete acknowled            406   32.3       1,050    2586       0.0
Streams AQ: qmn coordinator             470   33.8       1,050    2233       0.0
smon timer                              146     .0       1,039    7118       0.0
SGA: MMAN sleep for componen          3,928   99.3          35       9       0.3
          -------------------------------------------------------------

Operating System Statistics             DB/Inst: xxxx/xxxx  Snaps: 18085-18086

Statistic                                       Total
-------------------------------- --------------------
AVG_BUSY_TIME                                  68,992
AVG_IDLE_TIME                                  37,988
AVG_IOWAIT_TIME                                28,529
AVG_SYS_TIME                                   11,748
AVG_USER_TIME                                  57,214
BUSY_TIME                                     552,209
IDLE_TIME                                     304,181
IOWAIT_TIME                                   228,489
SYS_TIME                                       94,253
USER_TIME                                     457,956
LOAD                                                2
OS_CPU_WAIT_TIME                      147,872,604,500
RSRC_MGR_CPU_WAIT_TIME                              0
VM_IN_BYTES                                    49,152
VM_OUT_BYTES                                        0
PHYSICAL_MEMORY_BYTES                  25,630,269,440
NUM_CPUS                                            8
NUM_CPU_SOCKETS                                     8

Comments

avramits
Concurrency 1,413,633 97.5 %
and
cursor: pin S wait on X 1,378,354 100.0 %

telling that you had blocking lock on the system
mbobak
Hello user10634138,

The AWR report tells you that a significant amount of time, about 30%, was spent waiting on the cursor: pin S wait on X' event.

But, the question is, when this event happened, how long did a session wait on it? Well, the average, according to your report, is 10ms. But, we all know that ratios and averages hide details from us. What you really want to know is the range of wait times on this wait event, and how frequently you waited how long. In other words, a histogram of wait times. Unfortunately, AWR doesn't contain wait event histogram data until 11g. So, what to do?

Well, does the problem reproduce easily? If so, observe. Look at V$SESSION and V$SESSION_WAIT to see the 'cursor: pin S wait on X' events. How long do they last? 10ms is an average, but, is it also close to the median? If you really are seeing waits of around 10ms, and no real outliers, then, that tells a different story than if you have lots of really tiny (1-2ms) waits and a few really long (seconds long) waits.

If the situation is that you have many, many very short waits, and a few really long waits, then you need to track down the root cause of the really long waits. To do that, you could use a script like this: 
select p2/power(16,8) blocking_sid, p1 mutex_id, sid blocked_sid
   from v$session
  where event like 'cursor:%'
    and state='WAITING';
This will list the blocking SID and the blocked SID. You would then need to investigate the blocking SID, and why it's holding the mutex for extended periods of time, causing the serialization and slowness.

If, on the other hand, most all the waits are close the the average wait time, 10ms, well, that doesn't strike me as a particularly excessive wait time. So, rather than trying to reduce the duration of any given individual wait, it's probably going to make more sense to try to reduce the number of waits.

So, this is a parsing related wait. You already mentioned that you're doing lots of parsing, mostly soft. Do you have session_cursor_cache parameter set to a reasonable value? 10g, I believe the default is 50, which is probably not a bad starting point. You may get additional benefits with moderate increases, perhaps to 100-200 range. It can be costly to do so, but can the extra parsing be addressed in the application? Is there anything you can do to reduce parsing in the application? When the problem occurs, how is the CPU consumption on the box? Are the CPUs pegged? Are you bottlenecked on CPU resources? Finally, there are bugs around 10.2.0.x and mutexes, so, you may want to open an SR w/ Oracle support, and determine if the root cause is actually a bug.

Well, that's a bit longer than I planned, but, I hope it gives you some idea of how to systematically analyze your problem, and gets you to a root cause and resolution.

-Mark
Yoav
Well, there are few Row lock waits, but i dont think this is the root cause of my problem.
Indeed it seems that there are some waits on PS_NAP_TEL ,but since its insert statment
the waits are only on the indexes as you can see bellow.
Also please note that i set the initrans on all the involved indexes to 10.

Thanks
                               Reads              CPU     Elapsed
Physical Reads  Executions    per Exec   %Total Time (s)  Time (s)    SQL Id
-------------- ----------- ------------- ------ -------- --------- -------------
        36,672       2,381          15.4    3.8    71.19    670.67 96yxg40vbcfc4
INSERT INTO xxxx.PS_NAP_TEL...

...

Segments by Row Lock Waits             

                                                                     Row
           Tablespace                      Subobject  Obj.          Lock    % of
Owner         Name    Object Name            Name     Type         Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
xxxx      PTTBL      PSIBFOLOCK               TABLE          120   27.65
xxxx      PSINDEX    PSBNAP_TEL               INDEX          107   24.65

Segments by ITL Waits

           Tablespace                      Subobject  Obj.           ITL    % of
Owner         Name    Object Name            Name     Type         Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
xxxx      PSINDEX    PSBNAP_TEL               INDEX            1  100.00
          -------------------------------------------------------------

Segments by Buffer Busy Waits
                                                                  Buffer
           Tablespace                      Subobject  Obj.          Busy    % of
Owner         Name    Object Name            Name     Type         Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
xxxx      PSDEFAULT  PS_NAP_TEL              TABLE        1,770   26.83
xxxx      PSINDEX    PSDNAP_TEL               INDEX          838   12.70
xxxx      PSINDEX    PSGNAP_TEL               INDEX          733   11.11
xxxx      PSINDEX    PSINAP_TEL               INDEX          683   10.35
xxxx      PSINDEX    PSENAP_TEL               INDEX          573    8.68
          -------------------------------------------------------------
Jonathan Lewis
mbobak wrote:

So, this is a parsing related wait. You already mentioned that you're doing lots of parsing, mostly soft. Do you have session_cursor_cache parameter set to a reasonable value? 10g, I believe the default is 50, which is probably not a bad starting point. You may get additional benefits with moderate increases, perhaps to 100-200 range. It can be costly to do so, but can the extra parsing be addressed in the application? Is there anything you can do to reduce parsing in the application? When the problem occurs, how is the CPU consumption on the box? Are the CPUs pegged? Are you bottlenecked on CPU resources? Finally, there are bugs around 10.2.0.x and mutexes, so, you may want to open an SR w/ Oracle support, and determine if the root cause is actually a bug.
Mark,

I think you might read a little more into the stats than you have done - averaging etc. notwithstanding.
There are 8.55 "hard" parses per second - which in 17.96 minutes is about 9,500 hard parses - and there are 1.3M pin S wait on X: which is about 130 per hard parse (and 1.9M pin S). So the average statistics might be showing an interesting impact on individual actions.

The waits on "local write wait" are worth nothing. There are various reasons for this, one of which is the segment header block writes and index root block writes when you truncate a table - which could also be a cause of the "enq: RO - fast object reuse" waits in the body of the report.

Truncating tables tends to invalidate cursors and cause hard parsing.

So I would look for code that is popular, executed from a number of sessions, and truncates tables.

There were some bugs in this area relating to global temporay tables - but they should have been fixed in 10.2.0.4.

Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
http://www.jlcomp.demon.co.uk

To post code, statspack/AWR report, execution plans or trace files, start and end the section with the tag {noformat}
{noformat} (lowercase, curly brackets, no spaces) so that the text appears in
fixed format
.

There is a +"Preview"+ tab at the top of the text entry panel. Use this to check what your message will look like before you post the message. If it looks a complete mess you're unlikely to get a response. (Click on the +"Plain text"+ tab if you want to edit the text to tidy it up.)

+"Science is more than a body of knowledge; it is a way of thinking"+
+Carl Sagan+
Yoav
Hi ,
I just found a very interesting note in the metalink : 
Processes Hang Waiting on 'cursor: pin S wait on X' (and other Wait Events) on HP-UX 11.23 and 11.31 Itanium Systems [ID 580273.1]
Acurding to this note the 
 :Solution: on 11.23 install PHKL_37809 or later equivalent
Thanks
Randolf Geist
user10634138 wrote:
During those 17 min , the DB Time = 721.74 min and the "Top 5 Timed Events"
shows : "cursor: pin S wait on X" at the top of the Timed Events
Attached some details for the awr report

Could you please suggest where to focus ?
If you have a suitable license, what does the ADDM report for this time period tell you?

Regards,
Randolf

Oracle related stuff blog:
http://oracle-randolf.blogspot.com/

Co-author of the "OakTable Expert Oracle Practices" book:
http://www.apress.com/book/view/1430226684
http://www.amazon.com/Expert-Oracle-Practices-Database-Administration/dp/1430226684
avramits
Please also check if you have any bitmap indexes build on table. Bitmap index cause lock, when DML is undergoing on the table. Only one session will be manipulating data in a table with bitmap indexes in time. Rest DMLs will be waiting until transaction committed.
Jonathan Lewis
avramits wrote:
Please also check if you have any bitmap indexes build on table. Bitmap index cause lock, when DML is undergoing on the table. Only one session will be manipulating data in a table with bitmap indexes in time. Rest DMLs will be waiting until transaction committed.
Why are you chasing up 475 seconds of +"enq: TX - row lock contention"+ when there are 15,732 seconds of time lost to Cursor pin activity in the library cache ? At present it's a minor problem and not really worth chasing. If you want to chase a small but easy win the 1,510 seconds of +"log file switch (checkpoint"+ could probably be fixed by using larger, or more, log files.


(Your understanding of bitmap indexes is flawed, by the way - they can result in serious locking and deadlocking problems, but it is possible for multiple processes to modify the data in a table simultaneously even when there are multiple bitmaps on the table.)


Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
http://www.jlcomp.demon.co.uk

To post code, statspack/AWR report, execution plans or trace files, start and end the section with the tag {noformat}
{noformat} (lowercase, curly brackets, no spaces) so that the text appears in
fixed format
.

There is a +"Preview"+ tab at the top of the text entry panel. Use this to check what your message will look like before you post the message. If it looks a complete mess you're unlikely to get a response. (Click on the +"Plain text"+ tab if you want to edit the text to tidy it up.)

+"Science is more than a body of knowledge; it is a way of thinking"+
+Carl Sagan+
mbobak
Hi Jonathan,

I see the numbers you're referring to, with respect to hard parsing, but, what I don't understand is that if the level of hard parsing was that high, (and I do agree that 8.55 hard parses per second is pretty heavy), then I'd expect dominant wait events to be 'shared pool latch' and 'library cache latch'. Note that, if I recall correctly, mutexes are not used in hard parsing. Hard parsing requires acquisition of the shared pool latch, and any level of parsing other than session cursor cache hit requires a library cache latch (mutex is only used for session cursor cache hit and pinning/unpinning cursor). I believe that's true, at least in 10gR2. I think it may be more improved in 11g/11gR2.

But, my point is, this is a 10.2.0.4 database, so with a heavy hard parse load, I'd expect shared pool and libary cache latching to dominate. Since the dominant wait is on mutexes, that seems to imply an incredibly high soft parse/session cursor cache hit rate. And, fact, looking back at the Load Profile, while hard parses are 8.55/sec, total parses are 3,784.95/sec!! Over 17 minutes, that's more than 4 million soft parses (mostly cursor cache hits, presumably) in the 17.96 minute snapshot!

That seems just crazy. In fact, I'm starting to doubt the credibility of the data. Is this a monster of a box??

To the original poster: You mentioned it's an HP-UX box...any chance it's a monsterous Superdome, or something?

Jonathan,

Any further thoughts? I'd be interested in your reaction to my more recent analysis in this post....?

-Mark
Yoav
Hi,

I will try to answer some of the question being asked above
In fact, I'm starting to doubt the credibility of the data. Is this a monster of a box??
To the original poster: You mentioned it's an HP-UX box...any chance it's a monsterous Superdome, or something?
Yes it is a superdome : "ia64 hp superdome server SD32A" with 24GB and 8 cpus - I dont think its :"monster" machine.
P.S : You have no reason to "doubt the credibility of the data".


The application running against this instance is Oracle PeopleSoft 8.48 version.
In the past i opened a TAR to oracle PeopleSoft Team regarding the havy soft/hard parse , but i was told that this is
a normal behivor of PeopleSoft application.
Do you have session_cursor_cache parameter set to a reasonable value? 
10g, I believe the default is 50, which is probably not a bad starting point. 
You may get additional benefits with moderate increases, perhaps to 100-200 range
The session_cached_cursors is set to 300 , and open_cursor is set to 500.
But since cursor_space_for_time=FALSE , i will asked PeopleSoft if its OK with the application to set it to TRUE.
SQL> show parameter cursor
NAME                                 TYPE                              VALUE
------------------------------------ --------------------------------- ------------------------------
cursor_sharing                       string                            EXACT
cursor_space_for_time                boolean                           FALSE
open_cursors                         integer                           500
session_cached_cursors               integer                           300
Please also check if you have any bitmap indexes build on table
No i dont have any Bitmap indexes build on the table, as you can see bellow: 
SQL> select *
  2  from dba_indexes
  3  where table_name like 'PS_NAP%'
  4  and index_type like '%BITMAP%';

no rows selected
what does the ADDM report for this time period tell you?
The ADDM suggest to increase the SGA_TARGET from 7680M to 9600M
and also to increase open_cursors and session_cached_cursors.

It also recommand to tune the statment in FINDING 2 , and the rationale was:
RATIONALE: Waiting for event "cursor: pin S wait on X" in wait class
         "Concurrency" accounted for 98% of the database time spent in processing the SQL statement with SQL_ID "f3jf4n8unym33"
When i am trying to tune the statment i dont see any problem at all, whick make me think that this statment was hurt by
the cursor: pin S wait on X , and was not the reason for this wait event :
variable b1 number

begin
:b1 := 801494685;
end;
/

SQL> set lines 300
SQL> select * from table(dbms_xplan.display_cursor('3vnrxjacumxu8',0,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------
SQL_ID  3vnrxjacumxu8, child number 0
-------------------------------------
select /*+ gather_plan_statistics */        NAP_INT_CUST_NUM, NAP_LEAD_ID, NAP_ACRM_CHANNEL,
NAP_NBO_OFFER_DESC, TO_CHAR(ACTIVITY_DATE,'YYYY-MM-DD'),        NAP_ACRM_STATUS, NAP_TARGETAUDIENCE,
NAP_BILLING_CATNUM, NAP_DOC_ID,        NAP_DOC_NAME, AUDIENCE_IDENTIFY, NAP_TREATMENTID, NAP_CAMP_CODE FROM
  pssys.NAP_ACRM_HIST where  NAP_INT_CUST_NUM = :b1 AND    ROWNUM <= (SELECT Nap_Lead_Histview
     FROM   pssys.Nap_Parameters) ORDER BY NAP_INT_CUST_NUM, NAP_TREATMENTID, NAP_CAMP_CODE

Plan hash value: 4289755616

--------------------------------------------------------------------------------------------------------------------

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
--------------------------------------------------------------------------------------------------------------------
|*  1 |  COUNT STOPKEY               |                  |      1 |        |      3 |00:00:00.02 |      14 |      4 |
|   2 |   TABLE ACCESS BY INDEX ROWID| NAP_ACRM_HIST    |      1 |      2 |      3 |00:00:00.02 |      11 |      4 |
|*  3 |    INDEX RANGE SCAN          | PS_NAP_ACRM_HIST |      1 |      2 |      3 |00:00:00.01 |       5 |      1 |
|   4 |   TABLE ACCESS FULL          | NAP_PARAMETERS   |      1 |      1 |      1 |00:00:00.01 |       3 |      0 |
--------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------
   1 - filter(>=ROWNUM)
   3 - access("NAP_INT_CUST_NUM"=:B1)
25 rows selected.
Bellow is the part of ADDM output

 DETAILED ADDM REPORT FOR TASK 'TASK_61726' WITH ID 61726
          --------------------------------------------------------
              Analysis Period: 25-MAR-2010 from 10:30:42 to 10:48:39
         Database ID/Instance: xxxxx
      Database/Instance Names: xxxxx
                    Host Name: xxxxx
             Database Version: 10.2.0.4.0
               Snapshot Range: from 18085 to 18086
                Database Time: 43304 seconds
        Average Database Load: 40.2 active sessions
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

FINDING 1: 100% impact (43309 seconds)
--------------------------------------
The SGA was inadequately sized, causing additional I/O or hard parses.
RECOMMENDATION 1: DB Configuration, 100% benefit (43309 seconds)
ACTION: Increase the size of the SGA by setting the parameter "sga_target" to 9600 M.
ADDITIONAL INFORMATION: The value of parameter "sga_target" was "7680 M" during the analysis period.
SYMPTOMS THAT LED TO THE FINDING:
SYMPTOM: Wait class "User I/O" was consuming significant database time. (27% impact [11485 seconds])


FINDING 2: 40% impact (17213 seconds)
-------------------------------------
SQL statements consuming significant database time were found.

RECOMMENDATION 1: SQL Tuning, 32% benefit (13810 seconds)
ACTION: Investigate the SQL statement with SQL_ID "f3jf4n8unym33" for  possible performance improvements.
         RELEVANT OBJECT: SQL statement with SQL_ID f3jf4n8unym33 and  PLAN_HASH 4289755616

SELECT NAP_INT_CUST_NUM, NAP_LEAD_ID, NAP_ACRM_CHANNEL,
       NAP_NBO_OFFER_DESC, TO_CHAR(ACTIVITY_DATE,'YYYY-MM-DD'),
       NAP_ACRM_STATUS, NAP_TARGETAUDIENCE, NAP_BILLING_CATNUM, NAP_DOC_ID,
       NAP_DOC_NAME, AUDIENCE_IDENTIFY, NAP_TREATMENTID, NAP_CAMP_CODE 
FROM   NAP_ACRM_HIST 
where  NAP_INT_CUST_NUM = :1  
AND ROWNUM <= (SELECT Nap_Lead_Histview 
               FROM   Nap_Parameters) 
ORDER BY NAP_INT_CUST_NUM, NAP_TREATMENTID, NAP_CAMP_CODE

RATIONALE: SQL statement with SQL_ID "f3jf4n8unym33" was executed 894 times and had an average elapsed time of 15 seconds.
RATIONALE: Waiting for event "cursor: pin S wait on X" in wait class
         "Concurrency" accounted for 98% of the database time spent in processing the SQL statement with SQL_ID "f3jf4n8unym33".


FINDING 3: 40% impact (17133 seconds)
-------------------------------------
Soft parsing of SQL statements was consuming significant database time.

RECOMMENDATION 1: Application Analysis, 40% benefit (17133 seconds)
ACTION: Investigate application logic to keep open the frequently used
        cursors. Note that cursors are closed by both cursor close calls and session disconnects.

RECOMMENDATION 2: DB Configuration, 40% benefit (17133 seconds)
ACTION: Consider increasing the maximum number of open cursors a session
        can have by increasing the value of parameter "open_cursors".
ACTION: Consider increasing the session cursor cache size by increasing
         the value of parameter "session_cached_cursors".
RATIONALE: The value of parameter "open_cursors" was "500" during the  analysis period.
RATIONALE: The value of parameter "session_cached_cursors" was "300"   during the analysis period.

SYMPTOMS THAT LED TO THE FINDING:
SYMPTOM: Contention for latches related to the shared pool was consuming significant database time. (32% impact [13767 seconds])
INFO: Waits for "cursor: pin S wait on X" amounted to 31% of database time.
SYMPTOM: Wait class "Concurrency" was consuming significant database  time. (33% impact [14283 seconds])
Dom Brooks
Can you give any background/context to this sql statement from FINDING2?
What's going on here?
Is it static/dynamic sql?
Are there many child cursors for this parent?

Also, what does DBA_HIST_ACTIVE_SESS_HISTORY say about what's going on with the sessions involved with this mutex wait?
Possibly not a lot in 10g...

Also, dba_hist_sqlstat might be a good place to look to see whether, for the period in question, this particular sql is heavily involved in the parsing issues - I'd assume it was - notably the invalidations and parse numbers.

Edited by: DomBrooks on Mar 26, 2010 11:28 AM
Ospin
Hi user10634138

A Friend of mine had the same problem just after upgrading to 10g. It's BUG on HP-UX 11.23 and 11.31 and the real solution you realized is applying the Unix Patch just like metalink note show you. But if you are really worry, you can disable some Oracle behaviours with:

alter system set "_kks_use_mutex_pin"=FALSE;

This is not a good option, but if your Unix team, can't do anything now, you could try with this. Of course this is a hidden parameter, if you want to touch it, you must first consult with your Orale support.
This is just an emergency solution, please just depens on your situation.

John
Yoav
Hi Mr. Brooks
I run some queries against the views and that what i found out :
- Two statments had been wait on event : "cursor: pin S wait on X"
- Each time the statments were executed they had been parsed again
- They did not consume alot of memory/buffer gets
- The statment f3jf4n8unym33 wait much more time than the other.

Beside the parsing issue , my question is what i can do with this information - regarding those statments.
As i show in my previous post when i run it with sqlplus its finished after 0.02 second .

SQL> select count(*), sql_id,sql_child_number,session_state,blocking_session_status,event,wait_class
  2  from DBA_HIST_ACTIVE_SESS_HISTORY 
  3  where snap_id between 18085 and 18086
  4  and event like '%cursor: pin S wait on X%'
  5  group by sql_id,sql_child_number,session_state,blocking_session_status,event,wait_class
  6  /

   COUNT(*) SQL_ID        SQL_CHILD_NUMBER SESSION_STATE         BLOCKING_SESSIO EVENT                            WAIT_CLASS
 ---------- ------------- ---------------- --------------------- --------------- -------------------------------- --------------------
        945 f3jf4n8unym33               -1 WAITING               UNKNOWN         cursor: pin S wait on X          Concurrency
        463 f3jf4n8unym33                2 WAITING               UNKNOWN         cursor: pin S wait on X          Concurrency
          3 4gxckt3582p6x                2 WAITING               UNKNOWN         cursor: pin S wait on X          Concurrency
          2 4gxckt3582p6x               -1 WAITING               UNKNOWN         cursor: pin S wait on X          Concurrency
 
SQL> select sql_id,optimizer_cost o_cost,optimizer_mode o_mode ,SHARABLE_MEM mem ,
        version_count ver_c,fetches_total fetc_t ,END_OF_FETCH_COUNT_TOTAL cnt_total,
        EXECUTIONS_TOTAL exe ,PARSE_CALLS_TOTAL pars,DISK_READS_TOTAL disk_t,
        BUFFER_GETS_TOTAL buffer_t ,ROWS_PROCESSED_TOTAL rows_t ,cpu_time_total cpu_t,
        round(elapsed_time_total/1000000) elapsed_s ,iowait_total
from dba_hist_sqlstat
where snap_id between 18085 and 18086
and sql_id in ('f3jf4n8unym33','4gxckt3582p6x')
/

SQL_ID		O_COST	O_MODE	    MEM	   VER_C  FETC_T  CNT_TOTAL  EXE   PARS	DISK_T	BUFFER_T ROWS_T	CPU_T	  ELAPSED_S  IOWAIT_TOTAL
-------------   ------  ----------  ------ -----  ------  ---------  ---   ---- ------  -------- ------ --------  ---------  ------------  
f3jf4n8unym33	3	FIRST_ROWS  7173   5	  894	  894	     894   894	162	154482	 15	74418537  13538      1394408
4gxckt3582p6x	6	FIRST_ROWS  77810  5	  1948	  1948	     1948  1948	2586	2157033	 505	16973767  663        17332808
Yoav
Hello ,
I applied the recommended patch as suggested by oracle metalink note :
Processes Hang Waiting on 'cursor: pin S wait on X' (and other Wait Events) on HP-UX 11.23 and 11.31 Itanium Systems [ID 580273.1]

Yet, affter applying the patch i still find in the top 5 wait event : "cursor: pin S wait on X" with more than 40%.
For 18.91 (mins) awr report , the database spent : 520.52 (mins)

I am aware to the parsing issue but PeopleSoft claim that this the way that the application should work.

Can one suggest how to reduce the amount of :"cursor: pin S wait on X" wait event dramatically ? 

 
              Snap Id      Snap Time      Sessions Curs/Sess 
            --------- ------------------- -------- --------- 
Begin Snap:     20085 22-Apr-10 08:41:26       215       7.9 
  End Snap:     20086 22-Apr-10 09:00:21       229       9.3 
   Elapsed:               18.91 (mins) 
   DB Time:              520.52 (mins) 

Cache Sizes 
~~~~~~~~~~~                       Begin        End 
                             ---------- ---------- 
               Buffer Cache:     2,832M     2,832M  Std Block Size:         8K 
           Shared Pool Size:     4,384M     4,384M      Log Buffer:     2,080K 

Load Profile 
~~~~~~~~~~~~                            Per Second       Per Transaction 
                                   ---------------       --------------- 
                  Redo size:          3,685,552.61 ;           397,661.87 
              Logical reads:            129,726.29 ;            13,997.14 
              Block changes:             17,903.65 ;             1,931.76 
             Physical reads:              1,053.16 ;               113.63 
            Physical writes:                470.01 ;                50.71 
                 User calls:              4,054.90 ;               437.51 
                     Parses:              2,619.13 ;               282.60 
                Hard parses:                  3.06 ;                 0.33 
                      Sorts:                160.56 ;                17.32 
                     Logons:                  0.28 ;                 0.03 
                   Executes:              2,944.78 ;               317.73 
               Transactions:                  9.27 

  % Blocks changed per Read:   13.80 ;   Recursive Call %:    26.20 
Rollback per transaction %:    0.10 ;      Rows per Sort:    75.19 

Instance Efficiency Percentages (Target 100%) 
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 
            Buffer Nowait %:   99.97 ;      Redo NoWait %:   99.97 
            Buffer  Hit   %:   99.19 ;   In-memory Sort %:  100.00 
            Library Hit   %:   99.85 ;       Soft Parse %:   99.88 
         Execute to Parse %:   11.06 ;        Latch Hit %:   99.94 
Parse CPU to Parse Elapsd %:    1.22 ;    % Non-Parse CPU:   94.28 

Shared Pool Statistics        Begin    End 
                              ------  ------ 
             Memory Usage %:   74.28 ;  75.83 
    % SQL with executions>1:   96.61 ;  93.65 
  % Memory for SQL w/exec>1:   95.67 ;  92.79 

Top 5 Timed Events                                         Avg %Total 
~~~~~~~~~~~~~~~~~~                                        wait   Call 
Event                                 Waits    Time (s)   (ms)   Time Wait Class 
------------------------------ ------------ ----------- ------ ------ ---------- 
cursor: pin S wait on X           1,257,959      13,163     10   42.1 Concurrenc 
db file sequential read           1,111,123       8,775      8   28.1 ;  User I/O 
CPU time                                          2,938           9.4 
log file switch (checkpoint in        2,651       1,711    645    5.5 Configurat 
free buffer waits                   111,826       1,123     10    3.6 Configurat 
          ------------------------------------------------------------- 

.... 

                                                                   Avg 
                                             %Time  Total Wait    wait     Waits 
Event                                 Waits  -outs    Time (s)    (ms)      /txn 
---------------------------- -------------- ------ ----------- ------- --------- 
cursor: pin S wait on X           1,257,959  100.0 ;     13,163      10     119.6 
db file sequential read           1,111,123     .0       8,775       8     105.7 
log file switch (checkpoint           2,651   58.0 ;      1,711     645       0.3 
free buffer waits                   111,826   99.6 ;      1,123      10      10.6 
local write wait                        838   84.2 ;        717     856       0.1 
enq: RO - fast object reuse             258   82.6 ;        652    2527       0.0 
log file parallel write              17,561     .0         441      25       1.7 
log file sync                        12,167     .0         409      34       1.2 
read by other session                30,093     .0         312      10       2.9 
library cache lock                       92   95.7 ;        256    2786       0.0 
Log archive I/O                       4,189     .0         198      47       0.4 
buffer busy waits                     7,475    2.4 ;        190      25       0.7 
db file parallel read                10,159     .0         114      11       1.0 
db file scattered read                7,748     .0          92      12       0.7 
log buffer space                      1,486     .0          65      44       0.1 
log file sequential read              4,248     .0          46      11       0.4 
enq: TX - row lock contentio            102    8.8 ;         40     388       0.0 
latch: cache buffers chains           6,447     .0          32       5       0.6 
cursor: pin S                        60,439     .0          29       0       5.7 
SQL*Net more data from clien        293,638     .0          21       0      27.9 
latch: library cache                    781     .0          18      24       0.1 
control file parallel write           1,038     .0          14      13       0.1 
SQL*Net more data to client         225,055     .0          10       0      21.4 
control file sequential read          7,538     .0           9       1       0.7 
log file switch completion               67    7.5 ;          8     123       0.0 
SQL*Net message to client         4,078,820     .0           5       0     387.9 
enq: TX - contention                      9     .0           5     521       0.0 
latch free                              776     .0           4       5       0.1 
write complete waits                     50   72.0 ;          4      77       0.0 
enq: TX - index contention              276     .0           3      12       0.0 
block change tracking buffer             51     .0           2      47       0.0 
LGWR wait for redo copy               1,464    8.1 ;          2       1       0.1 
latch: session allocation                41     .0           1      23       0.0 
latch: redo allocation                  502     .0           1       2       0.0 
enq: CF - contention                      4     .0           1     191       0.0 
...
Charles Hooper
You might take a look at Metalink (MOS) Bug: 7462072 Unnecessary "cursor: pin S wait on X" waits, which describes a bug that results in unnecessary 10ms waits on 'cursor: pin S wait on X' - the problem is apparently corrected with the 10.2.0.4.3 patch. All of your 'cursor: pin S wait on X' waits resulted in timeouts (10ms), which might mean that 12 of the sessions were stuck in this wait event for the duration of the AWR/Statpack collection period.

I might be remembering incorrectly, but I believe that I have seen similiar sessions stuck in this wait event when a 10046 trace was enabled for a client computer which was running an 8i client that connected to a 10g R2 database, and also occasionally when flushing the shared pool.

A possibly related, recent blog article,:
http://blog.tanelpoder.com/2010/04/21/cursor-pin-s-waits-sporadic-cpu-spikes-and-systematic-troubleshooting/

Charles Hooper
Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
http://hoopercharles.wordpress.com/
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Yoav
Hello Charles,
Thank you for your feedback.

I already installed one month ago the 102043 Patch.
Regarding the very intresting blog of Mr. Tanle , in my case there isnt any CPU issue.

Thanks
user7983928
Have you thought of checking for the chained rows on the table.

There's a very strong relationship between Chained rows and Cursor pin wait on X especially runder under heavy concurrent Load.

Can you please check, and if any, remove the chained rows and see if it gives any error.

Also, what was the CPU Utilization on the db server during the time this wait events occurred
Jonathan Lewis
user7983928 wrote:
Have you thought of checking for the chained rows on the table.
There's a very strong relationship between Chained rows and Cursor pin wait on X especially runder under heavy concurrent Load.
That seems rather unlikely, given that chained rows are about data and would tend to have an impact on buffer cache handling while "cursor: pin S wait on X" is about the library cache.

Do you have any evidence or reference articles to back up your statement ?

Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
http://www.jlcomp.demon.co.uk

To post code, statspack/AWR report, execution plans or trace files, start and end the section with the tag {noformat}
{noformat} (lowercase, curly brackets, no spaces) so that the text appears in
fixed format
.

There is a +"Preview"+ tab at the top of the text entry panel. Use this to check what your message will look like before you post the message. If it looks a complete mess you're unlikely to get a response. (Click on the +"Plain text"+ tab if you want to edit the text to tidy it up.)

+"Science is more than a body of knowledge; it is a way of thinking"+
+Carl Sagan+
Jonathan Lewis
user10634138 wrote:
RECOMMENDATION 1: SQL Tuning, 32% benefit (13810 seconds)
ACTION: Investigate the SQL statement with SQL_ID "f3jf4n8unym33" for possible performance improvements.
RELEVANT OBJECT: SQL statement with SQL_ID f3jf4n8unym33 and PLAN_HASH 4289755616

SELECT NAP_INT_CUST_NUM, NAP_LEAD_ID, NAP_ACRM_CHANNEL,
NAP_NBO_OFFER_DESC, TO_CHAR(ACTIVITY_DATE,'YYYY-MM-DD'),
NAP_ACRM_STATUS, NAP_TARGETAUDIENCE, NAP_BILLING_CATNUM, NAP_DOC_ID,
NAP_DOC_NAME, AUDIENCE_IDENTIFY, NAP_TREATMENTID, NAP_CAMP_CODE
FROM NAP_ACRM_HIST
where NAP_INT_CUST_NUM = :1
AND ROWNUM <= (SELECT Nap_Lead_Histview
FROM Nap_Parameters)
ORDER BY NAP_INT_CUST_NUM, NAP_TREATMENTID, NAP_CAMP_CODE

RATIONALE: SQL statement with SQL_ID "f3jf4n8unym33" was executed 894 times and had an average elapsed time of 15 seconds.
RATIONALE: Waiting for event "cursor: pin S wait on X" in wait class
"Concurrency" accounted for 98% of the database time spent in processing the SQL statement with SQL_ID "f3jf4n8unym33".
Can you supply us with the result of running awrsqrpt.sql for this period and sql_id.
Are there any global temporary tables involved in this query ?
Are there any tables which have RLS predicates on them, or are private copies ?

Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
http://www.jlcomp.demon.co.uk

To post code, statspack/AWR report, execution plans or trace files, start and end the section with the tag {noformat}
{noformat} (lowercase, curly brackets, no spaces) so that the text appears in
fixed format
.

There is a +"Preview"+ tab at the top of the text entry panel. Use this to check what your message will look like before you post the message. If it looks a complete mess you're unlikely to get a response. (Click on the +"Plain text"+ tab if you want to edit the text to tidy it up.)

+"Science is more than a body of knowledge; it is a way of thinking"+
+Carl Sagan+
Yoav
Hello,

1. Bellow an updated awrsqlrpt.sql report for this statment
2. No global temporary tables are involved in this statment.
3. No RLS/VPD on them. The statment is being executed by Oracle PeopleSoft Application

Some general information:
- Table NAP_PARAMETERS contain just 1 row and it exists in the KEEP buffer pool
- Table NAP_ACRM_HIST contail about 1,000,000 rows and it exists in the DEFAULT buffer pool


During this update report, the statment was executed 664 times , Elapsed time per execution was 14.12 sec , and total time 9,373 sec ,
while CPU time just 74 sec.
Each time the statment was executed it was parsed :
Parse Calls = Executions = 664
Concurrency Wait time = 8711 sec

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
xxxx          111111111  xxxx                1 10.2.0.4.0  NO  xxxx

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     20085 22-Apr-10 08:41:26       215       7.9
  End Snap:     20086 22-Apr-10 09:00:21       229       9.3
   Elapsed:               18.91 (mins)
   DB Time:              520.52 (mins)

SQL Summary                             DB/Inst: xxxx/xxxx  Snaps: 20085-20086

                Elapsed
   SQL Id      Time (ms)
------------- ----------
f3jf4n8unym33  9,372,740
Module: PSAPPSRV@crmapp12 (TNS V1-V3)
SELECT NAP_INT_CUST_NUM, NAP_LEAD_ID, NAP_ACRM_CHANNEL, NAP_NBO_OFFER_DESC, TO_C
HAR(ACTIVITY_DATE,'YYYY-MM-DD'), NAP_ACRM_STATUS, NAP_TARGETAUDIENCE, NAP_BILLIN
G_CATNUM, NAP_DOC_ID, NAP_DOC_NAME, AUDIENCE_IDENTIFY, NAP_TREATMENTID, NAP_CAMP_CODE
FROM NAP_ACRM_HIST where NAP_INT_CUST_NUM = :1 AND ROWNUM <= (SELECT Nap_

          -------------------------------------------------------------

SQL ID: f3jf4n8unym33                   DB/Inst: xxxx/xxxx  Snaps: 20085-20086
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> SELECT NAP_INT_CUST_NUM, NAP_LEAD_ID, NAP_ACRM_CHANNEL, NAP_NBO_OFFER_...

    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   4289755616              9,372,740           664         20086          20086
          -------------------------------------------------------------


Plan 1(PHV: 4289755616)
-----------------------

Plan Statistics                         DB/Inst: xxxx/xxxx  Snaps: 20085-20086
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100

Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                         9,372,740       14,115.6    30.0
CPU Time (ms)                                73,597          110.8     2.5
Executions                                      664            N/A     N/A
Buffer Gets                                 180,401          271.7     0.1
Disk Reads                                    3,046            4.6     0.3
Parse Calls                                     664            1.0     0.0
Rows                                              0            0.0     N/A
User I/O Wait Time (ms)                       9,228            N/A     N/A
Cluster Wait Time (ms)                            0            N/A     N/A
Application Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                8,711,050            N/A     N/A
Invalidations                                     0            N/A     N/A
Version Count                                     3            N/A     N/A
Sharable Mem(KB)                                 27            N/A     N/A
          -------------------------------------------------------------

Execution Plan
-------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                  |       |       |     3 (100)|          |
|   1 |  COUNT STOPKEY               |                  |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| NAP_ACRM_HIST    |     2 |   258 |     1   (0)| 00:00:01 |
|   3 |    INDEX RANGE SCAN          | PS_NAP_ACRM_HIST |     2 |       |     1   (0)| 00:00:01 |
|   4 |   TABLE ACCESS FULL          | NAP_PARAMETERS   |     1 |    13 |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------



Full SQL Text

SQL ID       SQL Text
------------ -----------------------------------------------------------------
f3jf4n8unym3 SELECT NAP_INT_CUST_NUM, NAP_LEAD_ID, NAP_ACRM_CHANNEL, NAP_NBO_O
             OFFER_DESC, TO_CHAR(ACTIVITY_DATE, 'YYYY-MM-DD'), NAP_ACRM_STATUS
             , NAP_TARGETAUDIENCE, NAP_BILLING_CATNUM, NAP_DOC_ID, NAP_DOC_NAM
             E, AUDIENCE_IDENTIFY, NAP_TREATMENTID, NAP_CAMP_CODE FROM NAP_ACR
             M_HIST where NAP_INT_CUST_NUM = :1 AND ROWNUM <= (SELECT Nap_Lead
             _Histview FROM Nap_Parameters) ORDER BY NAP_INT_CUST_NUM, NAP_TRE
             ATMENTID, NAP_CAMP_CODE
Jonathan Lewis
user10634138 wrote:
Hello,

1. Bellow an updated awrsqlrpt.sql report for this statment
2. No global temporary tables are involved in this statment.
3. No RLS/VPD on them. The statment is being executed by Oracle PeopleSoft Application
Thanks for posting the output. I was hoping that there might be some clue in the details available through the awrsqrpt, but there doesn't seem to be any new information in it.

One thing, though: Charles Hooper mentioned a bug that matches your symptoms very well and pointed out that it's fixed in 10.2.0.4.3. I think you replied that you had already installed that patch. But this output shows the version as 10.2.0.4.0 - are you sure that the patch is installed on this database ?

Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
http://www.jlcomp.demon.co.uk

To post code, statspack/AWR report, execution plans or trace files, start and end the section with the tag {noformat}
{noformat} (lowercase, curly brackets, no spaces) so that the text appears in
fixed format
.

There is a +"Preview"+ tab at the top of the text entry panel. Use this to check what your message will look like before you post the message. If it looks a complete mess you're unlikely to get a response. (Click on the +"Plain text"+ tab if you want to edit the text to tidy it up.)

+"Science is more than a body of knowledge; it is a way of thinking"+
+Carl Sagan+
Yoav
Hello Mr.Lewis,
Thank you for your feedbacks.
+Mr.Lewis wrote:+
One thing, though: Charles Hooper mentioned a bug that matches your symptoms very well and pointed out that it's fixed in 10.2.0.4.3. I think you replied that you had already installed that patch. But this output shows the version as 10.2.0.4.0 - are you sure that the patch is installed on this database ?
Yes i am sure that the pacth was installed. The version in v$instance will not change after applyinh the PSU patch.

Metalink note: Patch Set Updates for Oracle Products [ID 854428.1] 
6 Determining the Patch Set Update Version
Patch Set Updates are referenced by their 5-place version number. 
Use the OPatch inventory and the relevant table in this section to determine the PSU version currently installed.
From Oracle Metalink Note : 9119284.8 
Bug 9119284 - 10.2.0.4.3 Patch Set Update (PSU 3) [ID 9119284.8]
...
Plus fixes for the following bugs:
....
Bug:7462072 Unnecessary "cursor: pin S wait on X" waits
...
And the opatch lsinventory for my database shows:
....
Patch  9119284      : applied on Mon Mar 15 03:43:37 GMT+02:00 2010
Unique Patch ID:  12095738
Created on 7 Jan 2010, 04:36:32 hrs PST8PDT
Bugs fixed:
...
7462072, 7600026, 6679303, 7197583, 7172752, 7326645, 7008262, 9173244
....
So , the patch was applied for sure.

Thanks
Jonathan Lewis
Thanks for confirming:

Can you see a fix in your list for bug 7234778 (SELECTS AGAINST DUAL CAUSE CURSOR PIN S WAIT ON X WAITS).
This is reported as "seen in 10.2.0.4" and fixed in 11.2.0.1.

I know the reference is to dual - but the text of the bug doesn't state that it HAS to be DUAL that causes the problem. (I got to this bug by tracking back through: 9320249 and 7462072 - so it would be worth checking if you have the fix for either of those in your patch set).


Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
http://www.jlcomp.demon.co.uk

To post code, statspack/AWR report, execution plans or trace files, start and end the section with the tag {noformat}
{noformat} (lowercase, curly brackets, no spaces) so that the text appears in
fixed format
.

There is a +"Preview"+ tab at the top of the text entry panel. Use this to check what your message will look like before you post the message. If it looks a complete mess you're unlikely to get a response. (Click on the +"Plain text"+ tab if you want to edit the text to tidy it up.)

+"Science is more than a body of knowledge; it is a way of thinking"+
+Carl Sagan+
Yoav
Hellow Mr.Lewis
Thanks for your feedback.

I searched the Metalink and found the follwing information:

MetaLink Note: 786507.1 - HOW TO FIND BLOCKING SESSION FOR MUTEX WAIT EVENT cursor: pin S wait on X 
 
" 
.... 
One of the most likely cause of cursor: pin S wait on X is high parsing time. 
So investigate what is cause of high parsing. 
"
And indeed one of the biggest problem is that the PeopleSoft application is parsing almost every statment that is being executed.
As you remmeber the latest sqlid that you asked to supply information about it, was executed=parsed=664 times.
But since its Oracle product and the PeopleSoft team claim that this the normal way that the application is working - I dont know
how to deal with this problem.

Related to list of bugs that you mentioned ,I recheck the applied list of bugs in my lsinventory :

Bug 7462072: SELECTS AGAINST DUAL CAUSE CURSOR PIN S WAIT ON X WAITS ==> Applied
Bug 9320249: HIGH CURSOR: PIN S WAIT ON X WAITS ==> Not Applied , but it Base Bug is 7462072
Bug 7234778: SELECTS AGAINST DUAL CAUSE CURSOR PIN S WAIT ON X WAITS ==> Not Applied


I executed the test they took in bug 7234778 , and bellow is the 10046 results.
Inside Bug they wrote : 
"Review the trace files and notice that over time sessions occassionally wait on:  "cursor: pin S wait on X" 
... 
" 
So there two related issues:      
1. We see "cursor: pin S wait on X" waits when there was no  X blocker which is confusing for diagnosis purposes.      
2. As the wait is taken to be "cursor: pin S wait on X" a  10mS sleep occurs in the process instead of just yielding. 
" 
{code}

But in my case 10046 trace files shows : "cursor: pin S"  and not "cursor: pin S wait on X" - So actually i dont know if i hit the bug or not. 

{code}
ALTER SESSION SET max_dump_file_size = unlimited; 
ALTER SESSION SET tracefile_identifier = '10046_1'; 
ALTER SESSION SET statistics_level = ALL; 
ALTER SESSION SET events '10046 trace name context forever, level 8'; 

declare 
vCHAR varchar2(10); 
BEGIN 
FOR I IN 1..1000000 LOOP 
   BEGIN 
        SELECT '' INTO vCHAR FROM DUAL WHERE 1=0; 
   EXCEPTION 
       WHEN NO_DATA_FOUND THEN 
       NULL; 
   END; 
END LOOP; 
COMMIT; 
END; 

call     count       cpu    elapsed       disk      query    current        rows 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
Parse        1      0.00 ;      0.00 ;         0          0          0           0 
Execute 1000000     13.79 ;     12.14 ;         0          0          0           0 
Fetch   1000000      3.15 ;      1.66 ;         0          0          0           0 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total   2000001     16.94 ;     13.80 ;         0          0          0           0 

Misses in library cache during parse: 0 
Optimizer mode: FIRST_ROWS 
Parsing user id: 65     (recursive depth: 1) 

Rows     Row Source Operation 
-------  --------------------------------------------------- 
      0  FILTER  (cr=0 pr=0 pw=0 time=1132625 us) 
      0   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us) 


Elapsed times include waiting on following events: 
  Event waited on                             Times   Max. Wait  Total Waited 
  ----------------------------------------   Waited  ----------  ------------ 
  SQL*Net message to client                       1        0.00 ;         0.00 
  SQL*Net message from client                     1       75.81 ;        75.81 
  cursor: pin S                                 601        0.00 ;         0.00 
{code}

Thanks again for your effort, and recommendations
Timur Akhmadeev
Hi,
Regarding the very intresting blog of Mr. Tanel , in my case there isnt any CPU issue.
and what's the CPU load in this period?
Can you post AWR sections 'SQL ordered by parse calls' & 'SQL ordered by executions'?
Yoav
Hello Timur,

Unfortunately , i cant supply numbers about CPU Load during this time. i just looked at the machine load , and did not see any cpu starvation.
Its a superdome machine with 8 CPUs.

Today, i installed OSW in order to collect more accurate information, and i belive that tommorow morning i will have accurate numbers.

Beside at Mr. Tanel Poder blog, he wrote that they set the init.ora parameter hpux_sched_noage in order to solve there problem (he didnt wrote to which value he set it ).
In my case this parameter is already being set in the past to a value of 178.

Regarding to your question about :"SQL ordered by Parse Calls" in the awr report.
As you can see the statments parse is almost identical to the number of the executions.
SQL ordered by Parse Calls             DB/Inst: xxxx/xxxx  Snaps: 20085-20086
-> Total Parse Calls:       2,971,801
-> Captured SQL account for      61.9% of Total

                            % Total
 Parse Calls  Executions     Parses    SQL Id
------------ ------------ --------- -------------
     200,656      200,664      6.75 14969yyrgat9y
Module: PSAPPSRV@crmapp5 (TNS V1-V3)
SELECT PKG.RB_TEMPLATE_ID, PKG.RB_TEMPLATE_NAME FROM PS_RBC_PACKAGE_DFN PKG, PS_
RBC_TEMPLAT_FIL TMPL WHERE PKG.RB_PACKAGE_NAME=:1 AND PKG.RB_PACKAGE_ID=:2 AND P
KG.LANGUAGE_CD=:3 AND PKG.RB_TEMPLATE_NAME = TMPL.RB_TEMPLATE_NAME AND PKG.RB_TE
MPLATE_ID = TMPL.RB_TEMPLATE_ID AND PKG.LANGUAGE_CD = TMPL.LANGUAGE_CD AND (TMPL

     195,598      195,604      6.58 a35hd9nzn6fbv
Module: PSAPPSRV@crmapp3 (TNS V1-V3)
SELECT FILENAME FROM PS_RBC_PACKAGE_FIL WHERE RB_PACKAGE_NAME=:1 AND RB_PACKAGE_
ID=:2 AND LANGUAGE_CD=:3

     179,270      179,271      6.03 1tzxyaam5uk1u
Module: pmdtm@ (TNS V1-V3)
 BEGIN PSSYS.NAP_TELEM_PG.GET_NEXT_LINE_SEQ_PR (:1,:2) ; END;

     175,887      175,896      5.92 1afwgd54arjvm
Module: PSAPPSRV@crmapp5 (TNS V1-V3)
SELECT 'X' FROM PS_RBC_PACKAG_TMPL PKG, PS_RBC_TEMPLAT_FIL TMPL WHERE PKG.RB_PAC
KAGE_NAME=:1 AND PKG.RB_PACKAGE_ID=:2 AND PKG.LANGUAGE_CD=:3 AND PKG.RB_TEMPLATE
_NAME = TMPL.RB_TEMPLATE_NAME AND PKG.RB_TEMPLATE_ID = TMPL.RB_TEMPLATE_ID AND P
KG.LANGUAGE_CD = TMPL.LANGUAGE_CD AND (TMPL.RB_DELV_CHANNEL = '1' OR TMPL.RB_DEL

     169,198      169,205      5.69 fpbfw8bq9mpdw
Module: PSAPPSRV@crmapp3 (TNS V1-V3)
SELECT ROLEUSER,ROLENAME,DYNAMIC_SW FROM PSROLEUSER WHERE ROLENAME = :1

     119,917      119,919      4.04 bdntyxtax2smq
Module: PSPRCSRV.exe
SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = 'SYS'
1 - 26
Locked Post
New comments cannot be posted to this locked post.

Post Details

Locked on May 22 2010
Added on Mar 25 2010
#general-database-discussions
26 comments
12,158 views