el-caro

RDBMS events

2010-07-29T21:36:00.001-07:00

RDBMS events are often used to do additional tracing and for debug purposes.
Most of them are listed in $ORACLE_HOME/rdbms/mesg/oraus.msg
One such event I use quite often to determine which locks/enqueues a session is requesting is the following.
For example the below trace indicates that an innocuous looking query on v$flash_recovery_area_usage takes a controlfile lock in mode 4 which might not be the best thing to happen on a high throughput multi node RAC environment with a huge number of flashback logs.
SQL> alter session set events '10704 trace name context forever, level 10';

Session altered.

SQL> oradebug setmypid
Statement processed.
SQL> oradebug
tracefile_name /u01/app/oracle/diag/rdbms/TEST/TEST1/trace/TEST1_ora_600.trc
SQL> select * from v$flash_recovery_area_usage;

*** 2010-07-30 10:07:33.978
ksqgtl *** CF-00000000-00000000 mode=4 flags=0x1a011 timeout=900 ***
ksqgtl: no transaction
ksqgtl: use existing ksusetxn DID
ksqgtl:
ksqlkdid: 0001-0036-00000169

*** 2010-07-30 10:07:33.978
*** ksudidTrace: ksqgtl
ksusesdi: 0001-0036-00000168
ksusetxn: 0001-0036-00000169

*** 2010-07-30 10:07:33.978
ksqcmi: CF,0,0 mode=4 timeout=900
ksqcmi: returns 0
ksqgtl: RETURNS 0

*** 2010-07-30 10:07:33.978
ksqgtl *** CF-00000000-00000004 mode=4 flags=0x10010 timeout=0 ***
ksqgtl: no transaction
ksqgtl: use existing ksusetxn DID
ksqgtl:
ksqlkdid: 0001-0036-00000169

Another event I have used in the past is related to parallel query to determine why PQ slaves do not get spawned
But to my surprise this event does not work anymore in 11.2

SQL> alter session set events '10392 trace name context forever, level 1';
Session altered.

SQL> oradebug setmypid
Statement processed.

SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/TEST/TEST1/trace/TEST1_ora_14748.trc

SQL> select /*+ parallel(a,8) */ count(*) from sys.obj$ a;

COUNT(*)
----------
231692

SQL> !cat /u01/app/oracle/diag/rdbms/TEST/TEST1/trace/TEST1_ora_14748.trc

*** 2010-07-30 14:41:02.547
*** SESSION ID:(316.58074) 2010-07-30 14:41:02.547
*** CLIENT ID:() 2010-07-30 14:41:02.547
*** SERVICE NAME:(SYS$USERS) 2010-07-30 14:41:02.547
*** MODULE NAME:(sqlplus@bart.au (TNS V1-V3)) 2010-07-30 14:41:02.547
*** ACTION NAME:() 2010-07-30 14:41:02.547

Processing Oradebug command 'setmypid'

*** 2010-07-30 14:41:02.547
Oradebug command 'setmypid' console output:

*** 2010-07-30 14:41:08.598
Processing Oradebug command 'tracefile_name'

*** 2010-07-30 14:41:08.598
Oradebug command 'tracefile_name' console output:

The trace does not contain any information

Feedback from Oracle was that “not many people use the px numeric ones and so they removed the code.”…
You can still use the _px_trace underscore parameter to determine why queries are not running in parallel

Dynamic Re-Mastering in 11g

2010-04-07T04:19:00.000-07:00

This is a follow-up on a post from last year

http://el-caro.blogspot.com/search/label/10g%20RAC%20DRM

Node 1
========
SQL> create table obj as select * from sys.obj$;

Table created.

SQL> select object_id,owner,object_type from dba_objects where object_name='OBJ' and object_type='TABLE';

OBJECT_ID OWNER OBJECT_TYPE
---------- ------------------------------ -------------------
136388 REGOFA TABLE

SQL> select * from V$GCSPFMASTER_INFO where DATA_OBJECT_ID=136388;

no rows selected

Now we go to node 2 and manually master the object there...

Node 2
=========
SQL> oradebug setmypid
Statement processed.
SQL> oradebug lkdebug -m pkey 136388
Statement processed.
SQL> select * from V$GCSPFMASTER_INFO where data_object_id=136388;

FILE_ID DATA_OBJECT_ID GC_MASTERIN CURRENT_MASTER PREVIOUS_MASTER
---------- -------------- ----------- -------------- ---------------
REMASTER_CNT
------------
0 136388 Affinity 1 32767
1

Node 1
======

SQL> oradebug setmypid
Statement processed.
SQL> oradebug lkdebug -m pkey 136388
Statement processed.

Also Bug 5649377: REMASTER_CNT IN V$GCSPFMASTER_INFO IS NOT GETTING UPDATED
which I logged in 2006 is fixed in 11g

SQL> /

FILE_ID DATA_OBJECT_ID GC_MASTERIN CURRENT_MASTER PREVIOUS_MASTER
---------- -------------- ----------- -------------- ---------------
REMASTER_CNT
------------
0 136388 Affinity 0 1
2

As you can see the remaster_cnt is correctly set to 2 above
SQL> select * from X$KJDRMAFNSTATS;

ADDR INDX INST_ID DRMS AVG_DRM_TIME OBJECTS_PER_DRM
---------------- ---------- ---------- ---------- ------------ ---------------
QUIESCE_T FRZ_T CLEANUP_T REPLAY_T FIXWRITE_T SYNC_T RES_CLEANED
---------- ---------- ---------- ---------- ---------- ---------- -----------
REPLAY_S REPLAY_R MY_OBJECTS
---------- ---------- ----------
0000000060016FC0 0 1 104 11291 186
3219 28 1622 1302 4589 510 0
26 191959 2

SQL> select count(*) from V$GCSPFMASTER_INFO where current_master=0;

COUNT(*)
----------
2

DRM info is now also available in AWR tables via DBA_HIST_DYN_REMASTER_STATS

Also the following event can be used to trace DRM information

Event can be turned ON dynamically

SQL> alter system set events '10430 trace name context forever, level 10';

System altered.

*** 2010-04-07 21:02:23.831
Begin DRM(245) (swin 0) - AFFINITY transfer pkey 136388.0 to 2 oscan 1.1
kjiobjscn 1
ftd (30) received from node 1 (8/0.0.0)
all ftds received

* kjxftdn: break from kjxftdn, post lmon later

Event can be turned off
SQL> alter system set events '10430 trace name context off';

System altered.

Also the LMON and LMS trace files contains DRM related info

Although I have seen a lot of issues in 10G and turned off DRM in many cases I haven't seen any such issues
in 11.2 so far

Oracle Advanced Compression Advisor

2009-12-05T18:28:00.000-08:00

Am currently working on how best to use compression techniques in an OLTP environment on a current 10g database which is due to be migrated to 11.2 in the next 6 months and I came across this OTN note

http://www.oracle.com/technology/products/database/compression/compression-advisor.html

The following statement got me very interested

This package can be used on Oracle Databases running Oracle Database 9i Release 2 through 11g Release 1.
A compression advisor (DBMS_COMPRESSION) comes packaged with Oracle Database 11g Release 2.

So lets give it a try...

I downloaded the package and compiled it..

SQL> @dbmscomp.sql

Package created.

Synonym created.

Grant succeeded.

No errors.

SQL> @prvtcomp.plb

Package body created.

Synonym created.

Grant succeeded.

No errors.

SQL> set serveroutput on

SQL> exec dbms_comp_advisor.getratio('OWNER1','CROSS','OLTP',1);

Invalid Compression option for the current COMPAT setting

Thankfully the package body is not encrypted and a quick look at the code reveals that it does the following

SQL> create table DBMS_COMPRESSION_TEMP_UNCMP as select /*+ full('CROSS') */ * from cross sample block( 1);

Table created.

SQL> create table DBMS_COMPRESSION_TEMP_CMP compress for all operations as select * from DBMS_COMPRESSION_TEMP_UNCMP;
create table DBMS_COMPRESSION_TEMP_CMP compress for all operations as select * from DBMS_COMPRESSION_TEMP_UNCMP
*
ERROR at line 1:
ORA-00922: missing or invalid option

Hmmm... not sure how they expect "compress for all operations" to work in a pre 11g database...

Interrupting Flashback Database

2009-09-18T18:52:00.000-07:00

So a user called me up and said he was flashing back a database and he was not too happy with the amount of time it was taking to complete the operation and so he did a Ctrl-C...

When he tried to open the database this is what he saw..

==================================================================================

SQL> shutdown abort
ORACLE instance shut down.
SQL> startup
ORACLE instance started.

Total System Global Area 838860800 bytes
Fixed Size 2033832 bytes
Variable Size 520099672 bytes
Database Buffers 310378496 bytes
Redo Buffers 6348800 bytes
Database mounted.
ORA-38760: This database instance failed to turn on flashback database

SQL> alter database flashback off;

Database altered.

SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-38760: This database instance failed to turn on flashback database

===>... Well he just turned off flashback..

SQL> alter database open resetlogs;
alter database open resetlogs
*
ERROR at line 1:
ORA-01139: RESETLOGS option only valid after an incomplete database recovery

==================================================================================

Looking through the alert.log

Fri Sep 18 08:35:05 2009
flashback database to restore point TEST_AFTER
Fri Sep 18 08:35:05 2009
ORA-38757 signalled during: flashback database to restore point TEST_AFTER...
Fri Sep 18 12:00:48 2009

No errors in the RVWR process trace file

So I just dropped the restore point and voila

> drop restore point TEST_AFTER;

Restore point dropped.

> select flashback_on from v$database;

FLASHBACK_ON
------------------
NO

> alter database open;

Database altered.

Are you sure you will be able to activate your standby??

2009-06-28T04:50:00.000-07:00

A couple of weeks I faced a scenario where the standby database crashed

On looking at the alert.log I see the following message in the alert.log of the standby

***********************************************************
Sat Jun 6 06:48:52 2009
Recovery interrupted!
cannot find needed online log for redo thread 1
Some recovered datafiles maybe left media fuzzy
Media recovery may continue but open resetlogs may fail
Sat Jun 6 06:48:53 2009
Errors in file /u01/app/oracle/admin/TEST/bdump/test1_mrp0_24533.trc:
ORA-10576: Give up restoring recovered datafiles to consistent state: some error occurred
ORA-16037: user requested cancel of managed recovery operation
Some recovered datafiles maybe left media fuzzy
Media recovery may continue but open resetlogs may fail
Sat Jun 6 06:48:54 2009
Waiting for MRP0 pid 24533 to terminate
************************************************************

Hmmm... this means that if the standby does not have the redo and cannot get it from the primary you will not be able to online media fuzzy files using supported methods

The same issue is explained in Bug 5956646
as an architectural limitation.

This is a very unlikely scenario but a possibility none the less

Outbound_connect_timeout

2009-01-27T15:34:00.000-08:00

Outbound_connect_timeout comes into play when nodes in a cluster are down and we cannot wait for the OS timeout as this causes long delays in connect time. For example on Solaris the value of tcp_ip_abort_interval = 180000 ==> which is 180 seconds ==> 3 mins

In this post I will demonstrate how outbound_connect_timeout (OCT) can effectively avoid timeouts experienced by clients connecting to RAC nodes

If we take an example of the following connect string

TEST =
(DESCRIPTION =
(ADDRESS_LIST =
(LOAD_BALANCE = OFF)
(ADDRESS = (PROTOCOL = TCP)(HOST = sdby1-vip)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = sdby2-vip)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = sdby3-vip)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = sdby4-vip)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = prim1-vip)(PORT = 1521))
)
(CONNECT_DATA =
(SERVER = DEDICATED)
(SERVICE_NAME = TEST)
)
)

In the above alias the first 4 nodes are non existent nodes and the service TEST
runs on the node prim1 which is listed last in the above alias.

I have deliberately set load_balance to OFF so that the client has to traverse through all nodes serially.

If we set an OUTBOUND_CONNECT_TIMEOUT of 3 seconds in the client's sqlnet.ora
(client is 10.2.0.3 Solaris) then the time to establish the connection is around 12 seconds.

If we were to run a sqlnet trace on the connection we see that the connection starts at

Connection started at
[27-JAN-2009 22:52:33:741] --- TRACE CONFIGURATION INFORMATION FOLLOWS ---
[27-JAN-2009 22:52:33:741] New trace stream is /tmp/cli_262.trc
and the first address which is tried is

[27-JAN-2009 22:52:33:757] nsc2addr: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=sdb1-vip)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=TEST)(CID=(PROGRAM=sqlplus@bart)(HOST=bart)(USER=oracle))))

Moving on we can see that OCT is enabled due to the line

[27-JAN-2009 22:52:33:759] nstoSetupTimeout: entry
[27-JAN-2009 22:52:33:759] nstoSetupTimeout: ATO enabled for ctx=0x1001c9280, val=3000(millisecs)

After this we the following pattern is seen continuously

[27-JAN-2009 22:52:33:776] nsevwtsg: entry
[27-JAN-2009 22:52:33:776] nsevwtsg: cid=0
[27-JAN-2009 22:52:33:776] nsevwait: entry
[27-JAN-2009 22:52:33:776] nsevwait: 1 registered connection(s)
[27-JAN-2009 22:52:33:776] nsevwait: 0 pre-posted event(s)
[27-JAN-2009 22:52:33:776] nsevwait: waiting for transport event (0 thru 0)...
[27-JAN-2009 22:52:33:776] nsevwait: 0 newly-posted event(s)
[27-JAN-2009 22:52:33:776] nsevwait: 0 posted event(s)
[27-JAN-2009 22:52:33:776] nsevwait: exit (0)
[27-JAN-2009 22:52:33:776] nstoToqCheckSingle: entry
[27-JAN-2009 22:52:33:776] nstoToqCheckSingle: normal exit

and the timeout occurs in 3 seconds

[27-JAN-2009 22:52:36:771] nstoHandleEventTO: ATO occurred for ctx=0x1001c9280

Ergo the OCT seems to be working perfectly

The client then tries to establish a connection with sdby2-vip and experiences
the same timeout

The connection is finally established at

[27-JAN-2009 22:52:45:915] nscon: no connect data
[27-JAN-2009 22:52:45:915] nscon: connect handshake is complete
[27-JAN-2009 22:52:45:915] nscon: nsctxinf[0]=0x41, [1]=0x41
[27-JAN-2009 22:52:45:915] nscon: normal exit

which translates to around 12 seconds.

From my testing for clients on Windows

OUTBOUND_CONNECT_TIMEOUT does not work with 10.2.0.3 base windows client. (Clients may get errors)
It works with patch 21 on top of 10.2.0.3
OUTBOUND_CONNECT_TIMEOUT does work with 11g client

Without OCT if we trace the connection again we see that we wait for more than 3 mins

[28-JAN-2009 14:18:35:299] nttcni: entry
[28-JAN-2009 14:18:35:299] nttcni: trying to connect to socket 10.
[28-JAN-2009 14:22:19:915] ntt2err: entry
[28-JAN-2009 14:22:19:915] ntt2err: soc 10 error - operation=1, ntresnt[0]=505, ntresnt[1]=145, ntresnt[2]=0
[28-JAN-2009 14:22:19:915] ntt2err: exit
[28-JAN-2009 14:22:19:915] nttcni: exit
[28-JAN-2009 14:22:19:915] nttcon: exit
[28-JAN-2009 14:22:19:921] nserror: entry
[28-JAN-2009 14:22:19:921] nserror: nsres: id=0, op=65, ns=12535, ns2=12560; nt[0]=505, nt[1]=145, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
[28-JAN-2009 14:22:19:921] nsopen: unable to open transport
[28-JAN-2009 14:22:19:921] nsiocancel: entry

Parallel Rollback

2008-11-30T01:13:00.000-08:00

I had a user call up and ask to kill a session which was causing him grief and hence I killed it without much thought since it was not a Production system

A few hours later I noticed that SMON was doing parallel txn recovery. This was validated by the view
select * from x$ktprxrt;

Unfortunately I have lost the output but it did show that it would take eons

But this was also confirmed from the pstack of smon which included the function ktprbeg which I believe begins parallel rollback. (Snippet below)

[syd0904:oracle:OSTA1]/u01/app/oracle => pstack 11905
11905: ora_smon_OSTA1

0000000100d80868 kturax (fffffffffffffffe, 380017150, b, 380017, 105ebe510, 5) + 928
0000000100e15620 ktprbeg (106502000, 0, 1065033c8, 105400, 1056b5, 1065033c8) + 1a0 ===> Begin parallel rollback
00000001007e9238 ktmmon (ffffffffffffffff, ffffffff7fffdda8, 0, 1056b5000, 1, 106502000) + f58
000000010106e0dc ksbrdp (105f1b000, 38000e, 106505ce0, 105f1b000, 105f1b, 1007e8260) + 39c
00000001024efed8 opirip (106510000, 106400, 106518, 380007000, 106510, 1066a5650) + 338
000000010033f7b4 opidrv (106512a90, 0, 32, 10650f7c8, 32, 0) + 4b4
0000000100339c50 sou2o (ffffffff7ffff3e8, 32, 4, ffffffff7ffff410, 105de9000, 105de9) + 50
00000001002fc00c opimai_real (3, ffffffff7ffff4e8, 0, 0, 247e09c, 14800) + 10c
00000001002fbe38 main (1, ffffffff7ffff5f8, 0, ffffffff7ffff4f0, ffffffff7ffff600, ffffffff79d00140) + 98
00000001002fbd5c _start (0, 0, 0, 0, 0, 0) + 17c
----------------- lwp# 2 / thread# 2 --------------------

and also confirmed from the SMON trace file

*** 2008-11-28 12:03:16.828
Parallel Transaction recovery caught exception 30319
Parallel Transaction recovery caught error 30319
*** 2008-11-28 12:07:17.163
Parallel Transaction recovery caught exception 30319
Parallel Transaction recovery caught error 30319

So the first thing I did was to disable parallel recovery because of the issue documented in Metalink
using

SQL> ALTER SYSTEM SET fast_start_parallel_rollback='FALSE';

System altered.

IMHO (atleast from past experience) serial recovery is faster than parallel recovery atleast in the case where the transaction causes a lot of index block splits.

