Oracle Scratchpad

February 15, 2013

Transactions

Filed under: Oracle,Statspack,Troubleshooting — Jonathan Lewis @ 8:07 am BST Feb 15,2013

It’s very easy to get a lot of information from an AWR (or Statspack) report – provided you remember what all the numbers represent. From time to time I find that someone asks me a question about some statistic and my mind goes completely blank about the exact interpretation; but fortunately it’s always possible to cross check because so many of the statistics are cross-linked. Here’s an example of a brief mental block I ran into a few days ago – I thought I knew the answer, but realised that I wasn’t 100% sure that my memory was correct:

In this Load Profile (for an AWR report of 60.25 minutes), what does that Transactions figure actually represent ?

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:             57,567.09             12,028.39
              Logical reads:             48,043.83             10,038.54
              Block changes:                314.07                 65.62
             Physical reads:                667.70                139.51
            Physical writes:                 46.25                  9.66
                 User calls:                619.33                129.41
                     Parses:                505.67                105.66
                Hard parses:                 36.94                  7.72
                      Sorts:                313.05                 65.41
                     Logons:                  0.56                  0.12
                   Executes:              1,165.42                243.51
               Transactions:                  4.79

  % Blocks changed per Read:    0.65    Recursive Call %:    95.18
 Rollback per transaction %:   24.95       Rows per Sort:    25.09

And, while we’re at it, what does the “Rollback per transaction %” actually mean – and what, if anything, can we infer from the value ?

