RE: Hard parse elapsed time in AWR

Hi Stefan,
Thank you. It is my understanding that the payload is large but I do not know exactly how it is processed. Here is the processing flow:

A large XML file is generated from the Oracle E-Business Suite application through a concurrent job and is sent to a system for tax calculations. That system is based on VERTEX software which uses Tomcat application server. The VERTEX database is Oracle (11.2.0.3). When the call is made from the Oracle E-Business Suite, the calling session calls a VERTEX web service for tax calculations using the UTL_HTTP call and then waits on the "TCP Socket (KGAS)" event. This call takes a long time to return and we are trying to troubleshoot where the time is being spent. On the VERTEX side, there are most likely only a very few sessions involved with the tax calculation activity and I believe your observation is correct. The VERTEX system is managed by a different group and on my ask, they provided AWR from both RAC instances generated at 15-minute interval.

I have discovered this statistics at two different intervals: 13:30 - 13:45
14:30 - 14:45

-----Original Message-----
From: Stefan Koehler [mailto:contact_at_soocs.de] Sent: Thursday, August 18, 2016 12:14 PM To: Ahmed Aangour <ahmed.aangour_at_gmail.com>; Hameed, Amir <Amir.Hameed_at_xerox.com> Cc: oracle-l <oracle-l_at_freelists.org> Subject: RE: Hard parse elapsed time in AWR

Hi Amir,
the metrics "parse time elapsed" and "parse time cpu" in "Instance Activity Stats" really look strange (but it can be an accounting behavior or bug in 11.2.0.3). However is it possible that only a few sessions (in your case round about 4) are optimizing very long (or endlessly) and have not finished at snap end time? You can cross-check this in ASH (column IN_HARD_PARSE).

Here is a short test case about such an issue on 12.1.0.1 in my lab:

---------------------8<---------------------------------

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:       186 18-Aug-16 17:19:09        34       1.5
  End Snap:       187 18-Aug-16 17:20:19        36       1.6
   Elapsed:                1.16 (mins)
   DB Time:                1.06 (mins)

Instance Efficiency Percentages (Target 100%) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   96.43    In-memory Sort %:  100.00
            Library Hit   %:   81.33        Soft Parse %:   78.17
         Execute to Parse %:   81.30         Latch Hit %:   99.99
Parse CPU to Parse Elapsd %:   24.29     % Non-Parse CPU:   98.88

Time Model Statistics                    DB/Inst: T12DB/T12DB  Snaps: 186-187
Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
parse time elapsed                                       56.2         88.6
hard parse elapsed time                                  56.1         88.6
DB CPU                                                   53.7         84.8
sql execute elapsed time                                 11.1         17.5
PL/SQL compilation elapsed time                           0.2           .4
PL/SQL execution elapsed time                             0.1           .2
repeated bind elapsed time                                0.0           .1
sequence load elapsed time                                0.0           .1
DB time                                                  63.4
background elapsed time                                   4.6
background cpu time                                       0.5
                          ------------------------------------------------------

Instance Activity Stats              DB/Inst: T12DB/T12DB  Snaps: 186-187


-> Ordered by statistic name


Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
parse count (total)                             852           12.3         284.0
parse time elapsed                              247            3.6          82.3
parse count (failures)                            0            0.0           0.0
parse count (hard)                              186            2.7          62.0
parse time cpu                                   60            0.9          20.0
---------------------8<---------------------------------

_at_Ahmed: DS related parse time is usually not CPU driven.

Best Regards
Stefan Koehler

Freelance Oracle performance consultant and researcher Homepage: http://www.soocs.de
Twitter: _at_OracleSK

> "Hameed, Amir" <Amir.Hameed_at_xerox.com> hat am 18. August 2016 um 17:33 geschrieben:
> 
>  Hi,
> 
>  The DB version is 11.2.0.3.
> 
>  Thanks,
> 
>  Amir
> 
>  From: Ahmed Aangour [mailto:ahmed.aangour_at_gmail.com]
>  Sent: Thursday, August 18, 2016 11:31 AM
>  To: Hameed, Amir <Amir.Hameed_at_xerox.com>
>  Cc: oracle-l <oracle-l_at_freelists.org>
>  Subject: Re: Hard parse elapsed time in AWR
>  
> 
>  Hi,
> 
>  What is the version of your DB?
>  Not using bind variables is not the only cause of hard parse issues.
>  ACS or 12c Adaptive feature can force queries to be reoptimized.
>  Automatic Dynamic sampling can also increase significantly the time of hard parses.
>  Check the v$sql_shared_cursor view to see the reason for not sharing cursors.
> 
>  Le 18 août 2016 16:56, "Hameed, Amir" <Amir.Hameed_at_xerox.com mailto:Amir.Hameed_at_xerox.com > a écrit :
> 
>   > >
> >   Hi,
> > 
> >   I am investigating a performance issue and looking at an AWR 
> > report from one of the two-node RAC instances. Below is the what I find interesting (highlighted in yellow).
> > 
> >   It seems that all of the DB CPU time is being spent on hard 
> > parsing but I am not finding any evidence that literal statements were being run during this interval.
> > 
> >   Thanks