After this the row from x$ktprxrt disappeared and the following appeared in the SMON trace file

*** 2008-11-28 12:08:32.763
SMON: parallel recovery restart with degree=0 (!=16)
Parallel Transaction recovery caught exception 30312
Parallel Transaction recovery caught error 30312
*** 2008-11-28 12:08:33.039
SMON: parallel recovery restart with degree=0 (!=16)
Parallel Transaction recovery caught exception 30312
Parallel Transaction recovery caught error 30312

The following views agree on how much time it is going to take to complete the rollback

SQL> select * from x$ktuxe where KTUXECFL='DEAD' and KTUXESTA='ACTIVE';

ADDR INDX INST_ID KTUXEUSN KTUXESLT KTUXESQN KTUXERDBF KTUXERDBB KTUXESCNB KTUXESCNW KTUXESTA
---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------------
KTUXECFL KTUXEUEL KTUXEDDBF KTUXEDDBB KTUXEPUSN KTUXEPSLT KTUXEPSQN KTUXESIZ
------------------------ ---------- ---------- ---------- ---------- ---------- ---------- ----------
FFFFFFFF79969D78 114 1 1 16 174276 2 36154 1113256061 1021 ACTIVE
DEAD 13 0 0 0 0 0 639787

SQL> select * from GV$FAST_START_TRANSACTIONS ;

INST_ID USN SLT SEQ STATE UNDOBLOCKSDONE UNDOBLOCKSTOTAL PID CPUTIME PARENTUSN PARENTSLT
---------- ---------- ---------- ---------- ---------------- -------------- --------------- ---------- ---------- ---------- ----------
PARENTSEQ XID PXID RCVSERVERS
---------- ---------------- ---------------- ----------
1 1 16 174276 RECOVERING 122712 762423 6312
000100100002A8C4 0

As you can see the value of
KTUXESIZ matches (UNDOBLOCKSTOTAL - UNDOBLOCKSDONE)

So rollback will complete when KTUXESIZ in x$ktuxe drops down to 0 which looks like alot of time !!!
Dumping the redo confirmed that it was the same transaction which was killed

Surprisingly the value of "rollback changes - undo records applied" in v$sysstat was not increasing during this timeline. I have tested this again (kill a long running job and watch the rollback) and can confirm that the stat does get incremented.

11g SQLNet Client trace files

2008-07-30T01:14:00.000-07:00

I spent half an hour wondering why I was not able to generate a SQL* Net client trace file from a 11g client to a 10.2 database.
Here are the contents of my client sqlnet.ora

bart:ELEV:/opt/oracle/product/11.1.0/db_1/network/admin> cat sqlnet.ora
#SQLNET.OUTBOUND_CONNECT_TIMEOUT = 3
TRACE_LEVEL_CLIENT= 16
TRACE_DIRECTORY_CLIENT = /tmp
TRACE_FILE_CLIENT= cli.trc
TRACE_TIMESTAMP_CLIENT = ON
TRACE_UNIQUE_CLIENT = ON

It took me a while to realize that thanks to ADR the client trace files were actually going to $ORACLE_BASE/diag/clients/user_oracle/host_xxx/trace

The only way to disable this is to add the following in the sqlnet.ora
DIAG_ADR_ENABLED=off

After setting the above line in the sqlnet.ora the client trace files were generated in /tmp

One off patches, conflicts and merges

2008-07-28T19:23:00.000-07:00

So you are applying one of the zillion patches on top of 10.2.0.3 and you hit the following error

************************************************************************

ApplySession applying interim patch '6338357' to OH
'/opt/oracle/product/10.2.0/db_1'
Interim patch 6338357 has File Conflict with patch(es) [ 5399670 ]
in OH /opt/oracle/product/10.2.0/db_1

************************************************************************

Wouldn't it be nice if you could check for conflicts before you apply a patch
Here is one way to do the same

1. You can check which source code file is being modified by doing the following

cd 6338357/etc/config
cat actions | grep .o
oneoff_actions
oracle.rdbms version="10.2.0.3.0" opt_req="R"
archive name="libserver10.a" path="%ORACLE_HOME%/lib" object_name="lib/libserver10.a/kelt.o"
make change_dir="%ORACLE_HOME%/rdbms/lib" make_file="ins_rdbms.mk" make_target="ioracle"
oracle.rdbms
oneoff_actions

2. Then go to the $ORACLE_HOME/.patch_storage and see if any of the previous patches have modified the same file

bart:TEST:/opt/oracle/product/10.2.0/db_1/.patch_storage> find . -name 'kelt.o' -print
./verify/archive/lib/libserver10.a/kelt.o
./5399670_Mar_20_2008_20_30_34/backup/.patch_storage/5399670_Mar_20_2008_20_30_34/files/lib/libserver10.a/kelt.o
./5399670_Mar_20_2008_20_30_34/original_patch/files/lib/libserver10.a/kelt.o
./5399670_Mar_20_2008_20_30_34/scratch/kelt.o./5399670_Mar_20_2008_20_30_34/files/lib/libserver10.a/kelt.o

So this clearly shows that Patch 5399670 was previously applied which modified the same source code file and you need a merge patch for both bugs (5399670 and 6338357)

Rolling invalidations Addendum

2008-02-04T17:47:00.000-08:00

If you enable cursor trace for the testcase in my previous post using the method described in http://el-caro.blogspot.com/search?q=unshared

The generated trace in udump will have the following

************************************************************
kksCheckCursor: pinning child #0 in shared mode 7d42bd0e8 7d7e87600
Failed sharing : Rolling invalidation
kksUnlockChild: releasing child
Failed sharing : 800000000000
kksSearchChildList: no suitable child found
Creating new child object #1
kksLoadChild: reload 0 child_reload 0
kksLoadChild: reload 0 child_reload 0
Compilation environment difference Failed sharing : 0
Change in cursor environment
************************************************************

Also the parameter _optimizer_invalidation_period does not work for statements using PQ. This can be tested by changing the degree of the table to 4 (say) and running the same test. In this case a new child cursor is generated on the first re-execution of the statement after stats are gathered even when the auto_invalidate flag is used.

Rolling invalidations

2008-01-30T01:17:00.000-08:00

There have been discussions which I have seen related to the feature of auto invalidation in dbms_stats. A couple of references are

http://forums.oracle.com/forums/thread.jspa?threadID=592771&tstart=30
and
http://www.orafaq.com/maillist/oracle-l/2006/10/10/0429.htm

I have tested the relevant parameter “_optimizer_invalidation_period” on 10.2.0.3 and believe that this is working as expected

Let us take the below testcase where the parameter (it is dynamic) is set to a value of 120

SQL> show parameter optimizer_inva

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
_optimizer_invalidation_period integer 120

We have the following sql statement

11:00:00 SQL> select * from source where rownum<2;

OBJ# LINE SOURCE
---------- ---------- ---------------------------------------------------------------------------
194107 171 -- *Action: Start a new job, or attach to an existing job that has a

1 row selected.

Elapsed: 00:00:00.12
11:00:00 SQL> select * from source where rownum<2;

OBJ# LINE SOURCE
---------- ---------- ---------------------------------------------------------------------------
194107 171 -- *Action: Start a new job, or attach to an existing job that has a

1 row selected.

Elapsed: 00:00:00.00
11:00:00 SQL> select a.child_number,LAST_LOAD_TIME, to_char(LAST_ACTIVE_TIME,'dd-mon-yyyy hh24:mi:ss') ,b.invalidations from
v$SQL_SHARED_CURSOR a, v$sql b where a.sql_id='954g5yyw5tn1s' and a.child_address=b.child_address ;

