Search

OakieTags

Who's online

There are currently 0 users and 46 guests online.

Recent comments

Affiliations

Troubleshooting

Advanced RAC Training by Oracle RAC expert Riyaj Shamsudeen

If you’ve troubleshooted (or tuned) RAC then you probably already know Riyaj Shamsudeen and his Orainternals blog & website (links below).

Anyway, since I started delivering my Advanced Oracle Troubleshooting classes some years ago, many people asked whether I would do a similar class for RAC. I had deliberately left out the RAC-specific stuff from my troubleshooting material, because it’s a very wide and complex topic and I feel like before trying to master RAC troubleshooting, you should master troubleshooting of regular single instance databases anyway. I realized that I didn’t have the time to build (and maintain) yet another set of trainig material, especially on so complex topic as RAC performance & troubleshooting. 

So, having seen Riyaj’s impressive work and his presentations at various conferences, I asked whether he would be interested in building a RAC troubleshooting class, going from fundamentals to advanced topics – and he said yes. By now we are that far that I’m happy to announce the first Advanced RAC online seminars by Riyaj Shamsudeen (split across two weeks of online sessions, 4-hours per day, in end of august and september).

We initially called the seminar “Advanced RAC Troubleshooting” but then realized, that there are some closely related non-troubleshooting topics to be covered, like fundamental concepts, internals and also how to configure RAC for performance (so that you wouldn’t have to troubleshoot performance later :-)

We’ll use the same infrastructure and seminar philosophy as I do in my own online seminars, it’s just that this is Riyaj’s material and he will deliver it too.

You can read more about the seminar content, dates and sign up at the seminars page:

Seminars:

Riyaj’s blog:

Riyaj’s website (articles, slides etc):

 

Let the RAC hacking begin! ;-)

 

IOUG Select Journal Editor’s Choice Award 2011

In May I received the IOUG Select Journal Editor’s Choice Award for my Systematic Oracle Latch Contention Troubleshooting article where I introduced my LatchProfX tool for advanced drilldown into complex latch contention problems (thanks IOUG and John Kanagaraj!).

As the relevant IOUG webpage hasn’t been updated yet, I thought to delay this announcement until the update was done – but I just found an official enough announcement (press release) by accident from Reuters site:

Woo-hoo! :-)

The article itself is here:

Thanks to IOUG crew, John Kanagaraj and everyone else who has read, used my stuff and given feedback! :-)

Mything 2

It’s about time I wrote a sequel to Mything in Action – and funnily enough it’s also about bitmap indexes. It starts with a note on the OTN database forum that prompted me to run up a quick test to examine something that turned out to be a limitation in the optimizer. The problem was that the optimizer didn’t do a “bitmap and” between two indexes when it was obviously a reasonable – possibly even good – idea. Here’s some sample code:

create table t1
as
with generator as (
	select	--+ materialize
		rownum id
	from dual
	connect by
		rownum <= 10000
)
select
	mod(rownum-1,10)	c1,
	mod(rownum-1,100)	c2,
	mod(rownum-1,101)	c3,
	rownum			id,
	lpad(rownum,10,'0')	small_vc,
	rpad('x',100)		padding
from
	generator	v1,
	generator	v2
where
	rownum <= 1000000
;

-- stats collection goes here.

create bitmap index t1_b1b2 on t1(c1,c2);
create bitmap index t1_b1b3 on t1(c1,c3);

This was a reasonable model of the situation described in the original posting; and here’s the critical query with the surprise execution path:

select
	/*+
		index_combine(t1 t1_b1b2 t1_b1b3)
	*/
	*
from
	t1
where
	c1 = 5
and	c2 = 50
and	c3 = 50
;

------------------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes | Cost  |
------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |    10 |  1250 |   231 |
|*  1 |  TABLE ACCESS BY INDEX ROWID | T1      |    10 |  1250 |   231 |
|   2 |   BITMAP CONVERSION TO ROWIDS|         |       |       |       |
|*  3 |    BITMAP INDEX SINGLE VALUE | T1_B1B2 |       |       |       |
------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C3"=50)
   3 - access("C1"=5 AND "C2"=50)

