Oracle Database Blog: Experiments & Learnings

December 16, 2011

Agent Framework for Managing Third Party applications in 11.2 Clusterware

Filed under: Oracle RDBMS — Tags: , — Saurabh Manroy @ 3:04 pm

The new Agent Framework in 11.2 GI for managing applications is better and simple. However, while reading about it from OTN, it gets a bit complicated with all the new terms that you get introduced to while you are trying to understand the basic architecture. Diagram below is a super simplified explanation of the Agent Framework and may prove handy while you are reading Oracle documentation on this subject:

November 11, 2011

Transpose: Power of PIVOT function in 11g

Filed under: Oracle RDBMS — Saurabh Manroy @ 1:22 pm

This post outlines basic usage of Oracle’s pivot function in sql.

Requirement was to create a list of granted roles that can be exported to Excel sheet. The list would contain One user per record and each column would list few (predefined) roles assigned to user.

First thing that came to mind was decode function, but the way I was using it: listed one record for each role that was granted to a user.  For example, the output looked like:

USERNAME                       RESOURCE        DBA
------------------------------ --------------- ----------
SCOTT                          YES             NO
SCOTT                          NO              YES

Since the requirement is to have one row per user, we needed to transpose the ‘granted_role’ column of dba_role_privs.   For this, Pivot function provided by Oracle (starting 11g)  serves the purpose.  So, using pivot function,  query was changed to something like this:

select * from (
	select username, granted_role
	from dba_role_privs r, dba_users u where
	u.username=r.grantee(+)
	and u.username not in ('SYS','SYSTEM','DBSNMP','ORACLE_OCM','CTXSYS'))
pivot
(
count(granted_role)
for granted_role in ('RESOURCE','DATAPUMP_EXP_FULL_DATABASE','EXP_FULL_DATABASE','DATAPUMP_IMP_FULL_DATABASE','DBA','IMP_FULL_DATABASE')
) order by username;

Output for SCOTT user:

USERNAME    'RESOURCE' 'DATAPUMP_EXP_FULL_DATABASE' 'EXP_FULL_DATABASE' 'DATAPUMP_IMP_FULL_DATABASE' 'DBA' 'IMP_FULL_DATABASE'
----------- ---------- ---------------------------- ------------------- ---------------------------- ----- -------------------
SCOTT                1                            0                   0                    0            1                   0

Only aggregate functions can be used as an argument to Pivot function. That is the reason count(granted_role) was performed. This works perfectly in our case because the count would be either 1 or 0 (always) depending upon if a role is granted or not.

September 28, 2011

One Node in RAC is slow to respond !

Filed under: Oracle RDBMS — Saurabh Manroy @ 9:04 pm

I was about to leave for home when I received a page asking me to join for a performance problem.
a.) Inserts, updates, Drop, truncate,commit were dead slow on one of RAC nodes, while other nodes responded as expected.
b.) Select queries were working fine.

It was pre-production database and was in no-archivelog mode.

I am not able to share the exact numbers and stats because system was behind citrix and copying was not possible due to security reasons.

Following is analysis that I did.

a.) 10046 trace on slow node revealed log file sync wait.
b.) Performed ‘strace’ on LGWR: It was quick enough to post message back to User after a commit operation.

As expected: Doubt was on response of I/O subsystem.

Quick check on storage revealed lot of write latency on one of the disks.

V$IOSTAT_FILE revealed interesting figures for node with slow response time. For FILE_TYPE as ‘log file’ I saw huge numbers against ‘SMALL_WRITE_SERVICETIME’ and ‘LARGE_WRITE_SERVICETIME’ columns. V$logfile was queried to understand the location of logfiles for that thread.  Logfiles for this node were on different diskgroup (DG_DATA) than for rest of the nodes (FG_DATA). This led me to check v$asm_disk:

SQL> select path,write_time from v$asm_disk where group_number=(select group_number from v$asm_diskgroup where name='DG_DATA');

Output was mapped to the one provided by storage team. Bang!

New redolog groups were created for this thread on a different storage array and old redolog groups were dropped. Response time came back to normal.

September 17, 2011

Run DataGuard Observer in Background on Windows

Filed under: Oracle RDBMS — Tags: , , — Saurabh Manroy @ 4:14 pm

As DBAs, some technical decisions are out of our hands. One of such case is when management suggests..hmm…rather decides to monitor the DG configuration from a third site which is good but remote site hosts Microsoft Windows. Because “start observer” command doesn’t return control to the user, a non-trivial question for a DBA is: how would observer run in background on Windows ? On Unix ‘&’ is the magic character to achieve this and when combined with nohup and Screen it does wonders.

Well, if you have a programming background with a bit of hands-on experience with Visual Basic, VC++ or Java, it shouldn’t be tough to make a small program to achieve this goal (something in Visual basic… may be setting WindowSize to zero) or Create a Service that can run a batch file. Batch file would contain commands to run observer.

A service creation tool that is available with Microsoft windows installation is : sc.exe which can be invoked from DOS Command Prompt to create service. But it is not able to read simple “.bat” or “.cmd” files. Its more for executable applications (notepad.exe/calc etc.).  Here is what I tried with sc.exe tool:

c:\> sc.exe create ObserverDG binPath= c:\observer.bat
-- contents of observer.bat
C:\app\product\11.2.0\client_1\bin\dgmgrl -silent sys/Oracle123@orcl "start observer"

Starting the service gives Error:1053

So, even if I was able to create a service this way, service didn’t start.

Another option is to use software which can run batch files in background on Windows.

a.) HSTART software from ntwind –> For commercial Use, a license is needed. Cost is around 20$ per user (as on 17th Sep 2011).

b.) SilentCMD software : FreeWare, No license Needed.

Both Software don’t have any installation files. Simple and easy to use.

DGMGRL> show configuration;

Configuration - DG_SOL

  Protection Mode: MaxAvailability
  Databases:
    ORCL  - Primary database
    STDBY - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS

Logon to the Windows host and create a batch file (.bat) with following contents:

-- contents of observer.bat
C:\app\product\11.2.0\client_1\bin\dgmgrl -silent sys/Oracle123@orcl "start observer"

Next step is to download HSTART or SilentCMD software.

C:\> hostname
SaurabhManroy
-- run hstart with /Noconsole switch
c:\> hstart.exe /NOCONSOLE "c:\observer.bat";
--or Run SilentCMD
C:\SilentCMD_1.0.2> SilentCMD.exe c:\Observer.bat

And we are done. Lets confirm if everything is alright.


DGMGRL> enable fast_start failover
Enabled.
DGMGRL> show configuration

Configuration - DG_SOL

  Protection Mode: MaxAvailability
  Databases:
    ORCL  - Primary database
    STDBY - (*) Physical standby database

Fast-Start Failover: ENABLED