CHILD_NUMBER LAST_LOAD_TIME TO_CHAR(LAST_ACTIVE_ INVALIDATIONS
------------ ------------------- -------------------- -------------
0 2008-01-29/11:00:00 29-jan-2008 11:00:00 0

1 row selected.

Elapsed: 00:00:00.14
11:00:00 SQL>
11:00:00 SQL> select executions, invalidations,child_number from v$sql where sql_id='954g5yyw5tn1s';

EXECUTIONS INVALIDATIONS CHILD_NUMBER
---------- ------------- ------------
2 0 0

1 row selected.

Now we gather stats on the table with the auto_invalidate parameter passed to the API.

11:00:00 SQL> exec dbms_stats.gather_table_stats('REGOFA','SOURCE',no_invalidate => DBMS_STATS.AUTO_INVALIDATE);

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.50

Then we keep executing the sql statement of interest to check when the new cursor will be generated.

Elapsed: 00:00:01.50
11:00:13 SQL> select a.child_number,LAST_LOAD_TIME, to_char(LAST_ACTIVE_TIME,'dd-mon-yyyy hh24:mi:ss') ,b.invalidations from
v$SQL_SHARED_CURSOR a, v$sql b where a.sql_id='954g5yyw5tn1s' and a.child_address=b.child_address ;

CHILD_NUMBER LAST_LOAD_TIME TO_CHAR(LAST_ACTIVE_ INVALIDATIONS
------------ ------------------- -------------------- -------------
0 2008-01-29/11:00:00 29-jan-2008 11:00:09 0

1 row selected.

Elapsed: 00:00:00.05
11:00:13 SQL> select executions, invalidations,child_number from v$sql where sql_id='954g5yyw5tn1s';

EXECUTIONS INVALIDATIONS CHILD_NUMBER
---------- ------------- ------------
3 0 0

1 row selected.

Elapsed: 00:00:00.00
11:00:13 SQL> select * from v$sql_shared_cursor where sql_id='954g5yyw5tn1s';

SQL_ID ADDRESS CHILD_ADDRESS CHILD_NUMBER U S O O S L S E B P
------------- ---------------- ---------------- ------------ - - - - - - - - - -
I S T A B D L T R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
M F L
- - -
954g5yyw5tn1s 00000007D3BBCBD8 00000007D5644028 0 N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
N N N

1 row selected.
…….
11:00:37 SQL> select * from source where rownum<2;

OBJ# LINE SOURCE
---------- ---------- ---------------------------------------------------------------------------
194107 171 -- *Action: Start a new job, or attach to an existing job that has a

1 row selected.

Elapsed: 00:00:00.01
11:00:39 SQL> select a.child_number,LAST_LOAD_TIME, to_char(LAST_ACTIVE_TIME,'dd-mon-yyyy hh24:mi:ss') ,b.invalidations from
v$SQL_SHARED_CURSOR a, v$sql b where a.sql_id='954g5yyw5tn1s' and a.child_address=b.child_address ;

CHILD_NUMBER LAST_LOAD_TIME TO_CHAR(LAST_ACTIVE_ INVALIDATIONS
------------ ------------------- -------------------- -------------
0 2008-01-29/11:00:00 29-jan-2008 11:00:25 0
1 2008-01-29/11:00:37 29-jan-2008 11:00:37 0

2 rows selected.

Elapsed: 00:00:00.04
11:00:39 SQL> select executions, invalidations,child_number from v$sql where sql_id='954g5yyw5tn1s';

EXECUTIONS INVALIDATIONS CHILD_NUMBER
---------- ------------- ------------
7 0 0
1 0 1

2 rows selected.

Elapsed: 00:00:00.00
11:00:39 SQL> select * from v$sql_shared_cursor where sql_id='954g5yyw5tn1s';

SQL_ID ADDRESS CHILD_ADDRESS CHILD_NUMBER U S O O S L S E B P
------------- ---------------- ---------------- ------------ - - - - - - - - - -
I S T A B D L T R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
M F L
- - -
954g5yyw5tn1s 00000007D3BBCBD8 00000007D5644028 0 N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
N N N

954g5yyw5tn1s 00000007D3BBCBD8 00000007D3753DC0 1 N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N Y N N
N N N

So somewhere between 11:00:00 and 11:00:39 (within the 2 minute window) a new child cursor has been generated with roll_invalid_mismatch set to ‘Y”

I have tested for the following values of _optimizer_invalidation_period and I see consistent results

120
210
600
1800
18000

Hence this would be an ideal way to avoid a hard parse storm

OCR Mirroring

2007-11-06T03:10:00.000-08:00

In my last blog I talked about adding mirrors to your voting disk. Here I will document how to add mirrors to your OCR on a clustered file system like vxfs.

In the existing configuration there is only one ocr. The location of your ocr is specified in /var/opt/oracle/ocr.loc (on Solaris). It would be different depending on your port.

You need to add an OCR mirror when CRS is up else you get an error message like the one below

root@bart # /u01/app/oracle/product/10.1.0/crs/bin/ocrconfig -replace ocrmirror /u02/oracrs/ocr_file_02
PROT-1: Failed to initialize ocrconfig

For more details on why you have received an error check the latest ocrconfig log file under $ORA_CRS_HOME/log/node/client

root@bart # cat ocrconfig_1742.log
Oracle Database 10g CRS Release 10.2.0.1.0 Production Copyright 1996, 2005 Oracle. All rights reserved.
2007-10-27 12:32:19.130: [ OCRCONF][1]ocrconfig starts...
2007-10-27 12:32:20.933: [ OCRCONF][1]Failure in initializing ocr in DEFAULT level. error:[PROC-32: Cluster Ready Services on the local node i
s not running Messaging error [9]]
2007-10-27 12:32:20.933: [ OCRCONF][1]Exiting [status=failed]...

From the above error message it is clear that CRS needs to be up.

So after starting up CRS

root@bart # /u01/app/oracle/product/10.1.0/crs/bin/ocrconfig -replace ocrmirror /u02/oracrs/ocr_file_02
PROT-16: Internal Error

But even though I get an error it appears to have created the mirror

root@bart # cat /var/opt/oracle/ocr.loc
#Device/file getting replaced by device
/u02/oracrs/ocr_file_02
ocrconfig_loc=/u02/oracrs/ocr.dbf
ocrmirrorconfig_loc=/u02/oracrs/ocr_file_02
local_only=falseroot@bart

# ocrcheck
Status of Oracle Cluster Registry is as follows :
Version : 2
Total space (kbytes) : 262120
Used space (kbytes) : 24932
Available space (kbytes) : 237188
ID : 1909893349
Device/File Name : /u02/oracrs/ocr.dbf
Device/File integrity check succeeded
Device/File Name : /u02/oracrs/ocr_file_02
Device/File integrity check succeeded

Now let us replace the existing OCR with a new one file

u01/app/oracle/product/10.1.0/crs/bin/ocrconfig -replace ocr /u02/oracrs/ocr_file_01
PROT-16: Internal Error

root@bart # cat /var/opt/oracle/ocr.loc
#Device/file /u02/oracrs/ocr.dbf getting replaced by device
/u02/oracrs/ocr_file_01
ocrconfig_loc=/u02/oracrs/ocr_file_01
ocrmirrorconfig_loc=/u02/oracrs/ocr_file_02
local_only=falseroot@bart

# ocrcheck
Status of Oracle Cluster Registry is as follows :
Version : 2
Total space (kbytes) : 262120
Used space (kbytes) : 24932
Available space (kbytes) : 237188
ID : 1909893349
Device/File Name : /u02/oracrs/ocr_file_01
Device/File integrity check succeeded
Device/File Name : /u02/oracrs/ocr_file_02
Device/File integrity check succeeded

Cluster registry integrity check succeeded

At this point you can shutdown and startup CRS and see if all is fine. One point to note is that you should check that the ocr.loc files on all remote nodes are updated with the updated location of the OCR file. In my testing the CRS stack on the remote node was down and in such cases the ocr.loc on the remote node does not get updated.

When the cluster is running if the OCR mirror is removed/corrupted the cluster continues running and all crs commands including ocrcheck can be run if you comment the following line from /var/opt/oracle/ocr.loc
ocrmirrorconfig_loc=/u02/oracrs/ocr_file_02

If you lose the primary OCR the cluster keeps running but
ocrcheck fails and CRS cannot be stopped even if you comment out the following line even though the mirror is available.

root@bart # cat /var/opt/oracle/ocr.loc
#Device/file /u02/oracrs/ocr_file_01 getting replaced by device /u02/oracrs/ocr_file_01
#ocrconfig_loc=/u02/oracrs/ocr_file_01
ocrmirrorconfig_loc=/u02/oracrs/ocr_file_02

Things are fine if I replace the ocr using
root@bart # /u01/app/oracle/product/10.1.0/crs/bin/ocrconfig -replace ocr /u02/oracrs/ocr_file_01
PROT-16: Internal Error

Voting disk mirroring

2007-11-03T02:34:00.000-07:00

A while ago I had blogged on how to add a voting disk to an existing RAC setup here.

To be safe it is best to do this with the cluster down.
I did the same recently on a 2 node RAC on 10.2.0.3 running Veritas SFRAC 4.1.

In the setup I am working on there is only one voting disk the location of which is
root@bart # /u01/app/oracle/product/10.1.0/crs/bin/crsctl query css votedisk
0. 0 /u02/oravoting/voting

With CRS down on all nodes you have to use the force option else you receive an error

root@bart # /u01/app/oracle/product/10.1.0/crs/bin/crsctl add css votedisk /u02/oravoting/voting_disk_01
Cluster is not in a ready state for online disk addition

root@bart # /u01/app/oracle/product/10.1.0/crs/bin/crsctl add css votedisk /u02/oravoting/voting_disk_01 -force
Now formatting voting disk: /u02/oravoting/voting_disk_01
CLSFMT returned with error [4].
failed 9 to initailize votedisk /u02/oravoting/voting_disk_01

root@bart # cd /u02/oravoting/
root@bart # ls -ltr
total 99992
-rw-r--r-- 1 oracle oinstall 10238976 Oct 30 11:53 voting
-rw-r--r-- 1 root other 10240000 Oct 30 12:05 voting_disk_01

So although it has created a second voting disk it has been created with the wrong permissions. When you do a fresh install of CRS the rootconfig script called from root.sh sets the owner of the voting disk to the owner of the crs software (in this case oracle). Hence this is a bug and the startup of css fails and you will see errors in the Unix logfile since the permissions are incorrect.

Lets’ add a second one..

root@bart # /u01/app/oracle/product/10.1.0/crs/bin/crsctl add css votedisk /u02/oravoting/voting_disk_02 -force
Now formatting voting disk: /u02/oravoting/voting_disk_02
CLSFMT returned with error [4].
failed 9 to initailize votedisk /u02/oravoting/voting_disk_02

If we do not change permissions of the second mirror css will startup (since we have 2 voting disks online and the algorithm requires that a majority of disks to be available) but the following message will be logged in the ocssd.log file

[ CSSD]2007-11-01 11:46:26.400 [1] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (0//u02/oravoting/voting)
[ CSSD]2007-11-01 11:46:26.401 [6] >TRACE: clssnmvDPT: spawned for disk 0
(/u02/oravoting/voting)
[ CSSD]2007-11-01 11:46:26.402 [1] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk
(1//u02/oravoting/voting_disk_01
)
[ CSSD]2007-11-01 11:46:26.402 [7] >TRACE: clssnmvDPT: spawned for disk 1 (/u02/oravoting/voting_disk_01)
[ CSSD]2007-11-01 11:46:26.403 [1] >TRACE: clssnmDiskStateChange: state from 1
to 2 disk (2//u02/oravoting/voting_disk_02
)
[ CSSD]2007-11-01 11:46:26.404 [8] >TRACE: clssnmvDPT: spawned for disk 2 (/u02/oravoting/voting_disk_02)
[ CSSD]2007-11-01 11:46:26.405 [8] >ERROR: Internal Error Information:
Category: 1234
Operation: scls_block_open
Location: open
Other: open failed /u02/oravoting/voting_disk_02
Dep: 9

[ CSSD]2007-11-01 11:46:26.405 [8] >TRACE: clssnmvDiskOpen: Unable to open voting device (2:
/u02/oravoting/voting_disk_0
2)

If you were to change the permissions to oracle:dba the 2nd mirror you would not see the above.

Remember that when you install CRS in 10.2 and use normal redundancy for your voting disk configuration it is mandatory to have 2 mirrors. The installer does not allow you to proceed with one mirror.

If you are adding mirrors manually using crsctl it is recommended that you add 2 mirrors. If you had a 1+1 configuration css will not come up if the mirror is unavailable/corrupt.

If you are deleting a voting disk you have to update the following files in $ORA_CRS_HOME/install with the new voting disk location

paramfile.crs
params.crs
rootconfig

This is required if you need to re-initialize your OCR by re-running root.sh assuming your OCR backups are stuffed and you cannot restore your OCR.

Identifying mutex holder

2007-10-16T18:55:00.000-07:00

In my previous post on flushing a cursor we see that a process is waiting on a mutex. In this post we will try to identify the holder from a systemstate dump

• Find the process executing the purge API. In this case it was process 22
• Open the systemstate dump and go to PROCESS 22
• Under this (if the systemstate is at level 266) you will see the short stack of the process

ksdxfstk()+36<-ksdxcb()+2452<-sspuser()+176<-sigacthandler()+44<-__systemcall()+52<-semtimedop()+28<-sskgpwwait()+224<-ksliwat
()+988<-kslwaitns_timed()+48<-kskthbwt()+232<-kslwait()+116<-kksLockWait()+396<-kgxWait()+444<-kgxExclusive()+132<-kxsPurgeCur
sor()+476<-psdpur()+1444<-pevm_icd_call_common()+728<-pfrinstr_ICAL()+132<-pfrrun_no_tool()+72<-pfrrun()+832<-plsql_run()+696<
-peicnt()+260<-kkxexe()+824<-opiexe()+12736<-kpoal8()+1912<-opiodr()+1548<-ttcpip()+1284<-opitsk()+1432<-opiino()+1128<-opiodr
()+1548<-opidrv()+896<-sou2o()+80<-opimai_real()+124<-main()+152<-_start()+380

As can be seen from the above stack it includes the function kxsPurgeCursor() which contains this piece of functionality (to flush the cursor)

• Under the session state object of this process you will see that the session is waiting on

waiting for 'cursor: pin X' blocking sess=0x0 seq=9208 wait_time=0 seconds since wait started=0 idn=dbabc3c, value=1, where|sleeps=e00000629

wait_time=0 indicates the session is waiting at the time this process was dumped.

• If you scroll down further in the same process state object and search for idn=dbabc3c

KGX Atomic Operation Log 3d6e12a08
Mutex 3da75c7d0(0, 1) idn dbabc3c oper GET_EXCL

Hence this process is waiting to acquire the mutex in exclusive mode.

• To find the process holding the mutex search on the string "dbabc3c oper"

You will find something like the below

KGX Atomic Operation Log 3d6e671e0
Mutex 3da75c7d0(0, 1) idn dbabc3c oper SHRD

Search the process holding this.
In vi editor you can use ?PROCESS which will lead you to

PROCESS 15:
-------------------------------------------

Hence Process 15 is holding the mutex and this is the process doing the merge join Cartesian in Session 1.

Flushing a single cursor

2007-10-12T17:33:00.000-07:00

In a very intensive OLTP environment plan stability is of utmost importance as a single sub optimal query can bring the system down to its knees.

Using sql outlines and sql profiles is always not possible if you have an application with more
than a million lines of code and any one of the thousands of sql statements could have a plan flip.

In 11g there is a new procedure in the DBMS_SHARED_POOL package which helps you flush out a single cursor.
There is a typo in the syntax portion of the documentation in
http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28419/d_shpool.htm#sthref8578
which I will try to get corrected in the next week.

PURGE Procedure
This procedure purges the named object or specified heap(s) of the object.

Syntax

DBMS_SHARED_POOL.KEEP (
name VARCHAR2,
flag CHAR DEFAULT 'P',
heaps NUMBER DEFAULT 1)
Parameters

Table 118-4 KEEP Procedure Parameters

Parameter Description
name Name of the object to keep.
The value for this identifier is the concatenation of the address and hash_value columns from the v$sqlarea view. This is displayed by the SIZES procedure.

Currently, TABLE and VIEW objects may not be kept.

flag (Optional) If this is not specified, then the package assumes that the first parameter is the name of a package/procedure/function and resolves the name.
Set to 'P' or 'p' to fully specify that the input is the name of a package/procedure/function.

Set to 'T' or 't' to specify that the input is the name of a type.

Set to 'R' or 'r' to specify that the input is the name of a trigger.

Set to 'Q' or 'q' to specify that the input is the name of a sequence.

In case the first argument is a cursor address and hash-value, the parameter should be set to any character except 'P' or 'p' or 'Q' or 'q' or 'R' or 'r' or 'T' or 't'.

heaps Heaps to be purged. For example, if heap 0 and heap 6 are to be purged:
1<<0 | 1<<6 => hex 0x41 => decimal 65, so specify heaps =>65.Default is 1, that is, heap 0 which means the whole object would be purged

This feature was introduced via the fix in bug 5614566 and I actually know a customer who has this applied on top of 10.2.0.3.

E.g

SQL> exec dbms_shared_pool.purge('00000003DE576D40,353632309','C',65); ==> purge heap 0 and heap 6

PL/SQL procedure successfully completed.

This would actually not work against a cursor which is currently executing.(pinned)

Session 1:
=========
Do a massive Merge Join Cartesian
select * from dba_objects a, dba_objects b, dba_objects c;

Session 2:
=========
Identify the sql address and hash value and try to purge the cursor..

exec dbms_shared_pool.purge('00000003DE825198,3691928467','C',65); ==> This hangs

and this session is waiting on "cursor: pin X" requesting an exclusive mutex pin for the cursor object whilst it has already been pinned by session 1

Session 3
==========
select event,p1,p2 from v$session where username='SYS' and type='USER';
EVENT P1 P2
----------------------------------------- ---------- ----------
cursor: pin X 3691928467 1

The p1 value here is the Hash value of the cursor we are trying to flush.

From the short stack of the process which is executing the purge API a function called kxsPurgeCursor is called which would try to take a mutex (since _kks_use_mutex_pin is TRUE by default)
The purge completes only after you cancel the sql in session 1 and exit from the same
or kill the session executing the sql.

Redwood Shores

2007-09-17T13:02:00.000-07:00

I was in Redwood last week and got a chance to meet some of the best minds in Server Technologies including a few ex-colleagues and a couple of guys on the revered
Oak Table

And although a significant part of the week was spent in the wine and lounge bars of San Francisco it was quite an enriching experience..

Disabling cursor trace

2007-09-05T06:55:00.000-07:00

Sometime last year I had blogged about unshared cursors and an event to trace the same here
http://el-caro.blogspot.com/search?q=cursor+trace

Well after you set the trace on and have got the required information you would obviously want to turn it off.

The command to do the same is

alter system set events 'immediate trace name cursortrace level 2147483648, addr 1';

However this does not work as I realized today when I was diagnosing multiple versions created for pl/sql procedure calls with ref cursors as arguments and the trace almost filled up my udump. New sessions spawned have entries such as the below
for any cursor executed.

CUR#2 XSC 0xxxxxxxx CHILD#0 CI 0xxxxxxx CTX (nil)

To fix this issue you need to apply the fix for unpublished bug

5555371 NO WAY TO TURN OFF TRACE AFTER SETTING CURSORTRACE EVENT

on top of 10.2.0.x

Another way to disable the trace would be to restart the instance.

Using dbx collector

2007-07-14T06:45:00.000-07:00

It is quite possible that you have a single piece of sql which consumes more and more cpu over time without an increase in logical i/o for the statement or due to increased amount of hard parsing.

The reason could be extra burning of cpu in an Oracle source code function with time which has not been instrumented as a wait in the RDBMS kernel. One way to find out which function in the Oracle source code is the culprit is via the dbx collector function available in the Sun Studio 11. I guess dtrace would also help but I haven’t played with it. This tool can also be used in diagnosing increased cpu usage of Oracle tools across different RDBMS versions.

Let us take a simple example on how to run this tool on a simple insert statement.

SQL> create table foo ( a number);

Table created.

> sqlplus

SQL*Plus: Release 10.2.0.3.0 - Production on Sat Jul 14 23:46:03 2007

Copyright (c) 1982, 2006, Oracle. All Rights Reserved.

Enter user-name: /

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

SQL> set sqlp sess1>>
sess1>>

Session 2
Find the server process servicing the previously spawned sqlplus session and attach to it via the debugger.

> ps -ef | grep sqlplus
oracle 20296 5857 0 23:47:38 pts/1 0:00 grep sqlplus
oracle 17205 23919 0 23:46:03 pts/4 0:00 sqlplus
> ps -ef | grep 17205
oracle 20615 5857 0 23:47:48 pts/1 0:00 grep 17205
oracle 17237 17205 0 23:46:04 ? 0:00 oracleTEST1 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 17205 23919 0 23:46:03 pts/4 0:00 sqlplus

> /opt/SUNWspro/bin/dbx $ORACLE_HOME/bin/oracle 17237

Reading oracle
==> Output trimmed for brevity.

dbx: warning: thread related commands will not be available
dbx: warning: see `help lwp', `help lwps' and `help where'
Attached to process 17237 with 2 LWPs
(l@1) stopped in _read at 0xffffffff7bfa8724
0xffffffff7bfa8724: _read+0x0008: ta 64
(dbx) collector enable

Session 1
==================================================================
begin
for i in 1..1000
loop
insert into foo values(i);
end loop;
end;
/

Session 2
==================================================================

(dbx) cont
Creating experiment database test.3.er ...
Reading libcollector.so

Session 1
==================================================================
PL/SQL procedure successfully completed.

sess1>>exit
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

Session 2
=========

execution completed, exit code is 0
(dbx) quit

The debugger creates a directory called test.1.er.
You can analyse the collected data by using analyser which is a GUI tool.

> export DISPLAY=10.59.49.9:0.0
> /opt/SUNWspro/bin/analyzer test.3.er

You can also generate a callers-callees report using the following syntax

/opt/SUNWspro/bin/er_print test.3.er
test.3.er: Experiment has warnings, see header for details
(/opt/SUNWspro/bin/er_print) callers-callees

A before and after image of the performance problem would help in diagnosing the function in the code which consumes more CPU with time.

2007-07-08T06:13:00.001-07:00

So 11g is finally upon us and it seems just the other day that 10g was released. I am looking forward to playing with some of the new features.

So here are some of the features in the TO DO list

Real Application Testing (RAT), which includes Database Replay and SQL Workload Analyzer.
APIs like
DBMS_WORKLOAD_CAPTURE
DBMS_WORKLOAD_REPLAY

Sql Plan Management
DBMS_SPM

DBMS_SHARED_POOL.PURGE api which can be used to flush a single cursor. This is important in a high intensive OLTP environment where you have a sql statement which has gone bad because of a sub-optimal execution plan. I believe this feature can be backported to 10.2.0.2/10.2.0.3

A new parameter MEMORY_MAX_TARGET has been introduced which would control both SGA and PGA memory allocation. I have not been a big fan of sga_target and hence would not pin my hopes too much on this feature.

There is a new SQL repair advisory provided through the DBMS_SQLDIAG api.

Fix Control

2007-06-30T06:59:00.000-07:00

Oracle has introduced a fix control mechanism in 10.2 which allows customers to turn off fixes for optimizer related bugs. This is governed by the underscore parameter _fix_control. The bugs for which fixes can be turned off are listed in v$session_fix_control and v$system_fix_control and can also be seen in a 10053 output.

On a 10.2.0.2 database

SQL> select distinct bugno from v$session_fix_control;

BUGNO
----------
3499674
4556762
4569940
3118776
4519016
4175830
4663698
4631959
4550003
4584065
4487253
4611850
4663804
4602374
4728348
4723244
4554846
4545833
4488689
4519340

20 rows selected.

SQL> select distinct sid from v$mystat;

SID
----------
143

SQL> alter session set "_fix_control"='4728348:OFF';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno=4728348;

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4728348 0 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

A value of 0 indicates the fix is off.

SQL> alter session set "_fix_control"='4728348:ON';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno=4728348;

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4728348 1 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

It appears to me that if you need two fixes off in a session you have to specify them together else you lose the first change.

SQL> alter session set "_fix_control"='4728348:OFF';

Session altered.

SQL> alter session set "_fix_control"='4663698:OFF';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno in (4728348,4663698);

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4663698 0 for cached NL table set tab_cost_io to zero 10.2.0.2 0 0
143 4728348 1 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

Hence if you need more than one fix OFF you need to supply both bug numbers in the same command

SQL> alter session set "_fix_control"='4728348:OFF','4663698:OFF';

Session altered.

SQL> select * from v$session_fix_control where session_id=143 and bugno in (4728348,4663698);

SESSION_ID BUGNO VALUE DESCRIPTION OPTIMIZER_FEATURE_ENABLE EVENT IS_DEFAULT
---------- ---------- ---------- ---------------------------------------------------------------- --
143 4663698 0 for cached NL table set tab_cost_io to zero 10.2.0.2 0 0
143 4728348 0 consider mjc if equi-joined pred is dropped in kkoipt 10.2.0.2

DBA_HIST_FILEMETRIC_HISTORY

2007-06-02T06:25:00.000-07:00

There are so many new views in 10G that you begin to wonder if many of them are
actually populated correctly. For example there are quite a few bugs with some of the DBA_HIST* views not being populated correctly. One such view DBA_HIST_TBSPC_SPACE_USAGE is notorious for incorrect values .But the view DBA_HIST_FILEMETRIC_HISTORY which supposedly stores alerts only for 7 days does not even seem to be getting populated.

So on a 10.1.0.5 database

SQL> select count(*) from dba_hist_filemetric_history;

COUNT(*)
----------
0

If you have a look at the definition of the view from catawrvw.sql

create or replace view DBA_HIST_FILEMETRIC_HISTORY
(SNAP_ID, DBID, INSTANCE_NUMBER, FILEID, CREATIONTIME, BEGIN_TIME,
END_TIME, INTSIZE, GROUP_ID, AVGREADTIME, AVGWRITETIME, PHYSICALREAD,
PHYSICALWRITE, PHYBLKREAD, PHYBLKWRITE)
as
select fm.snap_id, fm.dbid, fm.instance_number,
fileid, creationtime, begin_time,
end_time, intsize, group_id, avgreadtime, avgwritetime,
physicalread, physicalwrite, phyblkread, phyblkwrite
from wrm$_snapshot sn, WRH$_FILEMETRIC_HISTORY fm
where sn.snap_id = fm.snap_id
and sn.dbid = fm.dbid
and sn.instance_number = fm.instance_number
and sn.status = 0

SQL> select count(*) from WRH$_FILEMETRIC_HISTORY;

COUNT(*)
----------
0

I have tried various ways to get this base table populated but
am not sure when information is flushed to WRH$_FILEMETRIC_HISTORY.
This behaviour is also consistent in 10.2.0.3

What is Timeout?

2007-05-18T20:29:00.000-07:00

The problem with semi documented APIs like DBMS_SPACE is that some of the subprograms might not work as you might expect them to.
For example the object_space_usage procedure has a parameter called timeout_value which I would assume to mean the amount of time after the procedure will abort if it cannot complete its space calculations. But this does not work as I would expect it to

SQL> set timing on
SQL> set serveroutput on

SQL> declare
v_space_used number;
v_space_allocated number;
begin
dbms_space.object_space_usage('SCOTT','EMP','TABLE',0,v_space_used, v_space_allocated,'',TRUE,5);
dbms_output.put_line('SPACE USED = '||v_space_used);
dbms_output.put_line('SPACE ALLOCATED = '||v_space_allocated);
end;
/

SPACE USED = 0
SPACE ALLOCATED = 68034756608

PL/SQL procedure successfully completed.

Elapsed: 00:00:36.12

So even if I specify a timeout value of 5 the procedure completes in 36 seconds.

This behaviour reproduces on 10.1.0.5 and 10.2.0.3.

More undocumented APIs in DBMS_SPACE

2007-04-24T23:45:00.000-07:00

There seem to be quite a few procedures in the package DBMS_SPACE which do not find a mention in the Oracle documentation. One such procedure is

PROCEDURE OBJECT_SPACE_USAGE
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
OBJECT_OWNER VARCHAR2 IN
OBJECT_NAME VARCHAR2 IN
OBJECT_TYPE VARCHAR2 IN
SAMPLE_CONTROL NUMBER IN
SPACE_USED NUMBER OUT
SPACE_ALLOCATED NUMBER OUT
PARTITION_NAME VARCHAR2 IN DEFAULT
PRESERVE_RESULT BOOLEAN IN DEFAULT
TIMEOUT_SECONDS NUMBER IN DEFAULT

which is used by OEM if you use the Segment Findings section on the Database Home page if you configure the same.

It could be useful to monitor space consumption of segments whilst subjected to continuous DML operations.

set serveroutput on;
declare
v_space_used number;
v_space_allocated number;
begin
dbms_space.object_space_usage(‘SCOTT’,'EMP','TABLE PARTITION',0,v_space_used, v_space_allocated, 'P1');
dbms_output.put_line('SPACE USED = '||v_space_used);
dbms_output.put_line('SPACE ALLOCATED = '||v_space_allocated);
end;
/

SPACE USED = 454248
SPACE ALLOCATED = 458752

PL/SQL procedure successfully completed.

I haven’t figured out what sample_control is though. Also this procedure does not work for spatial indexes as you encounter an ora-600.

KST tracing

2007-04-23T05:11:00.000-07:00

In a recent post Kevin Closson highlights the perils of the effect of the the ORA_CRS_HOME mounpoint filling up.
If you use the RAC service framework services would relocate to another node after going offline on the node on which the filesystem is full

In a RAC cluster if a process encounters an ora-600 or an ora-7445 (I haven't checked for other errors) each node in the cluster dumps trace files for each process with suffix trw in directories called cdmp_YYYYMMDDHHMISS under bdump. This instrumentation is referred to as KST tracing. So if you have a batch job which continuously encounters the before mentioned errors this can cause a plethora of cdmp* directories generated which could fill up the filesystem.
These trace files can be formatted by an internal Oracle tool called Trace Loader (trcldr).

You can disable this functionality by setting trace_enabled=false which
can be changed dynamically. After making this change you will see the following
message in the diag trace file

***********************************************
KST tracing is turned off, no data is logged
***********************************************

This functionality is also disabled if you set _diag_daemon=false. This would disable the DIAG daemon and hence disable other functionality like the dumping of systemstates by the DIAG process when a self deadlock occurs. DIAG is the only background process which can be killed without instance death.It is the 2nd last process to be terminated because it needs to perform trace flushing to file system. By default, the terminating process, usually PMON, gives 5 seconds to DIAG for dumping. This is governed by the parameter _ksu_diag_kill_time. So after dumping all
diagnostic data PMON will wait for _ksu_diag_kill_time before killing the instance.
This delay has been fixed via bug 5599293

Diagnosing archivelog corruption

2007-03-24T05:24:00.000-07:00

When you encounter an archivelog corruption issue as seen from an ora-353 or ora-600 [3020] (stuck recovery) It is a common practice to dump the archivelog to determine the nature of the corruption.
Metalink note 1031381.6 explains various methods you can use to dump the same.

In addition you can also use the following command which only dumps the redo log file header although it reads the complete log file ( a truss on the associated server process can confirm the same) and hence you do not have the overhead of a large trace file (especially for large archivelogs)

SQL> alter system dump logfile 'D:\ARCHIVELOG\2007_03_24\O1_MF_1_48_3090F2FO_.ARC' layer 999 opcode 999;

System altered.

The associated trace file is shown below

***********************************************************
DUMP OF REDO FROM FILE 'D:\ARCHIVELOG\2007_03_24\O1_MF_1_48_3090F2FO_.ARC'
Opcode 999.999 only
RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
Times: creation thru eternity
FILE HEADER:
Compatibility Vsn = 169869824=0xa200200
Db ID=4004875527=0xeeb58d07, Db Name='TEN2'
Activation ID=4004873735=0xeeb58607
Control Seq=845=0x34d, File size=102400=0x19000
File Number=3, Blksiz=512, File Type=2 LOG
descrip:"Thread 0001, Seq# 0000000048, SCN 0x0000001614ba-0x0000001614df"
thread: 1 nab: 0xc seq: 0x00000030 hws: 0x2 eot: 0 dis: 0
resetlogs count: 0x2433e987 scn: 0x0000.00000001 (1)
resetlogs terminal rcv count: 0x0 scn: 0x0000.00000000
prev resetlogs count: 0x0 scn: 0x0000.00000000
prev resetlogs terminal rcv count: 0x0 scn: 0x0000.00000000
Low scn: 0x0000.001614ba (1447098) 03/24/2007 12:39:20
Next scn: 0x0000.001614df (1447135) 03/24/2007 12:40:50
Enabled scn: 0x0000.00000001 (1) 11/24/2006 21:11:44
Thread closed scn: 0x0000.001614ba (1447098) 03/24/2007 12:39:20
Disk cksum: 0xefe4 Calc cksum: 0xefe4
Terminal recovery stop scn: 0x0000.00000000
Terminal recovery 01/01/1988 00:00:00
Most recent redo scn: 0x0000.00000000
Largest LWN: 3 blocks
End-of-redo stream : No
Unprotected mode
Miscellaneous flags: 0x11
Thread internal enable indicator: thr: 0, seq: 0 scn: 0x0000.00000000
END OF REDO DUMP
----- Redo read statistics for thread 1 -----
Read rate (ASYNC): 5Kb in 0.05s => 0.10 Mb/sec
Total physical reads: 5Kb
Longest record: 1Kb, moves: 0/5 (0%)
Change moves: 6/33 (18%), moved: 0Mb
Longest LWN: 1Kb, moves: 0/4 (0%), moved: 0Mb
Last redo scn: 0x0000.001614db (1447131)

RMAN priorities

2007-02-27T21:38:00.001-08:00

Whilst playing around with "_high_priority_processes” I ran across another hidden parameter called _rman_io_priority. Ostensibly this looks like another magic switch like _serial_direct_read to improve the speed of RMAN backups and restores.
But alas this parameter cannot be modified from its default value of 3

SQL> alter system set "_rman_io_priority"=6 scope=spfile;
alter system set "_rman_io_priority"=6 scope=spfile
*
ERROR at line 1:
ORA-00068: invalid value 6 for parameter _rman_io_priority, must be between 6
and 18446744073709551615

SQL> alter system set "_rman_io_priority"=7 ;
alter system set "_rman_io_priority"=7
*
ERROR at line 1:
ORA-00068: invalid value 7 for parameter _rman_io_priority, must be between 6 and 18446744073709551615

SQL> alter system set "_rman_io_priority"=18446744073709551614;
alter system set "_rman_io_priority"=18446744073709551614
*
ERROR at line 1:
ORA-02017: integer value required

The maximum value of an integer is 2147483647 or (2e31 -1)

SQL> alter system set "_rman_io_priority"=2147483647;
alter system set "_rman_io_priority"=2147483647
*
ERROR at line 1:
ORA-00068: invalid value 2147483647 for parameter _rman_io_priority, must be between 6 and 18446744073709551615

As this is an undocumented parameter I cannot raise an SR on this issue. My understanding is that this has been fixed in 11g although it still remains an undocumented parameter.

LMS and real time priorities (2)

2007-02-18T13:51:00.000-08:00

From my testing on 10.2.0.3 with the following combination of parameters these are the results

_high_priority_processes _os_sched_high_priority Scheduler class
LMS* (default) 1 (default) RR
Null 0 TS
LMS* (default) 0 RR
Null 1 (default) TS

As can be seen the value of _os_sched_high_priority doesn’t seem to matter (or is this another bug) and LMS seems to run in the RR class only if the value of _high_priority_processes is LMS*.

Also we put other oracle processes in the RR class using this same parameter?

SQL> alter system set "_high_priority_processes"='PMON' scope=spfile;

System altered.

SQL> exit
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

elephant-> srvctl stop database -d F8902PRD
elephant-> srvctl start database -d F8902PRD

elephant-> ps -efc | grep pmon | grep –v grep
oracle 4929 1 RR 90 17:57 ? 00:00:00 ora_pmon_F8902PRD1

Also the parameter _high_priority_processes was not in the base release (10.2.0.1)
and introduced in the 10.2.0.3 patchset

LMS and real time priorities

2007-02-16T06:07:00.000-08:00

One of the oft mentioned RAC best practices is that the priority of LMS processes which ship blocks across the interconnect be higher so that they are not competing for cpu cycles with other processes.
Starting with 10.2 LMS is supposed to run in the real time class. This is new functionality which is governed by the underscore parameter _os_sched_high_priority

However in 10.2.0.1 LMS still runs in the time-sharing TS class (SCHED_OTHER standard time-sharing) due to the absence of the oradism executable
buffalo >ls -al oradism
-r-sr-s--- 1 root dba 0 Jul 1 2005 oradism

buffalo >ps -efc|grep lms
oracle 27263 1 TS 24 2006 ? 00:12:38 ora_lms0_F8900DMO1
oracle 27273 1 TS 24 2006 ? 00:04:30 ora_lms1_F8900DMO1

When you apply the 10.2.0.3 patchset you notice that the oradism executable seems to be generated and LMS runs in the RR class (SCHED_RR round robin)

elephant-> ls -al oradism
-r-sr-s--- 1 root dba 14456 Nov 15 12:52 oradism

elephant-> ps -efc | grep lms

oracle 11554 1 RR 90 15:09 ? 00:00:01 ora_lms0_F8902PRD1
oracle 11558 1 RR 90 15:09 ? 00:00:01 ora_lms1_F8902PRD1

whereas other background processes like PMON still run in TS

elephant-> ps -efc | grep pmon | grep PRD
oracle 11544 1 TS 23 Feb14 ? 00:00:00 ora_pmon_F8902PRD1

I am not sure if this is ideal on a box with a low number of CPUs or if cache fusion traffic is not a major concern.If you want LMS to run in the same class as other processes you need to set _os_sched_high_priority back to 0 from its default value of 1 as seen from below

But doing this does not seem to change the class to TS

SQL> alter system set "_os_sched_high_priority"=0 scope=spfile;

System altered.

SQL> exit
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options
elephant-> srvctl stop database -d F8902PRD
elephant-> srvctl start database -d F8902PRD
elephant-> ps -efc | grep lms | grep PRD
oracle 17097 1 RR 90 09:54 ? 00:00:00 ora_lms0_F8902PRD1
oracle 17101 1 RR 90 09:54 ? 00:00:00 ora_lms1_F8902PRD1

1 select a.ksppinm "Parameter",
2 b.ksppstvl "Session Value",
3 c.ksppstvl "Instance Value"
4 from x$ksppi a, x$ksppcv b, x$ksppsv c
5 where a.indx = b.indx and a.indx = c.indx
6* and a.ksppinm like '%os_sched%'
SQL> /

Parameter
--------------------------------------------------------------------------------
Session Value
-------------------------------------------------------------------------------------------------------------------------------------------------
Instance Value
-------------------------------------------------------------------------------------------------------------------------------------------------
_os_sched_high_priority
0
0

From bug 5635098 it appears there is another parameter called
_high_priority_processes which needs to be set to null for this to work.

SQL> alter system set "_high_priority_processes"='' scope=spfile;
System altered.

elephant-> srvctl stop database -d F8902PRD
elephant-> srvctl start database -d F8902PRD

elephant-> ps -efc | grep lms | grep -v grep

oracle 31654 1 TS 24 00:58 ? 00:00:01 ora_lms0_F8902PRD1
oracle 31656 1 TS 24 00:58 ? 00:00:00 ora_lms1_F8902PRD1

As you can lms is now running in TS class.
On Solaris Sparc 64 bit be aware of bug 5258549 which causes boxes with low number of CPUs to freeze.

CRS Version

2007-02-09T05:03:00.000-08:00

I notice that on a lot of forums the following is quite a common question
"How can I verify what version CRS is?".

The version of CRS can be higher than the version of database/ASM software. The commands to see the same are

crsctl query crs softwareversion
crsctl query crs activeversion

So although the difference between the two commands might be obvious I am not sure if this is documented anywhere. Also after upgrading from 10.2.0.1 to 10.2.0.2/10.2.0.3 the active version does not seem to change. This maybe due to bug 5278777 which should be fixed in the 10.2.0.4 patchset.

I upgraded a couple of clusters yesterday from 10.2.0.1 to 10.2.0.3 (without any issues per se) and this is what I see after the CRS upgrade.

elephant-> crsctl query crs softwareversion
CRS software version on node [elephant] is [10.2.0.3.0]
elephant-> crsctl query crs activeversion
CRS active version on the cluster is [10.2.0.1.0]

elephant-> cemutlo -w
2:1:

The cemutlo command is used by the EM agent to query CRS version.

Also a rolling upgrade of CRS causes the VIP to relocate to some other node and you have to manually relocate the same using crs_relocate. This is mentioned in the patchset readme though I am not sure how many customers actually read the section “Known Issues”.

Checkpoint progress record

2007-01-21T18:57:00.000-08:00

The checkpoint process record is written to by the CKPT process every 3 seconds.This update is more commonly known as the heartbeat.This can be verified from the following query

SELECT CPHBT from X$KCCCP where rownum < 2
CPHBT
----------
612542768

In versions prior to 10G there was only one record. For a single
instance in 10G there are 8 records in the above structure.

You can also check the same from a controlfile dump using the following event

alter session set events 'immediate trace name controlf level 12';

In versions prior to 10G level 10 would suffice to obtain a logical dump but
in my testing on versions 10.1.0.x and 10.2.0.x on various platforms
I have been able to get a controlfile dump only at level 12.

From the generate trace file in udump

***************************************************************************
CHECKPOINT PROGRESS RECORDS
***************************************************************************
(size = 8180, compat size = 8180, section max = 11, section in-use = 0,
last-recid= 0, old-recno = 0, last-recno = 0)
(extent = 1, blkno = 2, numrecs = 11)
THREAD #1 - status:0x2 flags:0x0 dirty:68
low cache rba:(0x7d.e82d.0) on disk rba:(0x7d.e8d9.0)
on disk scn: 0x0000.0043bea2 01/22/2007 13:10:24
resetlogs scn: 0x0000.0008026d 11/16/2006 16:57:26
heartbeat: 612542768 mount id: 2427095148
......

To verify that the heartbeat happens every 3 secs you can do an strace on the CKPT
process.

eiger-> ps -ef | grep ckp | grep -v grep
oracle 2739 1 0 07:14 ? 00:00:04 ora_ckpt_HRDEV
eiger-> strace -tt -o /tmp/ckpt.out -p 2739
Process 2739 attached - interrupt to quit

From /tmp/ckpt.out

13:31:26.742402 gettimeofday({1169433086, 742475}, NULL) = 0
13:31:26.742531 times(NULL) = 431667132
13:31:26.742602 pwrite(16, "\25\302\0\0\3\0\0\0\0\0\0\0\0\0\1\4a1\0\0\2\0\0\0\0\0\0"..., 16384, 49152) = 16384
13:31:26.743399 times(NULL) = 431667132
13:31:26.743529 times(NULL) = 431667132
13:31:26.743600 pwrite(17, "\25\302\0\0\3\0\0\0\0\0\0\0\0\0\1\4a1\0\0\2\0\0\0\0\0\0"..., 16384, 49152) = 16384
13:31:26.744262 times(NULL) = 431667132
13:31:26.744338 times(NULL) = 431667132
13:31:26.744409 pwrite(18, "\25\302\0\0\3\0\0\0\0\0\0\0\0\0\1\4a1\0\0\2\0\0\0\0\0\0"..., 16384, 49152) = 16384
13:31:26.744938 times(NULL) = 431667132
.........
13:31:29.750559 gettimeofday({1169433089, 750559}, NULL) = 0
13:31:29.750559 times(NULL) = 431667433
13:31:29.750559 pwrite(16, "\25\302\0\0\3\0\0\0\0\0\0\0\0\0\1\4`1\0\0\2\0\0\0\0\0\0"..., 16384, 49152) = 16384
13:31:29.752055 times(NULL) = 431667433
13:31:29.752122 times(NULL) = 431667433
13:31:29.752659 pwrite(17, "\25\302\0\0\3\0\0\0\0\0\0\0\0\0\1\4`1\0\0\2\0\0\0\0\0\0"..., 16384, 49152) = 16384
13:31:29.753758 times(NULL) = 431667433
13:31:29.753827 times(NULL) = 431667433
13:31:29.753896 pwrite(18, "\25\302\0\0\3\0\0\0\0\0\0\0\0\0\1\4`1\0\0\2\0\0\0\0\0\0"..., 16384, 49152) = 16384
13:31:29.754706 times(NULL) = 431667433

As seen from below file descriptors 16,17 and 18 correspond to the 3 controlfiles of this database

eiger-> cd /proc
eiger-> cd 2739
eiger-> cd fd
eiger-> ls -al 1?

eiger-> ls -al 1? | grep contro
lrwx------ 1 oracle oracle 64 Jan 22 13:42 16 -> /usr/opt/oracle/u01/oradata/HRDEV/control01.ctl
lrwx------ 1 oracle oracle 64 Jan 22 13:42 17 -> /usr/opt/oracle/u01/oradata/HRDEV/control02.ctl
lrwx------ 1 oracle oracle 64 Jan 22 13:42 18 -> /usr/opt/oracle/u01/oradata/HRDEV/control03.ctl

The block which holds the checkpoint progress record also holds the CFVRR (controlfile vote result record)which is used to resolve a split brain scenario when nodes in a cluster cannot talk to each other.

RAC, Archivelog mode and cluster_database

2007-01-18T15:03:00.000-08:00

In version prior to 10.2 one had to set the parameter cluster_database
to FALSE to switch the archivelog mode of a database

Starting with 10.2 you no longer need to modify the CLUSTER_DATABASE parameter setting to
change the archiving mode in RAC. You can change archivelog mode as long as
the database is mounted in the local instance and not open in any instances.

Lets' test the same...

elephant-> srvctl status database -d F8902PRD
Instance F8902PRD1 is running on node elephant
Instance F8902PRD2 is running on node rhino
Instance F8902PRD3 is running on node hippo

elephant-> sqlplus

SQL*Plus: Release 10.2.0.1.0 - Production on Fri Jan 19 09:12:21 2007

Copyright (c) 1982, 2005, Oracle. All rights reserved.

Enter user-name: / as sysdba

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

SQL> archive log list
Database log mode Archive Mode
Automatic archival Enabled
Archive destination /u03/backup/F8902PRD/arch/
Oldest online log sequence 1103
Next log sequence to archive 1104
Current log sequence 1104

elephant-> srvctl stop database -d F8902PRD

elephant-> srvctl start instance -d F8902PRD -i F8902PRD1 -o mount
elephant-> srvctl status database -d F8902PRD
Instance F8902PRD1 is running on node elephant
Instance F8902PRD2 is not running on node rhino
Instance F8902PRD3 is not running on node hippo

SQL> show parameter cluster_database

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
cluster_database boolean TRUE
cluster_database_instances integer 3
SQL> alter database noarchivelog;

Database altered.
SQL> archive log list
Database log mode No Archive Mode
Automatic archival Disabled
Archive destination /u03/backup/F8902PRD/arch/
Oldest online log sequence 1103
Current log sequence 1104

elephant-> srvctl stop instance -d F8902PRD -i F8902PRD1

Now lets try to change back to archivelog mode by mounting the database from more
than one instance.

elephant-> srvctl start instance -d F8902PRD -i F8902PRD1 -o mount
elephant-> srvctl start instance -d F8902PRD -i F8902PRD2 -o mount
elephant-> srvctl status database -d F8902PRD
Instance F8902PRD1 is running on node elephant
Instance F8902PRD2 is running on node rhino
Instance F8902PRD3 is not running on node hippo

SQL> show parameter cluster_database

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
cluster_database boolean TRUE
cluster_database_instances integer 3
SQL> alter database archivelog;

Database altered.

SQL> archive log list
Database log mode Archive Mode
Automatic archival Enabled
Archive destination /u03/backup/F8902PRD/arch/
Oldest online log sequence 1103
Next log sequence to archive 1104
Current log sequence 1104

elephant-> srvctl stop database -d F8902PRD
elephant-> srvctl start instance -d F8902PRD -i F8902PRD1 -o mount
elephant-> srvctl start instance -d F8902PRD -i F8902PRD2 -o mount
elephant-> srvctl start instance -d F8902PRD -i F8902PRD2 -o open ==> I made a typo here. It should have been F8902PRD3
instead of F8902PRD2 but notice srvctl does not generate any errors. So u don't know if instance 2 has actually opened the database.
elephant-> srvctl start instance -d F8902PRD -i F8902PRD3 -o open

SQL> select inst_id,open_mode from gv$database;

INST_ID OPEN_MODE
---------- ----------
1 MOUNTED
2 MOUNTED
3 READ WRITE

So instance 3 has the db open while instances 1 and 2 have just mounted the database.

SQL> alter database noarchivelog;
alter database noarchivelog
*
ERROR at line 1:
ORA-01126: database must be mounted in this instance and not open in any
instance

*****************************************************************************************
However if you need to recreate the controlfile you need to set cluster_database to false

elephant-> srvctl stop database -d F8902PRD
elephant-> srvctl start instance -d F8902PRD -i F8902PRD1 -o nomount
elephant-> srvctl status database -d F8902PRD
Instance F8902PRD1 is running on node elephant
Instance F8902PRD2 is not running on node rhino
Instance F8902PRD3 is not running on node hippo

SQL> select inst_id,DATABASE_STATUS from gv$instance;

INST_ID DATABASE_STATUS
---------- -----------------
1 ACTIVE

SQL> @controlfile.sql
CREATE CONTROLFILE REUSE DATABASE "F8902PRD" NORESETLOGS ARCHIVELOG
*
ERROR at line 1:
ORA-01503: CREATE CONTROLFILE failed
ORA-12720: operation requires database is in EXCLUSIVE mode

The Optimizer and cache related statistics.

2007-01-10T20:21:00.000-08:00

Jonathan Lewis in his excellent book on the CBO talks about new functionality within Oracle’s optimizer wherein the optimizer can use cache related statistics of objects to evaluate a more optimal execution plan.

All the following testing has been done on 10.2.0.3 with the hidden parameter _cache_stats_monitor set to TRUE (default is false)

The table cache_stats_1$ which is used to monitor lifetime caching statistics (c0902000.sql) is populated by MMON periodically via a MERGE statement which does not seem to be using bind variables. You can also populate the same directly using

SQL> exec dbms_stats_internal.flush_cache_stats;

PL/SQL procedure successfully completed.

For the purpose of this discussion we will concentrate on a normal heap table SCOTT.T1 with data_object_id = 58417 which is a replica of dba_tables.

SQL> select * from cache_stats_1$ where DATAOBJ#=58417

DATAOBJ# INST_ID CACHED_AVG CACHED_SQR_AVG CACHED_NO CACHED_SEQ_NO
---------- ---------- ---------- -------------- ---------- -------------
CHR_AVG CHR_SQR_AVG CHR_NO CHR_SEQ_NO LGR_SUM LGR_LAST PHR_LAST
---------- ----------- ---------- ---------- ---------- ---------- ----------
SPARE1 SPARE2 SPARE3 SPARE4 SPARE5
---------- ---------- ---------- ---------- ----------
58417 1 118.889076 14192.4521 35 2644
0 0 1 2575 0 768 0

Now if we were to gather cache related statistics for this table

SQL> exec dbms_stats.gather_table_stats('SCOTT','T1',stattype=>'CACHE');

PL/SQL procedure successfully completed.

A trace on the above API call reveals the following statement

********************************************************
insert into tab_stats$ (obj#,cachedblk,cachehit,logicalread) values (:1,:2,:3,:4)

Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=07723aa8 bln=22 avl=04 flg=05
value=58417
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=07723a84 bln=24 avl=03 flg=05
value=118
Bind#2
oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=07723a60 bln=24 avl=00 flg=05
Bind#3
oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=07723a3c bln=24 avl=00 flg=05

********************************************************

Only the cachedblk column appears to be populated. (I haven’t had a chance to check this value against x$bh)
SQL> select * from tab_stats$ where obj#=58417;

OBJ# CACHEDBLK CACHEHIT LOGICALREAD ROWCNT BLKCNT EMPCNT
---------- ---------- ---------- ----------- ---------- ---------- ----------
AVGSPC CHNCNT AVGRLN AVGSPC_FLB FLBCNT ANALYZETI SAMPLESIZE
---------- ---------- ---------- ---------- ---------- --------- ----------
FLAGS SPARE1 SPARE2 SPARE3
---------- ---------- ---------- ----------
SPARE4
--------------------------------------------------------------------------------
SPARE5
--------------------------------------------------------------------------------
SPARE6
---------
58417 118

Checking the execution plans of statements with "_optimizer_cache_stats" set to TRUE and FALSE we find the cost of the table is almost half in the former.

SQL> conn scott/tiger
Connected.
SQL> set autotrace traceonly explain
SQL> alter session set "_optimizer_cache_stats" = true;

Session altered.

SQL> select count(*) from t1;

Execution Plan
----------------------------------------------------------
Plan hash value: 3724264953

-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 29 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| T1 | 6446 | 29 (0)| 00:00:01 |
-------------------------------------------------------------------

SQL> alter session set "_optimizer_cache_stats" = false;

Session altered.

SQL> select count(*) from t1;

Execution Plan
----------------------------------------------------------
Plan hash value: 3724264953

-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 56 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| T1 | 6446 | 56 (0)| 00:00:01 |
-------------------------------------------------------------------

Also for fixed objects the API dbms_stats.gather_fixed_objects_stats populates tab_stats$

Extracting info from AWR

2007-01-08T19:26:00.000-08:00

The Automatic Workload Repository stores a wealth of performance related data in an Oracle 10g Database. Historical data can be viewed from the DBA_HIST* views depending on the retention period.

One can either write a query against any of the dba_hist_* views or use the API
dbms_sqltune.select_workload_repository

For e.g
To find out all sql stmts which took more than 1 hour to execute between 7:00 am and 10:00 am this morning

• Find the snapshots for that period
select snap_id,BEGIN_INTERVAL_TIME from DBA_HIST_SNAPSHOT
where BEGIN_INTERVAL_TIME between to_timestamp('09-JAN-2007 07:00:00','DD-MON-YYYY HH24:MI:SS')and to_timestamp('09-JAN-2007 10:00:00','DD-MON-YYYY HH24:MI:SS')

5064 09-JAN-07 09.00.45.370 AM
5062 09-JAN-07 07.00.45.786 AM
5063 09-JAN-07 08.00.47.623 AM

• Find the sql ids of statements which meet the criteria

SQL> select sql_id,ELAPSED_TIME_TOTAL,ELAPSED_TIME_DELTA from
dba_hist_sqlstat where snap_id between 5062 and 5064 and ELAPSED_TIME_TOTAL > 3600000000

5umujs4y5q05f 252683861535 14085330457
5umujs4y5q05f 266739511867 14055650332
5umujs4y5q05f 280852257550 14112745683

• Find the sql statement corresponding to this sql_id

SQL> select sql_text from dba_hist_sqltext where sql_id='5umujs4y5q05f';

SELECT A.JOURNAL_ID, B.SOURCE, B.ACCOUNTING_PERIOD, A.ACCOUNT, A.DEPTID, A.PROJE
CT_ID, A.CLASS_FLD, A.MONETARY_AMOUNT, A.LINE_DESCR, A.JRNL_LN_REF, TO_CHAR(A.JO
URNAL_DATE,'YYYY-MM-DD'), B.JRNL_HDR_STATUS, TO_CHAR(SYSDATE,'YYYY-MM-DD') FR
OM PS_JRNL_LN A, PS_JRNL_HEADER B, PS_DEPT_TBL C WHERE B.BUSINESS_UNIT = A.BU
SINESS_UNIT AND B.JOURNAL_ID = A.JOURNAL_ID AND B.JOURNAL_DATE = A.JOU
RNAL_DATE AND B.UNPOST_SEQ = A.UNPOST_SEQ AND ( C.EFFDT = (SE
LECT MAX(C_ED.EFFDT) FROM PS_DEPT_TBL C_ED WHERE C.SETID = C_ED.SETID
AND C.DEPTID = C_ED.DEPTID AND C_ED.EFFDT <= SYSDATE)
AND A.BUSINESS_UNIT = 'UNSYD' AND A.LEDGER = 'ACTUALS' AND A.CURREN
CY_CD = 'AUD' AND C.DEPTID = A.DEPTID AND B.FISCAL_YEAR = :1 A
ND B.ACCOUNTING_PERIOD BETWEEN :2 AND :3 AND ( A.ACCOUNT = :4 OR A.A
CCOUNT = :5 OR ( A.ACCOUNT = :6 OR A.ACCOUNT = :7 AND A.JOURNA
L_ID IN (SELECT D.JOURNAL_ID FROM PS_JRNL_LN D WHERE ( D.ACCOUNT = :8
OR D.ACCOUNT = :9)))) AND B.JRNL_HDR_STATUS IN ('P','U') ) ORDER BY 3
, 1, 4

You can obtain the same result with a single statement using the dbms_sqltune.select_workload_repository API as shown below

SELECT VALUE(P).sql_text FROM table(dbms_sqltune.select_workload_repository(5062,5064,'elapsed_time > 3600000000')) P ;

SELECT A.JOURNAL_ID, B.SOURCE, B.ACCOUNTING_PERIOD, A.ACCOUNT, A.DEPTID, A.PROJE
CT_ID, A.CLASS_FLD, A.MONETARY_AMOUNT, A.LINE_DESCR, A.JRNL_LN_REF, TO_CHAR(A.JO
URNAL_DATE,'YYYY-MM-DD'), B.JRNL_HDR_STATUS, TO_CHAR(SYSDATE,'YYYY-MM-DD') FR
OM PS_JRNL_LN A, PS_JRNL_HEADER B, PS_DEPT_TBL C WHERE B.BUSINESS_UNIT = A.BU
SINESS_UNIT AND B.JOURNAL_ID = A.JOURNAL_ID AND B.JOURNAL_DATE = A.JOU
RNAL_DATE AND B.UNPOST_SEQ = A.UNPOST_SEQ AND ( C.EFFDT = (SE
LECT MAX(C_ED.EFFDT) FROM PS_DEPT_TBL C_ED WHERE C.SETID = C_ED.SETID
AND C.DEPTID = C_ED.DEPTID AND C_ED.EFFDT <= SYSDATE)
AND A.BUSINESS_UNIT = 'UNSYD' AND A.LEDGER = 'ACTUALS' AND A.CURREN
CY_CD = 'AUD' AND C.DEPTID = A.DEPTID AND B.FISCAL_YEAR = :1 A
ND B.ACCOUNTING_PERIOD BETWEEN :2 AND :3 AND ( A.ACCOUNT = :4 OR A.A
CCOUNT = :5 OR ( A.ACCOUNT = :6 OR A.ACCOUNT = :7 AND A.JOURNA
L_ID IN (SELECT D.JOURNAL_ID FROM PS_JRNL_LN D WHERE ( D.ACCOUNT = :8
OR D.ACCOUNT = :9)))) AND B.JRNL_HDR_STATUS IN ('P','U') ) ORDER BY 3
, 1, 4

P.S You have to be licensed to use the Diagnostics Pack to use AWR and licensed to use Oracle Tuning Pack to use SQL Tuning Sets. For more information please refer to the Oracle Licensing documentation at
http://download-west.oracle.com/docs/cd/B19306_01/license.102/b14199/options.htm#sthref80

Merry Xmas and Happy New Year

2006-12-13T16:25:00.000-08:00

I am off to Goa for my annual Xmas vacation.

Here's wishing u all a Merry Christmas and a Happy New Year

See you all in the New Year

Regards
-Fairlie

Analysing systemstate dumps

2006-12-11T18:32:00.000-08:00

In my last article I discussed how to dump the systemstate using various methods. These files are quite huge and are sometimes difficult to decipher. You can parse the file using an awk script in
LTOM
provided by Oracle’s center of expertise. LTOM is a lite onboard monitor which is a diagnostic tool.

Once you download and install LTOM you can find a script called ass109.awk in tom_base/tom/src which parses the systemstate into a more readable format

buffalo>pwd
/usr/opt/oracle/bin/tom_base/tom/src
buffalo>ls -al ass*
-rwxr-x--- 1 oracle dba 34549 Nov 25 2003 ass109.awk

We will attempt to analyse a systemstate dump generated by the following error

>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=42
System State dumped to trace file /u00/app/oracle/admin/F8900DEV/udump/f8900dev1_ora_12057.trc
Mon Dec 11 09:58:05 2006

buffalo >awk -f ass109.awk f8900dev1_ora_12057.trc > rowcache.out

If you look at rowcache.out
42: last wait for 'ksdxexeotherwait' [Rcache object=0x483a70e4,]
The holder of 0x483a70e4 is
Rcache object=0x483a70e4, 48: 48: is waiting for Latch 5213eeb4

If you look at rowcache.out in conjunction with the raw trace file it can be concluded that process 42 has requested row cache lock on dc_profiles which is held by process 48.
Process 48 is in turn waiting on the “Child object queue header” latch which is held by process 44
Process 44 which is a DataPump Worker is in turn waiting on 'SGA: allocation forcing component growth' which is seen when using ASMM (sga_target)

Systemstate dumps

2006-12-10T22:08:00.001-08:00

A system state dump is trace file containing a snapshot of all processes running in a database. It is used to diagnose hang issues and has more information compared to a hanganalyze dump.There are various ways to dump the systemstate.

If you can connect to the database you can dump it using

SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit  this is important so that the file is not truncated.
Statement processed.
SQL> oradebug dump systemstate 10
Statement processed.
SQL> oradebug tracefile_name
c:\oracle\product\10.2.0\admin\usyd\udump\usyd_ora_17452.trc

A complete file should have the following string at the end
END OF SYSTEM STATE

If you want only the short stack of each process in the instance
you need to use

SQL> oradebug dump systemstate 256
Statement processed.

Alternatively you can dump the system state using

SQL> ALTER SESSION SET EVENTS 'IMMEDIATE TRACE NAME SYSTEMSTATE LEVEL 10';

Session altered.

If you cannot connect to the database instance you can use a session less connection in 10g using
sqlplus -prelim / as sysdba
oradebug setmypid
oradebug unlimit;
oradebug dump systemstate 10

Prior to 10g you can use a unix debugger like gdb, adb or dbx to attach to a shadow process and dump the system state using the function ksudss which is the subroutine in the Oracle source code which does the same.

eiger-> ps -ef | grep HRDEV | grep j00 | grep –v grep

oracle 14022 1 0 Dec10 ? 00:00:21 ora_j000_HRDEV

eiger-> gdb
GNU gdb Red Hat Linux (6.3.0.0-1.132.EL4rh)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.Type "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
(gdb) attach
Argument required (process-id to attach).
(gdb) attach 14022
Attaching to process 14022
Reading symbols
…… (output deleted for readability purposes)
0x000000324f7c7c0c in semtimedop () from /lib64/tls/libc.so.6
(gdb) print ksudss(10)
[Switching to Thread 182922098368 (LWP 14022)]
$1 = -1073747016
(gdb) detach
Detaching from program: /usr/opt/oracle/u00/app/oracle/product/10.2.0/bin/oracle, process 14022
(gdb) quit

Since in the above case we have attached to a job process the trace file containing the dump will be in bdump else the trace file would be in udump.

For RAC databases if you need to dump the systemstate on all instances

SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit
Statement processed.
SQL> oradebug -g all dump systemstate 266
Statement processed.
SQL> oradebug tracefile_name
/u00/app/oracle/admin/F8902UAT/udump/f8902uat1_ora_2513.trc

The trace file will have only the following contents

PORADEBUG REMOTE COMMAND BEGIN SERIAL:0 MYPID:2513
PORADEBUG REMOTE COMMAND END SERIAL:0 MYPID:2513 [SUCCESS]

The systemstate dump will be written to by the DIAG process on each node.

Please use these commands with caution. On busy systems with a large number of processes these commands can take quite a while. Also a systemstate dump need not always portray the correct information of a system especially when the time to
dump all the processes is long.

Adding a voting disk online

2006-12-03T21:25:00.000-08:00

In 10.2 RAC it is now possible to add a voting disk online in addition to specifying more than one voting disk during the ClusterWare install.In 10G R1 there was no software level mirroring of the voting disk.

I tried this out for the first time today and things didn't go as I expected.

[root@dbrac1 ~]# /home/oracle/oracle/product/10.2.0/crs/bin/crsctl add css votedisk /dev/raw/raw4
Cluster is not in a ready state for online disk addition

You have to use the force option in the above command due to
Bug 4898020 ADDING VOTING DISK ONLINE CRASH THE CRS
which is fixed in the 10.2.0.4 patchset. This is again another case where clearly documented functionality in 10.2 does not work.

Before using the force option make sure the CRS stack is not up on any of the nodes.

[root@dbrac1 init.d]# ps -ef | grep d.bin | grep -v grep
should retrun no rows.

[root@dbrac1 init.d]# /home/oracle/oracle/product/10.2.0/crs/bin/crsctl add css votedisk /dev/raw/raw4 -force
Now formatting voting disk: /dev/raw/raw4
successful addition of votedisk /dev/raw/raw4.
[root@dbrac1 init.d]#

Check that the newly added disk can be seen from both nodes.

[root@dbrac1 init.d]# /home/oracle/oracle/product/10.2.0/crs/bin/crsctl query css votedisk
0. 0 /dev/raw/raw2
1. 0 /dev/raw/raw4

located 2 votedisk(s).

[root@dbrac2 init.d]# /home/oracle/oracle/product/10.2.0/crs/bin/crsctl query css votedisk
0. 0 /dev/raw/raw2
1. 0 /dev/raw/raw4

located 2 votedisk(s).

The same error is encountered should you wish to delete the newly added disk

[root@dbrac1 bin]# ./crsctl delete css votedisk /dev/raw/raw4
Cluster is not in a ready state for online disk removal
[root@dbrac1 bin]# ./crsctl delete css votedisk /dev/raw/raw4 -force
successful deletion of votedisk /dev/raw/raw4.

Again please note that the force option should be used only after the CRS stack
is shutdown on all nodes. Failure to do so could result in OCR corruption.

Size of ASM files

2006-11-29T14:57:00.000-08:00

Whilst testing compression of archivelogs on ASM I was looking for ways to find the size of an archivelog stored on ASM

You can

• Use the bytes column in v$asm_file.
• Use the asmcmd line utility and use the du command there in
• Use an API called dbms_diskgroup as shown below

SQL> select thread#,blocks,compressed from v$archived_log where thread#=2 and SEQUENCE#=19

THREAD# SEQUENCE# BLOCKS COM
---------- ---------- ---------- ---
2 19 3794 YES

[oracle@dbrac2 ~]$ asmcmd
ASMCMD> cd ARCHIVELOG
ASMCMD> ls
2006_11_28/
ASMCMD> cd 2006_11_28
ASMCMD> ls
thread_1_seq_10.289.607731765
thread_1_seq_11.293.607732151
thread_1_seq_12.296.607732301
thread_1_seq_8.286.607731393
thread_1_seq_9.287.607731413
thread_2_seq_13.288.607731413
thread_2_seq_14.290.607731771
thread_2_seq_15.291.607732073
thread_2_seq_16.292.607732151
thread_2_seq_17.294.607732277
thread_2_seq_18.295.607732301
thread_2_seq_19.297.607732423

set serveroutput on
declare
vfilename varchar2(4000);
vfilesize number;
vlbks number;
vfiletype number;
begin
dbms_output.enable(5000);
vfilename := '&file_name';
dbms_diskgroup.getfileattr(vfilename,vfiletype,vfilesize,vlbks);
dbms_output.put_line('File: '||vfilename); dbms_output.new_line;
dbms_output.put_line('Size (Logical Block Size): '||vfilesize); dbms_output.new_line;
dbms_output.put_line('Logical Block Size: '||vlbks); dbms_output.new_line;
dbms_output.put_line('File type: '||vfiletype); dbms_output.new_line;
end;
/

Enter value for file_name: +ORADATA1/TEST/ARCHIVELOG/2006_11_28/thread_2_seq_19.297.607732423
old 9: vfilename := '&file_name';
new 9: vfilename := '+ORADATA1/TEST/ARCHIVELOG/2006_11_28/thread_2_seq_19.297.607732423';
File: +ORADATA1/TEST/ARCHIVELOG/2006_11_28/thread_2_seq_19.297.607732423
Size (Logical Block Size): 3794
Logical Block Size: 512
File type: 4

PL/SQL procedure successfully completed.

Recovery using compressed archivelogs

2006-11-28T14:35:00.000-08:00

A couple of days ago I mentioned about an undocumented feature where by it is
possible to generate compressed archivelogs

I did manage to test a couple of scenarios where I did manage to recover my database
with a mixture of compressed and non compressed archivelogs.

I guess this begs the question as to why this feature is not documented.

Archivelog compression?

2006-11-26T19:44:00.001-08:00

Apparently there is a command which could generate compressed archivelogs which goes something like this.

SQL> ALTER DATABASE ARCHIVELOG COMPRESS enable;

Database altered.

I have skimmed through the documentation but can't seem to find a reference to the same but the view v$archived_log seems to have a column called compressed which from the docs is

COMPRESSED VARCHAR2(3) This column is reserved for internal use only

I am assuming this is related to the underscore parameter _log_archive_compress_enable the description of which is below.
But changing the value of this parameter has not prevented the command from
working.

SQL> REM Formatting columns
SQL> set lines 9999
SQL> col indx format 9999
SQL> col inst_id heading "INST" format 9999
SQL> col ksppinm heading "NAME" format a30
SQL> col ksppdesc heading "DESC" format a60
SQL> col ksppstvl heading "CURR VAL" format a15
SQL> col ksppstdf heading "DEFAULT VAL" format a15

SQL> select v.indx,v.inst_id,ksppinm,ksppstvl,ksppstdf,ksppdesc from x$ksppi i ,
x$ksppcv v where i.indx=v.indx and ksppinm like '_log_archive_compress_enable';

INDX INST NAME CURR VAL DEFAULT VAL DESC
----- ----- ------------------------------ --------------- --------------- -------------------------
473 1 _log_archive_compress_enable FALSE TRUE Bypass database rules for enabling archiv

1 row selected.
So by default archivelogs are not compressed.
SQL> select distinct compressed from v$archived_log;

COM
---
NO

So I used this command, generated a few archivelogs and got the following message in one of the trace files.

Archivelog compression complete.
Input: 3139072 bytes Output: 810830 bytes
Compression Performance: 74.17 percent or 2.07 bits per byte

Lets verify the same.
SQL> alter database archivelog compress disable;

Database altered.

SQL> alter system switch logfile;

System altered.

SQL> create table scott.obj$ as select * from dba_objects;

Table created.

SQL> alter system switch logfile;

System altered.

SQL> alter database archivelog compress enable;

Database altered.

SQL> create table frego.obj$ as select * from dba_objects;

Table created.

SQL> alter system switch logfile;

System altered.

SQL> select sequence#,blocks,compressed from v$archived_log where sequence#>225;

SEQUENCE# BLOCKS COM
---------- ---------- ---
226 3820 NO
227 1 NO
228 11579 NO
229 83 YES
230 8 YES
231 1911 YES

6 rows selected.

If you compare the 2 logs of interest (228 and 231 since there were other commands in the interim) you find a compression performance similar to the one indicated above.

It would be wise to check if I can recover using compressed archivelogs though.

P.S This is an undocumented feature (AFAIK) and hence I do not advise anyone to use the same in a Production environment.

Block Change Tracking

2006-11-26T18:46:00.000-08:00

If anybody is using the new 10G backup feature of incremental backups using a block change tracking file or thinking of doing so I sincerely recommend reading Alex Gorbachev's presentation

Converting database at target

2006-11-21T15:35:00.000-08:00

There was a valid response for yesterday's post by The Human Fly where he suggested that this method was not feasible for large databases because of the need for a staging area to hold the converted files.
Well according to Oracle disk space is cheap :-) and I know a lot of bugs that have been closed on this premise (where the workaround has meant additional disk space)

But seriously you can get around this

• You can take a backup of the source database to tape and then overwrite the datafile location (assuming you don’t need the source database anymore)

CONVERT DATABASE NEW DATABASE 'USYD'
transport script 'C:\temp\newtransportscript'
to platform 'Linux 64-bit for AMD'
db_file_name_convert 'C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\' 'C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\'
;

It is also possible to convert the database at the target to free up CPU on the source. You need to run the following on the source database

CONVERT DATABASE ON TARGET PLATFORM
CONVERT SCRIPT 'C:\temp\convertscript.rman'
TRANSPORT SCRIPT 'C:\temp\transport_at_target.sql'
new database 'USYD'
FORMAT 'C:\temp\target\%U';

This will create 2 scripts

• convertscript.rman which will have convert commands for each datafile of the database to be converted.

• transport_at_target.sql contains the syntax to create the controlfile and start the database at the target

LINUX64>>startup nomount pfile='/u01/oradata/USYD/initUSYD.ora'
ORACLE instance started.

Total System Global Area 171966464 bytes
Fixed Size 2069712 bytes
Variable Size 113249072 bytes
Database Buffers 50331648 bytes
Redo Buffers 6316032 bytes

LINUX64>>CREATE CONTROLFILE REUSE SET DATABASE "USYD" RESETLOGS ARCHIVELOG
2 MAXLOGFILES 16
3 MAXLOGMEMBERS 3
4 MAXDATAFILES 100
5 MAXINSTANCES 8
6 MAXLOGHISTORY 292
7 LOGFILE
8 GROUP 1
9 '/u01/oradata/USYD/ARCH_D-USYD_ID-768471617_S-212_T-1_A-600609988_00I2I4PR' SIZE 50M,
GROUP 2
10 11 '/u01/oradata/USYD/ARCH_D-USYD_ID-768471617_S-213_T-1_A-600609988_00I2I4PR' SIZE 50M,
GROUP 3
12 13 '/u01/oradata/USYD/ARCH_D-USYD_ID-768471617_S-211_T-1_A-600609988_00I2I4PR' SIZE 50M
14 DATAFILE
15 '/u01/oradata/USYD/SYSTEM01.DBF',
16 '/u01/oradata/USYD/UNDOTBS01.DBF',
17 '/u01/oradata/USYD/SYSAUX01.DBF',
18 '/u01/oradata/USYD/USERS01.DBF'
19 CHARACTER SET WE8MSWIN1252;

Control file created.

Now convert the files using the script convertscript.rman
eiger-> rman target /

Recovery Manager: Release 10.2.0.2.0 - Production on Wed Nov 22 14:32:33 2006

Copyright (c) 1982, 2005, Oracle. All rights reserved.

connected to target database: USYD (DBID=768471617, not open)

RUN {

CONVERT DATAFILE '/u01/oradata/USYD/SYSTEM01.DBF'
FROM PLATFORM 'Microsoft Windows IA (32-bit)'
FORMAT '/u01/oradata/USYD/NEW/SYSTEM01.DBF';

CONVERT DATAFILE '/u01/oradata/USYD/SYSAUX01.DBF'
FROM PLATFORM 'Microsoft Windows IA (32-bit)'
FORMAT '/u01/oradata/USYD/NEW/SYSAUX01.DBF';

CONVERT DATAFILE '/u01/oradata/USYD/UNDOTBS01.DBF'
FROM PLATFORM 'Microsoft Windows IA (32-bit)'
FORMAT '/u01/oradata/USYD/NEW/UNDOTBS01.DBF';

CONVERT DATAFILE '/u01/oradata/USYD/USERS01.DBF'
FROM PLATFORM 'Microsoft Windows IA (32-bit)'
FORMAT '/u01/oradata/USYD/NEW/USERS01.DBF';

}

Starting backup at 22-NOV-06
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile conversion
input filename=/u01/oradata/USYD/SYSTEM01.DBF
converted datafile=/u01/oradata/USYD/NEW/SYSTEM01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time: 00:00:46
Finished backup at 22-NOV-06

Starting backup at 22-NOV-06
channel ORA_DISK_1: sid=39 devtype=DISK
channel ORA_DISK_1: starting datafile conversion
input filename=/u01/oradata/USYD/SYSAUX01.DBF
converted datafile=/u01/oradata/USYD/NEW/SYSAUX01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time: 00:02:17
Finished backup at 22-NOV-06

Starting backup at 22-NOV-06
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile conversion
input filename=/u01/oradata/USYD/UNDOTBS01.DBF
converted datafile=/u01/oradata/USYD/NEW/UNDOTBS01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time: 00:02:48
Finished backup at 22-NOV-06

Starting backup at 22-NOV-06
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile conversion
input filename=/u01/oradata/USYD/USERS01.DBF
converted datafile=/u01/oradata/USYD/NEW/USERS01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time: 00:00:07
Finished backup at 22-NOV-06

Unfortunately it appears that the file cannot be overwritten and hence
a staging area is required because when I tried to do that

RMAN> CONVERT DATAFILE '/u01/oradata/USYD/SYSTEM01.DBF'
FROM PLATFORM 'Microsoft Windows IA (32-bit)'
FORMAT '/u01/oradata/USYD/SYSTEM01.DBF';

Starting backup at 22-NOV-06
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=36 devtype=DISK
channel ORA_DISK_1: starting datafile conversion
input filename=/u01/oradata/USYD/SYSTEM01.DBF
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03009: failure of backup command on ORA_DISK_1 channel at 11/22/2006 14:35:00
ORA-19635: input and output filenames are identical: /u01/oradata/USYD/SYSTEM01.DBF

You then need to move the files from the staging area and resetlogs to start
the database

SQL> shutdown immediate
ORA-01109: database not open

Database dismounted.
ORACLE instance shut down.

eiger-> cd USYD/N*
eiger-> ls
SYSAUX01.DBF SYSTEM01.DBF UNDOTBS01.DBF USERS01.DBF
eiger-> pwd
/u01/oradata/USYD/NEW
eiger-> mv * ../

SQL> startup mount pfile='/u01/oradata/USYD/initUSYD.ora'
ORACLE instance started.

Total System Global Area 171966464 bytes
Fixed Size 2069712 bytes
Variable Size 113249072 bytes
Database Buffers 50331648 bytes
Redo Buffers 6316032 bytes
Database mounted.

SQL> recover database using BACKUP CONTROLFILE until cancel;
ORA-00279: change 6936865 generated at 11/22/2006 10:13:25 needed for thread 1
ORA-00289: suggestion :
/u00/app/oracle/product/10.2.0/dbs/arch1_219_600609988.dbf
ORA-00280: change 6936865 for thread 1 is in sequence #219

Specify log: {=suggested | filename | AUTO | CANCEL}
cancel
Media recovery cancelled.

SQL> alter database open resetlogs;

Database altered.

Performing Cross-Platform Database Transport

2006-11-20T00:00:00.000-08:00

Starting with 10g R2 it is now possible to transport an entire database (not just a few tablespaces) using the convert database RMAN command.

In the below scenario we are converting from a Windows 32 bit system to a Linux x86-64 bit system.

First we check if both platforms (source and destination) have the same endianness
using the dbms_tdb package.

The database needs to be open in read only mode for the following procedure to
work.

WINDOWS>>set serveroutput on
WINDOWS>>declare
2 db_ready boolean;
3 begin
4 db_ready := dbms_tdb.check_db('Linux 64-bit for
AMD',dbms_tdb.skip_readonly);
5 end;
6 /

PL/SQL procedure successfully completed.

If they did not have the same endianness we would have got a message like the one shown below

WINDOWS>>declare
2 db_ready boolean;
3 begin
4 db_ready := dbms_tdb.check_db('Solaris[tm] OE
(64-bit)',dbms_tdb.skip_readonly);
5 end;
6 /

The specified target platform name 'Solaris[tm] OE (64-bit)' is invalid
or the target platform is not transportable.

PL/SQL procedure successfully completed.

Next we need to identify any external objects which will not be transported.
These include external tables,directories or BFILES.

WINDOWS>>declare
2 external boolean;
3 begin
4 /* value of external is ignored, but with SERVEROUTPUT set to
ON
5 * dbms_tdb.check_external displays report of external objects
6 * on console */
7 external := dbms_tdb.check_external;
8 end;
9
10 /

The following directories exist in the database:
SYS.WORK_DIR, SYS.ADMIN_DIR, SYS.DATA_PUMP_DIR

RMAN> CONVERT DATABASE NEW DATABASE 'USYD'
2> transport script 'C:\temp\transportscript'
3> to platform 'Linux 64-bit for AMD'
4> db_file_name_convert 'C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\'
'C:\temp\USYD\'
5> ;

In the above command C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD is the
source destination for the datafiles and C:\temp\USYD\ is the folder in which
the files will be placed after they are converted. You can open this database in read write mode once the database is converted.

Starting convert at 16/NOV/06
using channel ORA_DISK_1

Directory SYS.WORK_DIR found in the database
Directory SYS.ADMIN_DIR found in the database
Directory SYS.DATA_PUMP_DIR found in the database

User SYS with SYSDBA and SYSOPER privilege found in password file
channel ORA_DISK_1: starting datafile conversion
input datafile fno=00001
name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\SYSTEM01.DBF

converted datafile=C:\TEMP\USYD\SYSTEM01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time:
00:00:25
channel ORA_DISK_1: starting datafile conversion
input datafile fno=00003
name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\SYSAUX01.DBF

converted datafile=C:\TEMP\USYD\SYSAUX01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time:
00:00:27
channel ORA_DISK_1: starting datafile conversion
input datafile fno=00002
name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\UNDOTBS01.DBF

converted datafile=C:\TEMP\USYD\UNDOTBS01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time:
00:00:25
channel ORA_DISK_1: starting datafile conversion
input datafile fno=00004
name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\USERS01.DBF
converted datafile=C:\TEMP\USYD\USERS01.DBF
channel ORA_DISK_1: datafile conversion complete, elapsed time:
00:00:08
Run SQL script C:\TEMP\TRANSPORTSCRIPT on the target platform to create
database

Edit init.ora file C:\ORACLE\PRODUCT\10.2.0\DB_1\DATABASE\INIT_00I2I4PR_1_0.ORA.
This pfile will be used to create the database on the target platform
To recompile all PL/SQL modules, run utlirp.sql and utlrp.sql on the
target platform
To change the internal database identifier, use DBNEWID Utility
Finished backup at 16/NOV/06

Since the source is a Windows Machine and the destination Linux x86-64
bit you have to change the location of the files in the transportscript created

Create an init.ora file called initUSYD.ora with the following parameters
control_files = "/u01/oradata/USYD/cf_D-USYD_id-1778429277_00gb9u2s"
instance_name = "USYD"
plsql_native_library_dir = "/tmp/convertdb/plsqlnld1"
db_name = "USYD"
sga_max_size =5000000
compatible='10.2.0'

eiger-> sqlplus

SQL*Plus: Release 10.2.0.2.0 - Production on Mon Nov 20 17:10:28 2006

Copyright (c) 1982, 2005, Oracle. All Rights Reserved.

Enter user-name: / as sysdba
Connected to an idle instance.

SQL> startup nomount pfile='/u01/oradata/USYD/initUSYD.ora'
ORACLE instance started.

Total System Global Area 171966464 bytes
Fixed Size 2069712 bytes
Variable Size 113249072 bytes
Database Buffers 50331648 bytes
Redo Buffers 6316032 bytes

Cut and paste the commands from the transportscript created.

SQL> CREATE CONTROLFILE REUSE SET DATABASE "USYD" RESETLOGS ARCHIVELOG
2 MAXLOGFILES 16
3 MAXLOGMEMBERS 3
4 MAXDATAFILES 100
MAXINSTANCES 8
5 MAXLOGHISTORY 292
7 LOGFILE
8 GROUP 1
'/u01/oradata/USYD/ARCH_D-USYD_ID-768471617_S-212_T-1_A-600609988_00I2I4PR' SIZE 50M,
9 GROUP 2
'/u01/oradata/USYD/ARCH_D-USYD_ID-768471617_S-213_T-1_A-600609988_00I2I4PR' SIZE 50M,
10 GROUP 3
'/u01/oradata/USYD/ARCH_D-USYD_ID-768471617_S-211_T-1_A-600609988_00I2I4PR' SIZE 50M
11 DATAFILE
12 '/u01/oradata/USYD/SYSTEM01.DBF',
13 '/u01/oradata/USYD/UNDOTBS01.DBF',
14 '/u01/oradata/USYD/SYSAUX01.DBF',
15 '/u01/oradata/USYD/USERS01.DBF'
16 CHARACTER SET WE8MSWIN1252
17 ;

Control file created.

SQL> set numwidth 20
SQL> select distinct checkpoint_change# from v$datafile;

CHECKPOINT_CHANGE#
--------------------
6631021

SQL> select distinct checkpoint_change# from v$datafile_header;

CHECKPOINT_CHANGE#
--------------------
6631021

SQL> ALTER DATABASE OPEN RESETLOGS;

Database altered.

SQL> ALTER TABLESPACE TEMP ADD TEMPFILE '/u01/oradata/USYD/DATA_D-USYD_I-768471617_TS-TEMP_FNO-1_00I2I4PR' SIZE 27262976 AUTOEXTEND ON NEXT 655360 MAXSIZE 32767M;

Tablespace altered.

Searching for X$ tables

2006-11-14T18:48:00.000-08:00

You can query the names of X$ tables from X$KQFTA.

I was looking for the X$ tables related to Dynamic Remastering and found them from

SQL> select KQFTANAM from x$kqfta where KQFTANAM like 'X$KJDR%';

KQFTANAM
------------------------------
X$KJDRHV
X$KJDRPCMHV
X$KJDRPCMPF
X$KJDRMAFNSTATS
X$KJDRMHVSTATS
X$KJDRMREQ

6 rows selected.

Similary to look for dictionary tables I query from the public synonym DICT which is based on SYS.DICTIONARY.

For e.g
SQL> select table_name from dict where table_name like '%FILEST%';

TABLE_NAME
------------------------------
DBA_HIST_FILESTATXS
GV$FILESTAT
V$FILESTAT

Diagnosing unshared SQL in 10g

2006-11-13T15:51:00.000-08:00

One of the ways to increase scalability and throughput of an application is to see to it that SQL statements are shared and reduce the number of children of sql statements. In versions prior to 10g the view V$SQL_SHARED_CURSOR would aid in diagnosing why sql statements were not being shared.In 10g there is a new event called CURSORTRACE which aids in the same.

Let us take the following simple sql statement.

SESSION1>> select count(*) from dept;

COUNT(*)
----------
4

SESSION1>> select sql_text, hash_value,address from v$sqlarea where sql_text like 'select count(*) from dept%';

SQL_TEXT HASH_VALUE ADDRESS
----------------------------------- ---------- --------
select count(*) from dept 761178024 19156098

This the first child of the above sql statement with all 'N's

SESSION1>> select * from v$sql_shared_cursor where address = '19156098';

SQL_ID ADDRESS CHILD_AD CHILD_NUMBER U S O O S L S E B P I S T A B D L T
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - -
R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P M F L
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
1jrz3ucqpx9x8 19156098 1CEFB584 0 N N N N N N N N N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N

Now let us open a new session and issue the above sql statement but see to it that the cursor is not shared

SESSION2>>alter session set optimizer_mode='RULE';

Session altered.

SESSION2>>select count(*) from dept;

COUNT(*)
----------
4

Check from Session 1 how many children have been generated
SESSION1>>select * from v$sql_shared_cursor where address = '19156098';

SQL_ID ADDRESS CHILD_AD CHILD_NUMBER U S O O S L S E B P I S T A B D L T
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - -
R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P M F L
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
1jrz3ucqpx9x8 19156098 1CEFB584 0 N N N N N N N N N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N

1jrz3ucqpx9x8 19156098 1BA90164 1 N N N N N N N N N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N Y N N N N

As expected we have one more child caused by the OPTIMIZER_MODE_MISMATCH which we
forced.

SESSION2>>alter session set events 'immediate trace name cursortrace level 612, address 761178024';

==> 761178024 is the hash value of the sql statement.

Session altered.

SESSION2>>select count(*) from dept;

COUNT(*)
----------
4

SESSION2>>alter session set optimizer_mode='FIRST_ROWS_1';

Session altered.

SESSION2>>select count(*) from dept;

COUNT(*)
----------
4

The resultant trace file generated in user_dump_dest will throw more
light into why the sql statement is not shared.

Here is a snippet from the trace file

*************************************************************************
PARSING SQLTEXT=select count(*) from dept
SQLHASH=2d5ea7a8
Checking for already pinned child.
No valid child pinned
Parent 1EA853E8(19156098) ready for search
kksSearchChildList outside while loop
kksCheckCursor: next child is #1
kksCheckCursor: pinning child #1 in shared mode 1eb62650 1ba90164
Compilation environment difference Failed sharing : 0
optimizer_mode = first_rows_1 rule
sqlstat_enabled = false true
SQL pgadep:0 pgapls:0 user
Failed sharing : Compilation environment mismatch
kksUnlockChild: releasing child
*************************************************************************

To use DRM or not to use DRM

2006-11-05T15:41:00.000-08:00

10g Real Application Clusters introduced a concept of resource remastering via Dynamic Resource Mastering (DRM). With DRM a resource can be re-mastered on another node in the cluster if it is found that the cache resource is accessed more frequently from that node.

In 10G R1 this was file based whereas the 10G R2 it is object based.
In 10G R1 due to a few bugs many related to high CPU usage during the DRM freeze window most customers disabled DRM by setting the following parameters
_gc_affinity_time=0
_gc_undo_affinity=FALSE

_gc_affinity_time defines the frequency in minutes to check if remastering
is needed.
_gc_affinity_limit defines the number of times a node must access an object
for it to be a DRM candidate
_gc_affinity_minimum defines the minimum number of times an object is accessed per minute before affinity kicks in

The performance problems may manifest themselves in terms of a DRM related wait event like 'gcs drm freeze in enter server mode'

In 10G R2 this feature appears to be more stable.

You can also manually remaster an object on a different node which
is different from the node on which the object is currrently mastered as shown below

SQL> select object_id,current_master, previous_master ,remaster_cnt from V$GCSPFMASTER_INFO where object_id = 144615

OBJECT_ID CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- -------------- --------------- ------------
144615 0 2 0

The object 144615 is currently mastered on node 0.
To remaster the object onto node 2 connect to node 2 as sysdba

Go to instance 2
NODE2> oradebug setmypid
Statement processed.
NODE2> oradebug lkdebug -m pkey 144615
Statement processed.
NODE2> select object_id,current_master, previous_master ,remaster_cnt from V$GCSPFMASTER_INFO where object_id = 144615

OBJECT_ID CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- -------------- --------------- ------------
144615 2 0 0
Note: In V$GCSPFMASTER_INFO you will also see resources with object ids in the 4Gb range (e.g. 4294950913)
These are for undo segments.

To dissolve remastering of this object on this instance
SQL> oradebug lkdebug -m dpkey 144615
Statement processed.

SQL> select object_id,current_master, previous_master ,remaster_cnt from V$GCSPFMASTER_INFO where object_id = 144615;
no rows selected

The remaster_cnt appears to be 0 for all objects. I have got Oracle
to log bug 5649377 on this issue.

SQL> select distinct remaster_cnt from V$GCSPFMASTER_INFO ;

REMASTER_CNT
------------
0

DRM statistics are available in X$KJDRMAFNSTATS

SQL> select * from X$KJDRMAFNSTATS
2 /

ADDR INDX INST_ID DRMS AVG_DRM_TIME OBJECTS_PER_DRM QUISCE_T FRZ_T CLEANUP_T REPLAY_T FIXWRITE_T SYNC_T
-------- ---------- ---------- ---------- ------------ --------------- ---------- ---------- ---------- ---------- ---------- ----------
RES_CLEANED REPLAY_S REPLAY_R MY_OBJECTS
----------- ---------- ---------- ----------
200089CC 0 1 32 214 1 3 14 0 0 0 99
0 2441 6952 30

The column MY_OBJECTS denotes the number of objects mastered on that node.
This should match with the following

SQL> select count(*) from V$GCSPFMASTER_INFO where current_master=0
2 /

COUNT(*)
----------
30

Recovering a Standby database from a missing archivelog

2006-10-24T21:29:00.000-07:00

A Physical Standby database relies on continuous application of archivelogs from a Primary Database to be in synch with it. In Oracle Database versions prior to 10g in the event of an archivelog gone missing or corrupt you had to rebuild the standby database from scratch.

In 10g you can use an incremental backup and recover the standby using the same to compensate for the missing archivelogs as shown below

In the case below archivelogs with sequence numbers 137 and 138 which are required on the standby are deleted to simulate this problem.

Step 1: On the standby database check the current scn.

STDBY>>select current_scn from v$database;
CURRENT_SCN
-----------
4793543

Step 2: On the primary database create the needed incremental backup from the above SCN

C:\Documents and Settings\frego>rman target /
Recovery Manager: Release 10.2.0.2.0 - Production on Wed Oct 25 13:39:04 2006

Copyright (c) 1982, 2005, Oracle. All rights reserved.

connected to target database: USYD (DBID=768471617)

RMAN> BACKUP DEVICE TYPE DISK INCREMENTAL FROM SCN 4793543 DATABASE
FORMAT 'C:\temp\bkup_%U';

Starting backup at 25/OCT/06
using channel ORA_DISK_1
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
input datafile fno=00001 name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\SYSTEM01.DBF
input datafile fno=00002 name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\UNDOTBS01.DBF
input datafile fno=00003 name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\SYSAUX01.DBF
input datafile fno=00004 name=C:\ORACLE\PRODUCT\10.2.0\ORADATA\USYD\USERS01.DBF
channel ORA_DISK_1: starting piece 1 at 25/OCT/06
channel ORA_DISK_1: finished piece 1 at 25/OCT/06
piece handle=C:\TEMP\BKUP_02I0NSNE_1_1 tag=TAG20061025T134102 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:35
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current control file in backupset
including current SPFILE in backupset
channel ORA_DISK_1: starting piece 1 at 25/OCT/06
channel ORA_DISK_1: finished piece 1 at 25/OCT/06
piece handle=C:\TEMP\BKUP_03I0NSOI_1_1 tag=TAG20061025T134102 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:02
Finished backup at 25/OCT/06

Step 3: Cancel managed recovery at the standby database

STDBY>>recover managed standby database cancel;
Media recovery complete.

Move the backup files to a new folder called INCR_BACKUP so that they are the only files in that folder.

Step 4: Catalog the Incremental Backup Files at the Standby Database

C:\oracle\product\10.2.0\db_1\database>rman target /

Recovery Manager: Release 10.2.0.2.0 - Production on Wed Oct 25 14:54:27 2006

Copyright (c) 1982, 2005, Oracle. All rights reserved.

connected to target database: USYD (DBID=768471617, not open)

RMAN> CATALOG START WITH 'C:\temp\INCR_BACKUP';
searching for all files that match the pattern C:\temp\INCR_BACKUP

List of Files Unknown to the Database
=====================================
File Name: C:\TEMP\INCR_BACKUP\BKUP_02I0NSNE_1_1
File Name: C:\TEMP\INCR_BACKUP\BKUP_03I0NSOI_1_1

Do you really want to catalog the above files (enter YES or NO)? YES
cataloging files...
cataloging done

List of Cataloged Files
=======================
File Name: C:\TEMP\INCR_BACKUP\BKUP_02I0NSNE_1_1
File Name: C:\TEMP\INCR_BACKUP\BKUP_03I0NSOI_1_1

Step 5: Apply the Incremental Backup to the Standby Database

RMAN> RECOVER DATABASE NOREDO;

Starting recover at 25/OCT/06
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=151 devtype=DISK
channel ORA_DISK_1: starting incremental datafile backupset restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
destination for restore of datafile 00001: C:\ORACLE\PRODUCT\10.2.0\ORADATA\STDB
Y\SYSTEM01.DBF
destination for restore of datafile 00002: C:\ORACLE\PRODUCT\10.2.0\ORADATA\STDB
Y\UNDOTBS01.DBF
destination for restore of datafile 00003: C:\ORACLE\PRODUCT\10.2.0\ORADATA\STDB
Y\SYSAUX01.DBF
destination for restore of datafile 00004: C:\ORACLE\PRODUCT\10.2.0\ORADATA\STDB
Y\USERS01.DBF
channel ORA_DISK_1: reading from backup piece C:\TEMP\INCR_BACKUP\BKUP_02I0NSNE_
1_1
channel ORA_DISK_1: restored backup piece 1
piece handle=C:\TEMP\INCR_BACKUP\BKUP_02I0NSNE_1_1 tag=TAG20061025T134102
channel ORA_DISK_1: restore complete, elapsed time: 00:00:03
Finished recover at 25/OCT/06

Step 6: Put the standby database back to managed recovery mode.

STDBY>> recover managed standby database nodelay disconnect;
Media recovery complete.

From the alert.log you will notice that the standby database is still looking for the old log files

*************************************************
FAL[client]: Failed to request gap sequence
GAP - thread 1 sequence 137-137
DBID 768471617 branch 600609988
**************************************************

This is because the controlfile has not been updated.
Hence the standby controlfile has to be recreated

On the primary

PRIM>>alter database create standby controlfile as 'C:\temp\standby01.ctl';
System altered.

Copy the standby control file to the standby site and restart the standby database in managed recovery mode...

Managed Standby Recovery not using Real Time Apply
parallel recovery started with 2 processes
Media Recovery Waiting for thread 1 sequence 139

As you can see from the above output the standby is now looking for the next archivelog.
If you have the luxury of time at your disposal you can do an export of the standby database in read only mode.

Case Study on How to diagnose a node reboot

2006-10-15T21:59:00.000-07:00

The following article looks at how to diagnose a node reboot in a 10G RAC cluster.

Configuration:
2 node RAC on 10.2.0.1 on RH ES 4.0 (kernel 2.6.9-34.0.2.ELsmp)

To diagnose such issues it is very important that you get the timelines of the occurrences of the reboot spot on. It is a recommended practice to have the NTP daemon running on all nodes in the cluster so that the wall clocks of all nodes in the cluster are in sync.

hippo >ps -ef | grep ntp | grep -v 'grep'
ntp 3349 1 0 Oct15 ? 00:00:00 ntpd -u ntp:ntp -p /var/run/ntpd.pid -g

1. Check the Linux log file (/var/log/messages) to determine the time of the reboot

In this case the reboot occurred at 02:09 hours on the node hippo

Oct 12 09:24:34 hippo sshd(pam_unix)[5885]: session opened for user frego by frego (uid=0)
Oct 15 02:09:17 hippo syslogd 1.4.1: restart.
Oct 15 02:09:17 hippo syslog: syslogd startup succeeded
Oct 15 02:09:17 hippo kernel: klogd 1.4.1, log source = /proc/kmsg started.

Check the Linux log file on the other node (elephant) at the same point in time.

Oct 14 17:42:01 elephant su(pam_unix)[18041]: session closed for user root
Oct 15 02:09:12 elephant syslogd 1.4.1: restart.
Oct 15 02:09:12 elephant syslog: syslogd startup succeeded
Oct 15 02:09:12 elephant kernel: klogd 1.4.1, log source = /proc/kmsg started.

From the above output it is clear that both the nodes rebooted at approximately the same time.

2. Check which process is responsible for the reboot.

Review the log file of the CSS daemon. The log file resides in $ORA_CRS_HOME/log/

hippo >pwd
/u00/app/oracle/product/10.2.0/crs/log/hippo

hippo >cd cssd

hippo >pwd
/u00/app/oracle/product/10.2.0/crs/log/hippo/cssd

hippo >ls -ltr
total 9376
drwxr-xr-x 2 oracle dba 4096 Sep 8 18:08 oclsmon
-rw-r----- 1 oracle dba 105 Oct 15 02:02 ocssd.trc
-rw-r--r-- 1 oracle dba 5 Oct 15 02:11 hippo.pid
-rw-r--r-- 1 oracle dba 17 Oct 15 02:11 cssdOUT.log
-rw-r--r-- 1 oracle dba 9567227 Oct 16 15:13 ocssd.log

From the ocssd.log file

[ CSSD]2006-10-15 02:02:48.697 [50609072] >WARNING: clssnmDiskPMT: long disk latency (54990 ms) to voting disk (0//crs/voting.dsk)
[ CSSD]2006-10-15 02:02:50.719 [50609072] >ERROR: clssnmDiskPMT: 1 of 1 voting disks unavailable (0/0/1)
[ CSSD]2006-10-15 02:02:50.734 [50609072] >TRACE: clssscctx: dump of 0x0x810d500, len 3528

Hence the reboot has been caused due to latency issues in accessing the voting disk. The specific function which monitors this is the DiskPing Monitor Thread which monitors the length of a single I/O to the voting disk and marks the voting disk is unavailable. This has caused the CSS daemon to fail.

As seen from the /etc/inittab
h2:35:respawn:/etc/init.d/init.cssd fatal > /dev/null 2>&1 < /dev/null

a failure exit of the CSS daemon causes the machine to reboot.
This indicates the node is rebooted in case of CSS daemon failure.

This is also logged in the alertelephant.log in the $ORA_CRS_HOME/log/ which is the alert.log of the CRS stack.

2006-10-15 02:02:50.740
[cssd(8533)]CRS-1606:CSSD Insufficient voting files available [0 of 1]. Details in /u00/app/oracle/product/10.2.0/crs/log/elephant/cssd/ocssd.log.

Check the ocssd.log file on the other node (elephant) too

[ CSSD]2006-10-15 02:01:40.255 [50617264] >TRACE: clssgmClientConnectMsg: Connect from con(0xb7c3f580) proc(0xb7c67918) pid() proto(10:2:1:1)
[ CSSD]2006-10-15 02:02:50.724 [112925616] >ERROR: clssnmDiskPMT: 1 of 1 voting disks unavailable (0/0/1)
[ CSSD]2006-10-15 02:02:50.777 [112925616] >TRACE: clssscctx: dump of 0x0x810d500, len 3528

There have been a couple of additional CSS related parameters introduced in the 10.2.0.2 patchset to address long I/O requirements of storage vendors such as EMC and NetApp.

• reboottime: (default 3 seconds)
The amount of time allowed for a node to complete a reboot after the CSS daemon has been evicted.
This parameter can be set via the command
crsctl set css reboottime R [-force] (R is seconds)

• disktimeout (default 200 seconds)
The maximum amount of time allowed for a voting file I/O to complete; if this time is exceeded the voting disk will be marked as unavailable
This parameter can be set via the command
crsctl set css disktimeout D [-force] (D is seconds)

These commands must be run as root on a node where the CRSD is up, unless
'-force' is specified, in which case the the CRS stack should not be up on any other node.
After the commands are run all CSS daemons must be restarted for the settings to take effect on all nodes asap.
You can verify the settings by doing an ocrdump and checking the values in the OCRDUMPFILE

Clearing UNKNOWN status of CRS resources

2006-10-03T23:21:00.000-07:00

If you get the following errors whilst starting up nodeapps on a 10G RAC
cluster

bart-> srvctl start nodeapps -n bart
CRS-1028: Dependency analysis failed because of:
CRS-0223: Resource 'ora.bart.gsd' has placement error.
CRS-1028: Dependency analysis failed because of:
CRS-0223: Resource 'ora.bart.ons' has placement error.

Check the status of these resources.

bart-> ./ShowCRS | grep UNK
ora.bart.gsd ONLINE UNKNOWN on bart
ora.bart.ons ONLINE UNKNOWN on bart

To clear the state of the resource you have to use the force option
in the crs_stop command

bart-> crs_stop ora.bart.gsd -f
Attempting to stop `ora.bart.gsd` on member `bart`
Stop of `ora.bart.gsd` on member `bart` succeeded.

bart-> crs_stop ora.bart.ons -f
Attempting to stop `ora.bart.ons` on member `bart`
Stop of `ora.bart.ons` on member `bart` succeeded.

bart-> srvctl start nodeapps -n bart
bart-> ./ShowCRS | grep UNK

bart-> ./ShowCRS | grep bart
ora.bart.gsd ONLINE ONLINE on bart
ora.bart.ons ONLINE ONLINE on bart
ora.bart.vip ONLINE ONLINE on bart

ShowCRS is a shell script which is based on Metalink Note 259301.1

How to find the location of your voting disk

2006-09-06T23:58:00.000-07:00

Below is a quick way to find the location of your voting disk in a 10G RAC cluster

bart-> ocrdump -stdout -keyname SYSTEM.css.diskfile
09/07/2006 16:51:53
ocrdump -stdout -keyname SYSTEM.css.diskfile

[SYSTEM.css.diskfile]
ORATEXT : /crs/voting.dsk
SECURITY : {USER_PERMISSION : PROCR_ALL_ACCESS, GROUP_PERMISSION : PROCR_READ, OTHER_PERMISSION : PROCR_READ, USER_NAME : root, GROUP_NAME : root}

Automatic Shared Memory Management

2006-08-30T21:41:00.000-07:00

Starting with Oracle 10G R1 there is a new parameter sga_target which determines whether you want Oracle to manage the sizes of various pools within the SGA or whether you want to manually manage memory allocated to Oracle.
To use this feature the value of STATISTICS_LEVEL should either be set to TYPICAL or ALL.

But this feature is not without its fair share of issues especially on large and intensive databases.

The reason for this is two fold.
The following bugs exist

4587117 (P) LARGE_POOL_SIZE AND JAVA_POOL_SIZE DO NOT SHRINK IN ASMM Fixed in 11.0
4466399 (U)
4472338 (U)
(duplicate of the above 4466399)
4507532 (U)
(turned out to be a bad diagnosis, but the bug is real)
4920199 (U)

Secondly the default behaviour is that if the shared pool is stressed and requires more memory it is removed from the buffer cache. But the reverse is not true. However this default behaviour can be changed by setting _memory_broker_shrink_heaps=30
The default value for the above parameter is 0

The shrinking of the Java pool depends on the value of _memory_broker_shrink_java_heaps. The default value is 900.

You can set the following event to trace memory management. The MMON process trace file will update statistics related to the different pools every 5 mins.

SQL> alter system set "_memory_management_tracing"=31;

System altered.

The default value for the above parameter is 0

Shrinking segments

2006-08-23T21:33:00.000-07:00

Shrinking of a segment makes unused space available to other segments in the tablespace and may improve the performance of queries and DML operations.

The function VERIFY_SHRINK_CANDIDATE in the DBMS_SPACE is an undocumented function which informs us about the size of the segment upto which we can shrink.

declare
res boolean;
begin
res := dbms_space.verify_shrink_candidate('SCOTT','EMP','TABLE',1032192);
if (res)
then dbms_output.put_line('Can shrink to this size');
end if;
end;
/

Can shrink to this size

PL/SQL procedure successfully completed.

declare
res boolean;
begin
res := dbms_space.verify_shrink_candidate('SCOTT','EMP','TABLE',1032191);
if (res)
then dbms_output.put_line('Can shrink to this size');
end if;
end;
/

PL/SQL procedure successfully completed.

In the above example we can shrink a segment to 1032192 bytes.

OCR backups

2006-07-14T01:15:00.000-07:00

In Oracle 10G Release 1 there is no provision to mirror the Oracle cluster registry (OCR) at the software level. In 10G R2 you can specify a mirror location.

Oracle automatically backs up the OCR every 4 hours. If your Oracle Home is not sitting on a shared mountpoint the backups go to
$ORA_CRS_HOME/cdata on the master node. This presents a single point of failure.

Oracle recommends that the CRS backups are put on shared storage. This can be done using the ocrconfig tool.

The syntax for the same is
ocrconfig -backuploc "dir"

Please note that the above command has to be run as root. If you run the command as the oracle user it does not take effect although the command returns successfully and you will see the following error in the ocrconfig.log file

ocrconfig starts...
Warning!! cluster checking is disabled
Failure in creating key [SYSTEM.OCR.BACKUP.LOC] OCR error [PROC-5: User does not have permission to perform a cluster registry operation on this key.]

Use the ocrconfig -showbackup command to check if the destination has changed

You can also take a logical backup using the export option in the ocrconfig command.
The command needs to be run as root

# ocrconfig -export ocr.tmp -s online

As you can see from the below output there is a difference in size between a backup taken by the export option and the OCR backup which is automatically taken every 4 hours.

/tmp> ls -ltr
-rw-r----- 1 root root 26951680 Aug 26 09:08 backup00.ocr
-rw-r--r-- 1 root other 690062 Aug 26 09:27 ocr.tmp

This is because the export is a logical backup and is to be restored using the import option. The OCR backups which happen every 4 hours are binary block by block
copies of the OCR.

As with all backups the only way to test their integrity is to restore them.

But you can use the following command to check the CRS stack and OCR integrity

bart:TEST1:/tmp/bin> ./cluvfy stage -post crsinst -n all -verbose

Performing post-checks for cluster services setup

Checking node reachability...

Check: Node reachability from node "bart"
Destination Node Reachable?
------------------------------------ ------------------------
homer yes
bart yes
Result: Node reachability check passed from node "bart".

Checking user equivalence...

Check: User equivalence for user "oracle"
Node Name Comment
------------------------------------ ------------------------
homer passed
bart passed
Result: User equivalence check passed for user "oracle".

Checking Cluster manager integrity...

Checking CSS daemon...
Node Name Status
------------------------------------ ------------------------
homer running
bart running
Result: Daemon status check passed for "CSS daemon".

Cluster manager integrity check passed.

Checking cluster integrity...

Node Name
------------------------------------
bart
homer

Cluster integrity check passed

Checking OCR integrity...

Checking the absence of a non-clustered configuration...
All nodes free of non-clustered, local-only configurations.

Checking the version of OCR...
OCR of correct Version "2" exists.

Checking data integrity of OCR...
Data integrity check for OCR passed.

OCR integrity check passed.

Checking CRS integrity...

Checking daemon liveness...

Check: Liveness for "CRS daemon"
Node Name Running
------------------------------------ ------------------------
homer yes
bart yes
Result: Liveness check passed for "CRS daemon".

Checking daemon liveness...

Check: Liveness for "CSS daemon"
Node Name Running
------------------------------------ ------------------------
homer yes
bart yes
Result: Liveness check passed for "CSS daemon".

Checking daemon liveness...

Check: Liveness for "EVM daemon"
Node Name Running
------------------------------------ ------------------------
homer yes
bart yes
Result: Liveness check passed for "EVM daemon".

Liveness of all the daemons
Node Name CRS daemon CSS daemon EVM daemon
------------ ------------------------ ------------------------ ----------
homer yes yes yes
bart yes yes yes

Checking CRS health...

Check: Health of CRS
Node Name CRS OK?
------------------------------------ ------------------------
homer yes
bart yes
Result: CRS health check passed.

CRS integrity check passed.

Post-check for cluster services setup was successful.

bart:TEST1:/tmp/bin> ./cluvfy comp ocr -n all -verbose

Verifying OCR integrity

Checking OCR integrity...

Checking the absence of a non-clustered configuration...
All nodes free of non-clustered, local-only configurations.

Checking the version of OCR...
OCR of correct Version "2" exists.

Checking data integrity of OCR...
Data integrity check for OCR passed.

OCR integrity check passed.

Verification of OCR integrity was successful.

bart:TEST1:/tmp/bin> ocrcheck

Status of Oracle Cluster Registry is as follows :
Version : 2
Total space (kbytes) : 262144
Used space (kbytes) : 16256
Available space (kbytes) : 245888

Cluster registry integrity check succeeded

You can also compare the properties of different nodes in the cluster
using cluvfy comp peer -n all

How to check the category of a Stored Outline

2006-05-26T06:34:00.000-07:00

Stored Outlines is a feature within Oracle which helps preserve Execution Plan Stability.

Unfortunately the parameter use_stored_oulines is not an initialisation parameter and hence cannot be set in the init.ora or spfile.The only way to determine if outlines are being used and their category is by using the oradebug utility.

SQL> oradebug setmypid
Statement processed.

SQL> oradebug dumpvar sga sgauso
qolprm sgauso_ [3C4C708, 3C4C72C) = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 0

The above output indicates that no outlines are being used

SQL> alter system set use_stored_outlines = true;

System altered.

SQL> oradebug dumpvar sga sgauso
qolprm sgauso_ [3C4C708, 3C4C72C) = 00000001 45440007 4C554146 00000054 00000000 00000000 00000000 0

The above output indicates that the stored outlines are being used and the category
is DEFAULT
(Ascii equivalent of 44 45 46 41 55 4C 54)
The 7 here stands for the length of the category.

If you set a value at the session level you need to check the UGA

SQL> alter session set use_stored_outlines = false;

Session altered.

SQL> oradebug dumpvar uga ugauso
qolprm ugauso_p [8EE7A90, 8EE7AB4) = 00000004 00000000 00000000 00000000 00000000 00000000 00000000

SQL> alter session set use_stored_outlines = true;

Session altered.

SQL> oradebug dumpvar uga ugauso
qolprm ugauso_p [8EE7A90, 8EE7AB4) = 00000004 45440007 4C554146 00000054 00000000 00000000 00000000

Block Recovery using RMAN

2006-05-23T21:25:00.000-07:00

BLOCK RECOVERY USING RMAN

The purpose of this article is to simulate a block level corruption and recover from the same using RMAN.
In this situation the datafile remains online throughout the recovery operation and hence other segments within the tablespace remain accessible.

Corrupt a block
Let us take the EMP table and find out the segment header of the same.
SQL> select header_file,header_block from dba_segments where segment_name='EMP';

HEADER_FILE HEADER_BLOCK
----------- ------------
4 24163

We now use the bbed utility to corrupt a block below the segment header which contains the actual data belonging to the EMP table.
In the exercise below we are corrupting the block which belongs to file 4 and block 24165

C:\>bbed parfile=bbed.par
Password:

BBED: Release 2.0.0.0.0 - Limited Production on Sat Feb 19 16:25:09 2005

Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.

************* !!! For Oracle Internal Use only !!! ***************

BBED> set dba 4,10
DBA 0x0100000a (16777226 4,10)

BBED> copy to block 24166

Warning: contents of previous BIFILE will be lost. Proceed? (Y/N) Y
File: E:\ORACLE\ORADATA\TENG\USERS01.DBF (4)
Block: 24166 Offsets: 0 to 511 Dba:0x01005e66
------------------------------------------------------------------------
1e820000 09000001 33280000 00000104 2fe10000 04000000 11002d00 00000000
00000000 00780000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

<32 bytes per line>

SQL> select * from emp;
select * from emp
*
ERROR at line 1:
ORA-01578: ORACLE data block corrupted (file # 4, block # 24165)
ORA-01110: data file 4: 'E:\ORACLE\ORADATA\TENG\USERS01.DBF'

Recover the block

We now run a validate database command which
- Checks datafiles for physical and logical corruption
- Confirms that all database files exist and are in the correct locations

RMAN> run {BACKUP VALIDATE DATABASE;}

Starting backup at 19-FEB-05
using target database controlfile instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=91 devtype=DISK
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
input datafile fno=00004 name=E:\ORACLE\ORADATA\TENG\USERS01.DBF
input datafile fno=00001 name=E:\ORACLE\ORADATA\TENG\SYSTEM01.DBF
input datafile fno=00002 name=E:\ORACLE\ORADATA\TENG\UNDOTBS01.DBF
input datafile fno=00003 name=E:\ORACLE\ORADATA\TENG\SYSAUX01.DBF
channel ORA_DISK_1: backup set complete, elapsed time: 00:01:35
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current controlfile in backupset
including current SPFILE in backupset
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:11
Finished backup at 19-FEB-05

SQL> select * from V$backup_corruption;

RECID STAMP SET_STAMP SET_COUNT PIECE# FILE# BLOCK# BLOCKS CORRUPTION_CHANGE# MAR CO
---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- --------------------------
1 550688483 550688389 46 1 4 24165 1 0 YES CORRUPT

The above output confirms that block 24165 in file 4 is indeed corrupt!
We can recover the same using the following command.

RMAN> run {blockrecover datafile 4 block 24165;}

Starting blockrecover at 19-FEB-05
using channel ORA_DISK_1

channel ORA_DISK_1: restoring block(s)
channel ORA_DISK_1: specifying block(s) to restore from backup set
restoring blocks of datafile 00004
channel ORA_DISK_1: restored block(s) from backup piece 1
piece handle=E:\ORACLE\FLASH_RECOVERY_AREA\TENG\BACKUPSET\2005_02_19\O1_MF_NNNDF_TAG20050219T164615_11FNO9BQ_.BKP tag=TAG20050219T164615
channel ORA_DISK_1: block restore complete

starting media recovery
media recovery complete

Finished blockrecover at 19-FEB-05

SQL> select * from emp;

EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
---------- ---------- --------- ---------- --------- ---------- ---------- ----------
7369 SMITH CLERK 7902 17-DEC-80 800 20
7499 ALLEN SALESMAN 7698 20-FEB-81 1600 300 30
7521 WARD SALESMAN 7698 22-FEB-81 1250 500 30
7566 JONES MANAGER 7839 02-APR-81 2975 20
7654 MARTIN SALESMAN 7698 28-SEP-81 1250 1400 30
7698 BLAKE MANAGER 7839 01-MAY-81 2850 30
7782 CLARK MANAGER 7839 09-JUN-81 2450 10
7788 SCOTT ANALYST 7566 19-APR-87 3000 20
7839 KING PRESIDENT 17-NOV-81 5000 10
7844 TURNER SALESMAN 7698 08-SEP-81 1500 0 30
7876 ADAMS CLERK 7788 23-MAY-87 1100 20
7900 JAMES CLERK 7698 03-DEC-81 950 30
7902 FORD ANALYST 7566 03-DEC-81 3000 20
7934 MILLER CLERK 7782 23-JAN-82 1300 10

14 rows selected.

Migrating an Oracle database from non ASM to ASM

2006-05-23T00:27:00.000-07:00

Migrating an Oracle database from non ASM to ASM is a piece of cake with new functionality available in 10G R2 Database Console.
Details are available in my article on
OTN