You might look at the query and the indexing and decide (as I did) that Oracle ought to be able to manage a “bitmap index single value” on both the indexes, then do a “bitmap and” to minimise the work – something like:

------------------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes | Cost  |
------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |    10 |  1250 |     6 |
|   1 |  TABLE ACCESS BY INDEX ROWID | T1      |    10 |  1250 |     6 |
|   2 |   BITMAP CONVERSION TO ROWIDS|         |       |       |       |
|   3 |    BITMAP AND                |         |       |       |       |
|*  4 |     BITMAP INDEX SINGLE VALUE| T1_B1B2 |       |       |       |
|*  5 |     BITMAP INDEX SINGLE VALUE| T1_B1B3 |       |       |       |
------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("C1"=5 AND "C2"=50)
   5 - access("C1"=5 AND "C3"=50)

But it doesn’t – and there’s a clue about why not in the “Predicate Information”. To create this plan the optimizer would have to duplicate an existing predicate (c1 = 5) so that it could find the second index after selecting the first one. There’s no reason, of course, why the optimizer code couldn’t do this – but at present, even in 11.2.0.2, it just doesn’t. Perhaps this is another opportunity for thinking about manual optimisation strategies – or perhaps ensuring that you’ve created the right set of indexes.

You might notice, of course, that Oracle seems to have ignored my index_combine() hint. Oracle doesn’t ignore hints, of course (apart from cases suffering from problems with syntax, legality, or bugs) but remember that index_combine() is only supplying a list of indexes that Oracle should consider, it doesn’t require the optimizer to use every index in the list. In this case, of course, the hint also has an error because it’s naming an index that can’t be used.

Anyway, I wrote a note suggesting that there was a gap in the optimizer’s strategies, specifically:

I’ve just spent a few minutes playing with a data set where this (c1,c2) (c1,c3) type of index combination is obviously a good idea – and can’t get the bitmap_tree() hint to force the path. I think this means there’s a hole in the optimizer’s legal strategies that you might have to fill by other methods.

Here’s where the mything starts. The OP replied as follows:

Do I right understand that it is impossible to combine bitmap non-one-column indexes?

ABSOLUTELY NOT!, the OP has jumped from the particular to the general; fortunately he asked the question, rather than silently making the assumption then spreading the gospel. Of course I was at fault because I could have pointed out explicitly that the pattern was dependent on the two indexes starting with the same column – but is it so hard to interpret patterns.

What’s more annoying is that the OP was already using a model to test what happened – would it have been so hard for him to try a few different combinations of indexes – switching the column order on both indexes. For example what happens if the indexes are (c2, c1)(c3,c1) ?


----------------------------------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |    10 |  1250 |    12   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID | T1      |    10 |  1250 |    12   (0)| 00:00:01 |
|   2 |   BITMAP CONVERSION TO ROWIDS|         |       |       |            |          |
|   3 |    BITMAP AND                |         |       |       |            |          |
|*  4 |     BITMAP INDEX SINGLE VALUE| T1_B2B1 |       |       |            |          |
|   5 |     BITMAP MERGE             |         |       |       |            |          |
|*  6 |      BITMAP INDEX RANGE SCAN | T1_B3B1 |       |       |            |          |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("C2"=50 AND "C1"=5)
   6 - access("C3"=50)
       filter("C3"=50)

See how easy it is to show that the optimizer can combine multi-column bitmap indexes; but we can observe, at the same time, that it doesn’t make “perfect” use of the (c3, c1) index. Oracle still does excess work in the index because it hasn’t repeated the use of the c1 predicate.

Maxim:

When you see some unexpected behaviour the least you should do when investigating it is to ask yourself: “in what way might this be a special case?”

How to hint – 1