Configuration Status:
SUCCESS

-- On Primary database
SQL> select FS_FAILOVER_STATUS,FS_FAILOVER_CURRENT_TARGET,
  2  FS_FAILOVER_OBSERVER_PRESENT,FS_FAILOVER_OBSERVER_HOST from v$database;

FS_FAILOVER_STATUS     FS_FAILOVER_CURRENT_TARGET     FS_FAIL FS_FAILOVER_OBSERVER_HOST
---------------------- ------------------------------ ------- ----------------------------------------
SYNCHRONIZED           STDBY                          YES     SaurabhManroy

Another option that I have not explored is using Windows Task Scheduler, which can also run batch files.

Edit (20/Sep/2011): Aforementioned third party software work only if session doesn’t log off. These are good only for hiding windows. If using remote desktop connection to server, just close the window of remote desktop rather than logging off. Ask Windows Server administrator to modify settings so that your session never logs off automatically. A dirty workaround !

Some software like Fire Daemon (from Firefox) may suite your needs.  Or a software that can read non-application batch files (like the one we are using) and create a service using those batch files.

Edit (28/Mar/2012):  PSExec  is a useful tool  (have a look at comment from Hans) which allows the batch file to run as a system user. That means, you can log on an log off any number of times and the command would still continue to run.

September 15, 2011

Order by clause and Cost

Filed under: Oracle RDBMS — Tags: , , , , — Saurabh Manroy @ 3:01 pm

This post is a result of tests done for the quiz series posted by Richard Foote on his blog.

Precisely, I create a table with one of its columns defined as not null. I index that column and then run a select query to select all columns and rows in table with an order by clause on indexed column. Optimizer performs a Index Full Scan rather than a Full Table Scan because:

a.) Orderby clause is used for a NOT Null Column. Normal B-Tree indexes don’t store nulls.

b.) Clustering factor is equal to number of blocks in the table.

and finally:

Cost of Full Table Scan (FTS) + Cost of Sorting (Order by clause)  >  (Cost of accessing already sorted data in index sequentially + Table access for each index leaf block access)

Then I tweak the “_smm_min_size” parameter to see what impact it has on query execution path.

SQL> create table bt_test as select rownum id, to_char('level_'||level) lv, sysdate dtime from dual connect by level <=500000;

Table created.

SQL> exec dbms_stats.gather_table_stats(user,'bt_test');

PL/SQL procedure successfully completed.

SQL> alter table bt_test modify id not null;

Table altered.

SQL> create index bt_idx on bt_test(id);

Index created.

SQL> set autot traceonly explain
SQL> select * from bt_test order by id;

Execution Plan
----------------------------------------------------------
Plan hash value: 1838880622

---------------------------------------------------------------------------------------
| Id  | Operation                   | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |   500K|    11M|  3254   (1)| 00:00:40 |
|   1 |  TABLE ACCESS BY INDEX ROWID| BT_TEST |   500K|    11M|  3254   (1)| 00:00:40 |
|   2 |   INDEX FULL SCAN           | BT_IDX  |   500K|       |  1120   (1)| 00:00:14 |
---------------------------------------------------------------------------------------
SQL> select clustering_factor from dba_indexes where index_name='BT_IDX';

CLUSTERING_FACTOR
-----------------
             2129
SQL> select blocks from dba_tables where table_name='BT_TEST';

    BLOCKS
----------
      2129

Note that Clustering factor is one of the major factors while considering Index path access in execution plan of any query.

Lets look at 10053 trace:

ORDER BY sort
    SORT ressource         Sort statistics
      Sort width:         531 Area size:      464896 Max Area size:    93113344
      Degree:               1
      Blocks to Sort: 2327 Row size:     38 Total Rows:         500000
      Initial runs:   2 Merge passes:  1 IO Cost / pass:       1262
      Total IO sort cost: 3589      Total CPU sort cost: 505932425
      Total Temp space used: 18138000

Area Size in the 10053 trace shown above corresponds to “_smm_min_size” for the session This parameter specifies minimum work area size in auto mode. Default value of this parameter is 454K in 11.1
Max Area Size in the trace corresponds to “_smm_max_size” for the session . This parameter specifies (maximum work area size in auto mode. Default value of this parameter is 90931 in 11.1

Optimizer thinks that sort will spill to disk (Temporary Tablespace) and it adds up cost of Disk Sorting as well to the overall cost and that makes (FTS+orderby) an expensive operation. Why have I used the word thinks because, “_smm_max_size” is already set to 90M (default) and for a small sized table (bt_test), 90M should be more than enough to perform the sort.

Lets pre-allocate some memory to work areas.

SQL> alter session set "_smm_min_size"=20000;

Session altered.

SQL> set autot traceonly explain
SQL> select * from bt_test order by id;

Execution Plan
----------------------------------------------------------
Plan hash value: 2233975280

------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 500K| 11M| 603 (5)| 00:00:08 |
| 1 | SORT ORDER BY | | 500K| 11M| 603 (5)| 00:00:08 |
| 2 | TABLE ACCESS FULL| BT_TEST | 500K| 11M| 583 (1)| 00:00:07 |
------------------------------------------------------------------------------
10053 Trace:
ORDER BY sort
 SORT ressource Sort statistics
 Sort width: 531 Area size: 20480000 Max Area size: 93113344
 Degree: 1
 Blocks to Sort: 2327 Row size: 38 Total Rows: 500000
 Initial runs: 1 Merge passes: 0 IO Cost / pass: 0
 Total IO sort cost: 0 Total CPU sort cost: 448627723
 Total Temp space used: 0

Trace file confirms that Area size is set to 20M. This makes optimizer think that complete sorting would finish in memory. Temp Space usage has changed to zero. I/O cost for sorting has reduced to zero which makes FTS + Sort a better option compared to Index full Scan.

August 29, 2011

11gR2 ASM password File in RAC

Filed under: Oracle RDBMS — Saurabh Manroy @ 11:15 pm

Pre 11gR2, each node in the cluster had ASM password file named as orapw<SID> .Starting 11gR2, password file in a RAC cluster is named using the format orapw<+’_asmsid’> .  “_asmsid” is an underscore parameter that defines default SID/Name of ASM instance.

If there are two nodes with +ASM1 running on node 1 and +ASM2 running on node2.

 -- Pre 11gR2 --
Password file on Node1: orapw+ASM1
Password file on Node2: orapw+ASM2
 -- 11gR2 --
Password file on Node1: orapw+ASM
Password file on Node2: orapw+ASM

So on 11gR2, when password is changed for a privileged user on ASM instance of one node in a cluster, it is immediately reflected on all other nodes in the cluster.  But who does it ?  Here is a simple test:

[oracle@node1 ~]$ sqlplus / as sysasm

SQL*Plus: Release 11.2.0.1.0 Production on Mon Aug 29 22:25:44 2011

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

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Real Application Clusters and Automatic Storage Management options

SQL> select * from v$pwfile_users;

USERNAME                       SYSDB SYSOP SYSAS
------------------------------ ----- ----- -----
SYS                            TRUE  TRUE  TRUE
ASMSNMP                        TRUE  FALSE FALSE

On Node2, lets check who is accessing the file

[root@node2 ~]# while true; do lsof | grep orapw+ASM; done
-- No Output so far--
-- lsof command means: lists open file descriptors.
-- This script will list processes which are currently accessing the file orapw+ASM on node 2

Lets change password on ASM instance on Node 1 and check the output of shell script on Node2

SQL> alter user sys identified by ********;

User altered.

-- On Node 2 --
[root@node2 ~]# while true; do lsof | grep orapw+ASM; done
oracle    4863    oracle   22u      REG       8,16      1536     198556 /u02/app/11.2.0/grid/dbs/orapw+ASM

[root@node2 ~]# ps -ef |grep 4863
oracle    4863     1  0 22:22 ?        00:00:00 asm_ckpt_+ASM2

Another check that can be performed is:

On one of the nodes, suspend the ASM CKPT process.  Then try to execute a password change command (on ASM) from any other node in the cluster and it would hang.

August 12, 2011

11gR2 Physical Standby Setup : Primary Database 2 Node RAC and Standalone Standby Database

The following demonstration is a step by step procedure to create a hybrid Disaster Recovery environment :  Primary database is 2 node RAC and Standby database is Standalone. This procedure gives a general idea and there are some steps that can be optimized.

Environment

Primary Database 2 Node RAC

Node Names: node1, node2
DB Name: ORCL
DB Unique Name: ORCL
DB Version: 11.2.0.1
Grid Infrastructure (CRS + ASM).
SCAN settings in /etc/hosts file, so SCAN listener only running on one node (Node2 for this demo)
ASM Diskgroups: +DATA, +FRA

Standby Database Single Instance:

ASM Diskgroup : +DG_DATA   (For datafiles  and FRA)
DB Unique Name: STDBY
DB Name: ORCL

Preparations at the Primary Site

GI_HOME=/u02/app/oracle/11.2.0/grid

ORACLE_HOME=/u02/app/oracle/product/11.1.0/db_1

Ensure force logging is enabled. Then following steps are needed:

a.) Dedicated Listener for duplication on Primary Site

