Search

OakieTags

Who's online

There are currently 0 users and 37 guests online.

Recent comments

Affiliations

Troubleshooting

Audit Excess

So you’ve decided you want to audit a particular table in your database, and think that Oracle’s built in audit command will do what you want. You discover two options that seem to be relevant:

audit all on t1 by access;
audit all on t1 by session;

To check the audit state of anything in your schema you can then run a simple query – with a few SQL*Plus formatting commands – to see something like the following:

select
	*
from
	user_obj_audit_opts
;

OBJECT_NAME          OBJECT_TYPE       ALT AUD COM DEL GRA IND INS LOC REN SEL UPD REF EXE CRE REA WRI FBK
-------------------- ----------------- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
T1                   TABLE             S/S S/S S/S S/S S/S S/S S/S S/S S/S S/S S/S -/- -/- -/- -/- -/- S/S

The appearance of all the ‘S’ markers in my output is because I actually ran the two earlier commands in the order shown, so the ‘by session’ command after the ‘by access’ command. If I’d run the commands the other way round then you would have seen ‘A’s everywhere.

Each of the columns (‘ALT’,'SEL’, etc.) represents an action that can be audited, and the column content shows when and why it will be audited. The significance of the “X/X” is that the default audit is “always” but could be limited to “whenever successful” (the first ‘X’) or “whenever not successful” (the second  ‘X’).

The question is this: is auditing by session cheaper than auditing by action ? You initial thought is that it probably ought to be, because you only need one row per audited object per session when auditing by session, not one row per session per access – but how much do you really save ? When in doubt, one of the first tests is to run a little code with sql_trace enabled.

Here, from 10.2.0.3, is the interesting bit from tkprof after running “select * from t1″ eleven times – enabling sql_trace after the first select so that I can see the work done by auditing for the last ten selects:

Audit by access
===============
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,
  userhost,terminal,action#,returncode, obj$creator,obj$name,auth$privileges,
  auth$grantee, new$owner,new$name,ses$actions,ses$tid,logoff$pread,
  logoff$lwrite,logoff$dead,comment$text,spare1,spare2,  priv$used,clientid,
  sessioncpu,proxy$sid,user$guid, instance#,process#,xid,scn,auditid,sqlbind,
  sqltext)
values
(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),     :4,:5,:6,:7,:8,     :9,:10,:11,
  :12,     :13,:14,:15,:16,:17,     :18,:19,:20,:21,:22,     :23,:24,:25,:26,
  :27,     :28,:29,:30,:31,:32,:33,:34)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0          0         41          10
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.00       0.00          0          0         41          10

Audit by session
================
update sys.aud$ set ses$actions=merge$actions(ses$actions,:3), spare2=
  nvl(spare2,:4)
where
 sessionid=:1 and ses$tid=:2 and action#=103 and (priv$used=:5 or priv$used
  is null and :5 is null)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     10      0.00       0.00          0         40         30          10
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.00       0.00          0         40         30          10

If you thought that auditing by session was a light-weight operation, think again. Interestingly, the auditing anomaly that I reported recently re-appears in the “audit by session” option. You will recall that when auditing is enabled, Oracle turns “update row” into “lock row, update row” – this happens to the audit table (aud$) as well, so every update to an aud$ row generates two redo entries. Here’s a comparison of the redo generated (by 10.2.0.3) for the two tests:

Audit by access
===============
redo entries                                                                30
redo size                                                               10,360
undo change vector size                                                  2,280

Audit by session
================
redo entries                                                                30
redo size                                                                8,112
undo change vector size                                                  2,320

The results are startlingly similar. For “audit by access” we see one redo entry for the table insert, one for the index insert, one for the commit; for “audit by session” we see one redo entry for the “lock row”, one for the “update row”, one for the commit. You may recall, by the way, that one of the comments on my blog about the lock/update anomaly pointed out that this bug was limited to 10.2.0.1 – 10.2.0.3; that may be true most of the time, but when you get to the aud$ table the same lock/update pattern reappears.

And here’s a final kicker when you think about auditing: sometimes it seems like a good idea to write a pl/sql function with an embedded query that you can use in a select list rather than doing an outer join to a table in the from clause. If you enable auditing on the embedded table, every call to the pl/sql function results in an insert (or update) of a row in the audit table.

Footnote: If you want to see what the three-letter column names in the user_obj_audit_opts view mean, you can run a query like this:


column column_name format a6 heading "Option"
column comments format a70 heading "Description"

select
	column_name, comments
from
	all_col_comments
where
	owner = 'SYS'
and	table_name = 'USER_DEF_AUDIT_OPTS'
;

Option Description
------ ----------------------------------------------------------------------
ALT    Auditing ALTER WHENEVER SUCCESSFUL / UNSUCCESSFUL
AUD    Auditing AUDIT WHENEVER SUCCESSFUL / UNSUCCESSFUL
COM    Auditing COMMENT WHENEVER SUCCESSFUL / UNSUCCESSFUL
DEL    Auditing DELETE WHENEVER SUCCESSFUL / UNSUCCESSFUL
GRA    Auditing GRANT WHENEVER SUCCESSFUL / UNSUCCESSFUL
IND    Auditing INDEX WHENEVER SUCCESSFUL / UNSUCCESSFUL
INS    Auditing INSERT WHENEVER SUCCESSFUL / UNSUCCESSFUL
LOC    Auditing LOCK WHENEVER SUCCESSFUL / UNSUCCESSFUL
REN    Auditing RENAME WHENEVER SUCCESSFUL / UNSUCCESSFUL
SEL    Auditing SELECT WHENEVER SUCCESSFUL / UNSUCCESSFUL
UPD    Auditing UPDATE WHENEVER SUCCESSFUL / UNSUCCESSFUL
REF    Dummy REF column. Maintained for backward compatibility of the view
EXE    Auditing EXECUTE WHENEVER SUCCESSFUL / UNSUCCESSFUL
FBK    Auditing FLASHBACK WHENEVER SUCCESSFUL / UNSUCCESSFUL
REA    Auditing READ WHENEVER SUCCESSFUL / UNSUCCESSFUL

Cache buffers chains latch contention troubleshooting using latchprofx.sql example

Laurent Demaret has written a good article about how he systematically troubleshooted cache buffers chains latch contention, starting from wait interface and drilling down into details with my latchprofx tool:

A common cause for cache buffers chains latch contention is that some blocks are visited and re-visited way too much by a query execution. This usually happens due to nested loops joins or FILTER loops retrieving many rows from their outer (driving) row sources and then visiting the inner row-source again for each row from driving row source. Once you manage to fix your execution plan (perhaps by getting a hash join instead of the loop), then the blocks will not be re-visited so much and the latches will be hammered much less too.

The moral of the story is that if you have latch contention in a modern Oracle database, you don’t need to start tweaking undocumented latching parameters, but reduce the latch usage instead. And Laurent has done a good job with systematically identifying the SQL that needs to be fixed.

Good stuff!

If you don’t know what LatchProfX is, read this:

 

audsid

Here’s an example of how the passing of time can allow a problem to creep up on you.

A recent client had a pair of logon/logoff database triggers to capture some information that wasn’t available in the normal audit trail, and they had been using these triggers successfully for many years, but one day they realised that the amount of redo generated per hour had become rather large, and had actually been quite bad and getting worse over the last few months for no apparent reason. (You’ve heard this one before … “honest, guv, nothing has changed”).

Here’s a clue to their problem. Their logoff trigger updated their own auditing table with the following code (although I’ve removed some columns) :

begin
        if sys_context('USERENV', 'SESSIONID') = 0 then
                update system.user_audit a
                set
                        logoff_time = sysdate
                where    audsid = sys_context('USERENV', 'SESSIONID')
                and     logon_time = (
                                select  max(logon_time)
                                from    system.user_audit b
                                where   b.audsid = a.audsid
                        );
        else
                update system.user_audit
                set
                        logoff_time = sysdate
                where   audsid = sys_context('USERENV', 'SESSIONID');
        end if;
end;

The table was suitably indexed to make the correlated update (“most recent of” subquery) operate very efficiently, so that wasn’t the problem.

