This discussion is archived
13 Replies Latest reply: Jan 25, 2013 11:03 AM by 961833 RSS

AWR Question on Executions and user-calls

961833 Newbie
Currently Being Moderated
NON-RAC db.
select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production


Load Profile               Per Second   Per Transaction
--------------------   --------------   ---------------
             DB Time              7.5
              DB CPU              3.6
           Redo size      2,153,376.6          14,650.7
       Logical reads        884,987.1           6,021.1
       Block changes         10,441.6              71.0
      Physical reads            732.1               5.0
     Physical writes            391.0               2.7
          User calls          9,141.4              62.2
              Parses          4,714.1              32.1
         Hard Parses               .9                .0
              Logons               .4                .0
            Executes          5,509.4              37.5
           Rollbacks               .0
        Transactions            147.0
        Applied urec              2.2                .0
I want to understand What exactly User calls and Executes suggests in above load-profile for awr snap which is taken for 30 min interval. Do they have any relation in between?
I got almost double Executes than User-calls, what does that suggest ?

A related question on awr ...Is that any script to get 'Top 5 Timed Foreground Events' section of AWR in SQLPLUS ?

PS: This thread is purely for knowledge gaining.
  • 1. Re: AWR Question on Executions and user-calls
    damorgan Oracle ACE Director
    Currently Being Moderated
    http://docs.oracle.com/cd/B16240_01/doc/doc.102/e16282/oracle_database_help/oracle_database_instance_throughput_usercalls_ps.html

    http://docs.oracle.com/cd/B16240_01/doc/doc.102/e16282/oracle_database_help/oracle_database_instance_throughput_executions_ps.html

    http://jonathanlewis.wordpress.com/2013/01/07/analysing-statspack-13/
  • 2. Re: AWR Question on Executions and user-calls
    Nikolay Savvinov Guru
    Currently Being Moderated
    Hi,

    that could mean that the extra execute calls are made by PL/SQL functions rather than by the user directly, or they could due to recursive SQL.

    Best regards,
    Nikolay
  • 3. Re: AWR Question on Executions and user-calls
    baskar.l Pro
    Currently Being Moderated
    Hi,

    User Calls is an overall activity level monitor for parse, execute and logon calls.

    Baskar.l
  • 4. Re: AWR Question on Executions and user-calls
    moreajays Pro
    Currently Being Moderated
    Hi,

    As per my knowledge these metrics are ..

    User calls = (User session Login + Parsing within a session + Executions of sql's/Cursors ) per second
    Executes = (Sql's execution) per second

    user calls includes execution as well

    Thanks,
    Ajay More
    http://www.moreajays.com
  • 5. Re: AWR Question on Executions and user-calls
    Rob_J Journeyer
    Currently Being Moderated
    Hi,

    Just a thought but if that is the case and it's kind of a summary, why does the sum of parse calls and executions exceed the user calls value?
  • 6. Re: AWR Question on Executions and user-calls
    moreajays Pro
    Currently Being Moderated
    Hi Rob,

    That was really good observation.Answer for the same might reside in AWR Instance Efficiency Percentages ( Execute to Parse % , Soft Parse %).
    It would be better if 958830 can post Instance Efficiency section of the same AWR report to make some conclusion

    Thanks,
    Ajay More
    http://www.moreajays.com
  • 7. Re: AWR Question on Executions and user-calls
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    958830 wrote:
    Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
    
    Load Profile               Per Second   Per Transaction
    --------------------   --------------   ---------------
    User calls          9,141.4              62.2
    Parses          4,714.1              32.1
    Hard Parses               .9                .0
    Executes          5,509.4              37.5
    Transactions            147.0
    I want to understand What exactly User calls and Executes suggests in above load-profile for awr snap which is taken for 30 min interval. Do they have any relation in between?
    Sometimes you can make some sensible guesses by comparing user calls with parses and executes, but sometimes there's very little implied by the values. In this case we can see that you're doing a lot of them, and hope that you have a fairly high powered machine that can cope, but apart from general business there's little more to say.

    User calls from from a client program to the server - and typically consist of parse calls, execute calls and fetch calls - and Oracle doesn't maintain a global count of fetch calls - with commits and rollback calls as a possibility. Depending on version of Oracle, the client code generator, and various session-related parameters, there could be many ways in which figures like yours could appear.

    Example - your user calls could have been a few parse calls and executes per second, with thousands of fetches per second, while most of the parses and executes could have been the result of PL/SQL function calls inside a few pl/sql packages that you may have called.
    I got almost double Executes than User-calls, what does that suggest ?
    Other way round. The only thing we can say about your figures is that since parses + executes > user calls, you must have had some code in the database generating recursive calls (not necessarily sys-recursive).

    Regards
    Jonathan Lewis
  • 8. Re: AWR Question on Executions and user-calls
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    moreajays wrote:
    Hi Rob,

    That was really good observation.Answer for the same might reside in AWR Instance Efficiency Percentages ( Execute to Parse % , Soft Parse %).
    It would be better if 958830 can post Instance Efficiency section of the same AWR report to make some conclusion
    The instance efficiency figures are virtually useless.
    We've got the parse cound and execute count in load profile so, allowing for a little rounding error, we can work out the "Execute to Parse %", and we also have the hard parse count, so we can work out the "Soft Parse %"

    What we need to see to get some idea of what's going on is a subset of the Instance Activity figures - the OP might be interested in the session cursor cache hits because in this version of Oracle parse calls which are satisfied through the session cursor cache don't increment the cache hit count - and the SQL Ordered by Parse Count and Execution Count.

    Regards
    Jonathan Lewis
  • 9. Re: AWR Question on Executions and user-calls
    krishan Explorer
    Currently Being Moderated
    It can be seen that soft parse(4,714.1) is very high. In this case, session_cached_cursors parameter value can be increased. At the same time you have to take care of shared_pool_size/sga_target.
  • 10. Re: AWR Question on Executions and user-calls
    961833 Newbie
    Currently Being Moderated
    Thanks Jonathan for taking a look.

    I have session_cached_cursors=50 which i am sure a very small number and worth incrementing it to leverage softer soft parse. If i increase it, should i expect few parse calls ?
    open_cursors is set to 600. Max open_Cursors ('opened cursors current') i found is 2 for most of the sessions.
    select
      100 * sess / calls  cursor_cache_hits,
      100 * (calls - sess - hard) / calls soft_parses,
      100 * hard / calls  hard_parses
    from
      ( select value calls from v$sysstat where name = 'parse count (total)' ),
      ( select value hard  from v$sysstat where name = 'parse count (hard)' ),
     ( select value sess  from v$sysstat where name = 'session cursor cache hits' )
    /
    Session
     Cached      Soft      Hard
     Cursor     Parse     Parse
          %         %         %
    -------   -------   -------
       3.29     96.71       .01
    My OLTP system got 1400 hibernate connections which stays connected all time. Talking about fetch calls, most of them are 'single row returned' sqls. However, such select have very large executions/sec. ~250 connections are commit single record per every second (update statement). That almost matches with TRANSACTION/SEC count.

    Here are top sql order by executions:
    Executions      Rows Processed     Rows per Exec     Elapsed Time (s)     %CPU     %IO          SQL Id               SQL Text
    519,301          519,301               1.00               9.40                    94.35     0.04     f8uuq3bskfjzq      select HIBERNATE_SEQUENCE.nextval from dual.
    519,297          519,249               1.00               73.06                    97.13     0.00     98132rq230fcn      BEGIN :1 := seq_pkg.get_nextval(:2 , :3 ); END;
    218,874          218,861               1.00               47.23                    93.22     0.00     7jdmx91c10pz8      BEGIN :1 := seq_pkg.get_global_nextval(:2 , :3 ); END;.
    90,906          90,905               1.00               105.24                    47.24     24.17     cmmf3s5231x9g      update tab...
    90,752          90,752               1.00               2.56                    93.40     0.00     3qmqdf7s6j192      select tab..nextval from dual
    sql order by parse calls:
    Parse Calls     Executions      % Total Parses     SQL Id     SQL      SQL Text
    519,212          519,297          12.55               98132rq230fcn      BEGIN :1 := seq_pkg.get_nextval(:2 , :3 ); END;
    218,873          218,874          5.29               7jdmx91c10pz8      BEGIN :1 := seq_pkg.get_global_nextval(:2 , :3 ); END;.
    90,903          90,906          2.20               cmmf3s5231x9g      update tab...
    81,395          519,301          1.97               f8uuq3bskfjzq      select HIBERNATE_SEQUENCE.nextval from dual.
    Please accept my apology for formatting. I had to cut Module information. My application does not have any other PL/SQL processing apart from two package listed above.
  • 11. Re: AWR Question on Executions and user-calls
    karan Pro
    Currently Being Moderated
    User call is a request from client to server like parse, execute and fetch, so for example it has hard parses included sisnt it ?

    Exections if they are large per user call means lets say function in plsql is called too often in 1 call because of a bad plan, In such cases looking into “SQL ordered by executions” will be the logical next step.
  • 12. Re: AWR Question on Executions and user-calls
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    958830 wrote:
    Thanks Jonathan for taking a look.
    You pointed out that your question was simply to acquire knowledge, so here are a few thoughts that might help:
    I have session_cached_cursors=50 which i am sure a very small number and worth incrementing it to leverage softer soft parse. If i increase it, should i expect few parse calls ?
    open_cursors is set to 600. Max open_Cursors ('opened cursors current') i found is 2 for most of the sessions.
    If you have 1,400 Hiberbate connections that are always open, but most of them only have 2 open cursors most of the time then you've probably got far more connections open than you need. (This is a common error - picking a suitable number of connections, and queueing method, depends on the envirnoment, application, and resources available).
    select
    100 * sess / calls  cursor_cache_hits,
    100 * (calls - sess - hard) / calls soft_parses,
    100 * hard / calls  hard_parses
    from
    ( select value calls from v$sysstat where name = 'parse count (total)' ),
    ( select value hard  from v$sysstat where name = 'parse count (hard)' ),
    ( select value sess  from v$sysstat where name = 'session cursor cache hits' )
    /
    Session
    Cached      Soft      Hard
    Cursor     Parse     Parse
    %         %         %
    -------   -------   -------
    3.29     96.71       .01
    Queries against V$sysstat (et. al.) give cumulative results since startup - they are usually a total waste of time.
    Ratios hide scale, they are usually a total waste of time
    In this version of Oracle a call that goes through the session cursor cache does NOT get recorded as a "parse count (total)" - so your "soft parses" calculation is wrong (though it would be right in (e.g.) 10gR2)
    My OLTP system got 1400 hibernate connections which stays connected all time. Talking about fetch calls, most of them are 'single row returned' sqls. However, such select have very large executions/sec. ~250 connections are commit single record per every second (update statement). That almost matches with TRANSACTION/SEC count.
    This helps to account for the large number of user calls.

    >
    Here are top sql order by executions:
    Executions      Rows Processed     Rows per Exec     Elapsed Time (s)     %CPU     %IO          SQL Id               SQL Text
    519,301          519,301               1.00               9.40                    94.35     0.04     f8uuq3bskfjzq      select HIBERNATE_SEQUENCE.nextval from dual.
    519,297          519,249               1.00               73.06                    97.13     0.00     98132rq230fcn      BEGIN :1 := seq_pkg.get_nextval(:2 , :3 ); END;
    218,874          218,861               1.00               47.23                    93.22     0.00     7jdmx91c10pz8      BEGIN :1 := seq_pkg.get_global_nextval(:2 , :3 ); END;.
    90,906          90,905               1.00               105.24                    47.24     24.17     cmmf3s5231x9g      update tab...
    90,752          90,752               1.00               2.56                    93.40     0.00     3qmqdf7s6j192      select tab..nextval from dual
    sql order by parse calls:
    Parse Calls     Executions      % Total Parses     SQL Id     SQL      SQL Text
    519,212          519,297          12.55               98132rq230fcn      BEGIN :1 := seq_pkg.get_nextval(:2 , :3 ); END;
    218,873          218,874          5.29               7jdmx91c10pz8      BEGIN :1 := seq_pkg.get_global_nextval(:2 , :3 ); END;.
    90,903          90,906          2.20               cmmf3s5231x9g      update tab...
    81,395          519,301          1.97               f8uuq3bskfjzq      select HIBERNATE_SEQUENCE.nextval from dual.
    Was this a standard 1 hour snapshot - if so there are a lot of "missing" statement. Your parse list here shows less than 1M calls, but your load profile shows 4,700 per second - even assuming the AWR has show 16 more statements at 80,000 calls per statement, it's still showing only about 8 minutes worth of parse calls: so I'd be interested in where the rest are going. (Similar arithmetic applies to the execute counts - AWR seems to have captured a small percentage of the total).


    Increasing the session_cached_cursors parameter may reduce the number of parse calls reported (and improving the efficiency a little) - but it does depend on how hibernate is calling the database - it may be doing a "reset session state" and clearing all session information after each little piece of work, so you may see very little difference - but it won't cost you anything to try.

    I wouldn't be surprised, by the way, if the 'select HIBERBATE_SEQUENCE.nectval from dual' was embedded in the seq_pkg.nextval() call with an "execute immediate" implementation.

    Regards
    Jonathan Lewis
  • 13. Re: AWR Question on Executions and user-calls
    961833 Newbie
    Currently Being Moderated
    Many thanks Jonathan.

    Load profile i pasted initially was bit stale. I did not expect thsi thread going too far. Feeling lucky here !
    I am attaching it for 10 min snap for sqls i gave earlier (sql -order by parse calls/executions)
    Host Name     Platform               CPUs     Cores     Sockets     Memory (GB)
    xxx               Linux x86 64-bit     24          12          2          94.41
    
                   Snap Id     Snap Time               Sessions     Cursors/Session
    Begin Snap:     161541     24-Jan-13 18:10:07     1337          2.9
    End Snap:     161542     24-Jan-13 18:20:08     1335          3.0
    Elapsed:           10.01 (mins)
    DB Time:           77.26 (mins)
    
    Load Profile
    
                             Per Second          Per Transaction          Per Exec     Per Call
    DB Time(s):               7.7                    0.0                         0.00          0.00
    DB CPU(s):               5.3                    0.0                         0.00          0.00
    Redo size:               2,921,229.5          13,689.9
    Logical reads:          1,166,465.8          5,466.4     
    Block changes:          14,584.4          68.4     
    Physical reads:          347.9               1.6           
    Physical writes:     551.0               2.6           
    User calls:               13,485.4          63.2     
    Parses:                    6,892.4               32.3     
    Hard parses:          1.4                    0.0           
    W/A MB processed:     9.8                    0.1           
    Logons:                    0.5                    0.0           
    Executes:               7,981.8               37.4     
    Rollbacks:               0.3                    0.0           
    Transactions:          213.4                  
    I apologies for the formatting here.
    If i count parse calls for all 19 statements under 'sql order by parse calls', it comes to 1,731,600 (1.7M). That would be just 2866/sec. Load-profile says 6892/sec
    Count for executions (sql order by executions) comes to 2,151,299 (2.1M). That came to 3585/sec. Again, load profiles says 7981/sec. Dont know why is such gap. Am i having rest as recursive calls ?

    Is that hibernate's "reset session state" that is leaving just 2 open cursors for all 1,400 Hiberbate connections ? Is there any negatives on db performance by 'resetting session stat' too aggressively ?

    Can you educate me on advantages of embedding 'select HIBERBATE_SEQUENCE.nectval from dual' in 'seq_pkg.nextval()' ? seems like a great recommendation.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points