Oracle Scratchpad

November 13, 2011

Irrational Ratios

Filed under: Oracle,Ratios,Statspack — Jonathan Lewis @ 11:23 am BST Nov 13,2011

I’ve pointed out in the past how bad the Instance Efficiency ratios are in highlighting a performance problem. Here’s a recent example from OTN repeating the point. The question, paraphrased, was:

After going through AWR reports (Instance Efficiency Percentages) I observed they have low Execute to Parse % but high Soft Parse %.
Please share if you had faced such issue and any suggestions to solve this


The first problem with this question is that ratios hide information.
The second problem is that we don’t know what values the OP considers to be “low” or “high” in this context.
The third is that there’s no reason why any such juxtaposition of ratios should implicitly mean there’s a problem.

The silly thing about the question is that the ratios are derived values, and actually share a common component, so it would be much easier to look at the absolute figures to see if they mean anything. Fortunately someone asked for more information and we got the following extract from an AWR. This was from a typical report (one hour snapshot interval) on a machine with 8 CPUs.

Load Profile
                                          Per Second       Per Transaction
                                    ---------------       ---------------
               Redo size:                  11,685.79              3,660.98
               Logical reads:              71,445.74             22,382.86
               Block changes:                  70.89                 22.21
               Physical reads:                 58.63                 18.37
               Physical writes:                 2.80                  0.88
               User calls:                    652.93                204.55
               Parses:                         48.39                 15.16
               Hard parses:                     0.33                  0.10
               Sorts:                           6.90                  2.16
               Logons:                          0.23                  0.07
               Executes:                       52.71                 16.51
               Transactions:                    3.19

            % Blocks changed per Read:     0.10    Recursive Call %:    30.48
            Rollback per transaction %:    2.57       Rows per Sort:    29.66

    Instance Efficiency Percentages (Target 100%)
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
             Buffer Nowait %:              100.00       Redo NoWait %:  100.00
             Buffer  Hit   %:               99.92    In-memory Sort %:  100.00
             Library Hit   %:               98.47        Soft Parse %:   99.32
             Execute to Parse %:             8.19         Latch Hit %:   99.63
             Parse CPU to Parse Elapsd %:   89.90     % Non-Parse CPU:   99.62

(Forgetting the ratios for a moment – what’s the strangest thing about the Load Profile ? )

The ratios quoted can be derived from the above as follows:

Execute to Parse %:  100 * (Executes - Parses) / Executes
Soft Parse %:        100 * (Parses - Hard Parses) / Parses

So why not look at Parses, Hard Parses, and Executes instead of confusing yourself with ratios:

Better still, you could just about squeeze some information from the % Non-Parse CPU figure namely: 99.62% of your CPU is spent on doing things other than parsing, so IF your largest time component is CPU, and IF you eliminated all the parsing costs then you would make virtually no difference to the performance. (And the first IF is why you wouldn’t really bother with the ratio, you should be looking elsewhere for CPU time spent.)

Coming back to the Parses – we see about 48 per second (which doesn’t sound a lot, really, for a system that’s been engineered with 8 CPUs) and 0.33 hard parses per second (i.e. virtually none). If we look at the Executes it’s about 53 per second (again, not a lot, but slightly more than Parses). So where’s the problem ? There isn’t one – not in the parses and executes, at least.

Quiz

Let’s go back to the strangest thing in the Load Profile – how do you do 48 Parses, 53 Executes but manage to total 653 User Calls per second ? (… to be continued)