b.) Prepare initialization Parameters

c.) Add Standby redo logs.

Why Dedicated listener for Duplicate database command ?

When duplicate database command is issued from RMAN, it copies the password file from Primary database host to Standby database host.  If this operation is performed from remote client (with tnsnames.ora having SCAN name), it would cause issues when password file gets copied from the Primary host to Standby host. This is because SCAN directs connection to a node based on load.  Here is the error:

RMAN>  duplicate target database for standby from active database;

Starting Duplicate Db at 12-AUG-11
using target database control file instead of recovery catalog
allocated channel: ORA_AUX_DISK_1
channel ORA_AUX_DISK_1: SID=26 device type=DISK

contents of Memory Script:
{
   backup as copy reuse
   targetfile  '/u02/app/oracle/product/11.1.0/db_1/dbs/orapwORCL1' auxiliary format
 '/u02/app/oracle/product/11.1.0/db_1/dbs/orapwSTDBY'   ;
}
executing Memory Script

Starting backup at 12-AUG-11
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=33 instance=ORCL2 device type=DISK
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of Duplicate Db command at 08/12/2011 14:38:59
RMAN-03015: error occurred in stored script Memory Script
RMAN-03009: failure of backup command on ORA_DISK_1 channel at 08/12/2011 14:38:59
ORA-19505: failed to identify file "/u02/app/oracle/product/11.1.0/db_1/dbs/orapwORCL1"
ORA-27037: unable to obtain file status
Linux Error: 2: No such file or directory
Additional information: 3

To Avoid this, create a dedicated Listener on a source node [node1] for this operation.

Here are the Settings from both nodes:

Node 1

</span>
<pre>[root@node1 bin]# ./srvctl config scan_listener
SCAN Listener LISTENER_SCAN1 exists. Port: TCP:1530
[root@node1 bin]# ./srvctl config scan
SCAN name: cluster1, Network: 1/192.168.10.0/255.255.255.0/
SCAN VIP name: scan1, IP: /cluster1.home.com/192.168.10.30

SQL> show parameter listener

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
listener_networks                    string
local_listener                       string      (DESCRIPTION=(ADDRESS_LIST=(AD
                                                 DRESS=(PROTOCOL=TCP)(HOST=192.
                                                 168.10.9)(PORT=1521))))
remote_listener                      string      cluster1.home.com:1530

[oracle@node1 admin]$ ps -ef |grep tns
oracle    7072     1  0 10:19 ?        00:00:00 /u02/app/11.2.0/grid/bin/tnslsnr LISTENER -inherit
oracle   12670  8486  0 10:51 pts/1    00:00:00 grep tns
[oracle@node1 admin]$ lsnrctl status listener

LSNRCTL for Linux: Version 11.2.0.1.0 - Production on 12-AUG-2011 10:52:04

Copyright (c) 1991, 2009, Oracle.  All rights reserved.

Connecting to (ADDRESS=(PROTOCOL=tcp)(HOST=)(PORT=1521))
STATUS of the LISTENER
------------------------
Alias                     LISTENER
Version                   TNSLSNR for Linux: Version 11.2.0.1.0 - Production
Start Date                12-AUG-2011 10:19:01
Uptime                    0 days 0 hr. 33 min. 3 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /u02/app/11.2.0/grid/network/admin/listener.ora
Listener Log File         /u02/app/oracle/diag/tnslsnr/node1/listener/alert/log.xml
Listening Endpoints Summary...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=LISTENER)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=192.168.10.2)(PORT=1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=192.168.10.8)(PORT=1521)))
Services Summary...
Service "+ASM" has 1 instance(s).
  Instance "+ASM1", status READY, has 1 handler(s) for this service...
Service "ORCL" has 1 instance(s).
  Instance "ORCL1", status READY, has 1 handler(s) for this service...
The command completed successfully

Node 2

[oracle@node2 ~]$ ps -ef |grep tns
oracle    5401     1  0 10:18 ?        00:00:00 /u02/app/11.2.0/grid/bin/tnslsnr LISTENER -inherit
oracle    5403     1  0 10:18 ?        00:00:00 /u02/app/11.2.0/grid/bin/tnslsnr LISTENER_SCAN1 -inherit
oracle    7684  7135  0 10:52 pts/1    00:00:00 grep tns
Local Listener: on port 1521
SCAN Listener: on port 1530

With SCAN listener in place, client’s tnsnames.ora file looks like:

orcl=
        (description=
                (address=(port=1530)(host=cluster1.home.com)(protocol=tcp))
        (connect_data=
        (service_name=ORCL))
        )

As mentioned above, duplicate database command fails in case the command is issued from a client with tnsnames.ora file entry as above.  To workaround this, create a dedicated Listener on a source node [node1] for this operation. Lets configure ORCL1 that runs from DB_HOME.

[oracle@node1 admin]$ lsnrctl start ORCL1

LSNRCTL for Linux: Version 11.2.0.1.0 - Production on 12-AUG-2011 14:47:54

Copyright (c) 1991, 2009, Oracle.  All rights reserved.

Starting /u02/app/oracle/product/11.1.0/db_1/bin/tnslsnr: please wait...

TNSLSNR for Linux: Version 11.2.0.1.0 - Production
System parameter file is /u02/app/oracle/product/11.1.0/db_1/network/admin/listener.ora
Log messages written to /u02/app/oracle/product/11.1.0/db_1/log/diag/tnslsnr/node1/orcl1/alert/log.xml
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=node1.home.com)(PORT=1523)))

So, the remote client’s tnsnames.ora file would look like:

orcl=
        (description=
                (address=(port=1530)(host=cluster1.home.com)(protocol=tcp))
        (connect_data=
        (service_name=ORCL))
        )

STDBY=
        (description=
                (address=(port=1522)(host=node1.home.com)(protocol=tcp))
        (connect_data=
        (service_name=STDBY))
        )
ORCL1=
        (description=
                (address=(port=1523)(host=node1.home.com)(protocol=tcp))
        (connect_data=
        (service_name=ORCL1))
        )

Initialization Parameters On Primary

Set Archiving Destinations and defer 2nd destination for the time being to avoid any errors.

SQL> alter system set log_archive_dest_1='LOCATION=+FRA valid_for=(ALL_LOGFILES,ALL_ROLES) db_unique_name=ORCL';

System altered.
SQL> alter system set
2 log_archive_dest_2='service=stdby lgwr sync Valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=STDBY';

System altered.
SQL> alter system set log_archive_dest_state_2=defer;

System altered.
SQL> alter system set standby_file_management=auto;

System altered.

Add Standby Redo Logs on the Primary

SQL> alter database add standby logfile thread 1 '+FRA';

Database altered.

SQL> alter database add standby logfile thread 1 '+FRA';

Database altered.

SQL> alter database add standby logfile thread 2 '+FRA';

Database altered.

SQL> alter database add standby logfile thread 2 '+FRA';

Database altered.

Preparations at the Standby Site

a.) Configure Listener

b.) Initialization parameters

Listener for Standby database has to be configured.  For this Demo, following has been configured:

[oracle@node1 admin]$ cat listener.ora
STDBY=
        (description=
                (address=(protocol=tcp)(host=node1.home.com)(port=1522))
        )
SID_LIST_STDBY=
        (SID_LIST=
        (SID_DESC=
        (SID_NAME=STDBY)
        (ORACLE_HOME=/u02/app/oracle/product/11.1.0/db_1))
        )

Initialization Parameters On Standby

db_name=ORCL
db_unique_name=STDBY
cluster_database=false
fal_server=orcl
fal_client=stdby
log_archive_dest_1='location=+DG_DATA valid_for=(ALL_LOGFILES,ALL_ROLES) DB_UNIQUE_NAME=STDBY'
log_archive_dest_2='service=orcl valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) DB_UNIQUE_NAME=ORCL'
compatible='11.1.0.0.0'
db_create_file_dest='+DG_DATA'
db_create_online_log_dest_1='+DG_DATA'

Since OMF is in use, we just Specify DB_CREATE_FILE_DEST and DB_CREATE_ONLINE_LOG_DEST_n parameters.  There is no need to specify DB_FILE_NAME_CONVERT and LOG_FILE_NAME_CONVERT parameters. Also note that COMPATIBLE parameter has to be set explicitly in order to avoid errors during Duplicate database command.

Duplication

a.) Copy password file from primary host to Standby host and then rename it on standby host. This is just to ensure that duplication can work from a remote client. Otherwise, password file is copied as a part of duplication process.

$ scp orapwORCL1  node1:$ORACLE_HOME/dbs

$ mv orapwORCL1 orapwSTDBY

Beware:  If you are explicitly creating password file on standby site, it would give errors while shipping the logs. Only copying of password file would work.

Run the duplicate command:

</span>
<pre>[oracle@node1 dbs]$ rman target sys/Oracle123@orcl1 auxiliary sys/Oracle123@stdby

Recovery Manager: Release 11.2.0.1.0 - Production on Fri Aug 12 15:29:11 2011

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCL (DBID=1286546160)
connected to auxiliary database: ORCL (not mounted)

RMAN> duplicate target database for standby from active database;

Starting Duplicate Db at 12-AUG-11
using target database control file instead of recovery catalog
allocated channel: ORA_AUX_DISK_1
channel ORA_AUX_DISK_1: SID=25 device type=DISK

contents of Memory Script:
{
   backup as copy reuse
   targetfile  '/u02/app/oracle/product/11.1.0/db_1/dbs/orapwORCL1' auxiliary format
 '/u02/app/oracle/product/11.1.0/db_1/dbs/orapwSTDBY'   ;
}
executing Memory Script

Starting backup at 12-AUG-11
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=34 instance=ORCL1 device type=DISK
Finished backup at 12-AUG-11

contents of Memory Script:
{
   backup as copy current controlfile for standby auxiliary format  '+DG_DATA/stdby/controlfile/current.256.758993371';
   sql clone "create spfile from memory";
   shutdown clone immediate;
   startup clone nomount;
   sql clone "alter system set  control_files = ''+DG_DATA/stdby/controlfile/current.256.758993371'' comment=
                                                ''Set by RMAN'' scope=spfile";
   shutdown clone immediate;
   startup clone nomount;
}
executing Memory Script

Starting backup at 12-AUG-11
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile copy
copying standby control file
output file name=/u02/app/oracle/product/11.1.0/db_1/dbs/snapcf_ORCL1.f tag=TAG20110812T152936 RECID=6 STAMP=758993377
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:04
Finished backup at 12-AUG-11

sql statement: create spfile from memory

Oracle instance shut down

connected to auxiliary database (not started)
Oracle instance started

Total System Global Area     146472960 bytes

Fixed Size                     1335080 bytes
Variable Size                 92274904 bytes
Database Buffers              50331648 bytes
Redo Buffers                   2531328 bytes

sql statement: alter system set  control_files =   ''+DG_DATA/stdby/controlfile/current.256.758993371''
comment= ''Set by RMAN'' scope=spfile

Oracle instance shut down

connected to auxiliary database (not started)
Oracle instance started

Total System Global Area     146472960 bytes