Here’s a quick tutorial in hinting, promped by a question on the OTN database forum.
The OP has a hash semi-join and Oracle appears to be ignoring a hint to use a nested loop:

    > I tried forcing the optimizer to not use hash join by adding NO_USE_HASH, USE_NL to my sql but it doesn’t seem to work.
    > Can anyone please help check what I have done wrong.
    > select /*+ NO_USE_HASH(C2)  USE_NL(C2) */
    >         SC.SID, SC.MID, SC.INDATE, SC.EXDATE, SC.AUDATE
    > FROM    SSCLASS SC
    > WHERE   SC.SID = 0
    > AND     SC.CID = 0
    > AND     SC.MID = 1
    > AND     SC.INDATE <= SC.EXDATE
    > AND     EXISTS (
    >                 SELECT  SSCID FROM SSCLASS C2
    >                 WHERE   C2.SSCID = SC.SSCID
    >                 AND     C2.AUDATE >= to_date('2009-01-01','yyyy-MM-dd')
    >         )
    > ORDER BY
    >        SSCID, INDATE, EXDATE
    >
    > PLAN_TABLE_OUTPUT
    > Plan hash value: 1476588646
    >
    > ------------------------------------------------------------------------------------------------------
    > | Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
    > ------------------------------------------------------------------------------------------------------
    > |   0 | SELECT STATEMENT              |              |   204K|    10M|       | 35799   (1)| 00:07:10 |
    > |   1 |  SORT ORDER BY                |              |   204K|    10M|    25M| 35799   (1)| 00:07:10 |
    > |*  2 |   HASH JOIN SEMI              |              |   204K|    10M|    10M| 33077   (1)| 00:06:37 |
    > |*  3 |    TABLE ACCESS BY INDEX ROWID| SSCLASS      |   204K|  7983K|       |  9110   (1)| 00:01:50 |
    > |*  4 |     INDEX RANGE SCAN          | X5_SSCLASS   |   204K|       |       |   582   (1)| 00:00:07 |
    > |*  5 |    INDEX RANGE SCAN           | X6_SSCLASS   |  4955K|    66M|       | 17276   (1)| 00:03:28 |
    > ------------------------------------------------------------------------------------------------------
    

I’m not going to argue about what plans might be good or bad, and I’m going to assume the OP simply wants a nested loop semi join using a “good” index into the table aliased as C2; so I’m just going to demonstrate on this simple example how to approach that specific problem. The critical error the OP has made is that the join he’s trying to affect doesn’t exist in the query block where he’s put his hint – so he needs to find out what query will exist after the subquery has been nested and the optimizer is looking at the semi-join.

Here’s initial query, with default execution plan, I’ll point out that there is an index on the n1 column that I’m using in the existence test:

select
	*
from
	t2
where	t2.n2 = 15
and	exists (
		select
			null
		from	t1
		where	t1.n1 = t2.n1
	)
;

-------------------------------------------------------------------------------
| Id  | Operation             | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |    15 |  2865 |    26   (4)| 00:00:01 |
|*  1 |  HASH JOIN SEMI       |       |    15 |  2865 |    26   (4)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL   | T2    |    15 |  2805 |    22   (0)| 00:00:01 |
|   3 |   INDEX FAST FULL SCAN| T1_I1 |  3000 | 12000 |     3   (0)| 00:00:01 |
-------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."N1"="T2"."N1")
   2 - filter("T2"."N2"=15)

So I’ve emulated the hash semi-join into the second table that the OP wants to get rid of, and I’m not using the target index in a “precision” fashion.

I happen to know that there is a hint that I can use to make the subquery operate as a nested loop semijoin. It’s /*+ nl_sj */ and it has to go in the subquery. Unfortunately it’s a hint that’s deprecated in 10g, but never mind that for the moment. I’m also going to adopt “sensible practice” and give each of my query blocks a name. Let’s see what we get from dbms_xplan with the hint.

explain plan
set statement_id = 'sj_hinted'
for
select
	/*+
		qb_name(main)
	*/
	*
from
	t2
where	t2.n2 = 15
and	exists (
		select
			/*+
				qb_name(subq) nl_sj
			*/
			null
		from	t1
		where	t1.n1 = t2.n1
	)
;