Since we’re looking at transactions, it’s a fairly safe bet that the figure is something to do with commits – but is it counting only committed transactions, or does it included rolled back transactions [philosophical question - is a change that's never committed really a transaction, since it "never happened" as far as the rest of the world is concerned?]. Fortunately we can look at the Intance Activity Statistics to check.

First, though, lets convert the “Per Second” figures into an absolute value by multiplying by the duration in seconds (3,615) of the report. Allowing for rounding errors we’re looking for a value between ceiling(4.785 *3615) and floor(4.795 * 3615), i.e. between 17,298 and 17,338.  Let’s also keep in mind that the “Rollback per transaction %” is very close to 25%.

Here, then, are a couple of useful figures from the Instance Activity:


Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
user commits                                 12,986            3.6           0.8
user rollbacks                                4,316            1.2           0.3

Almost immediately you can see that user rollbacks are roughly one third of user commits (I promise I didn’t massage these number), which means the rollback percentage is just (user rollbacks / (user commits + user rollbacks)). As a further sanity check, 4,316 + 12,986 = 17,302 which falls nicely into our required range. Ta-da, job done: “Transactions” is the sum of user commits and user rollbacks (as a first approximation – but is it the whole answer).

Of course, I picked a fairly extreme example from my AWR library to make a point – which means you might now be asking whether all those rollbacks pose some sort of threat. How serious are they ? Luckily there are a couple more statistics that tell us:


Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
rollback changes - undo records                 222            0.1           0.0
transaction rollbacks                            59            0.0           0.0

The name of the first statistic has been trimmed a little in this text report, the full name is: “rolllback changes – undo records applied”. As you can see, we’ve only applied 222 undo records in our 4,316 rollback calls, so we’re not really rolling anything back (most of the time). Moreoever, the “transaction rollbacks” corroborates this observation – we have only attempted to rollback 59 “real” (data-changing) transactions. Most of those rollbacks are probably the default “rollback after every call” that some web application servers make.

As a closing thought – if you’re responsible for several different systems, it’s convenient to keep a couple of “reference” AWR or Statspack reports from busy, normal, and quiet periods for each system; that way, if you use the figures from one system to work out the meaning of some derived value you can use the figures from another system to check if your hypothesis is correct.

Footnote: there are two other statistics that include the text “undo records applied” (not that you’ll see those words in the textual AWR report), but they both relate to creating read-consistent copies of blocks.

Footnote 2: Is anyone getting worried by my “first approximation” comment – and has anyone started wondering if there may be more to transaction rollbacks that user rollbacks, and if so where they fit into the arithmetic ?  To be continued.

19 Comments »

  1. Thanks Jonathan.
    Could You explain ‘Recursive Call %: 95.18′ this bothers me a lot :) seems quite high .
    Regards
    GregG

    Comment by goryszewskig — February 15, 2013 @ 9:26 am BST Feb 15,2013 | Reply

    • It could be just result of cursor loops in plsql, especially with plsql_optimize_level < 2.

      Comment by Valentin Nikotin — February 15, 2013 @ 8:20 pm BST Feb 15,2013 | Reply

    • GregG

      Every SQL statement inside a pl/sql block is recursive SQL – in my case I did little more than call an SQL statement inside a pl/sql loop – as Valentin surmised.

      Comment by Jonathan Lewis — February 16, 2013 @ 9:15 am BST Feb 16,2013 | Reply

      • Jonathan, I meant that just one cursor loop may cause a lot of recursive calls as every successful fetch call is counted as recursive. This is clear to see in case of plsql_optimize_level < 2 or select for update cursor loop where is no array optimization or for manual fetches of course.

        Comment by Valentin Nikotin — February 16, 2013 @ 7:49 pm BST Feb 16,2013 | Reply

        • Here is the simple code to check AWR reports and example for recursive calls counts :

          [oracle@DB1 ~]$ cat tst.sql 
          define row_cnt = &1
          define opt_lvl = &2
          
          exec dbms_workload_repository.create_snapshot;
          
          alter session set plsql_optimize_level = &opt_lvl;
          
          begin
            for rec in (with a as (select null from dual connect by level <= 1e5) select null from a,a where rownum <= &row_cnt) loop
              null;
            end loop; 
          end;
          /
          
          exec dbms_workload_repository.create_snapshot;
          
          define num_days = 1;
          define  report_type  = 'text';
          define  report_name  = '';
          
          column inst_num   new_value inst_num  format 99999;
          column inst_name  new_value inst_name format a12;
          column db_name    new_value db_name   format a12;
          column dbid       new_value dbid      format 9999999999;
          
          select d.dbid            dbid
               , d.name            db_name
               , i.instance_number inst_num
               , i.instance_name   inst_name
            from v$database d,
                 v$instance i;
          
          column begin_snap new_value begin_snap  format 99999;
          column end_snap   new_value end_snap    format 99999;
          
          select max(snap_id) end_snap, max(snap_id)-1 begin_snap from dba_hist_snapshot;
          
          @@?/rdbms/admin/awrrpti
          
          exit
          
          [oracle@DB1 ~]$ sqlplus / as sysdba @tst 1000000 0 | grep recursive
          recursive calls                           1,001,075      156,736.3      91,006.8
          recursive cpu usage                             467           73.1          42.5
          [oracle@DB1 ~]$ sqlplus / as sysdba @tst 1000000 2 | grep recursive
          recursive calls                              11,053        9,264.9       1,004.8
          recursive cpu usage                              92           77.1           8.4
          [oracle@DB1 ~]$ sqlplus / as sysdba @tst 0 0 | grep recursive
          recursive calls                               1,084        1,358.4          98.6
          recursive cpu usage                              58           72.7           5.3
          [oracle@DB1 ~]$
          

          Comment by Valentin Nikotin — February 17, 2013 @ 7:06 am BST Feb 17,2013

        • Valentin,

          Thanks for the demonstration. I’ve often wished that Oracle would introduce a “fetch count” statistic to match the parse count and execute count. (Splitting recursive calls into sys-recursive and user-recursive would be nice as well).

          Comment by Jonathan Lewis — February 18, 2013 @ 7:16 am BST Feb 18,2013

  2. I guess “rollback to savepoint”, statement and row level restarts can affect this statistics. I try to check this in a while.

    Comment by Valentin Nikotin — February 15, 2013 @ 10:07 am BST Feb 15,2013 | Reply

    • I had the same thought.
      Quick test did not increment any of user_commits, user_rollbacks or transaction rollbacks.

      SQL> create table t1
        2  (col1 number);
      
      Table created.
      
      SQL> @stats
      
      NAME                                                                  VALUE
      ---------------------------------------------------------------- ----------
      user commits                                                              3
      user rollbacks                                                            0
      transaction rollbacks                                                     0
      
      SQL> get svp
        1  begin
        2   savepoint s1;
        3   insert into t1 values (1);
        4   rollback to savepoint s1;
        5   savepoint s2;
        6   insert into t1 values (2);
        7   rollback to savepoint s2;
        8   insert into t1 values (3);
        9   commit;
       10* end;
      SQL> @svp
      
      PL/SQL procedure successfully completed.
      
      SQL> @stats
      
      NAME                                                                  VALUE
      ---------------------------------------------------------------- ----------
      user commits                                                              4
      user rollbacks                                                            0
      transaction rollbacks                                                     0
      
      SQL>
      
      

      Comment by Dom Brooks — February 15, 2013 @ 11:22 am BST Feb 15,2013 | Reply

      • Checked for rollback to savepoint and statement restart – only “rollback changes – undo records applied” increased.

        Comment by Valentin Nikotin — February 15, 2013 @ 8:42 pm BST Feb 15,2013 | Reply

      • Dom,

        Great, isn’t it.
        You can spend an awful lot of your time deliberately rolling back – but not quite far enough – and the “obvious” statistics tells you nothing about it. As Valentin points out, you have to cross-check with “rollback changes – undo records applied” to get an idea of how much work you are doing while rolling back. (And, of course, the rolling back from “write consistency” – as well as various other things – shows up in that statistic as well.)

        Comment by Jonathan Lewis — February 16, 2013 @ 9:18 am BST Feb 16,2013 | Reply

        • Jonathan
          If you issue a superflous COMMIT (commit that changes nothing ) the user commits statistics is not incremented. If you issue a superflous ROLLBACK (rollback that rolls nothing back as those probably done by web application servers ) the user rollback statistics is incremented while the rollback changes – undo records applied statistics aren’t incremented. If you issue a real rollback (rollback that rolls something back) both the user rollback statistics and the undo records applied are incremented. If you issue a rollback to savepoint (whatever it is superflous or real rollback savepoints) the user rollback statistics is not incremented while the statistics undo records applied is incremented for a real rollback to savepoint and it is not incremented for a superflous rollback to savepoint.

          That is : for commits, we can trust the statistics user_commits but for rollbacks we had better to trust rollback changes – undo records applied

          Comment by Mohamed — February 16, 2013 @ 12:20 pm BST Feb 16,2013

  3. Jonathan, what is this “rollback after every call” you refer to?
    Possibly I have never heard of this (“possibly” because I may have just forgotten it, and will soon have an ‘Ah hah!’ moment )

    Comment by Jared — February 15, 2013 @ 4:43 pm BST Feb 15,2013 | Reply

    • Jared,

      I can’t quote names and versions off the top of my head, but various middle-tier tools handling connection pooling will (or used to) “isolate” the work done by each request by issuing a rollback extremely frequently.

      Comment by Jonathan Lewis — February 16, 2013 @ 9:21 am BST Feb 16,2013 | Reply

  4. Jonathan,
    “Allowing for rounding errors we’re looking for a value between 4.785 *3616 and 4.795 * 3615, i.e. between 17.298 and 17,333. ”

    You obviously want to take the lowest and highest possible values – so I suppose you mean:
    ” 4.785 *3615 and 4.795 * 3616, i.e. between 17.298 and 17,333. “

    Comment by Todor Botev — February 15, 2013 @ 4:45 pm BST Feb 15,2013 | Reply

    • even better:
      ” 4.785 *3615 and 4.795 * 3616, i.e. between 17.298 and 17,339.”

      Comment by Todor Botev — February 16, 2013 @ 4:14 am BST Feb 16,2013 | Reply

      • Todor,

        I got there in the end (and even got the . changed to a ,).
        I’ve take the ceiling() of the lower and floor() of the higher value, though.

        Comment by Jonathan Lewis — February 16, 2013 @ 9:27 am BST Feb 16,2013 | Reply

  5. Jonathan,

    I am glad you touched on this topic since I was looking at my AWR last week and wondering what is my peak load in my system….so my question to you is …..can I use these stats ” Transactions per sec.” to determined when the peak load is on my production system?

    Comment by Lou — February 17, 2013 @ 5:04 am BST Feb 17,2013 | Reply

    • Lou,

      To answer that question indirectly – which is the higher load: 1,000 transactions that update one row each, or 100 transactions that update 10 rows each ?

      What if each type of transaction does a 10MB tablescan, what if the smaller transaction maintains 10 indexes per row, while the large transaction doesn’t maintain any indexes ?

      There are four or five key resources and measures that have different significance to different people. The same single measure will not be appropriate for everyone.

      Comment by Jonathan Lewis — February 18, 2013 @ 7:12 am BST Feb 18,2013 | Reply

  6. [...] a little follow-on from Friday’s posting. I’ll start it off as a quiz, and follow up tomorrow with an explanation of the results [...]

    Pingback by Transactions 2 « Oracle Scratchpad — February 18, 2013 @ 7:54 am BST Feb 18,2013 | 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

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,267 other followers