Fixed Size                     1335080 bytes
Variable Size                 92274904 bytes
Database Buffers              50331648 bytes
Redo Buffers                   2531328 bytes

contents of Memory Script:
{
   sql clone 'alter database mount standby database';
}
executing Memory Script

sql statement: alter database mount standby database

contents of Memory Script:
{
   set newname for clone tempfile  1 to new;
   switch clone tempfile all;
   set newname for clone datafile  1 to new;
   set newname for clone datafile  2 to new;
   set newname for clone datafile  3 to new;
   set newname for clone datafile  4 to new;
   backup as copy reuse
   datafile  1 auxiliary format new
   datafile  2 auxiliary format new
   datafile  3 auxiliary format new
   datafile  4 auxiliary format new
   ;
   sql 'alter system archive log current';
}
executing Memory Script

executing command: SET NEWNAME

renamed tempfile 1 to +DG_DATA in control file

executing command: SET NEWNAME

executing command: SET NEWNAME

executing command: SET NEWNAME

executing command: SET NEWNAME

Starting backup at 12-AUG-11
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile copy
input datafile file number=00001 name=+DATA/orcl/datafile/system.256.758765445
output file name=+DG_DATA/stdby/datafile/system.257.758993419 tag=TAG20110812T153017
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:01:26
channel ORA_DISK_1: starting datafile copy
input datafile file number=00002 name=+DATA/orcl/datafile/sysaux.284.758765459
output file name=+DG_DATA/stdby/datafile/sysaux.258.758993507 tag=TAG20110812T153017
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:01:15
channel ORA_DISK_1: starting datafile copy
input datafile file number=00003 name=+DATA/orcl/datafile/undotbs1.285.758765475
output file name=+DG_DATA/stdby/datafile/undotbs1.259.758993583 tag=TAG20110812T153017
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:15
channel ORA_DISK_1: starting datafile copy
input datafile file number=00004 name=+DATA/orcl/datafile/undotbs2.287.758768259
output file name=+DG_DATA/stdby/datafile/undotbs2.260.758993599 tag=TAG20110812T153017
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:03
Finished backup at 12-AUG-11

sql statement: alter system archive log current

contents of Memory Script:
{
   switch clone datafile all;
}
executing Memory Script

datafile 1 switched to datafile copy
input datafile copy RECID=6 STAMP=758993609 file name=+DG_DATA/stdby/datafile/system.257.758993419
datafile 2 switched to datafile copy
input datafile copy RECID=7 STAMP=758993609 file name=+DG_DATA/stdby/datafile/sysaux.258.758993507
datafile 3 switched to datafile copy
input datafile copy RECID=8 STAMP=758993609 file name=+DG_DATA/stdby/datafile/undotbs1.259.758993583
datafile 4 switched to datafile copy
input datafile copy RECID=9 STAMP=758993609 file name=+DG_DATA/stdby/datafile/undotbs2.260.758993599
Finished Duplicate Db at 12-AUG-11

Now enable the managed recovery on Standby host:

SQL> recover managed standby database disconnect from session;
 Media recovery complete.

And we are done. Few checks done to check the setup:

On Primary Site:

SQL> -- edited later to get output from GV$ view

SQL> select INST_ID,DEST_NAME,STATUS,RECOVERY_MODE,ARCHIVED_THREAD#,ARCHIVED_SEQ#,APPLIED_THREAD#,APPLIED_SEQ#,DB_UNIQUE_NAME
  2  from GV$ARCHIVE_DEST_STATUS
  3  where DEST_NAME in ('LOG_ARCHIVE_DEST_2');

INST_ID DEST_NAME            STATUS    RECOVERY ARCHIVED_THREAD# ARCHIVED_SEQ# APPLIED_THREAD# APPLIED_SEQ# DB_UNIQUE
------- -------------------- --------- -------- ---------------- ------------- --------------- ------------ ---------
   1    LOG_ARCHIVE_DEST_2   VALID     MANAGED                 1            25               2           24 STDBY
   2    LOG_ARCHIVE_DEST_2   VALID     MANAGED                 1            25               2           24 STDBY

On the Standby Site:

SQL>  select thread#,sequence#,applied from v$archived_log order by sequence#;

   THREAD#  SEQUENCE# APPLIED
---------- ---------- ---------
         2          7 YES
         2          8 YES
         2          9 YES
         2         10 YES
         2         11 YES
         2         12 YES
         2         13 YES
         2         14 YES
         2         15 YES
         2         16 YES
         1         20 YES
         1         21 YES
         1         22 YES
         1         23 YES
         1         24 YES
...
SQL> -- Output cut short for readability.

August 5, 2011

Flashback Data Archive

Filed under: Oracle RDBMS — Saurabh Manroy @ 2:02 pm

In a wonderful post from Laurent , he has demonstrated how shutdown abort may prove harmful. To summarize:  he creates flashback data archive and assigns it to a table.  Inserts few values in the table , followed by commit and shutdown abort.  After bringing up the database, he creates a a new undo tablespace (undo2) and tells database to use new tablespace, followed by clean shutdown and startup. After this, old undo tablespace can’t be dropped as it has active transactions in it . I tried the same test case and received similar results:

 
 
SQL> drop tablespace undotbs1 ;
drop tablespace undotbs1
*
ERROR at line 1:
ORA-01548: active rollback segment '_SYSSMU9_1312457103$' found, terminate
dropping tablespace

 
I thought of doing some more experiments.

Lets dump the undo header of the problematic undo segment and surprisingly: No Active Transactions found. Here is the transaction table:

For readability, only relevant portions are shown

 
TRN TBL::

  index  state cflags  wrap#    uel         scn            dba            parent-xid    nub     stmt_num    cmt
  ------------------------------------------------------------------------------------------------
   0x00    9    0x00  0x05f6  0x0001  0x0000.00451063  0x00c0010a  0x0000.000.00000000  0x00000001   0x00000000  1312478443
   0x01    9    0x00  0x05f6  0x0002  0x0000.0045106d  0x00c0010a  0x0000.000.00000000  0x00000001   0x00000000  1312478443
   ....
   0x1c    9    0x00  0x05f6  0x001d  0x0000.00451628  0x00c0010c  0x0000.000.00000000  0x00000001   0x00000000  1312480283
   0x1d    9    0x00  0x05f6  0x001e  0x0000.00451693  0x00c0010c  0x0000.000.00000000  0x00000001   0x00000000  1312480585
   0x1e    9    0x00  0x05f6  0x0020  0x0000.004516a3  0x00c0010c  0x0000.000.00000000  0x00000001   0x00000000  1312480585
   0x1f    9    0x00  0x05f6  0x0001  0x0000.004516d6  0x00c0010c  0x0000.000.00000000  0x00000001   0x00000000  1312480616
   0x20    9    0x00  0x05f6  0x0021  0x0000.00456600  0x00000000  0x0000.000.00000000  0x00000000   0x00000000  1312480634
   0x21    9    0x00  0x05f6  0xffff  0x0000.0045660b  0x00c0010d  0x0000.000.00000000  0x00000001   0x00000000  1312480636

 