select * from table(dbms_xplan.display(null,'sj_hinted','outline'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 635111780

----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |    15 |  2865 |    37   (0)| 00:00:01 |
|   1 |  NESTED LOOPS SEMI |       |    15 |  2865 |    37   (0)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL| T2    |    15 |  2805 |    22   (0)| 00:00:01 |
|*  3 |   INDEX RANGE SCAN | T1_I1 |  3000 | 12000 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      USE_NL(@"SEL$A93AFAED" "T1"@"SUBQ")
      LEADING(@"SEL$A93AFAED" "T2"@"MAIN" "T1"@"SUBQ")
      INDEX(@"SEL$A93AFAED" "T1"@"SUBQ" ("T1"."N1"))
      FULL(@"SEL$A93AFAED" "T2"@"MAIN")
      OUTLINE(@"SUBQ")
      OUTLINE(@"MAIN")
      UNNEST(@"SUBQ")
      OUTLINE_LEAF(@"SEL$A93AFAED")
      ALL_ROWS
      OPTIMIZER_FEATURES_ENABLE('10.2.0.3')
      IGNORE_OPTIM_EMBEDDED_HINTS
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("T2"."N2"=15)
   3 - access("T1"."N1"="T2"."N1")

Note how I’ve used a statement_id to label my plan, and I’ve added the extra predicate ‘outline’ to the call to dbms_xplan. The outline shows me the complete set of hints I need to reproduce the execution plan; technically it’s the information that would be stored by Oracle as an outline or an SQL Baseline.

There are a few session-level parameter settings I don’t really need included, and a couple of things which can’t qualify as “legal” SQL hints, though, and I’m going to ignore those. (Don’t you love the “ignore the hints” hint, though!)

So let’s take the minimum set of hints back into the SQL:

explain plan
set statement_id = 'full_hints'
for
select
	/*+
		qb_name(main)
		unnest(@subq)
		leading(@sel$a93afaed t2@main t1@subq)
		use_nl(@sel$a93afaed t1@subq)
		full(@sel$a93afaed t2@main)
		index(@sel$a93afaed t1@subq(t1.n1))
	*/
	*
from
	t2
where	t2.n2 = 15
and	exists (
		select
			/*+
				qb_name(subq)
			*/
			null
		from	t1
		where	t1.n1 = t2.n1
	)
;

select * from table(dbms_xplan.display(null,'full_hints','outline'));

----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |    15 |  2865 |    37   (0)| 00:00:01 |
|   1 |  NESTED LOOPS SEMI |       |    15 |  2865 |    37   (0)| 00:00:01 |
|*  2 |   TABLE ACCESS FULL| T2    |    15 |  2805 |    22   (0)| 00:00:01 |
|*  3 |   INDEX RANGE SCAN | T1_I1 |  3000 | 12000 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      USE_NL(@"SEL$A93AFAED" "T1"@"SUBQ")
      LEADING(@"SEL$A93AFAED" "T2"@"MAIN" "T1"@"SUBQ")
      INDEX(@"SEL$A93AFAED" "T1"@"SUBQ" ("T1"."N1"))
      FULL(@"SEL$A93AFAED" "T2"@"MAIN")
      OUTLINE(@"SUBQ")
      OUTLINE(@"MAIN")
      UNNEST(@"SUBQ")
      OUTLINE_LEAF(@"SEL$A93AFAED")
      ALL_ROWS
      OPTIMIZER_FEATURES_ENABLE('10.2.0.3')
      IGNORE_OPTIM_EMBEDDED_HINTS
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("T2"."N2"=15)
   3 - access("T1"."N1"="T2"."N1")

Job done – we used a bit of hackery to get the plan we wanted, then used the legal hints to reproduce the plan.

It is important to name your query blocks as this helps you to identify what transformations apply when, and how to label your tables correctly in your code; and you have to remember that the “strange” query block names that appear (such as @”SEL$A93AFAED”) are dependent on the query block names you originally supplied.

The method isn’t perfect since (a) sometimes hints that are needed don’t get into the outline, and (b) sometimes the outline actually doesn’t reproduce the plan if all you use are the “legal” hints – but it may help you in most cases.

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.