You might question the validity of updating just the rows with the most recent date when the sys_context(‘userenv’,'sessioned’) is zero, and why the SQL to do the update doesn’t then use literal zeros rather than calling the sys_context() function and using a correlation column – but those are minor details.

You might wonder why zero is a special case, of course, but then you may recall that when a user connects as SYS the audsid is zero – so this code is attempting to limit the update to just the row created by the most recent logon by SYS, which may introduce a few errors but really SYS shouldn’t be connecting to a production system very often.

At this point you might ask which version of Oracle the client was running. They had started using Oracle a long time ago, but this system had gone through Oracle 9i, and was now running 10g; and if you’ve kept an eye on things like autotrace you may have noticed that the audsid used by any SYS session changed from zero to 4294967295 in the upgrade to 10g. So this code is no longer treating SYS as a special case.

By the time I was on site, the client’s audit table held about 87,000 rows for the audsid 4294967295, and every time SYS logged off the session would update every single one of them. (It took a few seconds and about 45 MB of redo for SYS to log off – and SYS sessions connected rather more frequently than expected).

Warning:

If you still have to get through the upgrade from 8i or 9i to 10g, then watch out for code that does things with the deprecated userenv(‘sessionid’) or sys_context(‘userenv’,'sessionid’).

audit

Here’s one of those funny little details that can cause confusion:

SQL> select * from user_audit_object;

no rows selected

SQL> audit select on indjoin by session whenever successful;

Audit succeeded.

SQL> select
  2     count(*)
  3  from
  4     indjoin         ij
  5  where
  6     id between 100 and 200
  7  and        val between 50 and 150
  8  ;

  COUNT(*)
----------
        51

1 row selected.

SQL> select * from user_audit_object where obj_name = 'INDJOIN';

no rows selected

So we had nothing in our “object audit trail”, then we enabled auditing on one particular table for select statements (and audit_trail = db has been set in the parameter file) but our select statement hasn’t been audited. What went wrong ?

Let’s try a different query against the audit view which, until a moment ago, held no data:


SQL> select obj_name from user_audit_object;

OBJ_NAME
-----------------------------------------------
index$_join$_001

So we have audited something – but what ? Here’s the execution plan for our query:

----------------------------------------------------------------------------------------
| Id  | Operation           | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |                  |     1 |     8 |     5  (20)| 00:00:01 |
|   1 |  SORT AGGREGATE     |                  |     1 |     8 |            |          |
|*  2 |   VIEW              | index$_join$_001 |     3 |    24 |     5  (20)| 00:00:01 |
|*  3 |    HASH JOIN        |                  |       |       |            |          |
|*  4 |     INDEX RANGE SCAN| IJ_PK            |     3 |    24 |     3  (34)| 00:00:01 |
|*  5 |     INDEX RANGE SCAN| IJ_VAL           |     3 |    24 |     3  (34)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("VAL"<=150 AND "ID"<=200 AND "ID">=100 AND "VAL">=50)
   3 - access(ROWID=ROWID)
   4 - access("ID">=100 AND "ID"<=200)
   5 - access("VAL">=50 AND "VAL"<=150)

See that index$_join$_001 in line 2 ? We have a plan that uses the “index hash join” mechanism to query that table – so Oracle audits the query, but unfortunately uses the name of the internal view in the audit record.

Be very careful how you audit objects; you may think that an object has not been accessed when it has (sort of). If you’ve started doing this type of auditing to check whether or not an object is ever accessed you could be fooled.

You could claim, of course, that the object hasn’t really been accessed – but compare the index join above with the following (cut-n-paste) example, which I ran after deleting everything from the aud$ table:

SQL> connect test_user/test
Connected.

SQL> select obj_name from user_audit_object;

no rows selected

SQL> set autotrace on explain
SQL> select count(*) from indjoin where id = 23;

  COUNT(*)
----------
         1

1 row selected.

Execution Plan
----------------------------------------------------------
Plan hash value: 689603510

----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |     1 |     4 |     1   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE    |       |     1 |     4 |            |          |
|*  2 |   INDEX UNIQUE SCAN| IJ_PK |     1 |     4 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("ID"=23)

SQL> set autotrace off
SQL> select obj_name from user_audit_object;

OBJ_NAME
----------------
INDJOIN

1 row selected.

We haven’t actually visited the indjoin table, but the audit code recognises that that was the intent, even though the optimizer made physical access unnecessary. The behaviour ought to be the same for both cases.

(This example orginally came from a client site, by the way – with the question “how come the audit trail says we’re not visiting this table?”. The client version, and the version I tested on, was 10.2.0.3. There were a couple of other little surprises I found at the same time – I may find time to write about them some other day.)

oradebug peek

An odd little discovery today. The peek command of oradebug is fairly well documented on the internet, and I’ve used it from time to time to find the contents of memory. Earlier on today, though, I was running 11.1.0.6 and it didn’t do what I was expecting. I was trying to dump a log buffer block from memory so after logging on as sys and finding the location for the block I duly typed:


oradebug setmypid
peek 0x09090000 512

The response I got looked, as expected, like this:


[9090000, 9090200) = 00002201 0000E3D7 00000974 E1808044 00340035 00350035 00340035
0034002F 0022002F 0309002C 050C0AC2 010860C4 02C1023E 056F7807 08290714 ...

As you can see, the dump range is given as 512 bytes (the variation in bracketing for the "[9090000,9090200)" means include the low address but exclude the high address) but the dump itself is only 15 words. My memory told me that this is what Oracle does on screen and that all I had to do was read the trace file for the full 512 bytes. Unfortunately my memory was wrong - the trace file was limited to the same 15 words.

It wasn't until I added an extra number to the command that I got the full 512 bytes I wanted in the trace file:

=== On screen ===
SQL> oradebug peek 0x09090000 512 1
[9090000, 9090200) = 00002201 0000E3D7 00000974 E1808044 00340035 00350035 00340035
0034002F 0022002F 0309002C 050C0AC2 010860C4 02C1023E 056F7807 08290714 ...

=== from the trace file ===
Processing Oradebug command 'peek 0x09090000 512 1'
[9090000, 9090200) = 00002201 0000E3D7 00000974 E1808044 00340035 00350035 ...
Dump of memory from 0x9090018 to 0x9090200
9090010                   00340035 0034002F          [5.4./.4.]
9090020 0022002F 0309002C 050C0AC2 010860C4  [/.".,........`..]
9090030 02C1023E 056F7807 08290714 056F7807  [>....xo...)..xo.]
9090040 082A0714 023DC203 0303C102 091215C2  [..*...=.........]
     ...
90901E0 03083207 02083DC2 C20303C1 C2031215  [.2...=..........]
90901F0 00012D09 00000009 00000000 0016010B  [.-..............]

*** 2011-05-20 16:35:11.156
Oradebug command 'peek 0x09090000 512 1' console output:
[9090000, 9090200) = 00002201 0000E3D7 00000974 E1808044 00340035 00350035 00340035 0034002F 0022002F 0309002C 050C0AC2 010860C4 02C1023E 056F7807 08290714 ...

Apart from the repeating the on-screen dump, the trace file now reports the full dump, with both a raw list and a character-based interpretation of each 16 bytes that starts, unfortunately, by repeating the first 24 (0×18) bytes in the same format as the onscreen format.

Maybe I’m wrong about how I used to peek data – maybe it’s just a variation in this version of Oracle.

ASSM bug reprise - part 2

Introduction

In the first part of this post I've explained some of the details and underlying reasons of bug 6918210. The most important part of the bug is that it can only be hit if many row migrations happen during a single transaction. However, having excessive row migrations is usually a sign of poor design, so this point probably can't be stressed enough:

If you don't have excessive row migrations the bug can not become significant

Of course, there might be cases where you think you actually have a sound design but due to lack of information about the internal workings it might not be obvious that excessive row migrations could be caused by certain activities.

NoCOUG Journal – Ask the Oracle ACEs – Why is my database slow?

Dave Abercrombie mailed me earlier that the May 2011 NoCOUG Journal is already out and can be viewed online at http://www.nocoug.org/Journal/NoCOUG_Journal_201105.pdf.

I met Dave at Hotsos 2011 when he attended my presentation.. apparently we have the same interest about Statistics, Linear Regression, AWR, AAS and he’s got awesome blogs about it at http://aberdave.blogspot.com. Also being the Journal Editor at Northern California Oracle Users’s Group, he invited me to write a short article about the question:

ASSM bug reprise - part 1

This was meant to be published shortly after my latest quiz night post as an explanatory follow up, but unfortunately I only managed to complete this note by now.

There is a more or less famous bug in ASSM (see bug 6918210 in MOS as well as Greg Rahn's and Jonathan Lewis' post) in versions below 11.2 that so far has been classified as only showing up in case of a combination of larger block sizes (greater the current default of 8K) and excessive row migrations. With such a combination it was reproducible that an UPDATE of the same data pattern residing in an ASSM tablespace caused significantly more work than doing the same in a MSSM tablespace, because apparently ASSM had problems finding suitable blocks to store the migrated rows.

Overflow

Here’s a little gem I hadn’t come across before (because I hadn’t read the upgrade manuals). Try running the following pl/sql block in 9i, and then 10g (or later):

declare
        v1      number(38);
begin
        v1 := 256*256*256*256;
        dbms_output.put_line(v1);
end;
/

In 9i the result is 4294967296; but for later versions the result is:


declare
*
ERROR at line 1:
ORA-01426: numeric overflow
ORA-06512: at line 4

It’s not a bug, it’s expected behaviour. The expression consists of integers only, so Oracle uses INTEGER arithmetic that limits the result to roughly 9 significant figures. If you want the block to work in newer versions of Oracle you have to add a decimal point to (at least) one of the operands to make Oracle use NUMBER arithmetic that takes it up to roughly 38 significant figures.

Consistent Gets

There’s an interesting question on the OTN database forum at present – why does an update of 300,000 rows take a billion buffer visits. (There are 25 indexes on the table – so you might point a finger at then initially, but only one of the indexes is going to be changed by the update so that should only account for around an extra 10 gets per row in a clean environment.)

The answer to the question hadn’t been reached by the time I wrote this note – and this note isn’t intended as a suggested cause of the issue, it’s just an example of the type of thing that could cause an apparent excess of buffer visits. Here’s a little bit of code I’ve just tested on 11.1.0.6 using an 8KB block size

drop sequence t1_seq;
create sequence t1_seq;

drop table t1;

create table t1 as
select
	rownum id, rpad('x',10) small_vc
from
	all_objects
where
	rownum <= 11
;

execute dbms_stats.gather_table_stats(user,'t1')

select * from t1;

pause

execute snap_my_stats.start_snap
update t1 set small_vc = upper('small_vc') where id = 11;
execute snap_my_stats.end_snap

(The calls to the “snap_my_stats” package simply record the current contents of v$mystat joined to v$statname before and after the update and print the changes.)

The code simply creates a sequence and a table with 11 rows and no indexes, then updates one specific row in the table. However, where the “pause” appears, I start up 10 separate sessions to do the following:

column seqval new_value m_seq

select t1_seq.nextval seqval from dual;

update t1 set small_vc = upper(small_vc) where id = &m_seq;

pause

exit

So when I hit return on the pause for the first session, there are 10 separate active transactions on the single block in my table, one for each row except row 11. (And now you know what the sequence was for.)

Here’s a subset of the statistics from v$mystat after my update statement – remember, all I’ve done is update one row in one block using a tablescan:


Name                                                                     Value
----                                                                     -----
session logical reads                                                       45
db block gets                                                                3
db block gets from cache                                                     3
consistent gets                                                             42
consistent gets from cache                                                  42
consistent gets from cache (fastpath)                                        3
consistent gets - examination                                               39
db block changes                                                             7
consistent changes                                                          13
calls to kcmgrs                                                             26
calls to kcmgas                                                              1
calls to get snapshot scn: kcmgss                                            7
redo entries                                                                 3
redo size                                                                  764
undo change vector size                                                    236
data blocks consistent reads - undo records applied                         13
active txn count during cleanout                                            20
table scan blocks gotten                                                     1

Note the last statistics – just one block accessed by tablescan – compared to the session logical reads at 45 buffer visits.
That 45 buffer visits comes from 3 current (db) block gets and 42 consistent gets.
Of the 42 consistent gets 39 are examinations, which – in the absence of indexes and hash clusters are visits to undo blocks
The 39 undo visits are to find 13 undo records to apply, and 26 visits (to undo segment headers) to find 13 transaction SCNs.

What you’re seeing is one session doing (relatively speaking) a lot of work to hide the effects of other sessions which have not yet committed their transactions. (This was only a quick test, so I haven’t examined why the larger figures appear in multiples of 13 rather than multiples of 10 – the number of other transactions – and since this note is just trying to demonstrate a concept I won’t be looking into it any further.)

If you have a number of “non-interfering” transactions – i.e. transactions that don’t actually lock each other out – on a single table then you could find that they spend more time hiding each other’s work than they do doing their own work.

Footnote:

The numbers change significantly if I commit the 10 transactions (but wait until they’ve all executed, so they are all active at the same time) before I do the update to the 11th row.

The numbers changed even more surprisingly when I forgot to collect stats on the table in my initial example of the test.