Further look at the EXT (ended) Transaction table:

 
 
  EXT TRN TBL::
  index  extflag    extHash    extSpare1   extSpare2
  ---------------------------------------------------
   0x00  0x00000000 0x00000000 0x00000000  0x00000000
   0x01  0x00000000 0x00000000 0x00000000  0x00000000
   ....
   0x1c  0x00000000 0x00000000 0x00000000  0x00000000
   0x1d  0x00000000 0x00000000 0x00000000  0x00000000
   0x1e  0x00000000 0x00000000 0x00000000  0x00000000
   0x1f  0x00008c00 0x00000000 0x00000000  0x00000000
   0x20  0x00000000 0x00000000 0x00000000  0x00000000
   0x21  0x00000000 0x00000000 0x00000000  0x00000000

Every slot except 0x1f showed something interesting.Though not sure what is extflag pointing to. Going back to the Transaction table and to the same slot shows undo block address.  
 

 
SQL> select dbms_utility.DATA_BLOCK_ADDRESS_FILE(12583180) as FILE#,
  2  dbms_utility.DATA_BLOCK_ADDRESS_BLOCK(12583180) as BLOCK from dual;
     FILE#      BLOCK
---------- ----------
         3        268
SQL> alter system dump datafile 3 block 268;
System altered.

 
This is how the undo block looks like. 

 
 
UNDO BLK: 
xid: 0x0009.01f.000005f6  seq: 0x2da cnt: 0x14  irb: 0x14  icl: 0x0   flg: 0x0002

 Rec Offset      Rec Offset      Rec Offset      Rec Offset      Rec Offset
---------------------------------------------------------------------------
0x01 0x1f3c     0x02 0x1ec4     0x03 0x1e5c     0x04 0x1df4     0x05 0x1d48    
0x06 0x1ce0     0x07 0x1c34     0x08 0x1b88     0x09 0x1adc     0x0a 0x1a74    
0x0b 0x1a0c     0x0c 0x1964     0x0d 0x18bc     0x0e 0x1814     0x0f 0x176c    
0x10 0x16c8     0x11 0x163c     0x12 0x15ec     0x13 0x1544     0x14 0x14d8    
 

“In case”,  this was an undo block that contained an active transaction, to go through the undo chain, we consult irb value which is 0x14. This gives the first block from where the undo chain starts.   So, lets search through the block for Rec# 0x14.

 
 
*-----------------------------
* Rec #0x14  slt: 0x1f  objn: 74023(0x00012127)  objd: 74023  tblspc: 0(0x00000000)
*       Layer:  11 (Row)   opc: 1   rci 0x00  
Undo type:  Regular undo    Begin trans    Last buffer split:  No
Temp Object:  No
Tablespace Undo:  No
rdba: 0x00000000Ext idx: 0
flg2: 4
*-----------------------------
uba: 0x00c0010c.02da.13 ctl max scn: 0x0000.004492a3 prv tx scn: 0x0000.00450ffc
txn start scn: scn: 0x0000.004516d6 logon user: 0
 prev brb: 12583178 prev bcl: 0
KDO undo record:
KTB Redo
op: 0x03  ver: 0x01 
compat bit: 4 (post-11) padding: 0
op: Z
KDO Op code: DRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x00416362  hdba: 0x00416361
itli: 1  ispac: 0  maxfr: 4863
tabn: 0 slot: 0(0x0) 
.
SQL> select object_name from dba_objects where object_id=74023;
OBJECT_NAME
-------------------------------
TEST_TAB
 

Lets look at the flashback archive segments that got created when Flashback Archive (FLA_ARCH) was enabled for this object.

 
 
SQL>  select segment_name from dba_segments where tablespace_name='TEST_TS' and
  2  segment_name like '%74023';

SEGMENT_NAME
--------------------------------------------------------------------------------
SYS_FBA_TCRV_IDX_74023
SYS_FBA_TCRV_74023
SYS_FBA_HIST_74023
SYS_FBA_DDL_COLMAP_74023

 
SYS_FBA_TCRV_% table holds start SCN for every transaction done on the table.

 
 
SQL> select startscn from SYS_FBA_TCRV_74023 order by 1;

  STARTSCN
----------
   4527830
   4552384
   4552433
   4552433
   4552433
   4552433
6 rows selected.

  
Compare the Start SCN reported with TXN start SCN mentioned in the Rec# 0x14 of undo block dump. txn start scn: scn: 0x0000.004516d6. Converting this to Decimal gives same SCN 4527830. So, its likely that this transaction actually caused issues.  Now, lets bring the old undo tablespace online and then restart the database.

 
 
SQL> alter system set undo_tablespace=undotbs1;
System altered

SQL> shutdown immediate
Database closed.
Database dismounted.
ORACLE instance shut down.

SQL> startup
ORACLE instance started.
Total System Global Area  535662592 bytes
Fixed Size                  1348508 bytes
Variable Size             289410148 bytes
Database Buffers          222298112 bytes
Redo Buffers               22605824 bytes
Database mounted.
Database opened.
SQL> select segment_name from dba_undo_extents where tablespace_name='UNDOTBS1' and status='ACTIVE';
no rows selected

  
Dumping the same undo header clears the extflags in the transaction table. So, it can be concluded that there was no undo/block corruption but some pending cleanup actions in the old undo tablespace (due to Shutdown abort). Thats why the transaction table earlier didn’t report any Active Transactions in the undo header dump.

July 26, 2011

Other Options !

Filed under: Oracle RDBMS — Tags: , , , , , — Saurabh Manroy @ 9:50 am

In my last  post, I demonstrated how stored outlines ditched me. Then I started looking out for other options like SQL profiles and dbms_advanced_rewrite package.

a.) SQL Profiles

Tuning task was created using AWR snapshots. Endpoints of snapshot were chosen from the time interval when query wasn’t performing as expected.

DECLARE
 l_sql_tune_task_id  VARCHAR2(100);
BEGIN
 l_sql_tune_task_id := DBMS_SQLTUNE.create_tuning_task (
                         begin_snap  => 12956,
                         end_snap    => 12959,
                         sql_id      => '8pg71n7580t88',
                         scope       => DBMS_SQLTUNE.scope_comprehensive,
                         time_limit  => 60,
                         task_name   => '8pg71n7580t88_tuning_task',
                         description => 'Tuning task for statement 8pg71n7580t88 in AWR.');
 DBMS_OUTPUT.put_line('l_sql_tune_task_id: ' || l_sql_tune_task_id);