13 Comments »

  1. Here comes an example why user calls may apparently greater than the Executes.

    if the query request hundres of rows, with the arraysize is set to 10, and the FETCH need to be called many times for every query execution.

    FETCH #47980542003000:c=0,e=109,p=0,cr=0,cu=0,mis=0,r=10,dep=0,og=1,plh=59952636,tim=1318817204755624
    WAIT #47980542003000: nam='SQL*Net message from client' ela= 982 driver id=1952673792 #bytes=1 p3=0 obj#=76670WAIT #47980542003000: nam='SQL*Net message to client' ela= 0 driver id=1952673792 #bytes=1 p3=0 obj#=76670 FETCH #47980542003000:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=10,dep=0,og=1,plh=59952636,tim=1318817204756761
    WAIT #47980542003000: nam='SQL*Net message from client' ela= 967 driver id=1952673792 #bytes=1 p3=0 obj#=76670 WAIT #47980542003000: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=76670
    FETCH #47980542003000:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=10,dep=0,og=1,plh=59952636,tim=1318817204757883WAIT #47980542003000: nam='SQL*Net message from client' ela= 994 driver id=1952673792 #bytes=1 p3=0 obj#=76670 WAIT #47980542003000: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=76670
    FETCH #47980542003000:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=10,dep=0,og=1,plh=59952636,tim=1318817204759035WAIT #47980542003000: nam='SQL*Net message from client' ela= 978 driver id=1952673792 #bytes=1 p3=0 obj#=76670
    WAIT #47980542003000: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=76670
    FETCH #47980542003000:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=10,dep=0,og=1,plh=59952636,tim=1318817204760164WAIT #47980542003000: nam='SQL*Net message from client' ela= 970 driver id=1952673792 #bytes=1 p3=0 obj#=76670 
    WAIT #47980542003000: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=76670
    FETCH #47980542003000:c=1000,e=109,p=0,cr=0,cu=0,mis=0,r=10,dep=0,og=1,plh=59952636,tim=1318817204761294
    

    Comment by Sid — November 13, 2011 @ 3:11 pm BST Nov 13,2011 | Reply

    • Sid,

      Exactly.
      It’s a pity that Oracle doesn’t have some direct method for recording this somewhere in the instance activity statistics – it would be a useful number of highlight problems relating to arraysize.
      It seems, therefore, that this particular system is doing a very large number of round-trips that could be introducing overheads relating to process pre-emption (and associated phenomena).

      Comment by Jonathan Lewis — November 13, 2011 @ 4:38 pm BST Nov 13,2011 | Reply

      • Well, there’s the “SQL*Net roundtrips to/from client” instance statistic. A pity we don’t have it in the Load Profile.

        Then there are the FETCHES, EXECUTIONS, and ROWS_PROCESSED columns of V$SQLSTATS (and similar) – one could easily use them to build some rational ratios, I think :-)

        Comment by Flado — November 17, 2011 @ 12:23 pm BST Nov 17,2011 | Reply

        • Flado,

          There are ways we can estimate some figures – but they all have holes in them.

          SQL*Net roundtrips to/from client – Since 8i the OCI library has been able to bundle calls such as “close cursor”, parse, execute and even fetch into a single round-trip (a detail I avoided mentioning in my earlier comments), so we have room for error there; however, to a reasonable level of approximation, the number of user calls will be roughly the same as the number of executes plus fetches when a lot of single fetches are going on – which means the round-trips statistic doesn’t really add value.

          The drawback to the v$sqlstats (et. al.) statistics is that cursors come and go, values get reset, and so on. We might get reasonable figures from summing them, we might get totally misleading figures. Whatever we get, we still have to apply some thought to what it means and how valid it might be – an actual instance activity stat would be so much more helpful.

          Comment by Jonathan Lewis — November 18, 2011 @ 6:02 pm BST Nov 18,2011

  2. when the client has statement cache, then execute call can be larger than parses.
    when one execute return so many rows, then the fetch call can be larger than executes,
    If there were a query return so many rows with so many round trips , then the system can have a very large total call to executes ratio.

    Comment by jametong — November 14, 2011 @ 2:17 am BST Nov 14,2011 | Reply

    • hi jametong,

      The Executes may larger than user call also, here is one load profile from a 11gR2 db, when server result cache is enabled(92.4 user calls per sec compare to 1449 executes). not sure how to format the code:-)

                      Per Second      Per Transaction
      DB Time(s):            3.6            0.3     
      DB CPU(s):             1.1            0.1     
      Redo size:       247,762.1       22,120.8                
      Logical reads:    63,438.7        5,664.0                 
      Block changes:     1,239.5          110.7           
      Physical reads:    5,443.1          486.0           
      Physical writes:      31.6            2.8             
      User calls:           92.4            8.3             
      Parses:               62.4            5.6           
      Hard parses:           3.4            0.3             
      W/A MB processed:     16.4            1.5                     
      Logons:                0.5            0.1           
      Executes:          1,449.0          129.4           
      Rollbacks:             0.0            0.0             
      Transactions:         11.2
      

      Comment by Sid — November 14, 2011 @ 11:53 am BST Nov 14,2011 | Reply

      • Sid,

        This picks up very nicely the difficulty of identifying the true source of almost any of the available statistics.

        In this case you probably need to look at the instance activity stats for “recursive calls”. A single user call could be an execute call to a pl/sql procedure that then does lots of parse, execute and fetch calls.

        Comment by Jonathan Lewis — November 18, 2011 @ 5:31 pm BST Nov 18,2011 | Reply

  3. Hi Jonathan,

    I’ve just another question about the load profile. I found reports where the Physical Writes per second in the load profile didn’t match the numbers in the region Tablespace IO Stats. If I summarize the writes on every tablespace I come to 47 writes/s but in the load profile there are 397.8 writes/s listed.
    The number of reads/s mathes nearly. 107.7 from the sum of tablespace vs. 120.6 from the load profile.

    Are there any other writes included in the load profile?

    Many thanks!

    Thomas

    Comment by Thomas — November 14, 2011 @ 9:48 am BST Nov 14,2011 | Reply

    • Thomas,

      In recent versions of Oracle the stats about reads and writes have been extended to clarify what’s going on here.

      I think you’ll find that the writes reported in tablespace and file I/O stats are the number of I/O requests while the “Physical Writes” recorded in the load profile are the numbers for blocks read and written. SInce you can do multiblock writes to temp (and other direct path writes) the numbers in the load profile can be much higher than the numbers in the Tablespace and File I/O stats.

      Comment by Jonathan Lewis — November 18, 2011 @ 5:48 pm BST Nov 18,2011 | Reply

  4. Hi Jonathan. Thank you for explanation and giving advice.Of course just “Instance Efficiency Percentages” section of AWR is not give us to clear and direct performance information for giving period like BCHR(as you mentioned that in your previous posts).We have to refer Load Profile section to get exactly what was happen (specially “Per Second” column).But in above OTN forum thread we also talked about reducing soft parsing(however as you mentioned it is not a lot).
    So is it not important to investigate that in this situation? (to doing this we have to refer sql statement statistics related section of AWR ?)

    Comment by Chinar — November 17, 2011 @ 10:54 am BST Nov 17,2011 | Reply

  5. Chinar,

    This example is a little odd, since there’s very little going on at all and we haven’t even been given the “Top N timed events” section. However, when tracking down performance problems the general rule is to go for the most expensive things first and, as I pointed out in the thread, we have 652 user calls per second compared to the 48 parse calls (of which virtually none were hard parses) so the fetches – as Sid implied in his comment – are the most significant thing we could pursue.

    You are correct, of course, that we could look at the “SQL ordered by Parse Calls” section if we really felt the need to pursue the parse calls.

    Comment by Jonathan Lewis — November 18, 2011 @ 5:54 pm BST Nov 18,2011 | Reply

  6. sir can you please explain the how to identify the physical reads or writes are more in awr report. could you please explain awr report in which areas we need to put our effort.

    I am expecting from you.

    Regards,
    Ram

    Comment by Ram — February 5, 2012 @ 4:40 pm BST Feb 5,2012 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 3,530 other followers