Re: Parsing Problem - I think
From: Kenny Payton <k3nnyp_at_gmail.com>
Date: Tue, 25 Mar 2014 09:29:05 -0400
Message-Id: <2F17AFBB-AC6C-4235-B79A-CF5A36AA0AC0_at_gmail.com>
I have experienced this wait event on a number of occasions most notably caused by “drop trigger” and “dbms_stats.gather_table_stats” commands. In fact, we currently have a job that monitors application spawned stats gathering jobs which are causing this condition and kill the stats job when sizable contention occurs to alleviate the problem. The ‘cursor: pin S wait on X’ wait event will appear in user sessions trying to parse statements. This will prolong the elapsed parse time.
>> Hi, Fred
>> In my opinion, you should really check the hard parse issue in your db.
>> The soft parse percentage and hard pase time take up most of parse time.
>> And the most possible reason for wait event 'cursor: pin S wait on X' might really cause by this.
>>
>>
>> Best Regards,
>> Milo
>>
>> From: Fred Tilly
>> Date: 2014-03-25 20:29
>> To: oracle-l_at_freelists.org
>> Subject: Parsing Problem - I think
>> Hi All,
>>
>> Looking at an AWR report from a customer site where they have had some very slow performance.
>>
>> Server is 32 CPU and 26GB running Oracle 11.2.0.3
>>
>> AWR is over 1 hour and shows:
>>
>> Parses: 22.6 0.5
>> Hard parses: 5.1 0.1
>>
>> Elapsed: 59.37 (mins)
>> DB Time: 587.12 (mins)
>>
>> Buffer Nowait %: 100.00 Redo NoWait %: 100.00
>> Buffer Hit %: 99.91 In-memory Sort %: 100.00
>> Library Hit %: 94.89 Soft Parse %: 77.60
>> Execute to Parse %: 92.71 Latch Hit %: 99.95
>> Parse CPU to Parse Elapsd %: 57.49 % Non-Parse CPU: 54.03
>>
>> Top 5 Timed Foreground Events
>> Event Waits Time(s) Avg wait (ms) % DB time Wait Class
>> DB CPU 22,086 62.70
>> cursor: pin S wait on X 12 705 58760 2.00 Concurrency
>> log file sync 142,183 469 3 1.33 Commit
>> db file sequential read 48,259 155 3 0.44 User I/O
>> buffer busy waits 2,144 129 60 0.37 Concurrency
>>
>>
>> Statistic Name Time (s) % of DB Time
>> DB CPU 22,086.13 62.70
>> parse time elapsed 19,559.05 55.52
>> hard parse elapsed time 18,490.89 52.49
>> sql execute elapsed time 15,126.32 42.94
>>
>> From the information in the AWR report I do not appear to be parsing a lot of statements per second, but my hard parse time seems really high.
>>
>> What else do I need to look at to get to the bottom of this issue.
>>
>> Thanks
>>
>> Fred
Date: Tue, 25 Mar 2014 09:29:05 -0400
Message-Id: <2F17AFBB-AC6C-4235-B79A-CF5A36AA0AC0_at_gmail.com>
I have experienced this wait event on a number of occasions most notably caused by “drop trigger” and “dbms_stats.gather_table_stats” commands. In fact, we currently have a job that monitors application spawned stats gathering jobs which are causing this condition and kill the stats job when sizable contention occurs to alleviate the problem. The ‘cursor: pin S wait on X’ wait event will appear in user sessions trying to parse statements. This will prolong the elapsed parse time.
User A : DML against object
User B : Attempts DDL ( including dbms_stats ) waits for User A DML statement to complete ( does not need to commit )
User C-Z : ‘cursor: pin S wait on X’ wait event waiting for B to acquire lock on object.
When User A completes User B acquires needed latch and Users C-Z are able to once again parse.
To my earlier point this appears to me to be a minor portion of the wait time.
Kenny
On Mar 25, 2014, at 9:12 AM, Milo <xueyuan.luo_at_gmail.com> wrote:
> Hi, Kenny > Base on my knowledgement, if this cause by DDL statement, 'library cache lock' might show on top events. > So I prefer to say it might cause by hard parse. > If this issue ocurred in the past, v$active_session_history might be another choice to investigate the 'cursor: pin S wait on X' event. > Correct me if I am wrong. > Thanks very much. > > Best Regards, > Milo > > From: Kenny Payton > Date: 2014-03-25 20:57 > To: xueyuan.luo > CC: ftilly; Oracle Discussion List > Subject: Re: Parsing Problem - I think > > The ‘cursor: pin S wait on X’ appears to be a contributing factor but from these stats it appears to only be a small portion of time spent parsing ( 705s of 19,559s ). BTW, this wait event could be caused by almost any DDL, including the stats gathering. > > If you have sufficiently diverse sessions you could narrow down the sessions with poor parse time by looking at v$sess_time_model where stat_name = ‘parse time elapsed’. I don’t know of anywhere the parse time is recorded at a statement level but that would be nice. > > Once narrowed down pick a session and trace it, tkprof will show you parse times per statement. > > > Kenny > > > On Mar 25, 2014, at 8:40 AM, Milo <xueyuan.luo_at_gmail.com> wrote: >
>> Hi, Fred
>> In my opinion, you should really check the hard parse issue in your db.
>> The soft parse percentage and hard pase time take up most of parse time.
>> And the most possible reason for wait event 'cursor: pin S wait on X' might really cause by this.
>>
>>
>> Best Regards,
>> Milo
>>
>> From: Fred Tilly
>> Date: 2014-03-25 20:29
>> To: oracle-l_at_freelists.org
>> Subject: Parsing Problem - I think
>> Hi All,
>>
>> Looking at an AWR report from a customer site where they have had some very slow performance.
>>
>> Server is 32 CPU and 26GB running Oracle 11.2.0.3
>>
>> AWR is over 1 hour and shows:
>>
>> Parses: 22.6 0.5
>> Hard parses: 5.1 0.1
>>
>> Elapsed: 59.37 (mins)
>> DB Time: 587.12 (mins)
>>
>> Buffer Nowait %: 100.00 Redo NoWait %: 100.00
>> Buffer Hit %: 99.91 In-memory Sort %: 100.00
>> Library Hit %: 94.89 Soft Parse %: 77.60
>> Execute to Parse %: 92.71 Latch Hit %: 99.95
>> Parse CPU to Parse Elapsd %: 57.49 % Non-Parse CPU: 54.03
>>
>> Top 5 Timed Foreground Events
>> Event Waits Time(s) Avg wait (ms) % DB time Wait Class
>> DB CPU 22,086 62.70
>> cursor: pin S wait on X 12 705 58760 2.00 Concurrency
>> log file sync 142,183 469 3 1.33 Commit
>> db file sequential read 48,259 155 3 0.44 User I/O
>> buffer busy waits 2,144 129 60 0.37 Concurrency
>>
>>
>> Statistic Name Time (s) % of DB Time
>> DB CPU 22,086.13 62.70
>> parse time elapsed 19,559.05 55.52
>> hard parse elapsed time 18,490.89 52.49
>> sql execute elapsed time 15,126.32 42.94
>>
>> From the information in the AWR report I do not appear to be parsing a lot of statements per second, but my hard parse time seems really high.
>>
>> What else do I need to look at to get to the bottom of this issue.
>>
>> Thanks
>>
>> Fred
-- http://www.freelists.org/webpage/oracle-lReceived on Tue Mar 25 2014 - 14:29:05 CET