END;
/
EXEC DBMS_SQLTUNE.execute_tuning_task(task_name => '8pg71n7580t88_tuning_task');

SELECT DBMS_SQLTUNE.report_tuning_task('8pg71n7580t88_tuning_task') AS recommendations FROM dual;

 

 

Recommendation from SQL profile was to restructure the SQL statement which was not a possibility.  So, I moved to next option.

b.) DBMS_ADVANCED_REWRITE

While doing tests, I found that hinting the query with proper index worked and the query ran like a trace of bullet. So, without changing the application code, I thought of trying this option. Then  the same multibyte characterset  glitch : With multibyte characterset, this package didn’t work as expected. I google*d it and found couple of posts reporting same erratic  behavior with UTF8 characterset. So, using dbms_advanced_rewrite package to fix the plan was ruled out.

Further actions

There were two indexes on one of the tables (FILL). One was local index based on 6 columns  (PK_FILL)  and another was a Global index based on just 1 column (IND_FILL_ACCTFILL).  When query performed suboptimally, it used  PK_FILL index to perform a range scan. This used to cause lots of buffer gets and hence delay in processing.

Areas of Concern in the execution plan:

Good Plan

|   5 |      PARTITION RANGE ITERATOR          |                   |     8 |   720 |   179   (0)| 00:00:03 |   KEY |   KEY |
|   6 |       TABLE ACCESS BY LOCAL INDEX ROWID| FILLITEM          |     8 |   720 |   179   (0)| 00:00:03 |   KEY |   KEY |
|   7 |        INDEX RANGE SCAN                | INX_FILLITEM_ACCT |   168 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|   8 |      TABLE ACCESS BY GLOBAL INDEX ROWID| FILL              |     3 |   102 |     6   (0)| 00:00:01 | ROW L | ROW L |
|   9 |       INDEX RANGE SCAN                 | IND_FILL_ACCTFILL |     3 |       |     3   (0)| 00:00:01 |       |       |

Bad Plan

|   5 |      PARTITION RANGE ITERATOR          |                   |    12 |  1080 |   175   (0)| 00:00:03 |   KEY |   KEY |
|*  6 |       TABLE ACCESS BY LOCAL INDEX ROWID| FILLITEM          |    12 |  1080 |   175   (0)| 00:00:03 |   KEY |   KEY |
|*  7 |        INDEX RANGE SCAN                | INX_FILLITEM_ACCT |   159 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|   8 |      PARTITION RANGE ITERATOR          |                   |     1 |    34 |     3   (0)| 00:00:01 |   KEY |   KEY |
|*  9 |       INDEX RANGE SCAN                 | PK_FILL           |     1 |    34 |     3   (0)| 00:00:01 |   KEY |   KEY |

 
Base tables involved in the query were partitioned tables (partitioned month wise). Due to size of the partition, only 20% of table’s data was sampled for analysis. There were lots of inserts happening on these tables every second. So, keeping statistics upto date was another challenge (may be that was the reason, plan got changed everyday). During the night when activity on the database was negligible, I planned to have a closer look at the data distribution in table partition that was having data from last month (May).  I executed multiple queries on the table partition to understand the data distribution and then collected statistics using dbms_stats on this old partition from month of May (with estimate_percent => 100, cascade => true) and created histograms only for columns that actually needed them. Using this new data distribution, the query responded as expected.  I also checked the total amount of data that every partition had for last couple of months. Every month partition reported around 29 to 30 million rows. So, an immediate thought was to copy statistics from old partition (on which 100% data was sampled) to present and future partitions. This would help in making sure that optimizer has same statistics throughout the month (From 1st to 31st).

Similar activity was performed for FILLITEM table.

For Local Indexes like PK_FILL following was performed:

a.)  dbms_stats.set_index_stats was used to update statistics of current month and future months and stats were locked. Statistics Source: from the partition of May.

b.) Stats were also gathered without any partition information. dbms_stats.gather_index_stats (indname=> PK_FILL, partname=> null);

July 22, 2011

Stored Outlines Weird Behaviour

Filed under: Oracle RDBMS — Tags: , — Saurabh Manroy @ 7:42 pm

Similar to my last post, to fix an execution plan of a query, I decided to create stored outlines. It was a two node RAC environment running 10.2.0.4 RDBMS software. On one of the nodes, query was consuming lots of CPU.

SQL_ID 8pg71n7580t88

Plan with Good response time

Plan hash value: 1087074870
----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name              | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                   |       |       |   355 (100)|          |       |       |
|   1 |  SORT ORDER BY                         |                   |     2 |   248 |   355   (1)| 00:00:05 |       |       |
|   2 |   CONCATENATION                        |                   |       |       |            |          |       |       |
|   3 |    FILTER                              |                   |       |       |            |          |       |       |
|   4 |     HASH JOIN SEMI                     |                   |     1 |   124 |   186   (1)| 00:00:03 |       |       |
|   5 |      PARTITION RANGE ITERATOR          |                   |     8 |   720 |   179   (0)| 00:00:03 |   KEY |   KEY |
|   6 |       TABLE ACCESS BY LOCAL INDEX ROWID| xxxxxxx           |     8 |   720 |   179   (0)| 00:00:03 |   KEY |   KEY |
|   7 |        INDEX RANGE SCAN                | INX_xxxxxxx_ACCT  |   168 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|   8 |      TABLE ACCESS BY GLOBAL INDEX ROWID| YYYY              |     3 |   102 |     6   (0)| 00:00:01 | ROW L | ROW L |
|   9 |       INDEX RANGE SCAN                 | IND_YYYY_ACCTBILL |     3 |       |     3   (0)| 00:00:01 |       |       |
|  10 |    FILTER                              |                   |       |       |            |          |       |       |
|  11 |     NESTED LOOPS SEMI                  |                   |     1 |   124 |   168   (0)| 00:00:03 |       |       |
|  12 |      PARTITION RANGE ITERATOR          |                   |     1 |    90 |   167   (0)| 00:00:03 |   KEY |   KEY |
|  13 |       TABLE ACCESS BY LOCAL INDEX ROWID| xxxxxxx           |     1 |    90 |   167   (0)| 00:00:03 |   KEY |   KEY |
|  14 |        INDEX RANGE SCAN                | INX_xxxxxxx_SUBS  |   122 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|  15 |      PARTITION RANGE ITERATOR          |                   |     3 |   102 |     1   (0)| 00:00:01 |   KEY |   KEY |
|  16 |       INDEX UNIQUE SCAN                | PK_YYYY           |     3 |   102 |     1   (0)| 00:00:01 |   KEY |   KEY |
----------------------------------------------------------------------------------------------------------------------------

Plan with Bad response time

Plan hash value: 3132269520
----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name              | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                   |       |       |   352 (100)|          |       |       |
|   1 |  SORT ORDER BY                         |                   |     2 |   248 |   352   (1)| 00:00:05 |       |       |
|   2 |   CONCATENATION                        |                   |       |       |            |          |       |       |
|*  3 |    FILTER                              |                   |       |       |            |          |       |       |
|*  4 |     HASH JOIN SEMI                     |                   |     1 |   124 |   179   (1)| 00:00:03 |       |       |
|   5 |      PARTITION RANGE ITERATOR          |                   |    12 |  1080 |   175   (0)| 00:00:03 |   KEY |   KEY |
|*  6 |       TABLE ACCESS BY LOCAL INDEX ROWID| xxxxxxx           |    12 |  1080 |   175   (0)| 00:00:03 |   KEY |   KEY |
|*  7 |        INDEX RANGE SCAN                | INX_xxxxxxx_ACCT  |   159 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|   8 |      PARTITION RANGE ITERATOR          |                   |     1 |    34 |     3   (0)| 00:00:01 |   KEY |   KEY |
|*  9 |       INDEX RANGE SCAN                 | PK_YYYY           |     1 |    34 |     3   (0)| 00:00:01 |   KEY |   KEY |
|* 10 |    FILTER                              |                   |       |       |            |          |       |       |
|  11 |     NESTED LOOPS SEMI                  |                   |     1 |   124 |   172   (0)| 00:00:03 |       |       |
|  12 |      PARTITION RANGE ITERATOR          |                   |     1 |    90 |   171   (0)| 00:00:03 |   KEY |   KEY |
|* 13 |       TABLE ACCESS BY LOCAL INDEX ROWID| xxxxxxx           |     1 |    90 |   171   (0)| 00:00:03 |   KEY |   KEY |
|* 14 |        INDEX RANGE SCAN                | INX_xxxxxxx_SUBS  |   137 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|  15 |      PARTITION RANGE ITERATOR          |                   |     1 |    34 |     1   (0)| 00:00:01 |   KEY |   KEY |
|* 16 |       INDEX UNIQUE SCAN                | PK_YYYY           |     1 |    34 |     1   (0)| 00:00:01 |   KEY |   KEY |
----------------------------------------------------------------------------------------------------------------------------

Stored Outline was created from the node on which query was running supposedly Good Plan.

SQL>select outline_sid,hash_value,plan_hash_value,child_number from v$sql where sql_id='8pg71n7580t88';
OUTLINE_SID HASH_VALUE PLAN_HASH_VALUE CHILD_NUMBER
----------- ---------- --------------- ------------
3397412104      1087074870            2
SQL>alter session set create_stored_outlines=true;
Session altered.
SQL>exec dbms_outln.create_outline(3397412104,2);
PL/SQL procedure successfully completed.
SQL>select * from dba_outlines;
NAME                           OWNER                          CATEGORY                       USED   TIMESTAMP
------------------------------ ------------------------------ ------------------------------ ------ --------------
VERSION
----------------------------------------------------------------
SQL_TEXT                                                                         SIGNATURE
-------------------------------------------------------------------------------- --------------------------------
COMPATIBLE   ENABLED  FORMAT
------------ -------- ------
SYS_OUTLINE_11051118530725015  ACCT                           DEFAULT                        UNUSED 20110511185307
10.2.0.4.0
select  to_char(b.AcctId),b.YYYYCycle,b.YYYYNum,to_char(b.SubsId),b.ItemType,b.I 5266676E85773042383790483873E4FB
COMPATIBLE   ENABLED  NORMAL

Shared pool was flushed on the problematic node and I waited for fresh execution plan to be loaded into shared pool. Here is what I got:

SQL>select * from table (dbms_xplan.display_cursor('8pg71n7580t88'));
PLAN_TABLE_OUTPUT
SQL_ID  8pg71n7580t88, child number 0
-------------------------------------
Plan hash value: 3132269520
----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name              | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                   |       |       |   353 (100)|          |       |       |
|   1 |  SORT ORDER BY                         |                   |     2 |   248 |   353   (1)| 00:00:05 |       |       |
|   2 |   CONCATENATION                        |                   |       |       |            |          |       |       |
|*  3 |    FILTER                              |                   |       |       |            |          |       |       |
|*  4 |     HASH JOIN SEMI                     |                   |     1 |   124 |   179   (1)| 00:00:03 |       |       |
|   5 |      PARTITION RANGE ITERATOR          |                   |    14 |  1260 |   175   (0)| 00:00:03 |   KEY |   KEY |
|*  6 |       TABLE ACCESS BY LOCAL INDEX ROWID| xxxxxxx           |    14 |  1260 |   175   (0)| 00:00:03 |   KEY |   KEY |
|*  7 |        INDEX RANGE SCAN                | INX_xxxxxxx_ACCT  |   159 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|   8 |      PARTITION RANGE ITERATOR          |                   |     1 |    34 |     3   (0)| 00:00:01 |   KEY |   KEY |
|*  9 |       INDEX RANGE SCAN                 | PK_YYYY           |     1 |    34 |     3   (0)| 00:00:01 |   KEY |   KEY |
|* 10 |    FILTER                              |                   |       |       |            |          |       |       |
|  11 |     NESTED LOOPS SEMI                  |                   |     1 |   124 |   173   (0)| 00:00:03 |       |       |
|  12 |      PARTITION RANGE ITERATOR          |                   |     1 |    90 |   172   (0)| 00:00:03 |   KEY |   KEY |
|* 13 |       TABLE ACCESS BY LOCAL INDEX ROWID| xxxxxxx           |     1 |    90 |   172   (0)| 00:00:03 |   KEY |   KEY |
|* 14 |        INDEX RANGE SCAN                | INX_xxxxxxx_SUBS  |   140 |       |   127   (0)| 00:00:02 |   KEY |   KEY |
|  15 |      PARTITION RANGE ITERATOR          |                   |     1 |    34 |     1   (0)| 00:00:01 |   KEY |   KEY |
|* 16 |       INDEX UNIQUE SCAN                | PK_YYYY           |     1 |    34 |     1   (0)| 00:00:01 |   KEY |   KEY |
----------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
-- removed because of customer's data
Note
-----
- outline "SYS_OUTLINE_11051118530725015" used for this statement

So, outline was used but with BAD plan ?  I raised an SR for this problem and after weeks of investigation, it came out to be an Oracle Bug 6455659 which affects multibyte characterset. Customer’s database was having UTF8 characterset.

This bug affects 10.2.0.4 and 11.1.0.6 RDBMS versions. One-off patch is available for some platforms.  There is no workaround available. This bug is fixed in 10.2.0.5 and 11.1.0.7 versions.

In my next post I’ll explain how I fixed the problem of this slow running query.

« Newer PostsOlder Posts »

Create a free website or blog at WordPress.com.