Oracle Study Notes by Denis

Using CASE WHEN statement

2012-01-17T11:01:00.000-05:00

Suggested dev team to change the following SQL:


update t1 
set b=(SELECT    
               decode(count(*),0,'N','Y')
          FROM t2 
         WHERE t1.id = t2.id);

to the following structruce:

update t1  set b= case when  
                     exists ( select null from t2 where t1.id =t2.id  )
                       then 'Y' 
                       else 'N' end;

Implicit conversion of a character string to Oracle DATE type is dangerous

2011-12-21T11:29:00.000-05:00

Typically TO_DATE function is used by taking a char as the first argument and 'fmt' as the second argument. According to Oracle doc:

TO_DATE converts char of CHAR, VARCHAR2, NCHAR, or NVARCHAR2 datatype to a value of DATE datatype. The fmt is a datetime model format specifying the format of char. If you omit fmt, then char must be in the default date format. If fmt is J, for Julian, then char must be an integer.

It should be pointed out that omitting the fmt could be a very bad practise. If the character string does not match the default format, Oracle does not necessarily throw error in some cases. For example, I have executed the following commands in the SQL* Plus:

SQL>alter session set nls_date_format='yyyy-mm-dd HH24:mi:ss';

Session altered.


SQL>select count(*) from  dba_objects where created between '1-Nov-2011' and '14-Nov-2011';

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

1 row selected.

SQL>select to_date('1-Nov-2011') from dual;

TO_DATE('1-NOV-2011
-------------------
0001-11-20 11:00:00

1 row selected.

While the correct results should be as follows:

SQL>alter session set nls_date_format='dd-Mon-yyyy HH24:mi:ss';

Session altered.

SQL>select count(*) from  dba_objects where created between '1-Nov-2011' and '14-Nov-2011';

  COUNT(*)
----------
       171

1 row selected.

SQL>select to_date('1-Nov-2011') from dual;

TO_DATE('1-NOV-2011'
--------------------
01-Nov-2011 00:00:00

1 row selected.

I have learned this in a pretty hard way during a sql tuning effort. Many hours have been spent before I realized that the weired results were due to this implicit conversion "bug". ( See http://www.freelists.org/post/oracle-l/Huge-difference-between-sqlplus-and-sqldeveloper-sorting-in-memory-vs-disk,7)

Reorganize Table and Index

2011-11-27T21:11:00.000-05:00

I manage a database for the retail ordering application. The orders that were completed 90 days ago are subject to archiving. Due to various reasons there were about 80 million archiving backlog about two months ago. Since the backlog is caught up now, reorganization of the schema objects is desirable in order to reclaim space.

First of all, I need to estimate how much space can be saved potentially after the reorganization. For table segment, I use DBMS_SPACE.create_table_cost to estimate the size after reorganization. Given the number of row and average row size and the target tablespace, the following script can be used to estimate the size if the table is moved to the target tablespace.

--  script: tabsize_est.sql 
--  get the avg row size and row cnt from analyze job
--  dba_tables
-- @tabsize_est 'table_size' 100   10000000

set verify off feedback off
set SERVEROUTPUT ON
DECLARE
  l_ddl          VARCHAR2(500);
  l_used_bytes   NUMBER;
  l_alloc_bytes  NUMBER;
  l_message      varchar2(100);
BEGIN
  -- Estimate the size of a new table on the USERS tablespace.
  l_message := '&1';
  DBMS_SPACE.create_table_cost (
            tablespace_name => 'TTQ_ORD_DATA_4',
            avg_row_size    => &2,
            row_count       => &3 ,
            pct_free        => 10 ,
            used_bytes      => l_used_bytes,
            alloc_bytes     => l_alloc_bytes);

  DBMS_OUTPUT.put_line (  l_message  || ' Mbytes_allocated= ' || l_alloc_bytes/1024/1024 || ' Mbytes');
END;
/

I use the following script to generate command for each table:

--  script: tabsize_est_gen.sql
--  purpose: generate 
select '@@tabsize_est ' ||''' ' || t.owner || ' ' || t.table_name || ' ' || t.tablespace_name || ' ' 
     || trunc(s.bytes/1024/1024)  || ''' '||  t.avg_row_len || ' ' || t.num_rows
from
dba_segments s,
dba_tables t
where s.owner=t.owner
and  s.segment_name=t.table_name
and t.owner in  ('TTQ_ORD')
and  s.bytes > 1000000000
/

The output from above script looks like:

@@tabsize_est ' TTQ_ORD CUST_ORDER_ACTIVITY TTQ_ORD_DATA_2 2611' 139 15874503
@@tabsize_est ' TTQ_ORD CUST_HIGH_RISK_20110425 TTQ_ORD_DATA_2 1349' 82 14246227
@@tabsize_est ' TTQ_ORD ENCDEC_MIGRATION TTQ_ORD_DATA_4 1400' 29 2257790
@@tabsize_est ' TTQ_ORD ACCOUNT_COMMENTS TTQ_ORD_DATA_4 13600' 146 82486887
@@tabsize_est ' TTQ_ORD BUNDLE_RECON_TRACKING TTQ_ORD_DATA_3 7060' 957 6294040
@@tabsize_est ' TTQ_ORD ISP_MESSAGE_TRACKING TTQ_ORD_DATA_3 30480' 815 31089530
...

Then, executing above commands, I can obtain current and estimated table segment size as shown below:

TTQ_ORD CUST_ORDER_ACTIVITY TTQ_ORD_DATA_2 2611 Mbytes_allocated= 2600 Mbytes
TTQ_ORD CUST_HIGH_RISK_20110425 TTQ_ORD_DATA_2 1349 Mbytes_allocated= 1400 Mbytes
TTQ_ORD ENCDEC_MIGRATION TTQ_ORD_DATA_4 1400 Mbytes_allocated= 200 Mbytes
TTQ_ORD ACCOUNT_COMMENTS TTQ_ORD_DATA_4 13600 Mbytes_allocated= 13600 Mbytes
TTQ_ORD BUNDLE_RECON_TRACKING TTQ_ORD_DATA_3 7060 Mbytes_allocated= 7200 Mbytes
TTQ_ORD ISP_MESSAGE_TRACKING TTQ_ORD_DATA_3 30480 Mbytes_allocated= 30400 Mbytes
...

To estimate the size of index segment after rebuild, I use a script called index_est_proc_2.sql by Joanathan Lewis (http://jonathanlewis.wordpress.com/index-sizing/).

I use EXCEL to calcuate the size difference between the estimated size and current size for each index and table. As a result I can estimate the total space gain. Of course when I plan to do reoraganization, I can start with the segment which would give the most space gain.

The space gain estimated is at tabespace level. To actually release the space at OS level, the datafile needs to be shrinked. For this it is very useful to know which segments reside at the end of datafile. Those segments should be moved first to allow the datafile shrikable.

The following script is used to list the segment in each data file ordered by its max(block_id). The segments that reside at the end of datafile should have large max(block_id).

-- find segment at the end of the data files
-- so if this segment is removed, the data file could be resized down

spool shrinkdf_&tbs..log

col sum_mbytes format 999,999
col  diff format 999,999,999

select name from v$database;

break on file_id skip 1
select file_id, segment_name, sum_mbytes, count_blocks, max_block_id, 
max_block_id -  lead(max_block_id,1) over (partition by file_id order by max_block_id desc )  diff
from
(
select /*+ RULE */ 
file_id
, segment_name
, sum(bytes/1014/1024)  sum_mbytes
, count(block_id) count_blocks
, max(block_id) max_block_id
from dba_extents
where tablespace_name = upper('&&tbs') 
group by file_id, segment_name
order by 1, 5 desc,4
)
/

spool off

undef tbs

Sample outout from the above script looks like:

FILE_ID SEGMENT_NAME                   SUM_MBYTES COUNT_BLOCKS MAX_BLOCK_ID         DIFF
---------- ------------------------------ ---------- ------------ ------------ ------------
       227 ORDER_TRANS                         1,818            9      1868809      128,000
           AUDIT_TRAIL                         1,010            5      1740809       25,600
           ORD_ADDRESS                           808            4      1715209       51,200
           MASTER_ACCOUNT                        202            1      1664009      179,200
           ORD_TRANS_DETAILED_STATUS             202            1      1484809       51,200
           ORDER_MASTER                          202            1      1433609      153,600
           MASTER_SERVICE                        202            1      1280009       25,600
           ACCOUNT_HISTORY                       202            1      1254409       25,600
           ACCOUNT_COMMENTS                      202            1      1228809       51,200
           ORD_ACCOUNT                           202            1      1177609       51,200
           SUPP_HISTORY                          202            1      1126409      102,400
           CREDIT_CHECK                          202            1      1024009      153,600
           ORD_CONTACT                           404            2       870409       25,600
           ORD_TRANS_NOTES_HISTORY               404            2       844809      102,400
           ORD_DSL                               404            2       742409

It is clear that for the datafile with file_id=227, ORDER_TRANS is at the end, followed by AUDIT_TRAIL.

Finally, the following script can be used to generate the resize statement:

rem  script: red_df.sql 
rem 
rem  Purpose: This gives the Total size of datafiles in a tablespace
rem         and also the size to which it can be reduced.
rem     It generated rdf.log spool file with commands to resize datafiles
rem  Usage: @red_df.sql <TABLESPACE>
rem 
rem  Note: I got this script from a colleague but I once saw this script in AskTom website 

set verify off

col tsname  format         a24    justify c heading 'Tablespace'
col nfrags  format     9,999,990  justify c heading 'Free|Frags'
col mxfrag  format   999,990.999  justify c heading 'Largest|Free Frag'
col totsiz  format 9,999,990.999  justify c heading 'Total|Mbytes'
col avasiz  format 9,999,990.999  justify c heading 'Available|Mbytes'
col pctusd  format       990.99   justify c heading 'Percent|Used'

set pagesize 200
set linesize 120

select
total.tablespace_name                       tsname,
count(free.bytes)                           nfrags,
round(nvl(max(free.bytes)/1048576,0),2)              mxfrag,
total.bytes/1048576                         totsiz,
round(nvl(sum(free.bytes)/1048576,0),2)              avasiz,
round((1-nvl(sum(free.bytes),0)/total.bytes)*100,2)  pctusd
from
(select tablespace_name, sum(bytes) bytes
from dba_data_files
where tablespace_name = upper('&1')
group by tablespace_name)  total,
dba_free_space  free
where
total.tablespace_name = free.tablespace_name(+)
and total.tablespace_name = upper('&1')
group by
total.tablespace_name,
total.bytes;


set verify off
set linesize 150
set echo off

column file_name format a60 word_wrapped
column smallest format 999,990 heading "Smallest|Size|Poss."
column currsize format 999,990 heading "Current|Size"
column savings format 999,990 heading "Poss.|Savings" 
break on report
compute sum of savings on report

column value new_val blksize
select value from v$parameter where name = 'db_block_size'
/

select file_name,
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) smallest, 
ceil( blocks*&&blksize/1024/1024) currsize,
ceil( blocks*&&blksize/1024/1024) -
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) savings
from dba_data_files a,
( select file_id, max(block_id+blocks-1) hwm 
from dba_extents
group by file_id ) b
where a.file_id = b.file_id(+)
and a.tablespace_name = upper('&1')
/

spool rdf.log
column cmd format a75 word_wrapped
set pagesize 4000

select 'alter database datafile '''||file_name||''' resize ' ||
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) || 'm;' cmd 
from dba_data_files a,
( select file_id, max(block_id+blocks-1) hwm
from dba_extents
group by file_id ) b
where a.file_id = b.file_id(+)
and ceil( blocks*&&blksize/1024/1024) - 
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) > 0
and a.tablespace_name = upper('&1')
/
spool off

Cloud Computing and DBA career

2011-11-07T08:52:00.001-05:00

Recently, in reply to a question in the MITBBS database forum( in Chinese) –“Will the DBA career become down-hill and the future dimmed with the growth of Cloud Computing and NoSQL movement ?”, I made the following comments:

My understanding till today: NOSQL is just a special purpose database (or data model), it cannot replace traditional general purpose RDBMS. (The market of NoSQL is small). It has little impact on DBA’s career.

Cloud computing provides more choices for a company for its IT infrastructure. Basically three choices: traditional in-house IT； outsource IT totally ( i.e. to public cloud provider, pay-per-use ); consolidating in house IT infrastructure on private cloud; or maybe the fourth choice, some kind of mixing of all above. I think the demanding for DBA role (or system admin, network, storage admin in this regard) will be reduced when a company move part (or all) of its IT to cloud (either public or private).

Demanding for traditional DBA role is not only being affected by emerging of cloud computing. It has been affected by more and more self-managing and automation of RDBMS anyway ( In USA that role is being outsourced to India and China etc)

Obviously if there is a trend to move to cloud with significance, there will be a demanding for “cloud system/support administrator” It should not so difficult for a true DBA ( means he is always willing to learn new things) to transition his role to a cloud administrator.

After making the comments, I googled more and found the following article interesting: “The tech jobs that the cloud will eliminate” ( http://www.infoworld.com/d/adventures-in-it/tech-jobs-cloud-will-eliminate-008 ). There is also a two-part article describing Cloud IT roles here: http://open.eucalyptus.com/learn/cloud-it-roles. It indicated a DBA’s skill-set is extendable to assume Cloud Data Architect role.

I wrote a Perl script to non-interactively search dice.com to get the count of job listing with respect to some keywords. I scheduled to do this count every day. Hope this will give me some kind of insights into the trend about the DBA job market and the impact by Cloud Computing.

For example, the output of the script of yesterday looked like:

2011-11-06 07:59 System+Administrator 5688
2011-11-06 07:59 DBA 2799
2011-11-06 07:59 Oracle+DBA 1570
2011-11-06 07:59 Cloud+Administrator 277
2011-11-06 07:59 Cloud+DBA 74

SQL Server - Find out Transactions per second etc from DM_OS_PERFORMANCE_COUNTERS

2011-10-12T22:23:00.002-04:00

In a whitepaper named "Diagnosing and Resolving Latch Contention on SQL Server", a script is provided to snap DM_OS_WAITE_STATS view to calculate wait over a period of time. In this post, based on the same idea, I developed a script to snap the DM_OS_PERFORMANCE_COUNTERS view in order to find out transactions/sec for each database. It is also easy to be modified to get other performance counters.

-- script: snap_perf_conuter.sql

/* Snapshot the performance counters (such as transaction/sec) on sys.dm_os_performance_counters
   and store in a table so that they can be used to compute a per second value.
      This script is only applicable to Cntr_Type = 272696576. Different Cntr_type is explained
      in this blog:
        http://rtpsqlguy.wordpress.com/2009/08/11/sys-dm_os_performance_counters-explained/
** Data is maintained in tempdb so the connection must persist between each execution** 
**alternatively this could be modified to use a persisted table in tempdb. if that is changed code should be included to clean up the table at some point.**
 */


use tempdb
go
declare @current_snap_time datetime
declare @previous_snap_time datetime
-- declare @l_counter_name  nchar(128)
declare @sqlcmd nvarchar(4000)
declare @l_counter_name  nvarchar(2000)

-- modify the counter_name as needed, some examples provided 
set @l_counter_name  = '''transactions/sec'''
-- set @l_counter_name = '''Batch Requests/sec'''                                                                                                              
-- set @l_counter_name= '''Page Splits/sec'',''Page lookups/sec'''
-- set @l_counter_name = '''transactions/sec'',''Batch Requests/sec'''                                                                                                              
-- set @l_counter_name='''Page compression attempts/sec'',''Page Deallocations/sec'',''Page lookups/sec'',''Page reads/sec'',''Page Splits/sec'',''Page writes/sec'',''Pages Allocated/sec'',''Pages compressed/sec'''
-- set @l_counter_name = '''Logins/sec'',''Logouts/sec'''                                                                                              



if not exists(select name from tempdb.sys.sysobjects where name like '#_perf_counter%') 
create table #_perf_counter ( "object_name" nchar(128) ,counter_name nchar(128) ,instance_name nchar(128) ,cntr_value bigint ,cntr_type int ,snap_time datetime
)

set @sqlcmd ='
insert into #_perf_counter (
object_name
,counter_name
,instance_name
,cntr_value
,cntr_type
,snap_time
)
select
OBJECT_NAME
,counter_name
,instance_name
,cntr_value
,cntr_type
,getdate()
from sys.dm_os_performance_counters
where counter_name in (' +  @l_counter_name +  ')'

exec sp_executesql @sqlcmd

--get the previous and current collection point
select top 1 @previous_snap_time = snap_time from #_perf_counter where snap_time < (select max(snap_time) from #_perf_counter) order by snap_time desc

select @current_snap_time = max(snap_time) from #_perf_counter

-- debug
select @current_snap_time end_time, @previous_snap_time start_time

set @sqlcmd='
select
e.object_name
,e.counter_name
,e.instance_name
,(e.cntr_value -s.cntr_value) / DATEDIFF(ss, s.snap_time, e.snap_time)  Per_Sec_Value 
--, s.snap_time as [start_time] 
--, e.snap_time as [end_time] , DATEDIFF(ss, s.snap_time, e.snap_time) as [seconds_in_sample] from #_perf_counter e inner join  
( select * from #_perf_counter   
where snap_time ='''+ convert(varchar(100), @previous_snap_time, 21) + ''' ) s on ( e.instance_name=s.instance_name and e.object_name = s.object_name and e.instance_name=s.instance_name 
   and e.counter_name=s.counter_name)
where e.snap_time= '''+  convert(varchar(100), @current_snap_time, 21) + ''' and e.counter_name in (' +  @l_counter_name + ')order by Per_Sec_value desc'


exec sp_executesql @sqlcmd

--clean up table
 delete from #_perf_counter
 where snap_time = @previous_snap_time

-----------------  end of script  ----

Sample output (edited) :

end_time                start_time
----------------------- -----------------------
2011-10-12 18:47:25.173 2011-10-12 18:46:23.190

(1 row(s) affected)

object_name                         counter_name     instance_name               Per_Sec_Value        seconds_in_sample
----------------------------------- ---------------- --------------------------- -------------------- -----------------
MSSQL$FPSEFSDB_OP2:Databases        Transactions     _Total                      296                  62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     tempdb                      126                  62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     Orderplacement              100                  62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     master                      60                   62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     Distributor                 2                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     NOCVDB                      1                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     DBADB                       1                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     msdb                        1                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     tempdbx                     0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     spot_admin                  0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     ASPState                    0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     APPCACHELOG                 0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     VGISessions                 0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     SSNSDB                      0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     SSNS4DB                     0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     copper                      0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     VZWPCAT                     0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     model                       0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     mssqlsystemresource         0                    62

SQL Server - Troubleshooting Deadlock

2011-10-08T17:59:00.003-04:00

There is a thread in the SQLTeam forum that describes a deadlock scenario:
The application inserts a row into a status table. A trigger on the table fires so that when the status id inserted is a certain value it will call a stored procedure, which inserts a row into an accounting table. This whole thing is wrapped in a transaction so it should all be getting rolled back when there are errors. On occasion two threads of the application insert into the status table at nearly the same millisecond, and when both end up calling the stored procedure to insert into the accounting table a deadlock occurs and one is killed.

Two important details were unveiled during the discussion:
(1) the whole transaction took place with isolation level set to be serializable
(2) in the stored procedure, there is an existence check query doing full table scan on the status table before inserting the row into it.

I try to simulate the deadlock situation for my own better understanding, especially this is the first time I know how to use DBCC trace to troubleshooting deadlock. It is a good practise.

First of all, I created the following test table:

-- create a test table

USE testdata
go

IF OBJECT_ID ( 'mytable', 'U' ) IS NOT NULL
DROP TABLE mytable;
GO


CREATE TABLE mytable
 (
  id  INT,
  val INT,
  padding VARCHAR(4000),
  );

create unique clustered index index01
on mytable(id);

INSERT INTO mytable
SELECT 1, 1, REPLICATE('a', 4000);

INSERT INTO mytable
SELECT 2, 2, REPLICATE('a', 4000);

INSERT INTO mytable
SELECT 3, 3, REPLICATE('a', 4000);

INSERT INTO mytable
SELECT 4, 4, REPLICATE('a', 4000);

go

delete from mytable where id in (2,4);

-- show the location of rows
select
       a.%%physloc%%                          AS Address,
       sys.fn_PhysLocFormatter(a.%%physloc%%) AS AddressText,
       a.id
FROM   mytable a
ORDER BY 2;
go

The remaining two rows in the mytable are located in different page as shown below:

Address    AddressText            id
---------- ---------------------- -----------
0x99000000 (1:153:0)                        1
0xFF420000 (1:17151:0)                      3

Secondly I turn on the deadlock trace:

1> DBCC traceon(1222, -1)
2> go
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Then I run the following two scripts in two different SSMS windows:

-- script: ins_1.sql 
use testdata
go

set transaction isolation level serializable
begin tran
go
if not exists (select id from mytable where val = 2)
begin
  waitfor delay '00:01:00'
  insert into mytable values (2,2, replicate('a','4000'))
end
go
commit tran
go

-- script: ins_2.sql
use testdata
go

set transaction isolation level serializable
begin tran
go
if not exists (select id from mytable where val = 4)
begin
  waitfor delay '00:01:00'
  insert into mytable values (4,4, replicate('a','4000'))
end
go
commit tran
go

Withing the 1 min delay, run sp_lock procedure, I can see the key-range locks are requested by the two sessions:

spid   dbid   ObjId       IndId  Type Resource                         Mode     Status
------ ------ ----------- ------ ---- -------------------------------- -------- ------
53     8      0           0      DB                                    S        GRANT
52     8      0           0      DB                                    S        GRANT
52     8      0           0      MD   49(90c8bd04:fb81833:777569)      Sch-S    GRANT
53     8      0           0      MD   49(ead7fb30:916efee:7da7e5)      Sch-S    GRANT
53     8      66099276    1      PAG  1:153                            IS       GRANT
52     8      66099276    1      PAG  1:153                            IS       GRANT
53     8      66099276    1      PAG  1:17151                          IS       GRANT
52     8      66099276    1      PAG  1:17151                          IS       GRANT
53     8      66099276    0      TAB                                   IS       GRANT
52     8      66099276    0      TAB                                   IS       GRANT
53     8      66099276    1      KEY  (ffffffffffff)                   RangeS-S GRANT
52     8      66099276    1      KEY  (ffffffffffff)                   RangeS-S GRANT
53     8      66099276    1      KEY  (03000d8f0ecc)                   RangeS-S GRANT
52     8      66099276    1      KEY  (03000d8f0ecc)                   RangeS-S GRANT
53     8      66099276    1      KEY  (010086470766)                   RangeS-S GRANT
52     8      66099276    1      KEY  (010086470766)                   RangeS-S GRANT

Key-range locks protect a range of rows implicitly included in a record set being read by a Transact-SQL statement while using the serializable transaction isolation level. The serializable isolation level requires that any query executed during a transaction must obtain the same set of rows every time it is executed during the transaction. A key range lock protects this requirement by preventing other transactions from inserting new rows whose keys would fall in the range of keys read by the serializable transaction.

After about 1 min, one of the sessions received the following message:

Msg 1205, Level 13, State 48, Line 4
Transaction (Process ID 52) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
Msg 3902, Level 16, State 1, Line 1
The COMMIT TRANSACTION request has no corresponding BEGIN TRANSACTION.

In the error log, I can find the following:

--------------------- start of error log  ------------------

2011-10-08 11:01:06.38 spid55      DBCC TRACEON 1222, server process ID (SPID) 55. This is an informational message only; no user action is required.
2011-10-08 11:14:42.43 spid16s     deadlock-list
2011-10-08 11:14:42.43 spid16s      deadlock victim=process3313558
2011-10-08 11:14:42.43 spid16s       process-list
2011-10-08 11:14:42.43 spid16s        process id=process3313558 taskpriority=0 logused=132 waitresource=KEY: 8:72057594047889408 (03000d8f0ecc) waittime=3935 ownerId=623111 transactionname=user_transaction lasttranstarted=2011-10-08T11:13:38.497 XDES=0x574bb30 lockMode=RangeI-N schedulerid=4 kpid=8728 status=suspended spid=52 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2011-10-08T11:13:38.497 lastbatchcompleted=2011-10-08T11:13:38.497 clientapp=Microsoft SQL Server Management Studio - Query hostname=TUSNC012LKVT006 hostpid=4412 loginname=US1\v983294 isolationlevel=serializable (4) xactid=623111 currentdb=8 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2011-10-08 11:14:42.43 spid16s         executionStack
2011-10-08 11:14:42.43 spid16s          frame procname=adhoc line=4 stmtstart=182 stmtend=296 sqlhandle=0x02000000d2ef471c04bdc8903318b80f6975779f09b41ba8
2011-10-08 11:14:42.43 spid16s     insert into mytable values (2,2, replicate('a','4000'))     
2011-10-08 11:14:42.43 spid16s         inputbuf
2011-10-08 11:14:42.43 spid16s     if not exists (select id from mytable where val = 2)
2011-10-08 11:14:42.43 spid16s     begin
2011-10-08 11:14:42.43 spid16s       waitfor delay '00:01:00'
2011-10-08 11:14:42.43 spid16s       insert into mytable values (2,2, replicate('a','4000')) 
2011-10-08 11:14:42.43 spid16s     end
2011-10-08 11:14:42.43 spid16s        process id=process69eaa8 taskpriority=0 logused=132 waitresource=KEY: 8:72057594047889408 (ffffffffffff) waittime=9293 ownerId=623056 transactionname=user_transaction lasttranstarted=2011-10-08T11:13:32.760 XDES=0xff48c10 lockMode=RangeI-N schedulerid=2 kpid=11340 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2011-10-08T11:13:32.760 lastbatchcompleted=2011-10-08T11:13:32.760 clientapp=Microsoft SQL Server Management Studio - Query hostname=TUSNC012LKVT006 hostpid=4412 loginname=US1\v983294 isolationlevel=serializable (4) xactid=623056 currentdb=8 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2011-10-08 11:14:42.43 spid16s         executionStack
2011-10-08 11:14:42.43 spid16s          frame procname=adhoc line=4 stmtstart=182 stmtend=296 sqlhandle=0x02000000eec4b91030fbd7eaeeef1609e5a77d124395f09a
2011-10-08 11:14:42.43 spid16s     insert into mytable values (4,4, replicate('a','4000'))     
2011-10-08 11:14:42.43 spid16s         inputbuf
2011-10-08 11:14:42.43 spid16s     if not exists (select id from mytable where val = 4)
2011-10-08 11:14:42.43 spid16s     begin
2011-10-08 11:14:42.43 spid16s       waitfor delay '00:01:00'
2011-10-08 11:14:42.43 spid16s       insert into mytable values (4,4, replicate('a','4000')) 
2011-10-08 11:14:42.43 spid16s     end
2011-10-08 11:14:42.43 spid16s       resource-list
2011-10-08 11:14:42.43 spid16s        keylock hobtid=72057594047889408 dbid=8 objectname=testdata.dbo.mytable indexname=index01 id=lock55da680 mode=RangeS-S associatedObjectId=72057594047889408
2011-10-08 11:14:42.43 spid16s         owner-list
2011-10-08 11:14:42.43 spid16s          owner id=process69eaa8 mode=RangeS-S
2011-10-08 11:14:42.43 spid16s         waiter-list
2011-10-08 11:14:42.43 spid16s          waiter id=process3313558 mode=RangeI-N requestType=convert
2011-10-08 11:14:42.43 spid16s        keylock hobtid=72057594047889408 dbid=8 objectname=testdata.dbo.mytable indexname=index01 id=lock627aa80 mode=RangeS-S associatedObjectId=72057594047889408
2011-10-08 11:14:42.43 spid16s         owner-list
2011-10-08 11:14:42.43 spid16s          owner id=process3313558 mode=RangeS-S
2011-10-08 11:14:42.43 spid16s         waiter-list
2011-10-08 11:14:42.43 spid16s          waiter id=process69eaa8 mode=RangeI-N requestType=convert


--------------------- end of error log  ------------------

The solution to this deadlock situation could be (1) using repeated read isolation level and/or (2) create an index on the 'val' column. Bottom line, we have to fully understand the requirement to code properly: why we need to insert into a table then using trigger to insert into another table? But this is out of my reach. Here I am just satisfied with being familiar with SQL Server lock types and DBCC trace command a little bit.

The deadlock shown in this test case belong to a type of deadlock named conversion deadlock. Looking closely at the "resource-list" section of the error log. We can see that both sessions hold the same resource in shared mode (RangeS-S) at the begining. This is no problem. But both sessions then request to convert the lock type to RangeI-N, this reqires the other session give up the RangeS-S lock first. Thus a deadlock happens.

SQL Server - Are there any queries using any Plan Guides now?

2011-10-05T17:32:00.004-04:00

Plan Guide in SQL Server is equivalent to SQL Profile in Oracle functionally. In Oracle, v$sqlarea has a column called SQL_PROFILE, based on which I can query this view to check if any queries are using any SQL Profiles. Here is the an example:


select sql_profile, max(sql_text) sample_sql_text, sum(executions) total_executions, 

sum(buffer_gets)/ sum(executions)   gets_per_execs 

from v$sqlarea where sql_profile is not null group by sql_profile;





SQL_PROFILE                      SAMPLE_SQL_TEXT                     TOTAL_EXECUTIONS GETS_PER_EXECS

-------------------------------- ----------------------------------- ---------------- --------------

profile_sfh_user_1               SELECT U.SFH_USER_ID,B.SFH_BTN_ID,U             2254     10.3189885

                                 B.PMT_INDICATOR,U.EMAIL FROM SFH_US

                                 ER U,SFH_BTN B,SFH_USER_BTN UB WHER

                                 E U.SFH_USER_ID = UB.SFH_USER_ID AN

                                 D UB.SFH_BTN_ID = B.SFH_BTN_ID AND

                                 B.CUST_BTN = :B2 AND U.USER_ID = :B

                                 1 AND U.USER_STATUS_CD = 'A' AND UB

                                 .SVC_STATUS ='A' AND B.BTN_STATUS_C

                                 D = 'A'

 

COE_gg3zpxx6j5c8c_4057913317      SELECT COUNT(SESSION_KEY) FROM SFH           638642     7.52062032

                                 _MYACC_SUMMARY WHERE cust_btn=:cust

                                 _btn AND SESSION_KEY like :session_

                                 key_value AND LAST_ACCESS_DATE >= S

                                 YSDATE-1

 

profile_sfh_summary_1            SELECT * FROM SFH_SUMMARY_JOBS WHER             6088     3.84395532

                                 E TTQ_ACCOUNT_ID='999802381'AND CR_

                                 DATE > TRUNC(SYSDATE)

 

COE_1x13vygbj9k9t_142312094      DELETE FROM SFH_MYACC_SUMMARY WHERE             5047     11.3929067

                                  CUST_BTN = :CUST_BTN AND  SESSION_

                                 KEY LIKE :SESSION_KEY

It can been seen that there are four SQL Profiles being used in this Oracle database (This is one of our production databases. I modified some table names to protect the innocent).

How can I obtain the same information in SQL Server regarding the usage of Plan Guide ? This is what I try to find out in the past few days. Below is what I got so far.

First of all, the output of the following query shows there are three Plan Guids in my AdventureWorks sample database

--  Show Plan Guides I created in AdventureWorks sample database



use AdventureWorks

go

-- usp_p is my own print-rows-as-column procedure

exec usp_p'   

select name,create_date,query_text,scope_type_desc from sys.plan_guides

'

go







OUTPUT ROWS AS COLUMN    

    

----------------------------------------------

name                          : Guide1

create_date                   : Oct  4 2011  4:19PM

query_text                    : SELECT * FROM Sales.SalesOrderHeader AS h,

        Sales.Customer AS c, Sales.SalesTerritory AS t

        WHERE h.CustomerID = c.CustomerID AND c.TerritoryID = t.TerritoryID

            AND t.CountryRegionCode = @Country_region

scope_type_desc               : OBJECT

----------------------------------------------

name                          : MyPlan_Guide_1

create_date                   : Oct  4 2011  6:41PM

query_text                    : SELECT COUNT(*) FROM [HumanResources].[Employee] e INNER JOIN [Person].[Contact] c ON c.[ContactID] = e.[ContactID]

scope_type_desc               : SQL

----------------------------------------------

name                          : Template_Plan_1

create_date                   : Oct  5 2011 11:05AM

query_text                    : select SUM ( LineTotal ) as LineTotal from Sales . SalesOrderHeader H join Sales . SalesOrderDetail D on D . SalesOrderID = H . SalesOrderID where H . SalesOrderID = @0

scope_type_desc               : TEMPLATE

----------------------------------------------

As shown above in the "scope_type_desc" column, in SQL Server, there are three types of Plan Guide: Object, SQL and Template. In summary,

An OBJECT plan guide matches queries that execute in the context of Transact-SQL stored procedures, user-defined scalar functions, multi-statement user-defined table-valued functions, and DML triggers.
An SQL plan guide matches queries that execute in the context of stand-alone Transact-SQL statements and batches that are not part of a database object. SQL-based plan guides can also be used to match queries that parameterize to a specified form.
A TEMPLATE plan guide matches stand-alone queries that parameterize to a specified form. These plan guides are used to override the current PARAMETERIZATION database SET option of a database for a class of queries.

Now, I use the following query in SSMS to check whether any Plan Guides are being used

-- Show if any plan guides are in use now:



SELECT 

   SUBSTRING(st.TEXT, (qs.statement_start_offset/2)+1 , ((CASE qs.statement_end_offset WHEN -1 THEN datalength(st.TEXT) 

   ELSE qs.statement_end_offset END - qs.statement_start_offset)/2) + 1) AS sql_txt 

, qp.query_plan.value('declare default element namespace "http://schemas.microsoft.com/sqlserver/2004/07/showplan"; 

 (/ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple/@PlanGuideDB)[1]' , 'varchar(100)')  AS [PlanGuideDB]

, qp.query_plan.value('declare default element namespace "http://schemas.microsoft.com/sqlserver/2004/07/showplan"; 

 (/ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple/@PlanGuideName)[1]' , 'varchar(100)')  AS [PlanGuideName]

 ,qp.query_plan

, total_worker_time/execution_count AS AvgCPU 

, total_elapsed_time/execution_count AS AvgDuration 

, (total_logical_reads+total_physical_reads)/execution_count AS AvgReads 

, execution_count 

FROM sys.dm_exec_query_stats qs

cross apply sys.dm_exec_sql_text(sql_handle) st

cross apply sys.dm_exec_query_plan(plan_handle) qp

WHERE qp.query_plan.exist('declare default element namespace "http://schemas.microsoft.com/sqlserver/2004/07/showplan";

 /ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple[(@PlanGuideName)]') = 1

ORDER BY [PlanGuideDB], [PlanGuideName] DESC

The idea of this query is from this post: http://www.scarydba.com/2009/02/12/missing-index-information-and-query-stats/ , which tries to associate missing index info with the query causing it. Basically I used xquery exist funtion to search if there is a keyword 'PlanGuideName' in the XML text.

Here is the sample output screenshot.

As shown in the screenshot, the query works for the Object and SQL type Plan Guide. When comes to the template Plan Guide, I encountered difficulties.

The template Plan Guide was created by the following script, which is used to force replacing literals with parameters for a specific type query. By default, database PARAMEDTERIZATION is set to Simple, which will not be applicable to this type of query that has a two-table join.

USE AdventureWorks;

DECLARE @stmt nvarchar(max);

DECLARE @params nvarchar(max);

EXEC sp_get_query_template

    N' SELECT  SUM(LineTotal) AS LineTotal

       FROM    Sales.SalesOrderHeader H

       JOIN    Sales.SalesOrderDetail D ON D.SalesOrderID = H.SalesOrderID

      WHERE   H.SalesOrderID = 56000',

    @stmt OUTPUT,

    @params OUTPUT



EXEC sp_create_plan_guide

    N'Template_Plan_1',

    @stmt,

    N'TEMPLATE',

    NULL,

    @params,

    N'OPTION(PARAMETERIZATION FORCED)';

GO

Then I run the following test to see if the template Plan Guide works:

use AdventureWorks

go



SELECT  SUM(LineTotal) AS LineTotal

FROM    Sales.SalesOrderHeader H

JOIN    Sales.SalesOrderDetail D ON D.SalesOrderID = H.SalesOrderID

WHERE   H.SalesOrderID = 56001

GO

When checking the estimated plan, in the Show Plan XML window, I can find the following text for the "StmtSimple" node:

StmtSimple StatementCompId="1" StatementEstRows="1" StatementId="1" StatementOptmLevel="FULL" StatementOptmEarlyAbortReason="GoodEnoughPlanFound" StatementSubTreeCost="0.00658091"
StatementText="SELECT SUM(LineTotal) AS LineTotal FROM Sales.SalesOrderHeader H
JOIN Sales.SalesOrderDetail D ON D.SalesOrderID = H.SalesOrderID
WHERE H.SalesOrderID = 56001" StatementType="SELECT"
TemplatePlanGuideDB="AdventureWorks" TemplatePlanGuideName="Template_Plan_1" ParameterizedText="(@0 int)
select SUM ( LineTotal ) as LineTotal from Sales . SalesOrderHeader H join Sales . SalesOrderDetail D on D . SalesOrderID = H . SalesOrderID
where H . SalesOrderID = @0"
QueryHash="0x1170510D7B65D486" QueryPlanHash="0x1B1C9CA6A989FB7C"

It can be noticed that there are "TemplatePlanGuideDB" and "TemplatePlanGuideName" attributes presented, which indicates the template Plan Guide will be used. When checking the acutual plan, in the Show Plan XML window, I see different text than above:

StmtSimple StatementCompId="1" StatementEstRows="1" StatementId="1" StatementOptmLevel="FULL"

StatementOptmEarlyAbortReason="GoodEnoughPlanFound" StatementSubTreeCost="0.00658091"
StatementText="select SUM ( LineTotal ) as LineTotal from Sales . SalesOrderHeader H
join Sales . SalesOrderDetail D on D . SalesOrderID = H . SalesOrderID
where H . SalesOrderID = @0" StatementType="SELECT"
QueryHash="0x1170510D7B65D486" QueryPlanHash="0x1B1C9CA6A989FB7C"

Basically in the actual execution plan XML text, there is no such keywords as 'PlanGuideDBName' or 'TemplatePlanGuideDBName'. Due to the lacking of such marks, the query described previously cannot
be used to answer such a question " Are there any queries using any template Plan Guides now?"

SQL Server - A Procedure to Display Rows as Column

2011-09-23T11:21:00.001-04:00

As an Oracle DBA, I am used to using command line interface (CLI) for my many DBA tasks. When some long rows are output from a query, it is often very unconvenient to view in CLI windows due to text wrapping at certain lengh. Tom Kyte has developed a procedure in Oracle to display rows as column. Here I try to accomolish the same thing in SQL Server.

My procedure is called usp_p, the source code can be downloaded here.

Below is an example of using this procedure.

First of all, here is the script (top10_ela.sql ) that displays top 10 sqls ordered by average execution time:

declare @sqltext varchar(4000)

set @sqltext =
' SELECT   top 10                                                                           '+    
' sql_handle                                                                                '+
' , (SELECT TOP 1 SUBSTRING(s2.text,statement_start_offset / 2+1 ,                          '+ 
'      ( (CASE WHEN statement_end_offset = -1                                               '+ 
'             THEN (LEN(CONVERT(nvarchar(max),s2.text)) * 2)                                '+
'       ELSE statement_end_offset END)  - statement_start_offset) / 2+1))  AS sql_statement '+
'  , (total_elapsed_time/execution_count)/1000 AS [Avg Exec Time in ms]                     '+
'  , max_elapsed_time/1000 AS [MaxExecTime in ms]                                           '+
'  , min_elapsed_time/1000 AS [MinExecTime in ms]                                           '+
'  , (total_worker_time/execution_count)/1000 AS [Avg CPU Time in ms]                       '+
' , qs.execution_count AS NumberOfExecs                                                     '+
' , (total_logical_writes+total_logical_Reads)/execution_count AS [Avg Logical IOs]         '+
' , max_logical_reads AS MaxLogicalReads                                                    '+
' , min_logical_reads AS MinLogicalReads                                                    '+
' , max_logical_writes AS MaxLogicalWrites                                                  '+
' , min_logical_writes AS MinLogicalWrites                                                  '+
' , creation_time                                                                           '+
' , last_execution_time                                                                     '+
' FROM sys.dm_exec_query_stats qs                                                           '+ 
' CROSS APPLY sys.dm_exec_sql_text(sql_handle)  s2                                          '+ 
' WHERE s2.objectid is null                                                                 '+  
' ORDER BY [Avg Exec Time in ms] DESC                                                    '; 



exec testdata.dbo.usp_p @sqltext

go

The output looks like:

$ sqlcmd -i top10_ela.sql


OUTPUT ROWS AS COLUMN

----------------------------------------------
sql_handle                    : 0x02000000f2deb70ac53c5a28f974b9e33fc40ac4696e1f8d
sql_statement                 : select * from big_table

Avg Exec Time in ms           :     733709
MaxExecTime in ms             :     733709
MinExecTime in ms             :     733709
Avg CPU Time in ms            :     733236
NumberOfExecs                 :          1
Avg Logical IOs               :      28634
MaxLogicalReads               :      28634
MinLogicalReads               :      28634
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Sep 22 2011  6:03PM
last_execution_time           : Sep 22 2011  6:03PM
----------------------------------------------
sql_handle                    : 0x020000008c08dc2a83d90353b43ebdf73f967c6071cd7f40
sql_statement                 : update big_table set vc_padding = upper(vc_padding);


Avg Exec Time in ms           :      25434
MaxExecTime in ms             :      25434
MinExecTime in ms             :      25434
Avg CPU Time in ms            :      21236
NumberOfExecs                 :          1
Avg Logical IOs               :      57242
MaxLogicalReads               :      28651
MinLogicalReads               :      28651
MaxLogicalWrites              :      28591
MinLogicalWrites              :      28591
creation_time                 : Sep 23 2011  9:33AM
last_execution_time           : Sep 23 2011  9:33AM
----------------------------------------------
sql_handle                    : 0x02000000f35bee37d4134755a33f598165698922e569daee
sql_statement                 : update big_table set vc_padding = upper(vc_padding) where id > 1 ;

Avg Exec Time in ms           :      20409
MaxExecTime in ms             :      20409
MinExecTime in ms             :      20409
Avg CPU Time in ms            :      12484
NumberOfExecs                 :          1
Avg Logical IOs               :      53364
MaxLogicalReads               :      28637
MinLogicalReads               :      28637
MaxLogicalWrites              :      24727
MinLogicalWrites              :      24727
creation_time                 : Sep 23 2011  9:54AM
last_execution_time           : Sep 23 2011  9:54AM
----------------------------------------------
sql_handle                    : 0x02000000f35bee37d4134755a33f598165698922e569daee
sql_statement                 : update big_table set vc_padding = lower(vc_padding) where id > 2 ;

Avg Exec Time in ms           :      11945
MaxExecTime in ms             :      11945
MinExecTime in ms             :      11945
Avg CPU Time in ms            :      10801
NumberOfExecs                 :          1
Avg Logical IOs               :      32673
MaxLogicalReads               :      28636
MinLogicalReads               :      28636
MaxLogicalWrites              :       4037
MinLogicalWrites              :       4037
creation_time                 : Sep 23 2011  9:54AM
last_execution_time           : Sep 23 2011  9:54AM
----------------------------------------------
sql_handle                    : 0x02000000ce87d72c2c2b99271f90dd3617a175b49fb7654c
sql_statement                 : update big_table set vc_padding = lower(vc_padding);

Avg Exec Time in ms           :      10505
MaxExecTime in ms             :      10505
MinExecTime in ms             :      10505
Avg CPU Time in ms            :       9133
NumberOfExecs                 :          1
Avg Logical IOs               :      57214
MaxLogicalReads               :      28637
MinLogicalReads               :      28637
MaxLogicalWrites              :      28577
MinLogicalWrites              :      28577
creation_time                 : Sep 23 2011  9:43AM
last_execution_time           : Sep 23 2011  9:43AM
----------------------------------------------
sql_handle                    : 0x02000000ce87d72c2c2b99271f90dd3617a175b49fb7654c
sql_statement                 : update  /* 1 */ big_table set vc_padding = lower(vc_padding);

Avg Exec Time in ms           :       2164
MaxExecTime in ms             :       2164
MinExecTime in ms             :       2164
Avg CPU Time in ms            :       2164
NumberOfExecs                 :          1
Avg Logical IOs               :      28634
MaxLogicalReads               :      28634
MinLogicalReads               :      28634
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Sep 23 2011  9:43AM
last_execution_time           : Sep 23 2011  9:44AM
----------------------------------------------
sql_handle                    : 0x02000000ce87d72c2c2b99271f90dd3617a175b49fb7654c
sql_statement                 : update  /* 2 */ big_table set vc_padding = lower(vc_padding);

Avg Exec Time in ms           :       2070
MaxExecTime in ms             :       2070
MinExecTime in ms             :       2070
Avg CPU Time in ms            :       2070
NumberOfExecs                 :          1
Avg Logical IOs               :      28634
MaxLogicalReads               :      28634
MinLogicalReads               :      28634
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Sep 23 2011  9:43AM
last_execution_time           : Sep 23 2011  9:44AM
----------------------------------------------
sql_handle                    : 0x02000000ce87d72c2c2b99271f90dd3617a175b49fb7654c
sql_statement                 : update  /* 4 */ big_table set vc_padding = lower(vc_padding);

Avg Exec Time in ms           :       2054
MaxExecTime in ms             :       2054
MinExecTime in ms             :       2054
Avg CPU Time in ms            :       2054
NumberOfExecs                 :          1
Avg Logical IOs               :      28634
MaxLogicalReads               :      28634
MinLogicalReads               :      28634
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Sep 23 2011  9:43AM
last_execution_time           : Sep 23 2011  9:44AM
----------------------------------------------
sql_handle                    : 0x02000000f35bee37d4134755a33f598165698922e569daee
sql_statement                 : update big_table set vc_padding = lower(vc_padding) where id > 4 ;

Avg Exec Time in ms           :       2050
MaxExecTime in ms             :       2050
MinExecTime in ms             :       2050
Avg CPU Time in ms            :       2050
NumberOfExecs                 :          1
Avg Logical IOs               :      28634
MaxLogicalReads               :      28634
MinLogicalReads               :      28634
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Sep 23 2011  9:54AM
last_execution_time           : Sep 23 2011  9:54AM
----------------------------------------------
sql_handle                    : 0x02000000ce87d72c2c2b99271f90dd3617a175b49fb7654c
sql_statement                 : update  /* 3 */ big_table set vc_padding = lower(vc_padding);

Avg Exec Time in ms           :       1924
MaxExecTime in ms             :       1924
MinExecTime in ms             :       1924
Avg CPU Time in ms            :       1924
NumberOfExecs                 :          1
Avg Logical IOs               :      28634
MaxLogicalReads               :      28634
MinLogicalReads               :      28634
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Sep 23 2011  9:43AM
last_execution_time           : Sep 23 2011  9:44AM
----------------------------------------------

Note: I did not verify that every data type can be shown properly as of now, I will probably have to modify the code as time goes

SQL Server - Create a Policy to Enfore Naming Convention on Stored Procedure

2011-09-21T14:26:00.000-04:00

In SQL Server 2008, assuming we need to enforce a naming standard on stored procedures:
All stored procedures in the database (TestData) must start with "usp_" - ("usp" stands for user stored procedure).

Step 1 Create the Condition

In Object Explorer, expand Management, expand Policy Management, expand Conditions, right-click the Conditions node and then click New Condition.
On the Create New Condition, General page, in the Name box, type the name of the new condition: SP Naming
Select the Multipart Name facet in the Facet box.
In the Expression area, construct the condition expressions : @Name like 'usp_%'.
On the Description page, type a description and then click OK.

Step 2 Create the Policy

In Object Explorer, expand Management, expand Policy Management, right-click Policies, and then click New Policy.
On the Create New Policy, General page, in the Name box, type the name of the new policy: SP Naming Policy.
If you want the policy to be enabled as soon as it is created, select the Enabled check box.
If the evaluation mode is On demand, the Enabled check box is not available.
In the Check condition box, select the existing condition: SP Naming. To edit the condition, select the condition and then click the build (...) button.
In the Against targets box, select the Every StoredProcedure target. Create a new condition TestData DB Only in the Database Node (Facet: Database, Condition: @Name='testdata').
In the Evaluation Mode box, select how this policy will behave: On Change: Prevent. Different conditions can have different valid evaluation modes.
To limit the policy to subset of the target types, in the Server restriction box, select from limiting conditions or create a new condition.
On the Description page, in the Category box, select an optional policy category or create a new one.
Type n optional description of the policy.
Click OK.

When the policy is enabled, trying to create a procedure that violates the policy, the following message is received:

Changed database context to 'testdata'.
Policy 'SP Naming Policy' has been violated by 'SQLSERVER:\SQL\TUSNC012LKVT006\DEFAULT\Databases\testdata\StoredProcedures\dbo.HelloWorld3_proc'.
This transaction will be rolled back.
Policy condition: '@Name LIKE 'usp_%''
Policy description: ''
Additional help: '' : ''
Statement: '
create procedure HelloWorld3_proc
as
select 'HelloWorld'
'.
Msg 3609, Level 16, State 1, Server TUSNC012LKVT006, Procedure sp_syspolicy_dispatch_event, Line 65
The transaction ended in the trigger. The batch has been aborted.

SQL Server - test case showing rows moved when creating a clustered index

2011-09-08T18:39:00.024-04:00

Recently I have determined to study SQL Server. Of course, this is not the first time I attempt to do so. Just this time I decided not to spend time on Oracle voluntarily and to concentrate on SQL server instead.

I have noticed that in SQL Server it is highly recommended that every table should have a clustered index. A table with a clustered index (CI) conceptually corresponds to the Index Organized Table (IOT) in Oracle. Basically, the leaf node of the index contains the data block (called B+ tree index). I also found a blog post that attempted to explain why SQL Server needs to use CI to achieve performance while IOT is not used in Oracle as widely as the CI in SQL Sever. But I am still not very clear about the reasons after reading the post.

If a table does not have a CI and we want to create CI on it, the existing rows should be reorganized to occupy the pages in the sorted key order. This is what I try to confirm with the following test case.

Test case:

-- script: rowmove.sql
-- purpose: demonstrate table rows moved when creating clustered index
-- env    : SQL Server 2008
--

:setvar sqlcmdheaders            40     -- "page size"
:setvar sqlcmdcolwidth          132     -- line width
:setvar sqlcmdmaxfixedtypewidth  32     -- max column width (fixed length)
:setvar sqlcmdmaxvartypewidth    32     -- max column width (varying length)

USE testdata
go

IF OBJECT_ID ( 'mytable', 'U' ) IS NOT NULL 
DROP TABLE mytable;
GO


CREATE TABLE mytable
 (
  id  INT,
  col1 VARCHAR(2000),
  col2 VARCHAR(2000));

INSERT INTO mytable
SELECT 1, REPLICATE('a', 2000), REPLICATE('b', 2000);

INSERT INTO mytable
SELECT 4, REPLICATE('a', 2000), REPLICATE('b', 2000);


INSERT INTO mytable
SELECT 2, REPLICATE('a', 2000), REPLICATE('b', 2000);

INSERT INTO mytable
SELECT 3, REPLICATE('a', 2000), REPLICATE('b', 2000);


go

select 
       a.%%physloc%%                          AS Address,
       sys.fn_PhysLocFormatter(a.%%physloc%%) AS AddressText,
       a.id
FROM   mytable a
ORDER BY 2;
go

print " "
print "  ----  After created clustered index on ID ----"
print " "

go

create unique clustered index index01 
on mytable(id);
go

select 
       a.%%physloc%%                          AS Address,
       sys.fn_PhysLocFormatter(a.%%physloc%%) AS AddressText,
       a.id
FROM   mytable a
ORDER BY 2;
go

Test output:

Changed database context to 'testdata'.

(1 rows affected)
Address    AddressText                      id         
---------- -------------------------------- -----------
0xFA420000 (1:17146:0)                                1
0xFA420000 (1:17146:1)                                4
0xFD420000 (1:17149:0)                                2
0xFD420000 (1:17149:1)                                3

(4 rows affected)
 
  ----  After created clustered index on ID ----
 
Address    AddressText                      id         
---------- -------------------------------- -----------
0x99000000 (1:153:0)                                  3
0x99000000 (1:153:1)                                  4
0xFE420000 (1:17150:0)                                1
0xFE420000 (1:17150:1)                                2

(4 rows affected)

It can be seen that in this test case one page can hold maximum 2 table rows. At the begining, table rows with id=1 and 4 reside on page 17146, and with id=2,3 resides on page 17149. This is understandable as we inserted the rows in the order of 1,4,2,3. After create a CI on ID column, the rows with id=1,2 moved to page 153 and rows with id=3,4 moved to page 17150. So the rows occupies the pages in the sorted order of ID. It should be noted that the pages that belong to the table do not need to physically on the disk files closely to each other.

Setting CUROSR_SHARING To FORCE causes large amount of child cursors for an insert statement

2011-05-11T17:11:00.003-04:00

In a pre-production test, we found out that application did not use bind variables and there was no time to change code before the production rollout. So we suggested changing CURSOR_SHARING parameter from EXACT to FORCE in order to turn hard parse to soft parse. When testing this change for the two webservice functions , which mainly consists of two inserts, one update and bunch of select statements, the results are promising:

Summary of testing results from 15 min interval AWR reports from a 4-node 11.2.0.2 RAC database

2-node test (CURSOR_SHARING=EXACT)

dd1    DB Time:   23.04 (mins)  143 tx/s   Parses: 440.7 per sec  Hard parses: 315.2 per sec       
dd4    DB Time:   23.35 (mins)  140 tx/s   Parses: 414.4 per sec  Hard parses: 303.5 per sec               


2-node test (CURSOR_SHARING=FORCE)

dd1   DB Time:    16.68 (mins)  146 tx/s   Parses: 383.9 per sec  Hard parses: 2.6 per sec
dd4   DB Time:    16.01 (mins)  147 tx/s   Parses: 384.2 per sec  Hard parses: 2.6 per sec


-- dd1  Time Model Statistics (CURSOR_SHARING=FORCE) 
 
Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                                666.6         66.6
DB CPU                                                  350.0         35.0
parse time elapsed                                       80.0          8.0
hard parse elapsed time                                  15.1          1.5
hard parse (sharing criteria) elapsed time                1.7           .2
PL/SQL execution elapsed time                             1.1           .1
hard parse (bind mismatch) elapsed time                   1.0           .1
PL/SQL compilation elapsed time                           0.8           .1
connection management call elapsed time                   0.4           .0
sequence load elapsed time                                0.4           .0
repeated bind elapsed time                                0.0           .0
DB time                                               1,000.9
background elapsed time                                 200.0
background cpu time                                     143.9
          -------------------------------------------------------------
 
-- dd1  Time Model Statistics (CURSOR_SHARING=EXACT) 

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
DB CPU                                                  728.2         52.7
sql execute elapsed time                                632.9         45.8
parse time elapsed                                      481.2         34.8
hard parse elapsed time                                 390.0         28.2
hard parse (sharing criteria) elapsed time                3.2           .2
hard parse (bind mismatch) elapsed time                   2.9           .2
PL/SQL execution elapsed time                             1.4           .1
PL/SQL compilation elapsed time                           1.2           .1
connection management call elapsed time                   0.5           .0
sequence load elapsed time                                0.5           .0
repeated bind elapsed time                                0.0           .0
failed parse elapsed time                                 0.0           .0
DB time                                               1,382.4
background elapsed time                                 261.8
background cpu time                                     115.5
          -------------------------------------------------------------

Bascially, we saw hard parse was greatly reduced. For the same level transaction rate, DB time was reduced from 46 min to 32 min after changing to FORCE. However, when another module was enabled and added to the two webserverice workload, things went wrong. We saw large amount of "cursor:mutex S" and "liberary cache lock" waits (>80% DB time). We identified an insert statement that has large amount of child cursors ( ~ 8000) caused the problem.

Below is a test case demonstrating large number of child cursors are created with CURSOR_SHARING=FORCE:

Test case 1

This test was carried out to repeat what we encountered in our pre-production test. Inserts into a table called MY_STB_LOG2 were performed with CUROSR_SHARING=FORCE, with 324 total number of inserts similar to the following:

insert into MY_STB_LOG2 values('0000043862420080','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-04 07:51:40.000',timestamp'2011-05-04 02:20:45.000',timestamp'2011-05-04 02:35:07.000','N','N','','','','P',SYSDATE);
insert into MY_STB_LOG2 values('0000048201268050','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:02:07.000',timestamp'2011-05-04 21:10:22.000','','N','N','','','','P',SYSDATE);

After run, checking v$sqlarea and v$sql, we got:

SQL> select sql_text,sql_id, executions from v$sqlarea where sql_text like 'insert into MY_STB_LOG2%';
 
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
SQL_ID        EXECUTIONS
------------- ----------
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",:"SYS
_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
16yq35g1c433b         71
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",:"SYS_B_04",:"
SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
4yzz9r14n53fg         28
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",times
tamp:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
gpb19na8zd67s        210
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",timestamp:"SYS
_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
6ua1jndb5ud4x         15


SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;

SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;
 
SQL_ID          COUNT(*)
------------- ----------
gpb19na8zd67s        210
16yq35g1c433b         71
4yzz9r14n53fg         28
6ua1jndb5ud4x         15

It can be seen that we have 4 versions of insert statements after literals are replaced by system-generated bind varialbes. For each version, the execution times equal to the number of its child cursors. It indicates for every insert, Oracle actually does hard parse with extra cost to search child cursors.

When using Dion's script to query v$sql_shared_cursor, we can see the reason for unshared cursor is "HASH_MATCH_FAILED"

--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 0000000093C96F80
CHILD_NUMBER = 68
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 00000000AB5E4300
CHILD_NUMBER = 69
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 000000013C695090
CHILD_NUMBER = 70
HASH_MATCH_FAILED = Y
--------------------------------------------------

It should be noted that even application using the bind varialbe, this problem could occur. One possible solution is to use PL/SQL procedure to do the insert:

Test case 2

I create a procedure STB_INS (see appendix) to insert into a table called MY_STB_LOG3 ( same structure as LOG2), then I run 324 exec procedure such as:

exec STB_INS('0001097562293114','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:30:01.000',timestamp'2011-05-05 00:20:03.000',timestamp'2011-05-04 23:42:57.000','N','N','','','','P',SYSDATE);

exec STB_INS('0000027988805135','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:46:21.000',timestamp'2011-05-05 01:02:54.000',timestamp'2011-05-04 22:55:10.000','N','N','','','','P',SYSDATE);

After run, check v$sqlarea and v$sql

SQL>  select sql_id, sql_text, executions from v$sqlarea where sql_text like '%MY_STB_LOG3%';

SQL_ID
-------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
EXECUTIONS
----------
4fdv39rhjag5n
INSERT INTO MY_STB_LOG3 VALUES( :B13 ,:B12 ,:B11 ,:B10 ,:B9 ,:B8 ,:B7 ,:B6 ,:B5 ,:B4 ,:B3 ,:B2 ,:B1 )
       324



SQL> select count(*) from v$sql where sql_id='4fdv39rhjag5n';

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

We see 324 executions shared same cursor.

Appendix

create or replace procedure stb_ins(
p_UNIT_ADDRESS             VARCHAR2
,p_BATCH_NUMBER            VARCHAR2
,p_RECEIVED_TIME           TIMESTAMP
,p_LAST_LOG_TIME           TIMESTAMP
,p_POWERON_TIME            TIMESTAMP
,p_POWEROFF_TIME           TIMESTAMP
,p_UNAVAILABLE_FLAG        VARCHAR2
,p_UNSUBSCRIBE_FLAG        VARCHAR2
,p_WORK_ID                 VARCHAR2
,p_STATUS_CODE             VARCHAR2
,p_STATUS_DESC             VARCHAR2
,p_PROC_STATUS             VARCHAR2
,p_CREATE_DATE             DATE
) 
is
begin
  insert into my_stb_log3 values(
               p_UNIT_ADDRESS           
                ,p_BATCH_NUMBER          
                ,p_RECEIVED_TIME         
                ,p_LAST_LOG_TIME         
                ,p_POWERON_TIME          
                ,p_POWEROFF_TIME         
                ,p_UNAVAILABLE_FLAG      
                ,p_UNSUBSCRIBE_FLAG      
                ,p_WORK_ID               
                ,p_STATUS_CODE           
                ,p_STATUS_DESC           
                ,p_PROC_STATUS            
                ,p_CREATE_DATE            
  );
  commit;
end;
/

Index rebuild and archival procedure

2011-04-11T15:30:00.000-04:00

I administer one of the production databases that supports retail ordering application. We have an archival procedure that archives old orders. Last weekend, I rebuilt all of the indexes of 5 tables against which the delete statements in the archival procedure are identified most expensive. The total size of those indexes are reduced by 460GB after rebuild. After the rebuild, the archival of 350K orders took 1h40min compared to 2h30min typically before rebuild. The reason for the performance improvement as far as I can see are as follows:

(1) Decreasing the number of gets in the index range scan operation due to indexes are more compressed
(2) Increasing the chances of caching, thus reducing the need to wait for db file sequential read.
For example, let's say, index entry 1 is in block 1 and entry 2 is in block 2 before rebuild, so Oracle needs to read block1 and 2 to the buffer cache to delete them; while after rebuild both entry 1 and entry 2 could be in block 1, so Oracle needs to read block 1 once and can work on two entries.

Among those 5 tables, the top-most expensive delete is the one from a table called ORDER_TRANS. There is an index called ORDER_TRANS_IX4 of this table is 16GB after rebuild as compared to 150GB before rebuild. Why is the index so sparse? The index is on the LAST_MODIFIED_DATE column of the table. This is a typical right-hand index, i.e. new index key entries are added to the right hand size of the index tree. The key value is monotonically increasing, like a sequence-based PK. If assuming a leaf block of the index can hold 360 index entries, 99.9% blocks (hold <=180 entries) are >50% empty; 97.5% blocks (hold <=90 entries) are >75% empty. (see appendix) .The reasons that why especially right-hand index can grow bigger are described in a Jonathan Lewis's blog post. In my particular case, I believe the problems of the archival procedure itself contribute to the sparsity of the index greatly.

The candidate orders that are eligible for archiving is based on certain business logic. However I found that there are very old orders. e.g. competed in 2004, 2005, that are not selected out for archiving. I confirmed with a lead developer who called those orders "fallout" that those orders should be updated so that they could become eligible for archiving long time ago. In addition, the orders are not selected based on the increasing order of its completion date or cancel date. We can imagine that if we really archive old orders based on their completion or cancel date, i.e, the older the earlier to be archived, we won't have that sparse index in the first place, because left-hand size leaf block can become empty much sooner and easily and thus reused.

In summary, it appears that rebuild index improves our archival procedure performance; however, we may want to look it in the other way around. If the old orders are really archived based on common sense, we probably don't need to rebuild index at all.

Appendix - How the leaf blocks of ORDER_TRANS_IX4 are used based on JL's script. ( Sample 5% blocks)

ROWS_PER_BLOCK     BLOCKS     ROW_CT CUMULATIVE_BLOCKS
-------------- ---------- ---------- -----------------
             1      16232      16232             16232
             2      14696      29392             30928
             3      13739      41217             44667
             4      13840      55360             58507
             5      13316      66580             71823
             6      13859      83154             85682
             7      13787      96509             99469
             8      13842     110736            113311
             9      13937     125433            127248
            10      14127     141270            141375
            11      14244     156684            155619
            12      14528     174336            170147
            13      14566     189358            184713
            14      15005     210070            199718
            15      15150     227250            214868
            16      15492     247872            230360
            17      15868     269756            246228
            18      16015     288270            262243
            19      16026     304494            278269
            20      16217     324340            294486
            21      16106     338226            310592
            22      16121     354662            326713
            23      16257     373911            342970
            24      15860     380640            358830
            25      15912     397800            374742
            26      15920     413920            390662
            27      15859     428193            406521
            28      15462     432936            421983
            29      15288     443352            437271
            30      15095     452850            452366
            31      15346     475726            467712
            32      15000     480000            482712
            33      14832     489456            497544
            34      14719     500446            512263
            35      14147     495145            526410
            36      13925     501300            540335
            37      13671     505827            554006
            38      13452     511176            567458
            39      13278     517842            580736
            40      13109     524360            593845
            41      13040     534640            606885
            42      12801     537642            619686
            43      12338     530534            632024
            44      11986     527384            644010
            45      11732     527940            655742
            46      11123     511658            666865
            47      11126     522922            677991
            48      10896     523008            688887
            49      10546     516754            699433
            50      10178     508900            709611
            51       9644     491844            719255
            52       9593     498836            728848
            53       9208     488024            738056
            54       9009     486486            747065
            55       8421     463155            755486
            56       8393     470008            763879
            57       7992     455544            771871
            58       7651     443758            779522
            59       7329     432411            786851
            60       6941     416460            793792
            61       6662     406382            800454
            62       6526     404612            806980
            63       6320     398160            813300
            64       5864     375296            819164
            65       5687     369655            824851
            66       5334     352044            830185
            67       5182     347194            835367
            68       4953     336804            840320
            69       4728     326232            845048
            70       4379     306530            849427
            71       4219     299549            853646
            72       4124     296928            857770
            73       3769     275137            861539
            74       3737     276538            865276
            75       3553     266475            868829
            76       3268     248368            872097
            77       3102     238854            875199
            78       3010     234780            878209
            79       2860     225940            881069
            80       2608     208640            883677
            81       2552     206712            886229
            82       2408     197456            888637
            83       2238     185754            890875
            84       2236     187824            893111
            85       1989     169065            895100
            86       1883     161938            896983
            87       1737     151119            898720
            88       1705     150040            900425
            89       1627     144803            902052
            90       1479     133110            903531
            91       1447     131677            904978
            92       1314     120888            906292
            93       1316     122388            907608
            94       1207     113458            908815
            95       1258     119510            910073
            96       1065     102240            911138
            97       1049     101753            912187
            98        974      95452            913161
            99        927      91773            914088
           100        919      91900            915007
           101        877      88577            915884
           102        828      84456            916712
           103        794      81782            917506
           104        666      69264            918172
           105        635      66675            918807
           106        617      65402            919424
           107        549      58743            919973
           108        458      49464            920431
           109        475      51775            920906
           110        292      32120            921198
           111        243      26973            921441
           112        244      27328            921685
           113        201      22713            921886
           114        219      24966            922105
           115        169      19435            922274
           116        150      17400            922424
           117        167      19539            922591
           118        177      20886            922768
           119        128      15232            922896
           120        135      16200            923031
           121        140      16940            923171
           122        134      16348            923305
           123        130      15990            923435
           124         99      12276            923534
           125        107      13375            923641
           126        104      13104            923745
           127         84      10668            923829
           128        106      13568            923935
           129         86      11094            924021
           130         68       8840            924089
           131         97      12707            924186
           132         71       9372            924257
           133         71       9443            924328
           134         61       8174            924389
           135         72       9720            924461
           136         82      11152            924543
           137         48       6576            924591
           138         72       9936            924663
           139         64       8896            924727
           140         58       8120            924785
           141         41       5781            924826
           142         41       5822            924867
           143         35       5005            924902
           144         45       6480            924947
           145         39       5655            924986
           146         37       5402            925023
           147         32       4704            925055
           148         39       5772            925094
           149         26       3874            925120
           150         25       3750            925145
           151         38       5738            925183
           152         33       5016            925216
           153         34       5202            925250
           154         36       5544            925286
           155         33       5115            925319
           156         29       4524            925348
           157         33       5181            925381
           158         25       3950            925406
           159         22       3498            925428
           160         34       5440            925462
           161         22       3542            925484
           162         21       3402            925505
           163         21       3423            925526
           164         22       3608            925548
           165         21       3465            925569
           166         25       4150            925594
           167         19       3173            925613
           168         17       2856            925630
           169         16       2704            925646
           170         15       2550            925661
           171         17       2907            925678
           172          9       1548            925687
           173          9       1557            925696
           174         17       2958            925713
           175         13       2275            925726
           176         16       2816            925742
           177         13       2301            925755
           178         14       2492            925769
           179         10       1790            925779
           180          7       1260            925786
           181          7       1267            925793
           182          6       1092            925799
           183          9       1647            925808
           184          7       1288            925815
           185          7       1295            925822
           186          9       1674            925831
           187          6       1122            925837
           188          8       1504            925845
           189          5        945            925850
           190          7       1330            925857
           191          5        955            925862
           192          9       1728            925871
           193          6       1158            925877
           194          5        970            925882
           195          8       1560            925890
           196          8       1568            925898
           197          9       1773            925907
           198          6       1188            925913
           199          5        995            925918
           200          3        600            925921
           201          2        402            925923
           202          6       1212            925929
           203          5       1015            925934
           204          5       1020            925939
           205          4        820            925943
           206          5       1030            925948
           207          3        621            925951
           209          1        209            925952
           210          5       1050            925957
           211          3        633            925960
           212          3        636            925963
           213          3        639            925966
           214          4        856            925970
           215          3        645            925973
           216          1        216            925974
           217          2        434            925976
           218          4        872            925980
           219          3        657            925983
           220          2        440            925985
           221          2        442            925987
           222          2        444            925989
           223          4        892            925993
           224          2        448            925995
           225          2        450            925997
           226          2        452            925999
           227          2        454            926001
           228          1        228            926002
           229          4        916            926006
           230          5       1150            926011
           231          2        462            926013
           232          3        696            926016
           233          2        466            926018
           234          1        234            926019
           235          5       1175            926024
           236          3        708            926027
           237          3        711            926030
           239          3        717            926033
           240          4        960            926037
           241          4        964            926041
           242          1        242            926042
           243          2        486            926044
           244          5       1220            926049
           245          3        735            926052
           246          2        492            926054
           248          1        248            926055
           249          1        249            926056
           250          2        500            926058
           252          4       1008            926062
           255          4       1020            926066
           256          4       1024            926070
           257          2        514            926072
           258          1        258            926073
           259          4       1036            926077
           261          1        261            926078
           262          2        524            926080
           263          1        263            926081
           264          2        528            926083
           265          1        265            926084
           266          2        532            926086
           267          4       1068            926090
           268          2        536            926092
           269          2        538            926094
           271          1        271            926095
           272          1        272            926096
           273          3        819            926099
           275          2        550            926101
           277          1        277            926102
           278          1        278            926103
           279          1        279            926104
           280          2        560            926106
           281          1        281            926107
           283          1        283            926108
           284          3        852            926111
           285          1        285            926112
           286          3        858            926115
           288          2        576            926117
           289          1        289            926118
           290          1        290            926119
           291          2        582            926121
           292          3        876            926124
           293          3        879            926127
           294          1        294            926128
           295          1        295            926129
           296          1        296            926130
           297          2        594            926132
           298          2        596            926134
           299          1        299            926135
           301          1        301            926136
           302          4       1208            926140
           305          1        305            926141
           306          1        306            926142
           308          1        308            926143
           309          3        927            926146
           310          1        310            926147
           313          1        313            926148
           314          1        314            926149
           315          2        630            926151
           317          1        317            926152
           318          2        636            926154
           319          1        319            926155
           320          2        640            926157
           321          2        642            926159
           322          3        966            926162
           323          2        646            926164
           324          2        648            926166
           325          1        325            926167
           326          1        326            926168
           327          2        654            926170
           328          3        984            926173
           329          3        987            926176
           330          3        990            926179
           331          2        662            926181
           332          2        664            926183
           333          2        666            926185
           334          2        668            926187
           335          2        670            926189
           336          1        336            926190
           337          2        674            926192
           338          3       1014            926195
           340          3       1020            926198
           341          3       1023            926201
           342          1        342            926202
           343          3       1029            926205
           344          6       2064            926211
           345          4       1380            926215
           346          2        692            926217
           347          2        694            926219
           348          4       1392            926223
           349          4       1396            926227
           350          5       1750            926232
           351          3       1053            926235
           352          4       1408            926239
           354          3       1062            926242
           355          5       1775            926247
           356          5       1780            926252
           357          4       1428            926256
           358          6       2148            926262
           359          2        718            926264
           360          6       2160            926270
           361          9       3249            926279
           362          6       2172            926285
           363          5       1815            926290
           364          6       2184            926296
           365          9       3285            926305
           366         11       4026            926316
           367         43      15781            926359
               ---------- ----------
sum                926359   32433921

How can I confirm there was an I/O problem (2) ?

2011-02-28T19:47:00.000-05:00

In a previous post, I have mentioned that I have tried to mine AWR data to confirm an I/O issue occurred around 2:18 PM of Feb 18; however I encountered some issue and instead found out 'sar' was helpful. Today, I worked out the query against AWR tables. The query is as follows:

rem  awr_io_file_smpl.sql  
rem   -- Adapted from the scripts written by Karl Arao: http://karlarao.wordpress.com
rem
rem  check if there are I/O problem from AWR. 
rem  normally atpr (Average time per read)  should be less than 20 ms
rem  if atpr > 100 ms, it obviously indicates that we have problem
rem   
rem  note: the statistics are based on  (tm-interval, tm)
rem    


col atpr format 999,999
col atpw format 999,999

set echo off
-- set markup HTML ON
-- SPOOL ON ENTMAP ON PREFORMAT OFF
-- spool awr_io_file_smpl.html
spool awr_io_file_smpl.log
select * from (
SELECT 
--      s0.snap_id snap_id,
       to_char(s1.END_INTERVAL_TIME, 'YYMMDD HH24:MI') tm,
--      s0.instance_number inst,
       ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2) dur,
--      e.tsname,
      e.file# ,
--      SUBSTR(e.filename, 1, 52) filename ,
--      e.readtim         - NVL(b.readtim,0) readtim ,
      e.phyrds          - NVL(b.phyrds,0) reads ,
      DECODE ((e.phyrds - NVL(b.phyrds, 0)), 0, to_number(NULL), ((e.readtim - NVL(b.readtim,0)) 
                   / (e.phyrds - NVL(b.phyrds,0)))*10) atpr ,
--      (e.phyrds         - NVL(b.phyrds,0)) / ((ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2))*60) rps  ,
--      DECODE ((e.phyrds  - NVL(b.phyrds, 0)), 0, to_number(NULL), (e.phyblkrd - NVL(b.phyblkrd,0)) / (e.phyrds - NVL(b.phyrds,0)) ) bpr ,
--      e.writetim         - NVL(b.writetim,0) writetim ,
      e.phywrts          - NVL(b.phywrts,0) writes ,
      DECODE ((e.phywrts - NVL(b.phywrts, 0)), 0, to_number(NULL), ((e.writetim - NVL(b.writetim,0)) / (e.phywrts - NVL(b.phywrts,0)))*10) atpw ,
--      (e.phywrts         - NVL(b.phywrts,0)) / ((ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2))*60) wps ,
--      DECODE ((e.phywrts    - NVL(b.phywrts, 0)), 0, to_number(NULL), (e.phyblkwrt - NVL(b.phyblkwrt,0)) / (e.phywrts - NVL(b.phywrts,0)) ) bpw ,
--      e.wait_count          - NVL(b.wait_count,0) waits ,
--      DECODE ((e.wait_count - NVL(b.wait_count, 0)), 0, 0, ((e.time - NVL(b.time,0)) / (e.wait_count - NVL(b.wait_count,0)))*10) atpwt,
      (e.phyrds             - NVL(b.phyrds,0)) + (e.phywrts - NVL(b.phywrts,0)) ios,
      ((e.phyrds            - NVL(b.phyrds,0)) + (e.phywrts - NVL(b.phywrts,0))) / ((ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2))*60) iops
    FROM dba_hist_snapshot s0,
      dba_hist_snapshot s1,
      dba_hist_filestatxs e,
      dba_hist_filestatxs b
    WHERE s0.dbid =(select dbid from v$database)
    AND s1.dbid            = s0.dbid
    AND b.dbid(+)          = s0.dbid -- begin dbid
    AND e.dbid             = s0.dbid -- end dbid
    AND b.dbid             = e.dbid  -- remove oj
    AND s0.instance_number =dbms_utility.CURRENT_INSTANCE
    AND s1.instance_number = s0.instance_number
    AND b.instance_number(+) = s0.instance_number 
    AND e.instance_number    = s0.instance_number 
    AND b.instance_number    = e.instance_number 
    AND s1.snap_id           = s0.snap_id + 1
    AND b.snap_id(+)         = s0.snap_id      
    AND e.snap_id            = s0.snap_id + 1 
    AND b.tsname             = e.tsname      
    AND b.file#              = e.file#           
    AND b.creation_change#   = e.creation_change# 
    AND ((e.phyrds - NVL(b.phyrds,0)) + (e.phywrts - NVL(b.phywrts,0))) > 0
    AND s0.END_INTERVAL_TIME >= to_date('2011-02-18 13:00:00', 'YYYY-MM-DD HH24:MI:SS') 
    AND s0.END_INTERVAL_TIME <= to_date('2011-02-18 16:00:00', 'YYYY-MM-DD HH24:MI:SS') 
    order by s1.END_INTERVAL_TIME, e.tsname
--    and b.tsname='xxxx'
)
where atpr > 100 
;
spool off
set markup html off spool off
set termout on

The output of above query is as follows:

TM                  DUR      FILE#      READS     ATPR     WRITES     ATPW        IOS       IOPS
------------ ---------- ---------- ---------- -------- ---------- -------- ---------- ----------
110218 14:00      15.04        268          8      124          1        0          9 .009973404
110218 14:00      15.04        283          7      141          1        0          8 .008865248
110218 14:00      15.04        281          8      118          1        0          9 .009973404
110218 14:00      15.04        296          8      116          1        0          9 .009973404
110218 14:00      15.04        273          8      123          1        0          9 .009973404
110218 14:00      15.04        293          8      123          1        0          9 .009973404
110218 14:00      15.04        288          8      125          1        0          9 .009973404
110218 14:00      15.04        276          8      120          1        0          9 .009973404
110218 14:00      15.04        286          7      133          1        0          8 .008865248
110218 14:00      15.04        278          8      123          1        0          9 .009973404
110218 14:00      15.04        308          8      125          1        0          9 .009973404
110218 14:00      15.04        271          8      116          1        0          9 .009973404
110218 14:00      15.04        248          7      139          1       10          8 .008865248
110218 14:30       14.6        502       3472      205        620      816       4092 4.67123288
110218 14:30       14.6        519        351    1,695         72    1,749        423 .482876712
110218 14:30       14.6        515        664      347         90        6        754 .860730594
110218 14:30       14.6        504       1174      214        114    1,107       1288 1.47031963
110218 14:30       14.6        448       8463      139        550      461       9013 10.2888128
110218 14:30       14.6        412       5772      131        361      353       6133 7.00114155
110218 14:30       14.6        462       5889      215        437      291       6326 7.22146119
110218 14:30       14.6        429      10276      313        356      360      10632 12.1369863
110218 14:30       14.6        427       4255      189        183      691       4438 5.06621005
110218 14:30       14.6        473       7355      298        865      149       8220 9.38356164
110218 14:30       14.6        513        867      148        218      587       1085 1.23858447
110218 14:30       14.6        479       5903      196        986      144       6889 7.86415525
110218 14:30       14.6        475       7702      263       1163      221       8865  10.119863
110218 14:30       14.6        471       9543      155        141      906       9684 11.0547945
110218 14:30       14.6        523       2187      378       1014      253       3201 3.65410959
110218 14:30       14.6        482       6674      150       1536      252       8210 9.37214612
110218 14:30       14.6        437      10793      271       1920      401      12713 14.5125571
110218 14:30       14.6        395       8062      151        555      233       8617 9.83675799
110218 14:30       14.6        464      19537      431       4212      144      23749 27.1107306
110218 14:30       14.6        491      14568      440       4247      220      18815 21.4783105
110218 14:30       14.6        444      20026      385       2541      212      22567 25.7614155
110218 14:30       14.6        481      15496      444       3763      287      19259 21.9851598
110218 14:30       14.6        421      14930      334       1642       85      16572 18.9178082
110218 14:30       14.6        514       5464      597       2542      360       8006 9.13926941
110218 14:30       14.6        435       3804      165        167      751       3971 4.53310502
110218 14:30       14.6        512       2065      237        474      276       2539 2.89840183
110218 14:30       14.6        498       4540      186        508      993       5048 5.76255708
110218 14:30       14.6        478       8505      159       1161      561       9666 11.0342466
110218 14:30       14.6        470       8134      182        454      283       8588 9.80365297
110218 14:30       14.6        460       4841      168        391      325       5232 5.97260274
110218 14:30       14.6        474       6486      130        779      166       7265   8.293379
110218 14:30       14.6        411       3368      291        186      678       3554 4.05707763
110218 14:30       14.6        521       2447      183        543      235       2990 3.41324201
110218 14:30       14.6        418       3837      124        128      991       3965 4.52625571
110218 14:30       14.6        100        160    1,370        670      213        830 .947488584
110218 14:30       14.6        139        408      273       1061      366       1469 1.67694064
110218 15:00      15.03         62          4      103          1       10          5 .005544467
110218 15:30      15.04         69          6      107          2        0          8 .008865248
110218 15:30      15.04         62          6      102          2        5          8 .008865248
110218 15:30      15.04         63          6      102          2        5          8 .008865248
110218 15:30      15.04         64          6      107          2        5          8 .008865248
110218 15:30      15.04         78          6      113          2        5          8 .008865248
110218 15:30      15.04         77          6      107          2       10          8 .008865248
110218 15:30      15.04         66          6      107          2        5          8 .008865248
110218 16:00      15.04        125          6      282          1      180          7 .007757092
110218 16:00      15.04        110          6      282          1       70          7 .007757092

59 rows selected.

From the above output, it can be seen from about 14:15 -14:30, there are many data files having APTR > 100 ms. This clearly indicates there was I/O problem during that period.

A simple concept map for some basic storage terms

2011-02-28T13:39:00.000-05:00

Ref:
[1] NetApp University “Data ONTAP 7.3 Fundamentals” Version 5.0

[2] Using Oracle10 g™ Database Automatic Storage Management with Network Appliance™ Storage (2004 White paper, PDF)

Tip - List all of the tables in the Shareplex replication

2011-02-22T17:36:00.000-05:00

Some time ago a co-worker showed me how to do this with a query. Today I have a need to do it, but I forget. I have to get the table list from the configuration file. Now I blog this as a reference for future:

--- for port 2200 ---
select owner, object_name, objid
from splex.shareplex_objmap s, dba_objects o
where s.objid = o.object_id 
order by owner, object_name;

--- for port 2201 ----
select owner, object_name, objid
from splex_cpf.shareplex_objmap s, dba_objects o
where s.objid = o.object_id 
order by owner, object_name;

How can I confirm there was an I/O problem?

2011-02-22T10:59:00.001-05:00

Last Friday afternoon , our production support team ( this team manages application servers in my working environment) reported that arounnd 2:18 PM there were application queuing and some job time-out issues. Naturally, as a knee-jerk reaction, the problem was described as "Database is slow". Later, some "SCSI trans" errors are found somewhere , which indicated there were some I/O problem. So my question is as a DBA, how can I confirm there is an I/O problem?

At first, I tried to look into the AWR data. I modified awr_io_file.sql script by Karl Arao , in hope to report Average time per read time for the data file during the problem period. However, the script was running more than 20 min without results. I killed the job and decided to research on this mining AWR data approach later. BTW, one drawback I am aware of is that even I can get this data, it will be averaged over 15 min (our AWR snapshot interval). Averaging could hide the real problem.

After googling a while, I found that 'sar' utility in my Solaris platform can shed some light on I/O issue in the recent past history.

If we do 'man sar', we can found the following description about sar -f option:

sar [-aAbcdgkmpqruvwy] [-e time] [-f filename]  [-i sec]  [-s time]

sar  extracts  data  from  a  previously  recorded filename,
either the one specified by the -f option  or,  by  default,
the    standard    system    activity    daily   data   file
/var/adm/sa/sadd for the current day dd.  The  starting  and
ending  times  of the report can be bounded using the -e and
-s arguments with time specified in the  form  hh[:mm[:ss]].
The  -i option selects records at sec second intervals. Oth-
 erwise, all intervals found in the data file are reported.

This is the first time that I am aware of that there are 'standard system activity daily data file'
at /var/adm/sa/. As of now, I can see the following files:

myservnm:/var/adm/sa [orclsid] $ ls -l 
total 2177984
-rw-r--r--   1 sys      sys      241097472 Feb 18 23:55 sa18
-rw-r--r--   1 sys      sys      241097472 Feb 19 23:55 sa19
-rw-r--r--   1 sys      sys      241097472 Feb 20 23:55 sa20
-rw-r--r--   1 sys      sys      241097472 Feb 21 23:55 sa21
-rw-r--r--   1 sys      sys      78691536 Feb 22 07:45 sa22

So it looks like we have 5 days data.

What I did last Friday afternoon was:

sar -A  -e 14:28  -s 14:10   > ~/sar1410_1428.txt

If you don't specify the -f, it will extract from the current day's file, i.e. sa18 last Friday.
In the output file, we can see various info recorded at 5 min snapshot

For example, CPU utilization:

SunOS myservnm 5.10 Generic_142900-05 sun4u    02/18/2011
 
14:10:02    %usr    %sys    %wio   %idle
14:15:03      17      14       0      69
14:20:04      10      11       0      78
14:25:05      20      18       0      62
 
Average       16      15       0      70

In the device activity section, I can find at 14:20 snapshot some lines have very high avserv time.
while normally I saw avserv < 30 ms in my system. for examples:

14:10:02   device        %busy   avque   r+w/s  blks/s  avwait  avserv
 
14:15:03   sd7               1     0.0       1      12     0.0     9.0
           sd7,e             1     0.0       1      12     0.0     9.2
           sd8              32     0.3      46     426     0.0     7.4
....
14:20:04   sd7               1     0.0       1      16     0.0     9.1
           sd7,e             1     0.0       1      16     0.0     9.3
...          
sd1133,e          1     0.0       1      26     0.0    12.9
           sd1134           44     0.8       3      73    78.6   238.1
           sd1134,e         44     0.8       3      73    79.1   239.6
           sd1135           42     0.4       1      20     0.0   485.3
           sd1135,e         42     0.4       1      20     0.0   494.7
           sd1136           42     0.4       0      25     0.0  1000.9
           sd1136,e         42     0.4       0      25     0.0  1042.2
           sd1142            1     0.0       1      40     0.0    13.0
...
  sd1204,e          4     0.0       3      81     0.0    16.0
           sd1205           43     0.4       1      22     0.0   440.3
           sd1205,e         43     0.4       1      22     0.0   448.0
           sd1206           43     0.8       2      60    85.3   254.3
           sd1206,e         43     0.8       2      60    85.9   256.1
           sd1207            1     0.0       1      25     0.0    12.7

This webpage describes the meaning of some sar options and report fields.
This article called "Identifying disk I/O-bound systems" has information about intepreting sar report.

I am happy I have another tool under my tool-belt.

Tuning an inefficient SQL with semi-join

2011-02-15T15:09:00.001-05:00

Found a sql look like the following in a batch job:

SELECT    
 distinct
 C.INT_PSEFS_ID
,C.ACCOUNT_ID
,C.PSEFS_ID
,C.IS_PQ
,C.psefs_save_date
FROM     
   MYSCH.PSEFS_MSTR A
  ,MYSCH.PSEFS_DTLS B
  ,MYSCH.PSEFS_MSTR C
WHERE    
    A.INT_PSEFS_ID = B.INT_PSEFS_ID
  AND C.PSEFS_ID LIKE SUBSTR (A.PSEFS_ID, 1, 13)|| '%'
  AND A.IS_VALID = 'N' 
  AND B.PSEFS_STATUS_ID IN (4, 6)
  AND A.PSEFS_COMP_DATE  <= SYSDATE - 45
;

The execution plan is as follows:

---------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                  |    66T|  4861T|       |  3064G  (2)|999:59:59 |
|   1 |  HASH UNIQUE                 |                  |    66T|  4861T|    11P|  3064G  (2)|999:59:59 |
|   2 |   TABLE ACCESS BY INDEX ROWID| PSEFS_MSTR       |  3287K|   122M|       |   149K  (1)| 00:29:49 |
|   3 |    NESTED LOOPS              |                  |    66T|  4861T|       |  3027G  (1)|999:59:59 |
|*  4 |     HASH JOIN                |                  |    20M|   794M|   550M|   839K  (3)| 02:47:49 |
|*  5 |      TABLE ACCESS FULL       | PSEFS_DTLS       |    26M|   250M|       |   612K  (2)| 02:02:29 |
|*  6 |      TABLE ACCESS FULL       | PSEFS_MSTR       |    20M|   600M|       |   156K  (6)| 00:31:17 |
|*  7 |     INDEX RANGE SCAN         | PSEFS_MSTR_IX5   |   591K|       |       |  5154   (1)| 00:01:02 |
---------------------------------------------------------------------------------------------------------

INT_PSEFS_ID is a PK of A, and a FK of B, so A join B on INT_PSEFS_ID will generate a result set (refer to as R1) with duplicated records of A; Then we selected out row of C (same table as A) by join it with R1t based on an unusual join condition with LIKE operator. To see the problem by way of example, supposing we have a row in C with PSRFS_ID='ABCDEFGHIJKLM_2'; In R1, we could have several rows with PSRFS_ID in('ABCDEFGHIJKLM_3', 'ABCDEFGHIJKLM_4', 'ABCDEFGHIJKLM_4', 'ABCDEFGHIJKLM'), due to the LIKE, the row in C will match 4 rows in R1, thus generate 4 duplicated rows in the final result set. I rewrote the SQL to use sub-queries to enable the more efficient semi-joins intead of normal joins

select 
C.INT_PSEFS_ID
, C.ACCOUNT_ID
, C.PSEFS_ID,IS_PQ
, C.psefs_save_date
from MYSCH.PSEFS_MSTR C
where
   SUBSTR(C.PSEFS_ID,1,13) in
   (
   select  SUBSTR(A.PSEFS_ID,1,13)
   from MYSCH.PSEFS_MSTR  A
    where  A.IS_VALID = 'N'
     and A.PSEFS_COMP_DATE  <= SYSDATE - 45 
     and exists ( select 1 from MYSCH.PSEFS_DTLS B
     where A.int_psefs_id = B.int_psefs_id
       and B.PSEFS_STATUS_ID IN (4, 6) )
   ) ;

Now the execution plan looks like:

------------------------------------------------------------------------------------------------
| Id  | Operation              | Name          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |               |    26M|  1182M|       |  1174K  (3)| 03:54:49 |
|*  1 |  HASH JOIN RIGHT SEMI  |               |    26M|  1182M|   387M|  1174K  (3)| 03:54:49 |
|   2 |   VIEW                 | VW_NSO_1      |    20M|   155M|       |   839K  (3)| 02:47:49 |
|*  3 |    HASH JOIN RIGHT SEMI|               |    20M|   794M|   550M|   839K  (3)| 02:47:49 |
|*  4 |     TABLE ACCESS FULL  | PSEFS_DTLS    |    26M|   250M|       |   612K  (2)| 02:02:29 |
|*  5 |     TABLE ACCESS FULL  | PSEFS_MSTR    |    20M|   600M|       |   156K  (6)| 00:31:17 |
|   6 |   TABLE ACCESS FULL    | PSEFS_MSTR    |    65M|  2445M|       |   153K  (4)| 00:30:45 |
------------------------------------------------------------------------------------------------

Fig 1. Good query visual representation

Fig 2. Bad query visual representaion

Note: though this sql is actually rather simple, the visual approach advocated by Jonathan Lewis in this article really helps me to do the analysis

Open a HTML file from Cygwin command line

2011-02-14T09:45:00.000-05:00

Cygwin allows me have a UNIX-link enviroment inside my Windows XP environment. As a Cygwin user, sometimes I would like to open a HTML file from Cygwin command line. To achieve this, first of all I create the following file and put under ~/bin.

---- start of ie.bat -----
@start "" /b "C:\Program Files\Internet Explorer\iexplore.exe" %*
---- end of ie.bat  ------

Secondly, in Cygwin, if we type pwd, we get UNIX-like current path name, i.e. with forward slashs, for example:

$ pwd
/cygdrive/c/Denis_Files/VZ2009

I need to convert it to Windows path name, so I create a shell script as follows:

$ cat ~/bin/pwdw
pwd | sed s#/cygdrive/c#c:# |sed  -e 's#\/#\\#g'

Now if I type 'pwdw' in the Cygwin command windows, I got:

$ pwdw
c:\Denis_Files\VZ2009

To start a HTML file, such as AWR report, what I need to do is:

ie.bat 'c:\Denis_Files\VZ2009\awrrpt_20101003_1300_1330.html'

Just a small tip that makes my life easier :-).

Quick notes about troubleshooting a blocker issue involving an insert

2011-02-09T20:01:00.000-05:00

Called to help troubleshooting a production issue: an insert statemnt blocked many others. However, when I checked the database on 7:30 PM, the symptoms have gone.

In retrospective, the problem is most likely due to a configuration issue in context of DMT. This database was upgraded to 10g a year ago from 8i. A few tablespaces is still dictionary-managed.

Here is the AWR "Top 5 Timed Events" during the problem period:

Top 5 Timed Events (18:30 -19:00)

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class

enq: TX - contention 44,494 130,783 2,939 59.7 Other
enq: ST - contention 27,122 79,719 2,939 36.4 Configuration
CPU time 3,700 1.7
read by other session 839,265 2,843 3 1.3 User I/O
db file scattered read 405,142 2,121 5 1.0 User I/O

From: http://www.saptechies.com/faq-oracle-enqueues/, we can read some info about Oracle enqueue.

System enqueues:

ST (space transaction enqueue): This enqueue is held in dictionary-managed tablespaces within extent allocations and releases.

TYPE = ST

Very large numbers of extents are allocated or deallocated.

You can solve the problem permanently by using LMTS instead of DMTS (refer to Notes 214995 and 659946). If you use DMTS, you must ensure that the extents of temporary segments, tables and indexes are sufficiently big so that you can avoid large quantities of extents being allocated and deallocated.

I wan able to find the blocker from the DBA_HIST_ACTIVE_SESS_HISTORY view. Drunig 18:30 - 19:00 Session 651 is blocking many other sessions, which either wait for enq: TX or enq:ST for examples:

SAMPLE_TIME SESSION_ID SQL_ID EVENT BLOCKING_SESSION

---------------------------------------- ---------- ------------- ------------------------------ ----------------
08-FEB-11 06.59.56.243 PM 242 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 345 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 414 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 469 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 591 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 593 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 594 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 595 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 596 6wyrqa50whrjg enq: TX - contention 651

...

SAMPLE_TIME SESSION_ID SQL_ID EVENT BLOCKING_SESSION
---------------------------------------- ---------- ------------- ------------------------------ ----------------
08-FEB-11 06.59.56.243 PM 1976 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 49 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1841 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1763 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1693 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1660 dpc1k1djg5gh0 enq: ST - contention 651

....

Session 651 that was doing the same insert lasted about 1hour, from about 6:17 to 7:15

SAMPLE_TIME SESSION_ID SQL_ID EVENT BLOCKING_SESSION
---------------------------------------- ---------- ------------- ------------------------------ ----------------
08-FEB-11 06.17.23.778 PM 651 6wyrqa50whrjg
08-FEB-11 06.17.33.998 PM 651 6wyrqa50whrjg
08-FEB-11 06.17.44.198 PM 651 6wyrqa50whrjg
08-FEB-11 06.17.54.508 PM 651 6wyrqa50whrjg
...

08-FEB-11 07.14.45.919 PM 651 6wyrqa50whrjg
08-FEB-11 07.14.56.049 PM 651 6wyrqa50whrjg
08-FEB-11 07.15.06.159 PM 651 6wyrqa50whrjg
-- end --

After this sql ( 6wyrqa50whrjg is an simple insert into a table) was done, things become normal. I am still not sure why this insert took so long. I was unable to know what wait event it was experiencing. Apparantly, Oracle was allocating a new extent to the table segment, but why took about an hour? The table referred in the SQL has two extents now, first one has 64000 blocks, the second has 16000 blocks.

So the scenario appeared to be that a session wants to insert a row into a table that resides in a DMT tablespace, but the table segment is run out of space, Oracle firstly has to allocate a new extent to the table segment; the session is waiting for this allocation to complete; it blocks all other sessions doing the same insert into the same table with the latter waiting for enq:TX. It also blocks other sessions with enq:ST events, which are doing DML on different tables that resides in the same tablespace.

Anyway we really need to migrate DMT to LMT asap.

Using analytical function rank() - an example of improving query performance

2011-01-10T20:36:00.000-05:00

Today, I have encountered a sql in a production database, which looks like


select distinct rs, bid, 
     [some_other_cols ...  ]
  from
     prod_table n
   where ee_date in (
       select max(ee_date) from
                prod_table n1
           where n1.bid = n.bid
             and n1.cc = n.cc
             and n1.rs=n.rs)



---------------------------------------------------------------------------------------
| Id  | Operation             | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |               |   571 | 51390 |   197   (4)| 00:00:03 |
|   1 |  HASH UNIQUE          |               |   571 | 51390 |   197   (4)| 00:00:03 |
|*  2 |   FILTER              |               |       |       |            |          |
|   3 |    HASH GROUP BY      |               |   571 | 51390 |   197   (4)| 00:00:03 |
|*  4 |     HASH JOIN         |               | 22250 |  1955K|   194   (3)| 00:00:03 |
|   5 |      TABLE ACCESS FULL| PROD_TABLE    | 22250 |   738K|    96   (2)| 00:00:02 |
|   6 |      TABLE ACCESS FULL| PROD_TABLE    | 22250 |  1216K|    97   (3)| 00:00:02 |
---------------------------------------------------------------------------------------

It contains a correlated sub-query. I rewrote it by using the analytical function rank(). I found that the consistent gets reduced by half


select distinct rs,bid, 
     [some_other_cols ...  ]
    from
    (
    select  n1.*,
           rank() over ( partition by bid, cc, rs order by ee_date desc ) rank
    from  prod_table n1
    )
    where rank =1;


-------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |               | 22250 |   956K|       |   602   (2)| 00:00:08
|   1 |  HASH UNIQUE              |               | 22250 |   956K|  2984K|   602   (2)| 00:00:08
|*  2 |   VIEW                    |               | 22250 |   956K|       |   350   (2)| 00:00:05
|*  3 |    WINDOW SORT PUSHED RANK|               | 22250 |   956K|  2984K|   350   (2)| 00:00:05
|   4 |     TABLE ACCESS FULL     | PROD_TABLE    | 22250 |   956K|       |    98   (4)| 00:00:02
-------------------------------------------------------------------------------------------------

Composite index selectivity

2010-10-20T16:41:00.002-04:00

I did tests with 10053 trace today and found that Oracle CBO behavior changes regarding compute selectivity of 3-column composite index from 9.2.0.8 to 10.2.0.4. (note: no histogram on any columns)

In 9i: selectivty of index(col1, col2, col3)= density (co11) x denisty (col2) x denisity(col3);

In 10g and 11g selectivity of index(col1, col2, col3) = 1/DISTINCT_KEYS where DISTINCT_KEYS is from index stats obtainable through dba_indexes.

Here is the test case which mimics the production able and the problem sql.

----- begin of the test case ----

drop table test;
create table test
as
select level id,
       trunc(mod(level,80)) id1,
       20*trunc(mod(level, 40)) id2,
       1    id3,
       trunc(mod(level,50)) id4
from dual
connect by level <=1000000;


create index test_ix1 on test(id1, id2, id3);

exec dbms_stats.gather_table_stats(user,'test', method_opt=>'FOR ALL COLUMNS size 1', cascade=>true);


alter session set tracefile_identifier = test;
ALTER SESSION SET EVENTS='10053 trace name context forever, level 1';

explain plan for
select id
from test
where id1 = 20
and id3=1
and id2 = 400;

ALTER SESSION SET EVENTS '10053 trace name context off';
Exit
------ end of test case  -----------------------

#### 9.2.0.8  10053 trace excerpt


***************************************
SINGLE TABLE ACCESS PATH
Column:        ID1  Col#: 2      Table: TEST   Alias: TEST
    NDV: 80        NULLS: 0         DENS: 1.2500e-02 LO:  0  HI: 79
    NO HISTOGRAM: #BKT: 1 #VAL: 2
Column:        ID3  Col#: 4      Table: TEST   Alias: TEST
    NDV: 1         NULLS: 0         DENS: 1.0000e+00 LO:  1  HI: 1
    NO HISTOGRAM: #BKT: 1 #VAL: 2
Column:        ID2  Col#: 3      Table: TEST   Alias: TEST
    NDV: 40        NULLS: 0         DENS: 2.5000e-02 LO:  0  HI: 780
    NO HISTOGRAM: #BKT: 1 #VAL: 2
  TABLE: TEST     ORIG CDN: 1000000  ROUNDED CDN: 313  CMPTD CDN: 313
  Access path: tsc  Resc:  857  Resp:  847
  Access path: index (equal)
      Index: TEST_IX1
  TABLE: TEST
      RSC_CPU: 711380   RSC_IO: 82
  IX_SEL:  0.0000e+00  TB_SEL:  3.1250e-04
  BEST_CST: 83.00  PATH: 4  Degree:  1


#### 10.2.0.4  10053 trace excerpt

***************************************
SINGLE TABLE ACCESS PATH
  -----------------------------------------
  BEGIN Single Table Cardinality Estimation
  -----------------------------------------
  Column (#2): ID1(NUMBER)
    AvgLen: 3.00 NDV: 81 Nulls: 0 Density: 0.012346 Min: 0 Max: 79
  Column (#4): ID3(NUMBER)
    AvgLen: 3.00 NDV: 1 Nulls: 0 Density: 1 Min: 1 Max: 1
  Column (#3): ID2(NUMBER)
    AvgLen: 4.00 NDV: 40 Nulls: 0 Density: 0.025 Min: 0 Max: 780
  Table: TEST  Alias: TEST
    Card: Original: 1003092  Rounded: 310  Computed: 309.60  Non Adjusted: 309.60
  -----------------------------------------
  END   Single Table Cardinality Estimation
  -----------------------------------------
  Access Path: TableScan
    Cost:  730.88  Resp: 730.88  Degree: 0
      Cost_io: 700.00  Cost_cpu: 284170229
      Resp_io: 700.00  Resp_cpu: 284170229
  Access Path: index (AllEqRange)
    Index: TEST_IX1
    resc_io: 3173.00  resc_cpu: 27721329
    ix_sel: 0.0125  ix_sel_with_filters: 0.0125
    Cost: 3176.01  Resp: 3176.01  Degree: 1
  Best:: AccessPath: TableScan
         Cost: 730.88  Degree: 1  Resp: 730.88  Card: 309.60  Bytes: 0

Note:
select index_name, distinct_keys from user_indexes where index_name='TEST_IX1';

INDEX_NAME                     DISTINCT_KEYS
------------------------------ -------------
TEST_IX1                                  80


#### 11.2.0.1  10053 trace excerpt


***************************************
SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for TEST[TEST]
  ColGroup (#1, Index) TEST_IX1
    Col#: 2 3 4    CorStregth: 40.00
  ColGroup Usage:: PredCnt: 3  Matches Full: #1  Partial:  Sel: 0.0125
  Table: TEST  Alias: TEST
    Card: Original: 1000000.000000  Rounded: 12500  Computed: 12500.00  Non Adjusted: 12500.00
  Access Path: TableScan
    Cost:  629.80  Resp: 629.80  Degree: 0
      Cost_io: 617.00  Cost_cpu: 283372261
      Resp_io: 617.00  Resp_cpu: 283372261
  ColGroup Usage:: PredCnt: 3  Matches Full: #1  Partial:  Sel: 0.0125
  ColGroup Usage:: PredCnt: 3  Matches Full: #1  Partial:  Sel: 0.0125
  Access Path: index (AllEqRange)
    Index: TEST_IX1
    resc_io: 3173.00  resc_cpu: 27721329
    ix_sel: 0.012500  ix_sel_with_filters: 0.012500
    Cost: 3174.25  Resp: 3174.25  Degree: 1
  Best:: AccessPath: TableScan
         Cost: 629.80  Degree: 1  Resp: 629.80  Card: 12500.00  Bytes: 0

Notice the ix_sel line in the above 10053 trace excerpt; for 10g and 11g it equal to 1/80. for 9i seems computed through multiplying selectivity of eeach column.

Update:
Came accross Jonathan Lewis's comment, and came to know this CBO behavior changes acctually from 10.1.0.4 ie. 10.1.0.4 is still similar to 9i behavior.

Below is his comment: (http://kr.forums.oracle.com/forums/thread.jspa?messageID=3153224)

--------
For a single-table query with the predicate
(full list of index columns) = (set of values)

The selectivities vary across version as follows:

11.1.0.6: Table selectivity and index selectivity given by distinct_keys in index
10.2.0.1: Table selectivity given by product of column selectivities, index selectivity given by distinct_keys in index
10.1.0.4: Table selectivity and index selectivity given by product of column selectivities

------------

JL's original post about this behavior: http://jonathanlewis.wordpress.com/2008/03/11/everything-changes/

Privileges to enable a non-DBA user to generate AWR report

2010-09-15T21:45:00.000-04:00

The following privileges seem working for the stated purpose:

GRANT SELECT ON SYS.V_$DATABASE TO xxx
/
GRANT SELECT ON SYS.V_$INSTANCE TO xxx
/
GRANT EXECUTE ON SYS.DBMS_WORKLOAD_REPOSITORY TO xxx
/
GRANT SELECT ON SYS.DBA_HIST_DATABASE_INSTANCE TO xxx
/
GRANT SELECT ON SYS.DBA_HIST_SNAPSHOT TO xxx
/
GRANT ADVISOR TO xxx
/

CURSOR_SHARING and PL/SQL procedure

2010-08-16T19:24:00.000-04:00

With cursor_sharing=FORCE, in most cases, Oracle will replace literal values with bind variables, however,this is not the case for PL/SQL blocks. See the following test case. When using CALL proc_name(), it can. This behavior is mentioned in Jonathen Lewis's book "Cost-based Oracle Fundamentals" p159.

SQL>alter session set cursor_sharing=force;

Session altered.

SQL>drop table t;

Table dropped.

SQL>create table t(a number);

Table created.

SQL>
SQL>create or replace procedure denis_proc(a in number)
  2   is
  3  begin
  4    insert into t values(a);
  5   commit;
  6  end;
  7  /

Procedure created.

SQL>
SQL>exec denis_proc(1);

PL/SQL procedure successfully completed.

SQL>exec denis_proc(2);

PL/SQL procedure successfully completed.

SQL>exec denis_proc(3);

PL/SQL procedure successfully completed.

SQL>call denis_proc(4);

Call completed.

SQL>call denis_proc(5);

Call completed.

SQL>call denis_proc(6);

Call completed.

SQL>
SQL>col sql_text format a30
SQL>
SQL>select sql_id, executions, sql_text from v$sqlarea where sql_text like '%denis_proc%';

SQL_ID1G        EXECUTIONS SQL_TEXT
------------- ---------- ------------------------------
1ms5rkrgwt28v          1 BEGIN denis_proc(1); END;
0vcasv51bxgpv          1 BEGIN denis_proc(3); END;
dcna79fxryrkx          1 BEGIN denis_proc(2); END;
6skbuvu6fb9k0          3 call denis_proc(:"SYS_B_0")

SQL>
SQL>select * from t;

         A
----------
         1
         2
         3
         4
         5
         6

6 rows selected.

SQL>

Effect of a SQL* Plus environment variable: set pagesize 0

2010-08-03T13:22:00.002-04:00

Last night, I troubleshooted a ksh shell script, in which a variable is assigned a value that is returned from SQL* Plus commands. I found that without 'set pagesize 0', the value returned had an undesirable leading space. Below is a test case that demonstrate this effect.

SQL> select col1, col3 from t;
 
      COL1 C
---------- -
         1 Y


$ cat test3.sh 
#!/bin/ksh 
 
RET1=` sqlplus -s  / << EOF
set  echo off head off feed off verify off term off  
select col3 from t
where  col1=1;
EOF
`
 
echo "RET1  >>>>"$RET1"<<<<"
if [[ $RET1 == 'Y' ]]; then
  echo "Yes"
else
  echo "No"
fi
 
RET2=` sqlplus -s  / << EOF
set echo off head off feed off verify off term off 
set pagesize 0
select col3 from t
where  col1=1;
EOF
`
 
echo "RET2  >>>>"$RET2"<<<<"
if [[ $RET2 == 'Y' ]]; then
  echo "Yes"
else
  echo "No"
fi


$ ./test3.sh 
RET1  >>>> Y<<<<
No
RET2  >>>>Y<<<<
Yes

Tuning by cardinality feedback and understanding of join cardinality and transitive closure

2010-05-26T11:20:00.002-04:00

What comes out of my recent tuning experience of a 13-table join query is my deeper understanding of "Tuning by Cardinality Feedback", join cardinality and transitive closure. The problem for that 13-table join SQL is that Oracle predictes the join cardinality to be 1 always so it chooses nested loop join, whereas the hash join is able to bring the consistent gets from 400K to 6K.

First of all, let's see where the cardinality estimation is wrong. Below are the estimated cardinality from each operations in the first 4-table join: PACKAGE_MARKETS -> MARKETS -> PACKAGE_CATEGORY -> PACKAGE_PRODUCTS

10    9       NESTED LOOPS (Cost=10 Card=1 Bytes=522)
  11   10         NESTED LOOPS (Cost=9 Card=1 Bytes=325)
  12   11           NESTED LOOPS (Cost=4 Card=1 Bytes=229)
  13   12             NESTED LOOPS (Cost=3 Card=1 Bytes=224)
  14   13               NESTED LOOPS (Cost=2 Card=1 Bytes=104)
  15   14                 INDEX (UNIQUE SCAN) OF 'PK_PACKAGE_MARKETS' (UNIQUE) (Cost=1 Card=1 Bytes=12)
  16   14                 TABLE ACCESS (BY INDEX ROWID) OF 'MARKETS' (Cost=1 Card=1 Bytes=92)
  17   16                   INDEX (UNIQUE SCAN) OF 'PK_MARKETS' (UNIQUE)
  18   13               TABLE ACCESS (BY INDEX ROWID) OF 'PACKAGES' (Cost=1 Card=1 Bytes=120)
  19   18                 INDEX (UNIQUE SCAN) OF 'PK_PACKAGES' (UNIQUE)
  20   12             TABLE ACCESS (BY INDEX ROWID) OF 'PACKAGE_CATEGORY' (Cost=1 Card=1 Bytes=5)
  21   20               INDEX (UNIQUE SCAN) OF 'PK_PACKAGE_CATEGORY' (UNIQUE)
  22   11           TABLE ACCESS (BY INDEX ROWID) OF 'PACKAGE_PRODUCTS' (Cost=5 Card=1 Bytes=96)
  23   22             INDEX (RANGE SCAN) OF 'PK_PACKAGE_PRODUCTS' (UNIQUE) (Cost=2 Card=6)
  24   10         TABLE ACCESS (BY INDEX ROWID) OF 'PRODUCTS' (Cost=1 Card=1 Bytes=197

Below are the real cardinalities obtained from SQL_TRACE/TKPROF. we can see the real cardinality coming out of PACKAGE_PRODUCTS table is 2725 and the estimated one is 1 as shown above. This is where the whole execution plan becomes "wrong".

2725         NESTED LOOPS
      1          NESTED LOOPS
      1           NESTED LOOPS
      1            NESTED LOOPS
      1             INDEX UNIQUE SCAN PK_PACKAGE_MARKETS (object id 423961)
      1             TABLE ACCESS BY INDEX ROWID MARKETS
      1              INDEX UNIQUE SCAN PK_MARKETS (object id 423924)
      1            TABLE ACCESS BY INDEX ROWID PACKAGES
      1             INDEX UNIQUE SCAN PK_PACKAGES (object id 423954)
      1           TABLE ACCESS BY INDEX ROWID PACKAGE_CATEGORY
      1            INDEX UNIQUE SCAN PK_PACKAGE_CATEGORY (object id 423956)
   2725          TABLE ACCESS BY INDEX ROWID PACKAGE_PRODUCTS
   2811           INDEX RANGE SCAN PK_PACKAGE_PRODUCTS (object id 423963)

What I did is to add hints to force Oracle choose hash join instead of nested loop join for the remaining 9 tables.

This execersie also arouse my insterest to understand how join cardinality is calculated, thus I re-read Chapter 10 of Jonanth Lewis's Cost-Based Oracle Fundamentals. I found what he says is true ( as always :-)). Below is a test case output for a two table join SQL that involves "transitive closure" - there is a filter on the join column:

SQL>select * from v$version;

BANNER
----------------------------------------------------------------
Oracle9i Enterprise Edition Release 9.2.0.8.0 - 64bit Production
PL/SQL Release 9.2.0.8.0 - Production
CORE 9.2.0.8.0 Production
TNS for Solaris: Version 9.2.0.8.0 - Production
NLSRTL Version 9.2.0.8.0 - Production

SQL>
SQL>-- from the count we know the acutual join cardinality should be 86
SQL>select count(*) from packages where package_id='Y9995';

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

SQL>select count(*) from package_products where package_id='Y9995';

  COUNT(*)
----------
        86

SQL>
SQL>-- JL mentioned "query_reworte_enabled" has impact on join predicate removal
SQL>-- prior to 10g in hist book "Cost-Based Oracle Fundamentals"
SQL>-- I confirmed it is true in our 9i db. I also tested with rewrite/nowrite hints
SQL>-- instead of session level "query_rewrite_enabled parameter". No impact
SQL>-- from the hints.
SQL>
SQL>
SQL>show parameter query_rewrite_enabled

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
query_rewrite_enabled                string      TRUE
SQL>alter session set query_rewrite_enabled=true;

Session altered.

SQL>
SQL>
SQL>-- query_rewrite_enabled=true
SQL>explain plan for
  2  select  *
  3    from  packages a,   -- NROWS 2656
  4        package_products b   -- NROWS 284247
  5   where a.package_id   -- NDV  2656 PK
  6       = b.package_id   -- NDV  2610 NOT NULL
  7   and a.package_id = 'Y9995'
  8  ;

Explained.

SQL>select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------

-------------------------------------------------------------------------------------
| Id  | Operation                    |  Name                | Rows  | Bytes | Cost  |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                      |     1 |   240 |     5 |
|   1 |  NESTED LOOPS                |                      |     1 |   240 |     5 |
|   2 |   TABLE ACCESS BY INDEX ROWID| PACKAGES             |     1 |   144 |     2 |
|*  3 |    INDEX UNIQUE SCAN         | PK_PACKAGES          |     1 |       |     1 |
|   4 |   TABLE ACCESS BY INDEX ROWID| PACKAGE_PRODUCTS     |     1 |    96 |     3 |
|*  5 |    INDEX RANGE SCAN          | PK_PACKAGE_PRODUCTS  |     1 |       |     2 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("A"."PACKAGE_ID"='Y9995')
   5 - access("B"."PACKAGE_ID"='Y9995')
       filter("A"."PACKAGE_ID"="B"."PACKAGE_ID")

Note: cpu costing is off

20 rows selected.

SQL>
SQL>alter session set query_rewrite_enabled=false;

Session altered.

SQL>
SQL>-- query_rewrite_enabled=false
SQL>explain plan for
  2  select  *
  3    from  packages a,   -- NROWS 2656
  4        package_products b   -- NROWS 284247
  5   where a.package_id   -- NDV  2656 PK
  6       = b.package_id   -- NDV  2610 NOT NULL
  7   and a.package_id = 'Y9995'
  8  ;

Explained.

SQL>
SQL>select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------

-------------------------------------------------------------------------------------
| Id  | Operation                    |  Name                | Rows  | Bytes | Cost  |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                      |   109 | 26160 |    52 |
|   1 |  NESTED LOOPS                |                      |   109 | 26160 |    52 |
|   2 |   TABLE ACCESS BY INDEX ROWID| PACKAGES             |     1 |   144 |     2 |
|*  3 |    INDEX UNIQUE SCAN         | PK_PACKAGES          |     1 |       |     1 |
|   4 |   TABLE ACCESS BY INDEX ROWID| PACKAGE_PRODUCTS     |   109 | 10464 |    50 |
|*  5 |    INDEX RANGE SCAN          | PK_PACKAGE_PRODUCTS  |   109 |       |     2 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("A"."PACKAGE_ID"='Y9995')
   5 - access("B"."PACKAGE_ID"='Y9995')

Note: cpu costing is off

19 rows selected.

The test case showed two scenarios with same SQL and apparently obtained same execution plan, but
1. with query_rewrite_enabled=true, the estimated cardinality is 1
2. with query_rewrite_enabled=false, the estimated cardinality is 109
3. There are differences in the "Predicate Information" section of the execution plan. With query_rewrite_enabled=false, there is no join predicate

So how those cardinilities are calculated by Oracle? If we have two table join in the following form:

select *
  from t1, t2
 where t1.c1 = t2.c2
   and filter_predicates_of_t1
   and filter_predicates_of_t2;

The basic join cardinality formula is as follows (from "Cost-Based Oracle Fundamentals" p266):

Join Selectivity =
  ((num_rows(t1) - num_nulls(t1.c1)) / num_rows(t1)) *
  ((num_rows(t2) - num_nulls(t2.c2)) / num_rows(t2)) /
  greater(num_distinct(t1.c1), num_distinct(t2.c2))

Join Cardinality =
   join selectivity *
   filtered cardinality(t1) * filtered cardinality(t2)

In our scenario 1:

Join Selectivity = 
  (( 2656 -0) / 2656 ) *
  (( 284247 - 0) / 284247) /
  greater(2656, 2619)
  = 1/2656

Join Cardinaltiy =
   (1/2656) *
   (2656/2656) * ( 284247 /2610) 
   = 0.004 ( rounded to 1)

In our senario 2, notice we don't have join predicate actually, Oracle eliminated the Join Selectivity part:

Join Cardinlity =
   (2656/2656) * ( 284247 /2610)
   = 109

My production 9i database has set query_rewrite_enabled=true. So if I wrote the SQL without the join condition as follows::

select  *
 from  packages a,   -- NROWS 2656
       package_products b   -- NROWS 284247
where
      b.package_id = 'Y9995'
  and a.package_id = 'Y9995'
;

I can get the correct cardinality as in the scenaro 2.

BTW, for example, if a=b, and a=5; then b=5, this is called "transitive closure".

Play with my toy 10g RAC VII - Voting Disk

2010-05-07T18:15:00.003-04:00

The voting disk is a shared raw disk partition or file on a clustered file system that is accessible to all nodes in the cluster. Its primary purpose is to help in situations where the private network communication fails. When that happens, the cluster is unable to have all nodes remain available because they are no longer able to synchronize I/O to the shared disks. Therefore, some of the nodes must go offline. The voting disk is then used to communicate the node state information used to determine which nodes go offline.

If we have 3 nodes, presumably to the voting disk each node will write message as follows:

Node 1 writes : I can see Node 2 & 3
Node 2 writes : I can see Node 1 & 3
Node 3 writes : I can see Node 1 & 2

If for example Node 3's private network has problem, the message may become:

Node 1 writes : I can see Node 2 only
Node 2 writes : I can see Node 1 only
Node 3 writes : I can not see either Node 1 or Node 2 ( or it does not write anything)

In this situation, clearly Node 3 should be evicted from the cluster.

To avoid a single point of failure, we can multiplex voting disk. By design, if strictly more than half of the voting disks are up and contain consistent information, the cluster will be fine. That is to say if we have 5 voting disks, we can have at most 2 voting disk failures.
So the number_of_voting_disk = number_of_tolerable_disk_failure * 2 + 1.

This post is to document my test with the following task regarding voting disk administration:

Task - Recover from the lost of voting disks

1. Check the current voting disk configuration

[oracle@rac1 backup]$ crsctl query css votedisk
 0.     0    /dev/raw/raw6
 1.     0    /dev/raw/raw7
 2.     0    /dev/raw/raw8

located 3 votedisk(s).

2. Backup voting disk

[oracle@rac1 backup]$ dd if=/dev/raw/raw6 of=/home/oracle/backup/votingdisk_050710
80325+0 records in
80325+0 records out
[oracle@rac1 backup]$
[oracle@rac1 backup]$ ls -lhtr
total 40M
-rw-r--r--  1 oracle oinstall 40M May  7 16:23 votingdisk_050710

3. Wipe out the first voting disk

dd if=/dev/zero of=/dev/raw/raw6

Note: I have three voting disk files, in my understanding, the cluster should survive with 1 voting disk failure, however,rac1 and rac2 reboot right after I issue this command. I don't know why.

--------------- RAC 1 alert log  --------------------
 
Fri May  7 16:25:21 2010
Trace dumping is performing id=[cdmp_20100507162519]
Fri May  7 16:25:23 2010
Error: KGXGN aborts the instance (6)
Fri May  7 16:25:24 2010
Errors in file /u01/app/oracle/admin/devdb/bdump/devdb1_lmon_10476.trc:
ORA-29702: error occurred in Cluster Group Service operation
LMON: terminating instance due to error 29702


--------------- RAC 2 alert log --------------------
ri May  7 16:25:19 2010
Error: KGXGN aborts the instance (6)
Fri May  7 16:25:19 2010
Error: unexpected error (6) from the Cluster Service (LCK0)
Fri May  7 16:25:19 2010
Errors in file /u01/app/oracle/admin/devdb/bdump/devdb2_lmon_3150.trc:
ORA-29702: error occurred in Cluster Group Service operation
Fri May  7 16:25:19 2010
Errors in file /u01/app/oracle/admin/devdb/bdump/devdb2_lck0_3236.trc:
ORA-29702: error occurred in Cluster Group Service operation
Fri May  7 16:25:19 2010
LMON: terminating instance due to error 29702
Fri May  7 16:25:21 2010
System state dump is made for local instance
System State dumped to trace file /u01/app/oracle/admin/devdb/bdump/devdb2_diag_3146.trc
Fri May  7 16:31:01 2010

4. Restart CRS stack

[oracle@rac1 ~]$ sudo $ORA_CRS_HOME/bin/crsctl stop crs
Password:
Stopping resources.

Successfully stopped CRS resources
Stopping CSSD.
Shutting down CSS daemon.
Shutdown request successfully issued.
[oracle@rac1 ~]$
[oracle@rac1 ~]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl stop crs
Password:vz123ys

Stopping resources.
Successfully stopped CRS resources
Stopping CSSD.
Shutting down CSS daemon.
Shutdown request successfully issued.
[oracle@rac1 ~]$
[oracle@rac1 ~]$
[oracle@rac1 ~]$
[oracle@rac1 ~]$ ps -ef | grep d.bin
oracle   14672 30539  0 16:56 pts/1    00:00:00 grep d.bin
[oracle@rac1 ~]$ ssh rac2 ps -ef | grep d.bin
[oracle@rac1 ~]$ ./crsstat.sh
HA Resource                                   Target     State
-----------                                   ------     -----
error connecting to CRSD at [(ADDRESS=(PROTOCOL=ipc)(KEY=ora_crsqs))] clsccon 184

[oracle@rac1 ~]$ sudo $ORA_CRS_HOME/bin/crsctl start crs
Attempting to start CRS stack
The CRS stack will be started shortly
[oracle@rac1 ~]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl start crs
Attempting to start CRS stack
The CRS stack will be started shortly


[oracle@rac1 ~]$ ps -ef | grep d.bin
root     14242     1  0 16:54 ?        00:00:00 /u01/app/oracle/product/10.2.0/crs_1/bin/crsd.bin reboot
oracle   15219 14240  2 16:58 ?        00:00:00 /u01/app/oracle/product/10.2.0/crs_1/bin/evmd.bin
oracle   15383 15357  2 16:58 ?        00:00:00 /u01/app/oracle/product/10.2.0/crs_1/bin/ocssd.bin
oracle   15602 30539  0 16:58 pts/1    00:00:00 grep d.bin
[oracle@rac1 ~]$ ssh rac2 ps -ef | grep d.bin
root     23610     1  0 16:56 ?        00:00:00 /u01/app/oracle/product/10.2.0/crs_1/bin/crsd.bin reboot
oracle   24394 23609  2 16:58 ?        00:00:00 /u01/app/oracle/product/10.2.0/crs_1/bin/evmd.bin
oracle   24575 24549  2 16:58 ?        00:00:00 /u01/app/oracle/product/10.2.0/crs_1/bin/ocssd.bin
[oracle@rac1 ~]$ ./crsstat.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             OFFLINE    OFFLINE
ora.devdb.SLBA.devdb1.srv                     OFFLINE    OFFLINE
ora.devdb.SLBA.devdb2.srv                     OFFLINE    OFFLINE
ora.devdb.SNOLBA.cs                           OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb1.srv                   OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb2.srv                   OFFLINE    OFFLINE
ora.devdb.db                                  ONLINE     ONLINE on rac2
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     ONLINE on rac1
ora.rac1.gsd                                  ONLINE     ONLINE on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     ONLINE on rac2
ora.rac2.gsd                                  ONLINE     ONLINE on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2

5. Check log

[oracle@rac1 rac1]$ tail alertrac1.log
2010-05-07 16:58:50.358
[cssd(15383)]CRS-1601:CSSD Reconfiguration complete. Active nodes are rac1 rac2 .
2010-05-07 16:58:54.722
[crsd(14242)]CRS-1201:CRSD started on node rac1.
2010-05-07 16:59:45.626
[cssd(15383)]CRS-1604:CSSD voting file is offline: /dev/raw/raw6. Details in /u01/app/oracle/product/10.2.0/crs_1 /log/rac1/cssd/ocssd.log.
2010-05-07 17:00:47.657
[cssd(15383)]CRS-1604:CSSD voting file is offline: /dev/raw/raw6. Details in /u01/app/oracle/product/10.2.0/crs_1 /log/rac1/cssd/ocssd.log.
2010-05-07 17:01:49.730
[cssd(15383)]CRS-1604:CSSD voting file is offline: /dev/raw/raw6. Details in /u01/app/oracle/product/10.2.0/crs_1 /log/rac1/cssd/ocssd.log.
[oracle@rac1 rac1]$ tail /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log
[    CSSD]2010-05-07 17:00:16.337 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x8358600) proc( 0x8389ac8) pid() proto(10:2:1:1)
[    CSSD]2010-05-07 17:00:22.183 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x8358600) proc( 0x838eb90) pid() proto(10:2:1:1)
[    CSSD]2010-05-07 17:00:30.776 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x8358600) proc( 0x838ee90) pid() proto(10:2:1:1)
[    CSSD]2010-05-07 17:00:47.657 [62401440] >TRACE:   clssnmDiskStateChange: state from 3 to 3 disk (0//dev/raw/ raw6)
[    CSSD]2010-05-07 17:01:07.263 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x8358600) proc( 0x837e6b8) pid() proto(10:2:1:1)
[    CSSD]2010-05-07 17:01:09.009 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x8357dd8) proc( 0x8379340) pid() proto(10:2:1:1)
[    CSSD]2010-05-07 17:01:49.730 [62401440] >TRACE:   clssnmDiskStateChange: state from 3 to 3 disk (0//dev/raw/ raw6)
[    CSSD]2010-05-07 17:02:09.984 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x835a580) proc( 0x8365a50) pid() proto(10:2:1:1)
[    CSSD]2010-05-07 17:02:51.784 [62401440] >TRACE:   clssnmDiskStateChange: state from 3 to 3 disk (0//dev/raw/ raw6)
[    CSSD]2010-05-07 17:03:12.292 [132250528] >TRACE:   clssgmClientConnectMsg: Connect from con(0x835a580) proc( 0x8365a50) pid() proto(10:2:1:1)

Note: similar message from rac2 alertrac2.log and ocssd.log. It can be seen with three voting disk files, if one of them unavailable, the RAC is still functioning.

6. Wipe out the second voting disk

dd if=/dev/zero of=/dev/raw/raw7

Two nodes reboot right after issuing above command. After reboot, only see evmd running:

[oracle@rac1 ~]$ ps -ef | grep d.bin
oracle    8139  6985  3 17:12 ?        00:00:14 /u01/app/oracle/product/10.2.0/crs_1/bin/evmd.binoracle   11075 10255  0 17:20 pts/1    00:00:00 grep d.bin

7. Check log:

--- alertrac1.log   show two voting disk files are offline

2010-05-07 17:12:14.926
[cssd(8303)]CRS-1604:CSSD voting file is offline: /dev/raw/raw6. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
2010-05-07 17:12:15.099
[cssd(8303)]CRS-1604:CSSD voting file is offline: /dev/raw/raw7. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
2010-05-07 17:12:15.147
[cssd(8303)]CRS-1605:CSSD voting file is online: /dev/raw/raw8. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
[oracle@rac1 rac1]$

[oracle@rac1 crsd]$ tail crsd.log

2010-05-07 17:14:04.532: [ COMMCRS][36494240]clsc_connect: (0x8655528) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_rac1_crs))

2010-05-07 17:14:04.532: [ CSSCLNT][3086931648]clsssInitNative: connect failed, rc 9

2010-05-07 17:14:04.533: [  CRSRTI][3086931648]0CSS is not ready. Received status 3 from CSS. Waiting for good status ..

2010-05-07 17:14:05.536: [ CRSMAIN][3086931648][PANIC]0CRSD exiting: Could not init the CSS context

2010-05-07 17:14:05.540: [ default][3086931648]Terminating clsd session

8. Restore Voting Disk

[oracle@rac1 ~]$ dd if=/home/oracle/backup/votingdisk_050710 of=/dev/raw/raw6
80325+0 records in
80325+0 records out
[oracle@rac1 ~]$ dd if=/home/oracle/backup/votingdisk_050710 of=/dev/raw/raw7
dd: writing to `/dev/raw/raw7': No space left on device
80263+0 records in
80262+0 records out

9. Restart CRS

[oracle@rac1 ~]$ sudo $ORA_CRS_HOME/bin/crsctl start crs
Password:
Attempting to start CRS stack
The CRS stack will be started shortly
[oracle@rac1 ~]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl start crs
Password:vz123ys

Attempting to start CRS stack
The CRS stack will be started shortly


---- in alertrac1.log --------------------------

[oracle@rac1 rac1]$ pwd
/u01/app/oracle/product/10.2.0/crs_1/log/rac1
[oracle@rac1 rac1]$ tail -15 alertrac1.log
[cssd(8303)]CRS-1605:CSSD voting file is online: /dev/raw/raw8. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
2010-05-07 17:29:31.679
[cssd(13301)]CRS-1605:CSSD voting file is online: /dev/raw/raw6. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
2010-05-07 17:29:31.714
[cssd(13301)]CRS-1605:CSSD voting file is online: /dev/raw/raw7. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
2010-05-07 17:29:31.729
[cssd(13301)]CRS-1605:CSSD voting file is online: /dev/raw/raw8. Details in /u01/app/oracle/product/10.2.0/crs_1/log/rac1/cssd/ocssd.log.
2010-05-07 17:29:35.433
[cssd(13301)]CRS-1601:CSSD Reconfiguration complete. Active nodes are rac1 rac2 .
2010-05-07 17:29:38.247
[crsd(8910)]CRS-1012:The OCR service started on node rac1.
2010-05-07 17:29:38.287
[evmd(13364)]CRS-1401:EVMD started on node rac1.
2010-05-07 17:31:02.432
[crsd(8910)]CRS-1201:CRSD started on node rac1.

---- CTS resource are on-line

[oracle@rac1 ~]$ ~/crsstat.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             OFFLINE    OFFLINE
ora.devdb.SLBA.devdb1.srv                     OFFLINE    OFFLINE
ora.devdb.SLBA.devdb2.srv                     OFFLINE    OFFLINE
ora.devdb.SNOLBA.cs                           OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb1.srv                   OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb2.srv                   OFFLINE    OFFLINE
ora.devdb.db                                  ONLINE     ONLINE on rac2
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     ONLINE on rac1
ora.rac1.gsd                                  ONLINE     ONLINE on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     ONLINE on rac2
ora.rac2.gsd                                  ONLINE     ONLINE on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2
[oracle@rac1 ~]$ date
Fri May  7 17:37:35 EDT 2010

In conclusion, with 3 voting disks, my test did show RAC can be operational if one of them is offline; if two of them are not available, then the CRS daemon can not start at all. However, when zero-out one of the voting disks, the server reboots, this is not desirable, not sure if this is due to my particular environment.

Play with my toy 10g RAC VI - Failed to Start CRS Processes due to OCR Out-of-Sync

2010-05-04T14:39:00.001-04:00

Today is the first time I am trying to play with my toy RAC again since I have moved OCR and voting disk files to the raw devices last time as described here. To my surprise, I can not start CRS processes (i.e. those seen from ps -ef | grep d.bin) ! First of all, they should be started automatically after server reboots, but they did not. Secondly they did not start after I issued "crsctl start crs" or "/etc/init.d/init.crs start" either. It took me quite a while to find the right log that indicates the problem:

[oracle@rac1 client]$ pwd
/u01/app/oracle/product/10.2.0/crs_1/log/rac1/client
[oracle@rac1 client]$
[oracle@rac1 client]$ tail -10 css.log
2010-04-05 10:15:01.231: [ CSSCLNT][3086931648]clsssInitNative: connect failed, rc 9

2010-04-05 10:15:02.249: [ CSSCLNT][3086931648]clsssInitNative: connect failed, rc 9

2010-04-21 13:44:32.807: [ default][3068479168]prlsndmain: olsnodes successful!!
2010-04-28 11:13:01.999: [  OCRRAW][3086931648]propriogid:1: INVALID FORMAT
2010-04-28 12:02:36.960: [  OCRRAW][3086931648]propriogid:1: INVALID FORMAT
2010-05-04 10:58:31.850: [  OCRRAW][3068479168]propriogid:1: INVALID FORMAT
2010-05-04 10:58:31.932: [ default][3068479168]prlsndmain: olsnodes successful!!
2010-05-04 11:06:06.374: [  OCRRAW][3086931648]propriogid:1: INVALID FORMAT

It showed that OCR had problems. I then noticed "Device/File needs to be synchronized with the other device" in the ocrcheck output:

root@rac1:/u01/app/oracle/product/10.2.0/crs_1/log/rac1/client [devdb1]# ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     505928
         Used space (kbytes)      :       5372
         Available space (kbytes) :     500556
         ID                       :  645781380
         Device/File Name         : /dev/raw/raw4
                                    Device/File needs to be synchronized with the other device
         Device/File Name         : /dev/raw/raw5
                                    Device/File integrity check succeeded

         Cluster registry integrity check succeeded

I executed the following command:

# dd if=/dev/raw/raw5 of=/dev/raw/raw4

Then, I found ocrcheck was good again.

[oracle@rac1 ~]$ ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     505928
         Used space (kbytes)      :       5348
         Available space (kbytes) :     500580
         ID                       :  219149972
         Device/File Name         : /dev/raw/raw4
                                    Device/File integrity check succeeded
         Device/File Name         : /dev/raw/raw5
                                    Device/File integrity check succeeded

         Cluster registry integrity check succeeded

I am not sure it is the right or best way to fix this problem, but it worked. BTW, I tried "ocrconfig -replace ocr /dev/raw/raw5", not working. After that, I was able to bring everything back to normal. Actually, the problem was there when I created ocr and ocrmirror on the raw devices, but I did not notice it at that time.

Execution Plan of a Subquery inside CASE statement

2010-04-30T15:55:00.002-04:00

I found that in our 9.2.0.8 database the execution plan of a subquery inside CASE statement can not be seen in the SQL_TRACE/TKPROF report or from the excution plan extracted from the shared pool. However, it can be seen from Autotrace explain plan. I constructed a test case to demonstrate this as follows:

rem script: xplan_diff.sql
rem   execution plan for the subquery in the CASE statement not shown in SQL_TRACE/TKPROF in 9i
rem
rem

spool xplan_diff.log
set echo on

drop table t;
drop table t2;

create table t 
as 
select rownum id,
       'GOOD' val
from all_objects
where rownum <=20;
 
update t set val='BAD' where mod(id,2) = 0;
commit;

create table t2
as
select rownum id,
       'TEST' val
from all_objects
where rownum <=20; 


alter session set tracefile_identifier = test;
alter session set timed_statistics=true;
alter session set events '10046 trace name context forever, level 12';
set autotrace traceonly
select id,
       case when  val = 'GOOD' then 
  (select t2.val 
  from t, t2
  where t.id = t2.id
    and rownum = 1
         )
       else 'NO TEST'
       END  as IS_TEST
from t;
set autotrace off
alter session set events '10046 trace name context forever, level 12';
spool off
exit;


set doc off
doc

---- 9.2.0.8 Autotrace xplan  ---------------------------

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   COUNT (STOPKEY)
   2    1     MERGE JOIN
   3    2       SORT (JOIN)
   4    3         TABLE ACCESS (FULL) OF 'T2'
   5    2       SORT (JOIN)
   6    5         TABLE ACCESS (FULL) OF 'T'
   7    0   TABLE ACCESS (FULL) OF 'T'


----- 9.2.0.8  tkprof  -----------------------------------

Rows     Row Source Operation
-------  ---------------------------------------------------
     20  TABLE ACCESS FULL T
 
 

------ 10.2.0.4  Autotrace  xplan -------------------------------------------
----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |    20 |   380 |     2   (0)| 00:00:01 |
|*  1 |  COUNT STOPKEY      |      |       |       |            |          |
|*  2 |   HASH JOIN         |      |    20 |   640 |     5  (20)| 00:00:01 |
|   3 |    TABLE ACCESS FULL| T    |    20 |   260 |     2   (0)| 00:00:01 |
|   4 |    TABLE ACCESS FULL| T2   |    20 |   380 |     2   (0)| 00:00:01 |
|   5 |  TABLE ACCESS FULL  | T    |    20 |   380 |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter(ROWNUM=1)
   2 - access("T"."ID"="T2"."ID")

------ 10.2.0.4  tkprof ------------
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  COUNT STOPKEY (cr=6 pr=0 pw=0 time=1435 us)
      1   HASH JOIN  (cr=6 pr=0 pw=0 time=1417 us)
     20    TABLE ACCESS FULL T (cr=3 pr=0 pw=0 time=109 us)
      1    TABLE ACCESS FULL T2 (cr=3 pr=0 pw=0 time=64 us)
     20  TABLE ACCESS FULL T (cr=4 pr=0 pw=0 time=72 us)

#

Note: in 10.2.0.4 no such problem.

I was puzzled the other day about a similar sql to that in the above test case in our 9i production database, which has two cursors with very different sql_plan_hash_value and gets_per_exections when I checked it from v$sql. But when I pulled the execution plan out from v$sql_plan, the execution plan from both cursors are exactly same. Now I understand the subquery execution plan parts are missing. The different cost is due to the join order swapped in the subquery.

Play with my toy 10g RAC V - Move OCR and voting disk from OCFS2 to RAW device

2010-04-28T13:18:00.002-04:00

My toy 10g RAC was set up based on Vincent Chan's article originally, in which OCFS2 filesystem was used for the shared OCR and votingdisk files. In this post, I document steps I have taken to move them to RAW devices.

Steps:

1. Create a new shared virtual SCSI hard disk

a. Add a virtual disk (3GB) for RAC1

b. In the "Add Hardward Wizard" and "Hard Disk" windows for RAC2, Select the following option:
Use an Existing Virtual Disk - Choose this option to reuse or share a hard disk from another Virtual Machine

2. Modify virtual machine configuration file

Additional parameters are required to enable disk sharing between the two virtual RAC nodes. (Details see Vincent's article). Additonal reference is here.

3. Identify the device name for the disk

In RAC1 and RAC2, login as root, run command: fdisk -l, the following message can be seen:

Disk /dev/sdf: 3221 MB, 3221225472 bytes
255 heads, 63 sectors/track, 391 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes

Disk /dev/sdf doesn't contain a valid partition table

4. Create disk partitions
General reference about fdisk can be seen here.

At the end, I created partitions for /dev/sdf shown as follows:

Disk /dev/sdf: 3221 MB, 3221225472 bytes
255 heads, 63 sectors/track, 391 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes

   Device Boot      Start         End      Blocks   Id  System
/dev/sdf1               1          63      506016   83  Linux
/dev/sdf2              64         126      506047+  83  Linux
/dev/sdf3             127         131       40162+  83  Linux
/dev/sdf4             132         391     2088450    5  Extended
/dev/sdf5             132         136       40131   83  Linux
/dev/sdf6             137         141       40131   83  Linux
/dev/sdf7             142         391     2008093+  83  Linux

Note: in reality, OCR, OCRMIRROR and each votingdisk file should be placed on seperate physical disks. Here I placed them in the same disk but different partitions. This is just for learning purpose.

5. Binding the partition
To map the raw devices to the shared partitions created, I did the following:

a. Edit /etc/sysconfig/rawdevices on both nodes, add the following:

/dev/raw/raw4 /dev/sdf1             
/dev/raw/raw5 /dev/sdf2             
/dev/raw/raw6 /dev/sdf3             
/dev/raw/raw7 /dev/sdf5             
/dev/raw/raw8 /dev/sdf6             
/dev/raw/raw9 /dev/sdf7

b. Issue: /sbin/service rawdevices restart

root@rac1:/dev/raw [devdb1]# /sbin/service rawdevices restart
Assigning devices:
           /dev/raw/raw1  -->   /dev/sdc1
/dev/raw/raw1:  bound to major 8, minor 33
           /dev/raw/raw2  -->   /dev/sdd1
/dev/raw/raw2:  bound to major 8, minor 49
           /dev/raw/raw3  -->   /dev/sde1
/dev/raw/raw3:  bound to major 8, minor 65
           /dev/raw/raw4  -->   /dev/sdf1
/dev/raw/raw4:  bound to major 8, minor 81
           /dev/raw/raw5  -->   /dev/sdf2
/dev/raw/raw5:  bound to major 8, minor 82
           /dev/raw/raw6  -->   /dev/sdf3
/dev/raw/raw6:  bound to major 8, minor 83
           /dev/raw/raw7  -->   /dev/sdf5
/dev/raw/raw7:  bound to major 8, minor 85
           /dev/raw/raw8  -->   /dev/sdf6
/dev/raw/raw8:  bound to major 8, minor 86
           /dev/raw/raw9  -->   /dev/sdf7
/dev/raw/raw9:  bound to major 8, minor 87
done

Note: when issuing above command in RAC2, I recieve message: /dev/sdfn (n=1-7) is not a block device.
After reboot both node, everything is fine:

root@rac1:~ [devdb1]# raw -qa
/dev/raw/raw1:  bound to major 8, minor 33
/dev/raw/raw2:  bound to major 8, minor 49
/dev/raw/raw3:  bound to major 8, minor 65
/dev/raw/raw4:  bound to major 8, minor 81
/dev/raw/raw5:  bound to major 8, minor 82
/dev/raw/raw6:  bound to major 8, minor 83
/dev/raw/raw7:  bound to major 8, minor 85
/dev/raw/raw8:  bound to major 8, minor 86
/dev/raw/raw9:  bound to major 8, minor 87

[root@rac2 ~]# raw -qa
/dev/raw/raw1:  bound to major 8, minor 33
/dev/raw/raw2:  bound to major 8, minor 49
/dev/raw/raw3:  bound to major 8, minor 65
/dev/raw/raw4:  bound to major 8, minor 81
/dev/raw/raw5:  bound to major 8, minor 82
/dev/raw/raw6:  bound to major 8, minor 83
/dev/raw/raw7:  bound to major 8, minor 85
/dev/raw/raw8:  bound to major 8, minor 86
/dev/raw/raw9:  bound to major 8, minor 87

c. Edit /etc/udev/permissions.d/50-udev.permissions, add the following entries, and reboot

raw/raw1:oracle:dba:0660
raw/raw2:oracle:dba:0660
raw/raw3:oracle:dba:0660
raw/raw4:root:dba:0640
raw/raw5:root:dba:0640
raw/raw6:oracle:dba:0640
raw/raw7:oracle:dba:0640
raw/raw8:oracle:dba:0640
raw/raw9:oracle:dba:0660

Note: my intended use of raw devices is raw4 and raw5 for OCR and OCRMIRROR; raw6, raw7, raw8 for voting disk files.

6. Moving OCR file from OCFS to raw devices
a. shutdown CRS resource
b. Determine current OCR configuration:

[oracle@rac2 ~]$ ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     262144
         Used space (kbytes)      :       5364
         Available space (kbytes) :     256780
         ID                       :  645781380
         Device/File Name         : /ocfs/clusterware/ocr
                                    Device/File integrity check succeeded

                                    Device/File not configured

         Cluster registry integrity check succeeded

c. Relocate ocr and add ocr mirror

root@rac1:~ [devdb1]# ocrconfig -replace ocrmirror /dev/raw/raw5
root@rac1:~ [devdb1]# ocrconfig -replace ocr /dev/raw/raw4

Note: if ocrmirror is not added first, the following errors will be seen:

root@rac1:~ [devdb1]# ocrconfig -replace ocr /dev/raw/raw4
PROT-16: Internal Error

d. Verify and start CRS resources

root@rac1:/ocfs/clusterware [devdb1]# ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     505928
         Used space (kbytes)      :       5364
         Available space (kbytes) :     500564
         ID                       :  645781380
         Device/File Name         : /dev/raw/raw4
                                    Device/File needs to be synchronized with the other device
         Device/File Name         : /dev/raw/raw5
                                    Device/File integrity check succeeded

         Cluster registry integrity check succeeded

[May 4,2010, update: I did not notice "Device/File needs to be synchronized ..." in the above ocrcheck output on Apr 28. CRS processes could be started despite of this. But today I have to fix this to get CRS started. see http://oracle-study-notes.blogspot.com/2010/05/play-with-my-toy-10g-rac-vi-failed-to.html ]

7. Moving voting disk files from OCFS to raw devices

a. Determine the current voting disk location

oracle@rac1:~ [devdb1]$ crsctl query css votedisk
 0.     0    /ocfs/clusterware/votingdisk

located 1 votedisk(s).

b. Shutdown Oracle Clusterware on both node;

oracle@rac1:~ [devdb1]$ sudo $ORA_CRS_HOME/bin/crsctl stop crs
Password:
Stopping resources.
Successfully stopped CRS resources
Stopping CSSD.
Shutting down CSS daemon.
Shutdown request successfully issued.
oracle@rac1:~ [devdb1]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl stop crs
Password:vz123ys

Stopping resources.
Successfully stopped CRS resources
Stopping CSSD.
Shutting down CSS daemon.
Shutdown request successfully issued.

c. Take a backup of all voting disk:

oracle@rac1:~ [devdb1]$ dd if=/ocfs/clusterware/votingdisk of=/home/oracle/backup/votingdisk_042810
20000+0 records in
20000+0 records out

d. Move

root@rac1:~ [devdb1]# crsctl delete votedisk css /ocfs/clusterware/votingdisk -force
Unexpected parameter: votedisk
root@rac1:~ [devdb1]# crsctl delete css votedisk /ocfs/clusterware/votingdisk -force
only one votedisk /ocfs/clusterware/votingdisk configured.
please add another disk before removing the last one.
root@rac1:~ [devdb1]# crsctl add  css votedisk  /dev/raw/raw7 -force
Now formatting voting disk: /dev/raw/raw7
successful addition of votedisk /dev/raw/raw7.
root@rac1:~ [devdb1]# crsctl delete css votedisk /ocfs/clusterware/votingdisk -force
successful deletion of votedisk /ocfs/clusterware/votingdisk.
root@rac1:~ [devdb1]# crsctl add  css votedisk  /dev/raw/raw6 -force
Now formatting voting disk: /dev/raw/raw6
successful addition of votedisk /dev/raw/raw6.
root@rac1:~ [devdb1]# crsctl add  css votedisk  /dev/raw/raw8 -force
Now formatting voting disk: /dev/raw/raw8
successful addition of votedisk /dev/raw/raw8.
root@rac1:~ [devdb1]# crsctl query css votedisk
 0.     0    /dev/raw/raw6
 1.     0    /dev/raw/raw7
 2.     0    /dev/raw/raw8

located 3 votedisk(s).

e. Start Oracle Clusterware and verify everything is ok

oracle@rac1:~ [devdb1]$ sudo $ORA_CRS_HOME/bin/crsctl start crs
Password:
Attempting to start CRS stack
The CRS stack will be started shortly
oracle@rac1:~ [devdb1]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl start crs
Password:vz123ys

Attempting to start CRS stack
The CRS stack will be started shortly

--- Wait for several min here  -----------

oracle@rac1:~ [devdb1]$
oracle@rac1:~ [devdb1]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             ONLINE     ONLINE on rac1
ora.devdb.SLBA.devdb1.srv                     ONLINE     ONLINE on rac1
ora.devdb.SLBA.devdb2.srv                     ONLINE     ONLINE on rac2
ora.devdb.SNOLBA.cs                           ONLINE     ONLINE on rac1
ora.devdb.SNOLBA.devdb1.srv                   ONLINE     ONLINE on rac1
ora.devdb.SNOLBA.devdb2.srv                   ONLINE     ONLINE on rac2
ora.devdb.db                                  ONLINE     ONLINE on rac2
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     ONLINE on rac1
ora.rac1.gsd                                  ONLINE     ONLINE on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     ONLINE on rac2
ora.rac2.gsd                                  ONLINE     ONLINE on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2
oracle@rac1:~ [devdb1]$ crsctl query css votingdisk
Unexpected parameter: votingdisk
oracle@rac1:~ [devdb1]$ crsctl query css votedisk
 0.     0    /dev/raw/raw6
 1.     0    /dev/raw/raw7
 2.     0    /dev/raw/raw8

located 3 votedisk(s).

Play with my toy 10g RAC IV - Test two OCR adminstration tasks

2010-04-21T18:55:00.000-04:00

The OCR contains information about the cluster node list, instance-to-node mapping information, and information about Oracle Clusterware resource profiles for applications that may have been customized

Task 1 - Mirror the OCR

Oracle RAC environments do not support more than two OCRs, at most a primary OCR and a second OCR. As my OCR is on the OCFS2 filesystem, I need to first create a new OCR file to complete the task of mirroring the OCR

1). Verify I don't have ocrmirror:

root@rac1:~ [devdb1]# ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     262144
         Used space (kbytes)      :       5348
         Available space (kbytes) :     256796
         ID                       :  645781380
         Device/File Name         : /ocfs/clusterware/ocr
                                    Device/File integrity check succeeded

                                    Device/File not configured

         Cluster registry integrity check succeeded

2) Create a new OCR file:

dd if=/dev/zero of=/ocfs/clusterware/ocrmirror.dbf bs=1M count=128

root@rac1:/ocfs/clusterware [devdb1]# dd if=/dev/zero of=/ocfs/clusterware/ocrmirror.dbf bs=1M count=128
128+0 records in
128+0 records out
root@rac1:/ocfs/clusterware [devdb1]# ls -lh
total 144M
-rw-r-----  1 root   oinstall 5.5M Apr 15 10:15 ocr
-rw-r--r--  1 root   root     128M Apr 20 16:10 ocrmirror.dbf
-rw-r--r--  1 oracle oinstall 9.8M Apr 20 16:10 votingdisk

3) Add the OCRMIRROR

root@rac1:/ocfs/clusterware [devdb1]# ocrconfig -replace ocrmirror /ocfs/clusterware/ocrmirror.dbf

root@rac1:/ocfs/clusterware [devdb1]# ls -lhtr
total 397M
-rw-r-----  1 root   oinstall 5.5M Apr 15 10:15 ocr
-rw-r--r--  1 root   root     381M Apr 20 16:13 ocrmirror.dbf
-rw-r--r--  1 oracle oinstall 9.8M Apr 20 16:14 votingdisk

Note: the size of ocrmirror.dbf becomes 381M, this is quite unusal.

4) Verify:

root@rac1:/ocfs/clusterware [devdb1]# ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     262144
         Used space (kbytes)      :       5348
         Available space (kbytes) :     256796
         ID                       :  645781380
         Device/File Name         : /ocfs/clusterware/ocr
                                    Device/File integrity check succeeded
         Device/File Name         : /ocfs/clusterware/ocrmirror.dbf
                                    Device/File integrity check succeeded

         Cluster registry integrity check succeeded

5) Remove OCRMRROR if we want

root@rac1:/ocfs/clusterware [devdb1]# ocrconfig -replace ocrmirror
root@rac1:/ocfs/clusterware [devdb1]# ocrcheck
Status of Oracle Cluster Registry is as follows :
         Version                  :          2
         Total space (kbytes)     :     262144
         Used space (kbytes)      :       5348
         Available space (kbytes) :     256796
         ID                       :  645781380
         Device/File Name         : /ocfs/clusterware/ocr
                                    Device/File integrity check succeeded

                                    Device/File not configured

         Cluster registry integrity check succeeded

root@rac1:/ocfs/clusterware [devdb1]# rm ocrmirror.dbf
rm: remove regular file `ocrmirror.dbf'? yes
root@rac1:/ocfs/clusterware [devdb1]#
root@rac1:/ocfs/clusterware [devdb1]# df -h .
Filesystem            Size  Used Avail Use% Mounted on
/dev/sdb1             512M   90M  423M  18% /ocfs

Task 2 - Backup and restore an OCR file

1) For security purpose, generate a logical OCR backup file

[oracle@rac1 ~]$ sudo /u01/app/oracle/product/10.2.0/crs_1/bin/ocrconfig -export ./backup/logicalocrbak
Password:
[oracle@rac1 ~]$ ls -lh ./backup/
total 128K
-rw-r--r--  1 root root 122K Apr 21 15:16 logicalocrbak

2) Delete the OCR file to simulate lost of OCR

root@rac1:/ocfs/clusterware [devdb1]# ls -lhtr
total 138M
-rw-r--r--  1 root   root     128M Apr 21 15:17 ocr
-rw-r--r--  1 oracle oinstall 9.8M Apr 21 15:17 votingdisk
root@rac1:/ocfs/clusterware [devdb1]# rm -f ocr
root@rac1:/ocfs/clusterware [devdb1]# ls -lhtr
total 9.8M
-rw-r--r--  1 oracle oinstall 9.8M Apr 21 15:17 votingdisk

[oracle@rac1 ~]$ ocrcheck
PROT-602: Failed to retrieve data from the cluster registry

3) Locate a physical backup of OCR

[oracle@rac1 ~]$ ocrconfig -showbackup

rac2     2010/04/20 17:58:54     /u01/app/oracle/product/10.2.0/crs_1/cdata/crs

rac2     2010/04/19 19:47:53     /u01/app/oracle/product/10.2.0/crs_1/cdata/crs

rac2     2010/04/19 15:47:51     /u01/app/oracle/product/10.2.0/crs_1/cdata/crs

rac2     2010/04/19 11:47:47     /u01/app/oracle/product/10.2.0/crs_1/cdata/crs

rac2     2010/04/19 15:47:51     /u01/app/oracle/product/10.2.0/crs_1/cdata/crs
[oracle@rac1 ~]$ ssh rac2 ls -lhtr /u01/app/oracle/product/10.2.0/crs_1/cdata/crs
total 37M
-rw-r--r--  1 root root 4.6M Apr 12 21:14 week_.ocr
-rw-r--r--  1 root root 5.4M Apr 19 11:47 day.ocr
-rw-r--r--  1 root root 5.4M Apr 19 15:47 backup02.ocr
-rw-r--r--  1 root root 5.4M Apr 19 15:47 week.ocr
-rw-r--r--  1 root root 5.4M Apr 19 19:47 backup01.ocr
-rw-r--r--  1 root root 5.4M Apr 20 17:58 backup00.ocr
-rw-r--r--  1 root root 5.4M Apr 20 17:58 day_.ocr

Note: The Oracle Clusterware automatically creates OCR backups every four hours. Default location: CRS_home/cdata/cluster_name

4) Stop CRS resources on both nodes

[oracle@rac1 ~]$ crs_stop -all
Attempting to stop `ora.devdb.SNOLBA.devdb1.srv` on member `rac1`
Attempting to stop `ora.devdb.SLBA.devdb1.srv` on member `rac1`
Attempting to stop `ora.devdb.SNOLBA.cs` on member `rac1`
Attempting to stop `ora.rac1.gsd` on member `rac1`
Attempting to stop `ora.devdb.SLBA.cs` on member `rac1`
Attempting to stop `ora.devdb.SLBA.devdb2.srv` on member `rac2`
Attempting to stop `ora.devdb.SNOLBA.devdb2.srv` on member `rac2`
Stop of `ora.rac1.gsd` on member `rac1` succeeded.
Stop of `ora.devdb.SLBA.devdb2.srv` on member `rac2` succeeded.
Stop of `ora.devdb.SLBA.devdb1.srv` on member `rac1` succeeded.
Stop of `ora.devdb.SNOLBA.devdb2.srv` on member `rac2` succeeded.
Stop of `ora.devdb.SNOLBA.devdb1.srv` on member `rac1` succeeded.
Attempting to stop `ora.rac1.ons` on member `rac1`
Attempting to stop `ora.rac2.gsd` on member `rac2`
Attempting to stop `ora.rac2.ons` on member `rac2`
Stop of `ora.rac2.gsd` on member `rac2` succeeded.
Attempting to stop `ora.devdb.db` on member `rac2`
Stop of `ora.rac1.ons` on member `rac1` succeeded.
Stop of `ora.rac2.ons` on member `rac2` succeeded.
Stop of `ora.devdb.SLBA.cs` on member `rac1` succeeded.
Stop of `ora.devdb.SNOLBA.cs` on member `rac1` succeeded.
Stop of `ora.devdb.db` on member `rac2` succeeded.
Attempting to stop `ora.rac1.LISTENER_RAC1.lsnr` on member `rac1`
Attempting to stop `ora.rac2.LISTENER_RAC2.lsnr` on member `rac2`
Stop of `ora.rac1.LISTENER_RAC1.lsnr` on member `rac1` succeeded.
`ora.devdb.devdb1.inst` is already OFFLINE.
Attempting to stop `ora.rac1.ASM1.asm` on member `rac1`
Stop of `ora.rac2.LISTENER_RAC2.lsnr` on member `rac2` succeeded.
`ora.devdb.devdb2.inst` is already OFFLINE.
Attempting to stop `ora.rac2.ASM2.asm` on member `rac2`
Stop of `ora.rac1.ASM1.asm` on member `rac1` succeeded.
Attempting to stop `ora.rac1.vip` on member `rac1`
Stop of `ora.rac2.ASM2.asm` on member `rac2` succeeded.
Stop of `ora.rac1.vip` on member `rac1` succeeded.
Attempting to stop `ora.rac2.vip` on member `rac2`
Stop of `ora.rac2.vip` on member `rac2` succeeded.
CRS-0216: Could not stop resource 'ora.devdb.devdb1.inst'.

CRS-0216: Could not stop resource 'ora.devdb.devdb2.inst'.

[oracle@rac1 ~]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             OFFLINE    OFFLINE
ora.devdb.SLBA.devdb1.srv                     OFFLINE    OFFLINE
ora.devdb.SLBA.devdb2.srv                     OFFLINE    OFFLINE
ora.devdb.SNOLBA.cs                           OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb1.srv                   OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb2.srv                   OFFLINE    OFFLINE
ora.devdb.db                                  OFFLINE    OFFLINE
ora.devdb.devdb1.inst                         OFFLINE    OFFLINE
ora.devdb.devdb2.inst                         OFFLINE    OFFLINE
ora.rac1.ASM1.asm                             OFFLINE    OFFLINE
ora.rac1.LISTENER_RAC1.lsnr                   OFFLINE    OFFLINE
ora.rac1.gsd                                  OFFLINE    OFFLINE
ora.rac1.ons                                  OFFLINE    OFFLINE
ora.rac1.vip                                  OFFLINE    OFFLINE
ora.rac2.ASM2.asm                             OFFLINE    OFFLINE
ora.rac2.LISTENER_RAC2.lsnr                   OFFLINE    OFFLINE
ora.rac2.gsd                                  OFFLINE    OFFLINE
ora.rac2.ons                                  OFFLINE    OFFLINE
ora.rac2.vip                                  OFFLINE    OFFLINE

5) Stop CRS on both node

The following command has failed due to OCR was deleted:

[oracle@rac1 ~]$ sudo $ORA_CRS_HOME/bin/crsctl stop crs
Password:
OCR initialization failed accessing OCR device: PROC-26: Error while accessing the physical storage Operating System error [No such file or directory] [2]

Note: normally we should see:

[oracle@rac1 ~]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl stop crs
Stopping resources.
Successfully stopped CRS resources
Stopping CSSD.
Shutting down CSS daemon.
Shutdown request successfully issued.

Tried to kill ocssd.bin processes on both nodes at OS level. Server reboot automatically after they are killed.
After reboot, no CRS procesess are running.

[oracle@rac1 ~]$ ps -ef | grep d.bin
oracle    8887  8391  0 15:36 pts/1    00:00:00 grep d.bin
[oracle@rac1 ~]$ ssh rac2 ps -ef | grep d.bin
[oracle@rac1 ~]$

6) Restore OCR using the backup identified at step 3

Due to my OCR resides on OCFS2 filesystem, I need to create the file at first.

root@rac1:/ocfs/clusterware [devdb1]# dd if=/dev/zero of=/ocfs/clusterware/ocr bs=1M count=128
128+0 records in
128+0 records out
root@rac1:/ocfs/clusterware [devdb1]# ls -lhtr
total 138M
-rw-r--r--  1 oracle oinstall 9.8M Apr  5 10:17 votingdisk
-rw-r--r--  1 root   root     128M Apr 21 15:41 ocr

Then I can do a restore from backup:

[oracle@rac1 clusterware]$ ssh rac2 sudo $ORA_CRS_HOME/bin/ocrconfig -restore /u01/app/oracle/product/10.2.0/crs_1/cdata/crs/backup00.ocr
Password:vz123ys




[oracle@rac1 ~]$ 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.

Uniqueness check for OCR device passed.

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.

Note: the syntax for restore from logical backup is: ocrconfig -import /home/oracle/backup/ocrlogicbackup

7) Restart CRS on both nodes

[oracle@rac1 ~]$ sudo $ORA_CRS_HOME/bin/crsctl start crs
Password:
Attempting to start CRS stack
The CRS stack will be started shortly
[oracle@rac1 ~]$ ssh rac2 sudo $ORA_CRS_HOME/bin/crsctl start crs
Password:vz123ys

Attempting to start CRS stack
The CRS stack will be started shortly

[oracle@rac1 ~]$ ps -ef | grep d.bin
root      6591     1  0 15:29 ?        00:00:04 /u01/app/oracle/product/10.2.0/crs_1/bin/crsd.bin reboot
oracle    9941  6589  0 15:45 ?        00:00:01 /u01/app/oracle/product/10.2.0/crs_1/bin/evmd.bin
oracle   10071 10045  0 15:45 ?        00:00:01 /u01/app/oracle/product/10.2.0/crs_1/bin/ocssd.bin
oracle   20444  8391  0 15:51 pts/1    00:00:00 grep d.bin

After serveral trials using SRVCTL to shutdown/bring up individual commponent and manually shutdown ASM and RAC2 instances, finally I got:

[oracle@rac1 ~]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             ONLINE     ONLINE on rac1
ora.devdb.SLBA.devdb1.srv                     ONLINE     ONLINE on rac1
ora.devdb.SLBA.devdb2.srv                     ONLINE     ONLINE on rac2
ora.devdb.SNOLBA.cs                           ONLINE     ONLINE on rac1
ora.devdb.SNOLBA.devdb1.srv                   ONLINE     ONLINE on rac1
ora.devdb.SNOLBA.devdb2.srv                   ONLINE     ONLINE on rac2
ora.devdb.db                                  ONLINE     ONLINE on rac2
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     ONLINE on rac1
ora.rac1.gsd                                  ONLINE     ONLINE on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     ONLINE on rac2
ora.rac2.gsd                                  ONLINE     ONLINE on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2
[oracle@rac1 ~]$

Ref:
(1) http://download.oracle.com/docs/cd/B19306_01/rac.102/b14197/votocr.htm#BABIHADG
(2) OCR / Vote disk Maintenance Operations: (ADD/REMOVE/REPLACE/MOVE), including moving from RAW Devices to Block Devices. [MOS ID 428681.1]
(3) 'ocrconfig -replace ocr' Fails With PROT-16 [MOS ID 444757.1]

Play with my toy 10g RAC III - Demonstrate Load Balancing Advisory

2010-04-16T14:14:00.005-04:00

By design, RAC involves multiple instances accessing the same database. By analogy, a database can be thought of as an island, which is accessible by multiple brigdes (i.e. instances). If there were two brigdes and 10 incoming cars that are being driven to the island, and if the 10 cars are directed randomly toward one of the bridges, each bridge will be added 5 cars roughly, this is so-called Client-side connect-time load balancing . That is to say regardless of how busy a brigde is, how many cars already on that brigde, and how much longer to travel through that bridge etc, each brige is treated equally. We can easily imagine that if we have a mechanizm to monitor the condition of each brigde and direct the incoming cars based on the current traffic conditions, we will be much better in providing the service. Such a mechanizm in Oracle RAC is called Load balancing Advisory, which can be used in the Server-side connect-time load balancing. Both client-side and server-side load balancings are applied to the time when a physical connection to a database is initially opened. Since opening a connection is an expensive operation, ideally application should be able to open a connection once, then reuse it for as many times as needed. There is a function called connection pooling at the application server layer, which establishs physical connections once and never close them. With respect to connection pools, there is a feature called "Runtime Connection Load Balancing", esstially it allocates logical connections among the physical connections in the connection pool at the transaction level instead of load balancing at the time of the initial database connection.

In this post, I will describe a test which is to demonstrate server-side connect-time load balancing with load balancing advisory feature. The idea used in this test was inspired from Jim Czuprynski's article , as well as in his Oracle University RAC class, which I attended about two and half years ago.

First of all, a "job" in this test is defined as a workload that involves:

(1) connect to the database as user "DENIS"
(2) do an insert and an delete to a table 1000 times
(3) disconnect
(4) repeat (1) to (3) during predefined time period, e.g 20 min.

So if I submit 100 such jobs, I would expect 100 sessions count by username "DENIS"

Secondly, I created a service called 'SLBA', which is used for the job to connect to the database. The details about how to create a LBA-enabled service can be seen in Jim's article or Oracle documentation.

The steps are as follows:

1. Query GV$SERVICEMEATIC for instance goodness before starting any jobs

12:39:59 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:40:00   12:40:05       2     100     100
         12:39:58   12:40:01       1     100     100
         12:38:58   12:39:58       1     100     100
         12:38:53   12:39:53       2     100     100

Note: In Oracle 10.2 and above, the GOODNESS indicates how attractive the instance is with respect to processing the workload presented to the database service. Lower numbers are preferred. The umber is internally calculated based on any goal (long or short) that was specified for that database service. In Oracle 10.2 and above, the DELTA column predicts how much GOODNESS will increase for every
additional session that connects to the instance.

2. Start 10 jobs using SERVICE SLBA at RAC2

[oracle@rac2 ~]$ startSLBAload.sh 20


12:41:18 system@DEVDB> @ct
count # of session by username DENIS

       Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:41:27     1          3
2010-04-16 12:41:27     2          7


12:42:30 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:42:39   12:42:45       2     416    9998
         12:42:33   12:42:38       1     384    9844
         12:40:58   12:41:58       1     384    9844
         12:40:53   12:41:54       2     416    9998

3. Start CPU LOAD at RAC2

[oracle@rac2 ~]$ cpu_load.sh &
[1] 8882
[oracle@rac2 ~]$ ps -ef | grep zip
oracle    8883  8882 16 12:43 pts/1    00:00:01 gzip video1.mpg
oracle    8884  8882  8 12:43 pts/1    00:00:00 gzip video2.mpg

Note: I created two gzip/guzip jobs at RAC2 to increase CPU utilization at RAC2.

4. Query GV$SERVICEMEATIC for instance goodness

12:44:46 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:44:48   12:44:54       2    1666    9998
         12:44:43   12:44:49       1     500    9994
         12:43:54   12:44:54       2    1666    9998
         12:42:58   12:43:58       1     500    9994

Note: it is expected to see "Goodness" increasing in RAC2, compared to RAC1, RAC2 should be less attractive to the incomming connections.

5. Start 10 jobs using SERVICE SLBA at RAC2 - total 20 jobs

12:45:55 system@DEVDB> @ct
count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:46:11     1          7
2010-04-16 12:46:11     2         13

12:46:03 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:46:10   12:46:14       2   12500    9998
         12:46:03   12:46:07       1     588    9998
         12:44:57   12:45:58       1     588    9998
         12:44:54   12:45:54       2   12500    9998

6. Start 10 jobs using SERVICE SLBA at RAC2 - total 30 jobs

12:47:52 system@DEVDB> @ct
count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:48:06     1         15
2010-04-16 12:48:06     2         15

12:47:58 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:48:05   12:48:10       2   12500    9998
         12:47:43   12:47:48       1     750    9998
         12:46:54   12:47:55       2   12500    9998
         12:45:58   12:46:58       1     750    9998

7. Start 10 jobs using SERVICE SLBA at RAC2 - total 40 jobs

12:50:14 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:50:19   12:50:22       1    1428    9998
         12:50:19   12:50:23       2   12500    9998
         12:48:58   12:49:58       1    1428    9998
         12:48:55   12:49:54       2   12500    9998

12:50:21 system@DEVDB> @ct
count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:50:39     1         15
2010-04-16 12:50:39     2         25


12:51:23 system@DEVDB> @ct
count # of session by username DENIS

8. Start 10 jobs using SERVICE SLBA at RAC2 - total 50 jobs

Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:51:37     1         26
2010-04-16 12:51:37     2         24

12:51:30 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:51:40   12:51:43       2   12500    9998
         12:51:28   12:51:33       1    2500    9998
         12:49:58   12:50:58       1    2500    9998
         12:49:54   12:50:55       2   12500    9998

Note: We started to see # of session in RAC1 greater than that in RAC2

8. Start 10 jobs using SERVICE SLBA at RAC2 - total 60 jobs

Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:53:15     1         34
2010-04-16 12:53:15     2         26

12:53:09 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:53:15   12:53:20       2   12500    9998
         12:53:08   12:53:13       1    1700    9998
         12:51:58   12:52:58       1    1700    9998
         12:51:55   12:52:55       2   12500    9998

9. Start 10 jobs using SERVICE SLBA at RAC2 - total 70 jobs

count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:54:23     1         42
2010-04-16 12:54:23     2         28

12:54:15 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:54:19   12:54:24       2   12500    9998
         12:54:13   12:54:18       1    2100    9998
         12:52:58   12:53:58       1    2100    9998
         12:52:55   12:53:54       2   12500    9998

9. Start 10 jobs using SERVICE SLBA at RAC2 - total 80 jobs

12:55:37 system@DEVDB> @ct
count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:55:55     1         53
2010-04-16 12:55:55     2         27

12:55:50 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:55:55   12:55:59       2   12500    9998
         12:55:48   12:55:52       1    2650    9998
         12:54:52   12:55:55       2   12500    9998
         12:53:58   12:54:58       1    2650    9998

9. Start 10 jobs using SERVICE SLBA at RAC2 - total 90 jobs

12:56:48 system@DEVDB> @ct
count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:56:59     1         59
2010-04-16 12:56:59     2         31

12:56:52 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:56:55   12:57:00       2   12500    9998
         12:56:48   12:56:53       1    5000    9998
         12:55:55   12:56:55       2   12500    9998
         12:54:58   12:55:57       1    5000    9998

10. Start 10 jobs using SERVICE SLBA at RAC2 - total 100 jobs

12:58:55 system@DEVDB> @ct
count # of session by username DENIS

                     Inst
SYSDATE                ID   COUNT(*)
------------------- ----- ----------
2010-04-16 12:59:08     1         65
2010-04-16 12:59:08     2         35

12:59:01 system@DEVDB> @servicemetric.sql SLBA

Service                         Inst    Good
Name     Start Time End Time      ID    ness   DELTA
-------- ---------- ---------- ----- ------- -------
SLBA     12:59:05   12:59:10       2   12500    9998
         12:58:54   12:58:57       1   12500    9998
         12:57:58   12:58:57       1   12500    9998
         12:57:52   12:58:52       2   12500    9998

Note: At total jobs 100, the GOODNESS of two instances were evened out. The change of GOODNESS inidicated the LBA was working and somehow was used to direct the incomming connections to the less-loaded instance.

Scripts used in this test can be found here.

Play with my toy 10g RAC II - Familiar with SRVCTL

2010-04-12T12:03:00.003-04:00

In this post, I continue to describe the experiences I have gained through playing with my little toy RAC. First of all, I found my RAC database could not fully function after restarting the VM servers, i.e. after my VM RAC1 and RAC2 nodes are powered on, the status of the cluster is usually shown as following:

[oracle@rac1 ~]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.CRM.cs                              OFFLINE    OFFLINE
ora.devdb.CRM.devdb1.srv                      OFFLINE    OFFLINE
ora.devdb.db                                  ONLINE     ONLINE on rac1
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     UNKNOWN on rac1
ora.rac1.gsd                                  ONLINE     UNKNOWN on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     UNKNOWN on rac2
ora.rac2.gsd                                  ONLINE     UNKNOWN on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2

It can be seen that the status of gsd and listener rescours are unknown. The service CRM is not started. I have to follow the following steps, which use SRVCTL exlusively to get the RAC work:

- Stop application resources

srvctl stop database -d devdb
srvctl stop asm -n rac1
srvctl stop asm -n rac2
srvctl stop nodeapps -n rac1
srvctl stop nodeapps -n rac2
- Start application resources

srvctl start nodeapps -n rac1

srvctl start nodeapps -n rac2
srvctl start asm -n rac1
srvctl start asm -n rac2
srvctl start database -d devdb
srvctl start service -d devdb -s CRM

Here I list some other srvctl commands which may be useful for reference:

- Start and stop instances
srvctl start instance -d devdb -i devdb1
srvctl stop instance -d devdb -i devdb1

- Start and stop listeners
srvctl start listener -n devdb1 -l LISTENER_RAC1
srvctl stop listener -n devdb2 -l LISTENER_RAC2

- View current configuration for the entire cluster database
srvctl config database -d devdb -a

[oracle@rac1 ~]$ srvctl config database -d devdb -a
rac1 devdb1 /u01/app/oracle/product/10.2.0/db_1
rac2 devdb2 /u01/app/oracle/product/10.2.0/db_1
DB_NAME: devdb
ORACLE_HOME: /u01/app/oracle/product/10.2.0/db_1
SPFILE: +DG1/devdb/spfiledevdb.ora
DOMAIN: null
DB_ROLE: null
START_OPTIONS: null
POLICY:  AUTOMATIC
ENABLE FLAG: DB ENABLED

- View the configuration for all node applications for node rac2
srvctl config nodeapps -n rac2

- Create a new service
srvctl add service -d devdb -s CRM

- Start a service on the whole cluster
srvctl start service -d devdb -s CRM

- Stop a service on both instance, force it to stop (-f)
srvctl stop service -d devdb -s CRM -i devdb1,devdb2 -f

Note: it does not work, I have to do:
srvctl stop service -d devdb -s CRM -i devdb1 -f
srvctl stop service -d devdb -s CRM -i devdb2 -f

- Enable a service on the devdb2 instance only
srvctl enable service -d devdb -s CRM -i devdb2

- Disable a service on the devdb1 instance only
srvctl disable service -d devdb -s CRM -i devdb1

- Modify a service so that devdb2 becomes preferred instance
srvctl modify service -d devdb -s CRM -i devdb2 -r

- Remove a service
srvctl remove service -d devdb -s CRM

- View config for a service
srvctl config service -d devdb -s CRM -a

Apr 17,2010 Update:

After all CRS resource offline, I was able to bring everything up by: crs_start -all

[oracle@rac1 ~]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             OFFLINE    OFFLINE
ora.devdb.SLBA.devdb1.srv                     OFFLINE    OFFLINE
ora.devdb.SLBA.devdb2.srv                     OFFLINE    OFFLINE
ora.devdb.SNOLBA.cs                           OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb1.srv                   OFFLINE    OFFLINE
ora.devdb.SNOLBA.devdb2.srv                   OFFLINE    OFFLINE
ora.devdb.db                                  OFFLINE    OFFLINE
ora.devdb.devdb1.inst                         OFFLINE    OFFLINE
ora.devdb.devdb2.inst                         OFFLINE    OFFLINE
ora.rac1.ASM1.asm                             OFFLINE    OFFLINE
ora.rac1.LISTENER_RAC1.lsnr                   OFFLINE    OFFLINE
ora.rac1.gsd                                  OFFLINE    OFFLINE
ora.rac1.ons                                  OFFLINE    OFFLINE
ora.rac1.vip                                  OFFLINE    OFFLINE
ora.rac2.ASM2.asm                             OFFLINE    OFFLINE
ora.rac2.LISTENER_RAC2.lsnr                   OFFLINE    OFFLINE
ora.rac2.gsd                                  OFFLINE    OFFLINE
ora.rac2.ons                                  OFFLINE    OFFLINE
ora.rac2.vip                                  OFFLINE    OFFLINE
oracle@rac1 ~]$ crs_start -all
Attempting to start `ora.rac1.vip` on member `rac1`
Attempting to start `ora.rac2.vip` on member `rac2`
Start of `ora.rac2.vip` on member `rac2` succeeded.
Start of `ora.rac1.vip` on member `rac1` succeeded.
Attempting to start `ora.rac1.ASM1.asm` on member `rac1`
Attempting to start `ora.rac2.ASM2.asm` on member `rac2`
Start of `ora.rac2.ASM2.asm` on member `rac2` succeeded.
Attempting to start `ora.devdb.devdb2.inst` on member `rac2`
Start of `ora.rac1.ASM1.asm` on member `rac1` succeeded.
Attempting to start `ora.devdb.devdb1.inst` on member `rac1`
Start of `ora.devdb.devdb2.inst` on member `rac2` succeeded.
Attempting to start `ora.rac2.LISTENER_RAC2.lsnr` on member `rac2`
Start of `ora.rac2.LISTENER_RAC2.lsnr` on member `rac2` succeeded.
Start of `ora.devdb.devdb1.inst` on member `rac1` succeeded.
Attempting to start `ora.rac1.LISTENER_RAC1.lsnr` on member `rac1`
Start of `ora.rac1.LISTENER_RAC1.lsnr` on member `rac1` succeeded.
Attempting to start `ora.devdb.SLBA.cs` on member `rac1`
Attempting to start `ora.devdb.SLBA.devdb2.srv` on member `rac2`
Attempting to start `ora.devdb.SLBA.devdb1.srv` on member `rac1`
Start of `ora.devdb.SLBA.devdb2.srv` on member `rac2` succeeded.
Attempting to start `ora.devdb.SNOLBA.cs` on member `rac1`
Attempting to start `ora.devdb.SNOLBA.devdb1.srv` on member `rac1`
Start of `ora.devdb.SLBA.cs` on member `rac1` succeeded.
Attempting to start `ora.rac1.gsd` on member `rac1`
CRS-1002: Resource 'ora.rac1.ons' is already running on member 'rac1'

Attempting to start `ora.devdb.SNOLBA.devdb2.srv` on member `rac2`
Start of `ora.devdb.SNOLBA.devdb2.srv` on member `rac2` succeeded.
Start of `ora.rac1.gsd` on member `rac1` succeeded.
CRS-1002: Resource 'ora.devdb.db' is already running on member 'rac1'

CRS-1002: Resource 'ora.rac2.ons' is already running on member 'rac2'

Start of `ora.devdb.SLBA.devdb1.srv` on member `rac1` succeeded.
Attempting to start `ora.rac2.gsd` on member `rac2`
Start of `ora.devdb.SNOLBA.cs` on member `rac1` succeeded.
Start of `ora.rac2.gsd` on member `rac2` succeeded.
Start of `ora.devdb.SNOLBA.devdb1.srv` on member `rac1` succeeded.
CRS-0223: Resource 'ora.devdb.db' has placement error.

CRS-0223: Resource 'ora.rac1.ons' has placement error.

CRS-0223: Resource 'ora.rac2.ons' has placement error.

[oracle@rac1 ~]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.SLBA.cs                             ONLINE     ONLINE on rac1
ora.devdb.SLBA.devdb1.srv                     ONLINE     ONLINE on rac1
ora.devdb.SLBA.devdb2.srv                     ONLINE     ONLINE on rac2
ora.devdb.SNOLBA.cs                           ONLINE     ONLINE on rac1
ora.devdb.SNOLBA.devdb1.srv                   ONLINE     ONLINE on rac1
ora.devdb.SNOLBA.devdb2.srv                   ONLINE     ONLINE on rac2
ora.devdb.db                                  ONLINE     ONLINE on rac1
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     ONLINE on rac1
ora.rac1.gsd                                  ONLINE     ONLINE on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     ONLINE on rac2
ora.rac2.gsd                                  ONLINE     ONLINE on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2

Play with my toy 10g RAC - Test Transparent Application Failover (TAF)

2010-04-06T17:24:00.004-04:00

Finally I got my first toy 10g RAC set up based on Vincent Chan's excellent document (published in 2007, this doc has been not availabe on the original OTN websitr any more). This toy RAC has two nodes, which are VMWare server 2.0 Virtual Machines with CentOS 4.7 hosted on Windows XP. The next steps are of course to explore various RAC specific features on it as much as possible. I plan to re-visit all the hands-on labs I experienced when I was in an Oracle University Course "Oracle Database 10g: RAC for Adminstrators" about 2.5 years ago. I have been planning to set up a RAC since then, however, the actual action has been delayed again and again. Now the world is talking about 11g RAC though, I am still excited that I finally got this little out-dated toy done.

Vicent's document also provided a test to demonstrate TAF, which I repeated here as a warm-up for my exploration:

(1) Create a Service and start it

Service Name : CRM
Database Name : devdb
Preferred Instance : devdb1
Available Instance : devdb2
TAF Policy : BASIC

[oracle@rac1 ~]$ srvctl add service -d devdb -s CRM -r devdb1 -a devdb2 -P BASIC
[oracle@rac1 ~]$ srvctl config service -d devdb -s CRM -a
CRM PREF: devdb1 AVAIL: devdb2 TAF: BASIC
[oracle@rac1 ~]$ srvctl start service -d devdb -s CRM
[oracle@rac1 ~]$ ./crs_rep.sh
HA Resource                                   Target     State
-----------                                   ------     -----
ora.devdb.CRM.cs                              ONLINE     ONLINE on rac1
ora.devdb.CRM.devdb1.srv                      ONLINE     ONLINE on rac1
ora.devdb.CRM.devdb2.srv                      ONLINE     ONLINE on rac2
ora.devdb.db                                  ONLINE     ONLINE on rac1
ora.devdb.devdb1.inst                         ONLINE     ONLINE on rac1
ora.devdb.devdb2.inst                         ONLINE     ONLINE on rac2
ora.rac1.ASM1.asm                             ONLINE     ONLINE on rac1
ora.rac1.LISTENER_RAC1.lsnr                   ONLINE     ONLINE on rac1
ora.rac1.gsd                                  ONLINE     ONLINE on rac1
ora.rac1.ons                                  ONLINE     ONLINE on rac1
ora.rac1.vip                                  ONLINE     ONLINE on rac1
ora.rac2.ASM2.asm                             ONLINE     ONLINE on rac2
ora.rac2.LISTENER_RAC2.lsnr                   ONLINE     ONLINE on rac2
ora.rac2.gsd                                  ONLINE     ONLINE on rac2
ora.rac2.ons                                  ONLINE     ONLINE on rac2
ora.rac2.vip                                  ONLINE     ONLINE on rac2

(2) Add the following entry in the client tnsnames.ora

CRM =
(DESCRIPTION =
   (ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.2.31)(PORT = 1521))
   (ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.2.32)(PORT = 1521))
   (LOAD_BALANCE = yes)
   (CONNECT_DATA =
     (SERVER = DEDICATED)
     (SERVICE_NAME = CRM)
     (FAILOVER_MODE =
        (TYPE = SELECT)
        (METHOD = BASIC)
        (RETRIES = 180)
        (DELAY = 5)
     )
   )
)

(3) Connect the first session using CRM Service

C:\Documents and Settings\denis>sqlplus denis@CRM

SQL*Plus: Release 11.1.0.6.0 - Production on Tue Apr 6 14:48:54 2010

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

Enter password:

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> select
  2   failover_type,
  3   failover_method,
  4   failed_over
  5   from v$session
  6   where username='DENIS';

FAILOVER_TYPE FAILOVER_M FAI
------------- ---------- ---
SELECT        BASIC      NO


SQL> select
  2   instance_number instance#,
  3   instance_name,
  4   host_name,
  5   status
  6   from v$instance;

 INSTANCE# INSTANCE_NAME    HOST_NAME            STATUS
---------- ---------------- -------------------- ------------
         1 devdb1           rac1.localdomain     OPEN

(4) Shutdwon instance devdb1 from another session login as SYS

sys@DEVDB> select
  2   instance_number instance#,
  3   instance_name,
  4   host_name,
  5   status
  6  from v$instance;

 INSTANCE# INSTANCE_NAME    HOST_NAME            STATUS
---------- ---------------- -------------------- ------------
         1 devdb1           rac1.localdomain     OPEN


sys@DEVDB> shutdown abort
ORACLE instance shut down.

(5) Verify the session has failed over.
In the first session:

SQL> select
  2   instance_number instance#,
  3   instance_name,
  4   host_name,
  5   status
  6  from v$instance;

 INSTANCE# INSTANCE_NAME    HOST_NAME            STATUS
---------- ---------------- -------------------- ------------
         2 devdb2           rac2.localdomain     OPEN


SQL> select
  2    failover_type,
  3    failover_method,
  4    failed_over
  5   from v$session
  6  where username='DENIS';

FAILOVER_TYPE FAILOVER_M FAI
------------- ---------- ---
SELECT        BASIC      YES

(6) Relocate the CRM service back to the preferred instance.

After devdb1 is brought back up, the CRM service does not automatically relocate
back to the preferred instance. This means any new connections using CRM service will be on devdb2, instead of the preferred instance
devdb1. This can be achieved by the following command:

$ srvctl relocate service -d devdb -s CRM -i devdb2 -t devdb1

The meaning of the command options can be seen here:

[oracle@rac1 ~]$ srvctl relocate service -h
Usage: srvctl relocate service -d <name> -s <service_name> -i <old_inst_name> -t <new_inst_name> [-f]
    -d <name>           Unique name for the database
    -s <service>        Service name
    -i <old_inst>       Old instance name
    -t <new_inst>       New instance name
    -f                  Disconnect all sessions during stop or relocate service operations
    -h                  Print usage

Data block was loaded using the NOLOGGING option

2010-04-01T14:15:00.003-04:00

A production database went live last weekend through cloning and applying archived logs by similiar approach as described in this post. However, when users did an insert into a table, they recieved " ORA-26040: Data block was loaded using the NOLOGGING option", "ORA-01578: ORACLE data block corrupted (file # xx, block # xxx)". By querying DBA_EXTENTS with file # and block #, I identfied this block belongs to an index segment. After discussing with app DBAs, I realized that during cloning period, at source database, rebuild indexes for that table has been performed and those indexes have nologging option turned on. During dissussion, app DBAs also suggested to use DBVERIFY to check other possible block corruption, I was not so sure it could work. I was under assumption that DBVEFRIFY can only detect physical block corruptions, not logical block corruptions. As we have already identified the root cause, we have not done DBV for all data files, we just dropped the table and re-created all indexes (app DBA confirms that we don't need the data in the new database acutally).

Today, I did a test to see if DBV is supposed to catch such kind of block corruption. The overall test steps is described as follows:

1. Create a test tablespace, idx_temp
2. Create a table and an index on idx_temp tablespace
3. Backup idx_temp tablespace
4. Rebuild the index with nologging
5. Some DML activities
6. Lost of idx_temp tablespace datafile
7. Recover tablespace
8. Full scan the index
9. Identify corrupted block by DBV and analyze statement

Note: during test I have learned that FORCE_LOGGING should not be turned on at database level, otherwise the test will fail to demonstrate the points.

SQL> drop table t;
drop table t
           *
ERROR at line 1:
ORA-00942: table or view does not exist
 
 
SQL> drop tablespace idx_temp including contents and datafiles;
 
Tablespace dropped.
 
SQL> create tablespace idx_temp datafile '/tmp/idx_temp_data_1.dbf' size 200M;
 
Tablespace created.
 
SQL> create table t as select rownum id, a.* from dba_objects a;
 
Table created.
 
SQL> create index t_idx on t(id) tablespace idx_temp nologging;
 
Index created.
 
SQL> alter tablespace idx_temp begin backup;
 
Tablespace altered.
 
SQL> ho cp /tmp/idx_temp_data_1.dbf /tmp/idx_temp_data_1.dbf.bak
 
SQL> alter tablespace idx_temp end backup;
 
Tablespace altered.
 
SQL> alter index t_idx rebuild;
 
Index altered.
 
SQL> update t set object_name=lower(object_name);
 
50842 rows updated.
 
SQL> ho rm -f /tmp/idx_temp_data_1.dbf
 
SQL> alter tablespace idx_temp offline immediate;
 
Tablespace altered.
 
SQL> ho cp /tmp/idx_temp_data_1.dbf.bak /tmp/idx_temp_data_1.dbf
 
SQL> recover tablespace idx_temp;
Media recovery complete.
SQL> alter tablespace idx_temp online;
 
Tablespace altered.
 
SQL> select count(id) from t;
select count(id) from t
                      *
ERROR at line 1:
ORA-01578: ORACLE data block corrupted (file # 14, block # 141)
ORA-01110: data file 14: '/tmp/idx_temp_data_1.dbf'
ORA-26040: Data block was loaded using the NOLOGGING option
 
 
SQL> analyze index t_idx validate structure;
analyze index t_idx validate structure
*
ERROR at line 1:
ORA-01578: ORACLE data block corrupted (file # 14, block # 141)
ORA-01110: data file 14: '/tmp/idx_temp_data_1.dbf'
ORA-26040: Data block was loaded using the NOLOGGING option

It can be seen that full scan the index blocks or using analyze validate structure can identify the block corruption. Let's see how DBVERIFY utility can tell us.

This utility can run against the data file:
dbv file='/tmp/idx_temp_data_1.dbf' logfile='dbv.log'

From the screen, I can see:

DBVERIFY: Release 10.2.0.1.0 - Production on Thu Apr 1 09:09:50 2010
 
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
 
 
DBV-00200: Block, dba 58720397, already marked corrupted
 
DBV-00200: Block, dba 58720398, already marked corrupted
 
DBV-00200: Block, dba 58720399, already marked corrupted
 
...

DBV-00200: Block, dba 58720513, already marked corrupted
 
DBV-00200: Block, dba 58720514, already marked corrupted
 
DBV-00200: Block, dba 58720515, already marked corrupted

In the log file, I have:

DBVERIFY: Release 10.2.0.1.0 - Production on Thu Apr 1 09:09:50 2010
 
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
 
 
DBVERIFY - Verification starting : FILE = /tmp/idx_temp_data_1.dbf
 
DBVERIFY - Verification complete
 
Total Pages Examined         : 25600
Total Pages Processed (Data) : 0
Total Pages Failing   (Data) : 0
Total Pages Processed (Index): 114
Total Pages Failing   (Index): 0
Total Pages Processed (Other): 140
Total Pages Processed (Seg)  : 0
Total Pages Failing   (Seg)  : 0
Total Pages Empty            : 25346
Total Pages Marked Corrupt   : 112
Total Pages Influx           : 0
Highest block SCN            : 1781276169 (2536.1781276169)

So, the DBVERIFY utility did catch corrupted blocks.To find out which segments having corrupted blocks, I have to convert DBA to file# and block# by following, for example:

SQL> SELECT dbms_utility.data_block_address_block(58720399) "BLOCK",
       dbms_utility.data_block_address_file(58720399) "FILE"
FROM dual;
  2    3  
     BLOCK       FILE
---------- ----------
       143         14


SQL> SELECT owner, segment_name
  FROM DBA_EXTENTS
 WHERE file_id = &p1
   AND &p2 between block_id AND block_id + blocks - 1 ;
  2    3    4  Enter value for p1: 14
old   3:  WHERE file_id = &p1
new   3:  WHERE file_id = 14
Enter value for p2: 143
old   4:    AND &p2 between block_id AND block_id + blocks - 1
new   4:    AND 143 between block_id AND block_id + blocks - 1
 
OWNER
------------------------------
SEGMENT_NAME
--------------------------------------------------------------------------------
OPS$ORACLE
T_IDX

The DBVERIFY can also be used to check segments using segment_id as input. Per Oracle document:

SEGMENT_ID Specifies the segment that you want to verify. It is composed of the tablespace ID number (tsn), segment header file number (segfile), and segment header block number (segblock). You can get this information from SYS_USER_SEGS. The relevant columns are TABLESPACE_ID, HEADER_FILE, and HEADER_BLOCK. You must have SYSDBA privileges to query SYS_USER_SEGS.

However, in my test case, I can not find anything from SYS_USER_SEGS. Don't know why yet.

SQL> select TABLESPACE_ID, HEADER_FILE, HEADER_BLOCK from SYS_USER_SEGS where segment_name='T_IDX';
 
no rows selected

To obtain the segment_id, I have to do:

SQL> select segment_name, tablespace_name, header_file, header_block   
from dba_segments      
where segment_name='T_IDX';  
  2    3  
SEGMENT_NAME         TABLESPACE_NAME       HEADER_FILE HEADER_BLOCK
-------------------- --------------------- ----------- ------------
T_IDX                IDX_TEMP                       14          139
 

SQL> select ts#,name from v$tablespace where name='IDX_TEMP';
 
       TS# NAME
---------- ------------------------------
        17 IDX_TEMP

Finally I can do: dbv user/pass segment_id=17.14.139 , and in this case, I received same info as in the case of running against the data file.

In retrospective, "anaylyze validate structure" probably was the best option to check table and index block corruption for that database if we suspected there were other corruptions.

Bump up sequences

2010-03-24T17:11:00.001-04:00

I got a requirement to bump up more than 200 sequences in a database. Initially I developed SQL scripts to bump up based on the difference between the target value and the dba_sequneces.last_number column for each of the sequences. However, I soon found out that the last_number does not necessarily equal to the seq.nextval. This is apparently due to the cache_size option. For example:

TESTDB> create sequence temp_seq;

Sequence created.

TESTDB> select temp_seq.nextval from dual;

   NEXTVAL
----------
         1

TESTDB> select temp_seq.nextval from dual;

   NEXTVAL
----------
         2

TESTDB> select SEQUENCE_NAME, cache_size, last_number from user_sequences;

SEQUENCE_NAME                  CACHE_SIZE LAST_NUMBER
------------------------------ ---------- -----------
TEMP_SEQ                               20          21

I finally decdied to adopt a PL/SQL solution. I first created a helper table (seq_bump), which stores the target values. Then, I created the following PL/SQL procedure:

declare
  cursor c is 
   select seq_owner, seq_name, bump_number 
   from seq_bump;

  stmt varchar2(300);
  l_seq_owner seq_bump.seq_owner%type;
  l_seq_name seq_bump.seq_name%type;
  l_bump_number seq_bump.bump_number%type;
  l_nextval number;
  l_inc   number;
  l_count number :=0;
begin
  open c;
  loop
   -- l_count := l_count + 1;
   --  dbms_output.put_line('**** conunter = ' || l_count );
    fetch c into l_seq_owner, l_seq_name, l_bump_number;
    stmt:= 'select ' || l_seq_owner || '.' || l_seq_name || '.nextval from dual';
    execute immediate stmt into l_nextval;
   --  dbms_output.put_line('next values is ' || l_nextval);
    l_inc := l_bump_number - l_nextval;
    stmt:= 'alter sequence ' || l_seq_owner || '.' || l_seq_name || ' increment by ' || l_inc ;
   --  dbms_output.put_line(stmt);
    execute immediate stmt;
    stmt:= 'select ' || l_seq_owner || '.' || l_seq_name || '.nextval from dual';
  --  dbms_output.put_line(stmt);
    execute immediate stmt into l_nextval;
    stmt:= 'alter sequence ' || l_seq_owner || '.' || l_seq_name || ' increment by 1 ';
    execute immediate stmt;
    exit when c%notfound;
  end loop;
  close c;
end;
/

I tested above procedure and this will be implemented in production this weekend, hopefully it will work as I expect.

Demonstrate a function-based index is unable to be used due to cursor_sharing setting

2010-03-22T19:13:00.005-04:00

rem  Demonstrate a function-based index is unable to be used
rem  due to cursor_sharing setting
rem
rem  The function is substr(col, 1,6), when cursor_sharing = 
rem  FORCE or SIMILAR, the literals, i,e, 1 and 6 are replaced 
rem  by system-generated variables. This may casued mis-match 
rem  against the index definition
rem
rem  When we use autotrace to check the exection plan,
rem  we do see the index is used; however, at run time, this is 
rem  not the case as shown by 10046 trace. 
rem
rem  Test env: 9.2.0.8 

set echo on
spool fun_idx

drop table t;
create table t as
select rownum id,
       object_name name,
       rpad('x',8) val
from all_objects 
where rownum <=2000;

create index t_idx on t(substr(name, 1,6));
exec dbms_stats.gather_table_stats(user,'t', cascade=>true);

select * from v$version;

alter session set tracefile_identifier=fun;
alter session set timed_statistics=true;
alter session set events '10046 trace name context forever, level 12';

alter session set cursor_sharing=force;
select /* force */ * 
from t 
where substr(name,1,6)='ABCDEF';

alter session set cursor_sharing=similar;
select /* similar */ * 
from t 
where substr(name,1,6)='ABCDEF';

alter session set cursor_sharing=exact;
select /* exact */ * 
from t 
where substr(name,1,6)='ABCDEF';

exit;


set doc off
doc

--- force  ----

select /* force */ *
from t
where substr(name,:"SYS_B_0",:"SYS_B_1")=:"SYS_B_2"
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         13          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0         13          0           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 183
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL T

--- similar ----
 
select /* similar */ *
from t
where substr(name,:"SYS_B_0",:"SYS_B_1")=:"SYS_B_2"
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         13          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.00          0         13          0           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 183
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL T

--- exact ---

select /* exact */ *
from t
where substr(name,1,6)='ABCDEF'
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          2          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          2          0           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 183
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS BY INDEX ROWID T
      0   INDEX RANGE SCAN T_IDX (object id 224130)
#

May 11, 2010 updated: Original post ended at the previous line, all below is added today:

I was pinged by one of my colleagues the other day saying "Jonathan Lewis referred to your blog". I was surprized to hear that. Then I found out that Coskan first included this post in his blog , then Jonathan mentioned it in one of his blog posts (footnote section), which describes the same issue but of course includes deeper technical insights. I regarded Jonathan as my mentor secretly :-). First of all, I learned a lot from his blog and website, and his book "Cost-based Oracle Fundenmental" as well. In my LinkedIn profile "Reading List by Amazon" section, I commented "I read it through when I was on bench in Fall 2007. Even 20% of understanding of it helped me gain some respect from app team and peer DBAs by showing I was able to tune sqls . I will read it again and again utill fully digest it hopefully one day. " Secondly, I once listened to a podcast of his interview with DBAZine, in which he emphasized how the approach of building test cases can help one become better DBA or troubleshooter. I kept this in mind and have been trying practise this tip always. The test case I showed in this post is a proof :-). The style of this test case is actually somewhat mimicing the code examples of the above mentioned book. Especially the "set doc off" syntax, which I did not know until I read his book.

This test case was resulted from my trouble-shooting experience for a real production issue at the posting date. A production database server CPU utilization reached 100% from time to time from the morning and some jobs were slower than normal. Top SQL during the problem period was an update statement, supposedly using a function-based index. I was called by a fellow DBA to check why full table scan was actually used instead. From the shared pool, we knew it has been executed by FTS .

My favorite tool to check the execution plan at the first round is Autotrace :

** Autotrace showing index scan but consistent gets = 148626

myusrid@MYPRDDB1> set autotrace traceonly
myusrid@MYPRDDB1> select * from
2 XYZ_UVW.ABC_ABCDEFG_ABCDEF_ABCDEF
3 WHERE substr(DEPENDANT_ORDER,1,13) = '123456789012'
4 ;

o rows selected

ecution Plan
---------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=18 Bytes=1494)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'ABC_ABCDEFG_ABCDEF_ABCDEF' (Cost=4 Card=18 Bytes=1494)
2 1 INDEX (RANGE SCAN) OF 'ABC_ABCDEFG_ABCDEF_ABCDE_IDX5N' (NON-UNIQUE) (Cost=Card=1)

statistics
---------------------------------------------------------
0 recursive calls
0 db block gets
148626 consistent gets
135926 physical reads
0 redo size
490 bytes sent via SQL*Net to client
229 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

I knew parse-time execution plan could be different from run-time. So from Autotrace, I confirmed index scan was considered favarable, however from the "consistent gets", I knew at run time Oracle did FTS as it matched stackpack "Gets per Execution":

** From statspack during problem period, Gets Per Exec = 149314

Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
98,995,283 663 149,314.2 49.0 ######## 10769.86 3803649956
Module: JDBC Thin Client
UPDATE ABC_ABCDEFG_ABCDEF_ABCDEF SET DEPENDANT_ORDER =:1 WHERE S
UBSTR(DEPENDANT_ORDER,:"SYS_B_0",:"SYS_B_1") =:2

It took me quite a while to realize what happened was due to CURSOR_SHARING setting:

** Autotrace showing index scan and consistent gets = 3 after seting cursor_sharing=exact

myusrid@MYPRDDB1> alter session set cursor_sharing=exact;

Session altered.

myusrid@MYPRDDB1> select * from
2 XYZ_UVW.ABC_ABCDEFG_ABCDEF_ABCDEF
3 WHERE substr(DEPENDANT_ORDER,1,13) = '123456789012'
4 ;

no rows selected

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=18 Bytes=1494)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'ABC_ABCDEFG_ABCDEF_ABCDEF' (Cost=4 Card=18 Bytes=1494)
2 1 INDEX (RANGE SCAN) OF 'ABC_ABCDEFG_ABCDEF_ABCDE_IDX5N' (NON-UNIQUE) (Cost=3 Card=1)

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3 consistent gets
2 physical reads
0 redo size
490 bytes sent via SQL*Net to client
229 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

I took a brave step to solve the prodution issue as during the middle of the day code change was not possible and also it was subjected to some change management processes in my working envrionment. I told the development team, I was going to change CURSOR_SHARING from FORCE to EXACT in the production database as an emergent performance stablizing measure ( as this change should be subjected to change management process too), and if we saw problems after the change, I would revert it back and they still needed to plan code change to fix that update statment (Dev think they should have used bind variables appropriately, but no one could really gurantee this change would not cause other more serious problems). So I changed it to EXACT, so far so good.

How to find out which session caused ORA-01555?

2010-03-19T16:23:00.003-04:00

Some times ago, my colleague asked me this question since we frequently recieved ORA-01555 alert email from our reporting database. The alerts came from the alert log monitoring job, which contains sql text but nothing more than that. I searched the internet and was excited to find a thread on the AskTom site, which appeared to be exactly addressing our needs.

Based on that thread, I tested and installed the following database event trigger in our reporting database:

create or replace trigger servererror_trig
after servererror on database
declare
   var_id        number; 
   var_user      varchar2(30);
   var_osuser    varchar2(30);
   var_machine   varchar2(64);
   var_process   varchar2(8);
   var_program   varchar2(48);
   var_txt       varchar2(4000);
   l_sql_text    ora_name_list_t;
   l_n           number;
begin
  if ( is_servererror(1555) )
  then
     select
      username,
      osuser,
      machine,
      process,
      program
    into
      var_user,
      var_osuser,
      var_machine,
      var_process,
      var_program
    from
      v$session
    where
     audsid=userenv('sessionid');
 
     l_n := ora_sql_txt( l_sql_text );
     var_txt :=  'ora_sysevent = ' || ora_sysevent || ' ora_login_user = ' || ora_login_user || 
                   ' ora_server_error = ' || ora_server_error(1) || chr(10); 
 
     for i in 1 .. l_n
     loop
        var_txt := var_txt || l_sql_text(i); 
     end loop;
 
     insert into
      db_admin.servererror_log
     values(
      dbms_standard.server_error(1),
      sysdate,
      var_user,
      var_osuser,
      var_machine,
      var_process,
      var_program,
      var_txt);
  end if;
end;
/

At begining, it looked good, however, soon I found that not all ORA-01555s that were appeared in the alert log were captured by this trigger. Being aware that some tables in the reporting database are referred by remote SQLs through dblink, I set up a test to see if this trigger workes for remote queries.

First of all, I did everything in the local database:

denis@DBWRKEV1> -- create undo tablespace small datafile  '/tmp/small.dbf' size 2m autoextend OFF;
denis@DBWRKEV1> drop table ora_1555;
 
Table dropped.
 
denis@DBWRKEV1> create table ora_1555 as select * from all_objects;
 
Table created.
 
denis@DBWRKEV1> alter system set undo_tablespace = small;
 
System altered.
 
denis@DBWRKEV1> 
denis@DBWRKEV1> --  Now open a cursor -- it is read consistent as of NOW
denis@DBWRKEV1> variable x refcursor
denis@DBWRKEV1> exec open :x for select * from ora_1555;
 
PL/SQL procedure successfully completed.
 
denis@DBWRKEV1> 
denis@DBWRKEV1> -- generate lots of undo and commit and do it over again and again,
denis@DBWRKEV1> 
denis@DBWRKEV1> begin
  2    for i in 1 .. 10
  3    loop
  4         loop
  5            delete from ora_1555 where rownum <= 1000;
  6            exit when sql%rowcount = 0;
  7            commit;
  8         end loop;
  9             commit;
 10      insert into ora_1555 select * from all_objects;
 11      commit;
 12    end loop;
 13  end;
 14  /
 
PL/SQL procedure successfully completed.
 
denis@DBWRKEV1> 
denis@DBWRKEV1> print x
ERROR:
ORA-01555: snapshot too old: rollback segment number 19 with name "_SYSSMU19$" too small
 
 
 
no rows selected
 
denis@DBWRKEV1> 
denis@DBWRKEV1> 
denis@DBWRKEV1> select * from db_admin.servererror_log;
 
ERROR                                                             TIMESTAMP           USERNAME
----------------------------------------------------------------- ------------------- ------------------------------
OSUSER                         MACHINE                                                          PROCESS
------------------------------ ---------------------------------------------------------------- --------
PROGRAM
------------------------------------------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
1555                                                              2010-03-19 12:12:01 DENIS
oracle                         sjscqdd1                                                         19823
sqlplus@sjscqdd1 (TNS V1-V3)
ora_sysevent = SERVERERROR ora_login_user = DENIS ora_server_error = 1555
SELECT * FROM ORA_1555

Check the alert log, I can find:

Fri Mar 19 12:12:01 2010
ORA-01555 caused by SQL statement below (SQL ID: 0kj3gdzq34dk9, Query Duration=100 sec, SCN: 0x09e8.6a0a74a2):
Fri Mar 19 12:12:01 2010
SELECT * FROM ORA_1555

Now I do a test from remote db:

-- At remote, open a curor for the test table through db link

denis@REMOTEDB>variable x refcursor
denis@REMOTEDB>exec open :x for select * from ora_1555@dbwrkev1;

PL/SQL procedure successfully completed.

-- At local

denis@DBWRKEV1> begin
  2    for i in 1 .. 10
  3    loop
  4         loop
  5            delete from ora_1555 where rownum <= 1000;
  6            exit when sql%rowcount = 0;
  7            commit;
  8         end loop;
  9             commit;
 10      insert into ora_1555 select * from all_objects;
 11      commit;
 12    end loop;
 13  end;
 14  /

PL/SQL procedure successfully completed.

-- At remote

denis@REMOTEDB>print x
ERROR:
ORA-01555: snapshot too old: rollback segment number 19 with name "_SYSSMU19$" too small
ORA-02063: preceding line from DBWRKEV1



no rows selected

-- Local alert log (PST)

Fri Mar 19 12:20:11 2010
ORA-01555 caused by SQL statement below (SQL ID: 7xnnz01z88xhp, Query Duration=249 sec, SCN: 0x09e8.6a135bd3):
Fri Mar 19 12:20:11 2010
SELECT "A1"."OWNER","A1"."OBJECT_NAME","A1"."SUBOBJECT_NAME","A1"."OBJECT_ID","A1"."DATA_OBJECT_ID","A1"."OBJECT_TYPE","
A1"."CREATED","A1"."LAST_DDL_TIME","A1"."TIMESTAMP","A1"."STATUS","A1"."TEMPORARY","A1"."GENERATED","A1"."SECONDARY" FRO
M "ORA_1555" "A1"

Note: it is intereting to see Oracle rewrites the original SQL in such a way that the '*' is expanded to full column list and charaters are capitalized.

-- Remote alert log
Not see any 1555, I am a little surprized.

-- at local note the ORA-01555 in alert log at time 12:20 not captured by the trigger.

denis@DBWRKEV1> select * from db_admin.servererror_log;
 
ERROR                                                             TIMESTAMP           USERNAME
----------------------------------------------------------------- ------------------- ------------------------------
OSUSER                         MACHINE                                                          PROCESS
------------------------------ ---------------------------------------------------------------- --------
PROGRAM
------------------------------------------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
1555                                                              2010-03-19 12:12:01 DENIS
oracle                         sjscqdd1                                                         19823
sqlplus@sjscqdd1 (TNS V1-V3)
ora_sysevent = SERVERERROR ora_login_user = DENIS ora_server_error = 1555
SELECT * FROM ORA_1555

In conclusion, the database event trigger solution to identify sessions cause ORA-01555 has its limitation when the session is initiated by a remote query through dblink.

Copy schema between databases through transportable tablespace

2010-03-17T16:01:00.001-04:00

Today, I worked out a plan to copy a schema from one database to another using transportable tablespace feature.The schema objects only reside in three tablespaces. Below are the steps: (as usual, real schema, server name etc are modified):

1. Check if the tablespace is self-contained

conn / as sysdba
execute dbms_tts.transport_set_check('TST_PCD_DATA_1,TST_PCD_DATA_2,TST_PCD_IDX_1', true);

SELECT * FROM TRANSPORT_SET_VIOLATIONS;

Note: we should see no rows returned.

2. Make the tablespace READ ONLY at source:

alter tablespace TST_PCD_DATA_1 read only;
alter tablespace TST_PCD_DATA_2 read only;
alter tablespace TST_PCD_IDX_1 read only;

select tablespace_name, status from dba_tablespaces where status='READ ONLY';

4. Export the tablespace

exp tablespaces=TST_PCD_DATA_1,TST_PCD_DATA_2,TST_PCD_IDX_1 transport_tablespace=y file=sch1_tts.dmp

Username: / as sysdba

5. Drop the tablespaces in the target database

drop tablespace TST_PCD_DATA_1 including contents and datafiles;
drop tablespace TST_PCD_DATA_2 including contents and datafiles;
drop tablespace TST_PCD_IDX_1 including contents and datafiles;

6. Copy the data files and dump file to target server

select file_name from dba_data_files
where tablespace_name in ('TST_PCD_DATA_1','TST_PCD_DATA_2','TST_PCD_IDX_1');

FILE_NAME
--------------------------------------------------------------------------------
/db1/u01/oradata/sch1stg1/TST_PCD_IDX_1_01.dbf
/db1/u01/oradata/sch1stg1/TST_PCD_DATA_2_01.dbf
/db1/u01/oradata/sch1stg1/TST_PCD_DATA_1_01.dbf

ssh2 srcserv 'cat /db1/u01/oradata/sch1stg1/TST_PCD_IDX_1_01.dbf | gzip -c' | gunzip -c > /db1st2/u07/oradata/trgtdbsid/TST_PCD_IDX_1_01.dbf
ssh2 srcserv 'cat /db1/u01/oradata/sch1stg1/TST_PCD_DATA_2_01.dbf | gzip -c' | gunzip -c > /db1st2/u07/oradata/trgtdbsid/TST_PCD_DATA_2_01.dbf
ssh2 srcserv 'cat /db1/u01/oradata/sch1stg1/TST_PCD_DATA_1_01.dbf | gzip -c' | gunzip -c > /db1st2/u07/oradata/trgtdbsid/TST_PCD_DATA_1_01.dbf

7. Make the tablespace read write at source database

alter tablespace TST_PCD_DATA_1 read write;
alter tablespace TST_PCD_DATA_2 read write;
alter tablespace TST_PCD_IDX_1 read write;

8. At the target host, plug the tablespace into the target database.
From the OS command prompt, issue:

imp parfile=imp_tts.par

-- imp_tts.par --------------------------------------------
tablespaces=TST_PCD_DATA_1,TST_PCD_DATA_2,TST_PCD_IDX_1
transport_tablespace=y
file=sch1_tts.dmp
datafiles=(
'/db1st2/u07/oradata/trgtdbsid/TST_PCD_IDX_1_01.dbf'
,'/db1st2/u07/oradata/trgtdbsid/TST_PCD_DATA_2_01.dbf'
,'/db1st2/u07/oradata/trgtdbsid/TST_PCD_DATA_1_01.dbf'
)
tts_owners=ssp2_sch1
------------------------------------------------------------

Note: enter / as sysdba for username

Best practices and recommendations for preparing SQL Scripts

2010-03-13T08:34:00.011-05:00

We have code release for our Oracle databases frequently. Typically it is implemented by executing various SQL or PL/SQL scripits on servers from SQL*Plus. Many times I have observed there are simple syntax errors in the scripts we received from development team and also the format of the script is not consistent. I thus tried to compile a list of best practices and recommendations for preparing the release scripts for the team. Here are some points:

Add spool to every script in the following format as minimum:

             set echo on timing on
             spool log/script_name.log
              ...
             spool off

Separate DDL and DML SQL statements into different scripts.

Recommend using suffix to distinguish DDL and DML script: e.g. script_ddl.sql, script_dml.sql.

Separate different type of object creation into different scripts:

          i.e. table, index, package etc. Recommend using the following suffix to distinguish different script in   the format: script_xxx.sql. The ‘xxx’can be:

                      Package specification             pks
                      Package body                        pkb
                      Package sepc and body          pkg
                      Procdueure                            pro
                      Trigger                                   trg
                      Function                                  fun
                      Create table script(s)               tab or ddl
                      Synonym creation statements   syn
                      Index definition                       idx
                      Constraint definitions               con

Use lower case ".sql" as a suffix for all scripts

[Mar 16,2010 Update - I tried to do: grep -i create *.sql yesterday, I failed to find a new table creation due to the script ended with ".SQL". ]

Recommend consolidating the script in the execution sequence of DDL first followed by DML.

Recommend using some GUI tools such as TOAD, SQL Developer etc to minimize the syntax errors.

                  At minimum, everyone should do the following:
                   - Check if missing "schema" prefix for table, index names etc.
                   - Check if missing ";" in SQL
                   - Check if missing "/" as the end the PL/SQL begin/end block
                   - Check if comma used properly in the table column list for example
                   - Check if upper or lower cases are used consistently

Recommend including the back out method (CTAS) for DML script

Recommend formatting and aligning SQL statements properly whenever possible for improving readability

Add "show error;" at the end of PL/SQL procedure, function, packages units.

Avoid using ampersand character ‘&’ within any comment lines in the SQL scripts.

Avoid using space in the script file name.

Avoid adding storage clause in the table or index creation statement

Note: defer to primary DBA to make such a decision if defaults are not desirable

Avoid using more than 30 characters for table name or column name.

Avoid using system-generated constraint names.

For example the following method to add a primary key constraint is not acceptable:
alter table myschema.t modify (id primary key);

Recommend using the following methods to create primary key

         (1) Within CREATE TABLE statement

              CREATE TABLE t
              ( id number,
               val varchar2(40),
                constraint t_pk primary key (id) using index tablespace tablespace_name
              ) tablespace tablespace_name;

        (2) Through ALTER TABLE statement

              CREATE TABLE t
              ( id number,
               val varchar2(40)
               ) tablespace tablespace_name ;

              ALTER TABLE t
              add constraint t_pk primary key(id) using index tablespace tablespace_name;

Complete recovery after lost of all control files and data files.

2010-01-27T18:52:00.001-05:00

Assuming all of the control files and one or more data files are lost during media failure, but the online redo logs are intact, can we do a complete recovery? In a previous post, I have demonstrated that it is possible when I have backup control files though I have to open database by resetlogs. In this post, I will demonstrate in this case we can do complete recovery without resetlogs by re-creating the control files.

Note: the scripts used see previous post.

Steps

1. perform hot backup

#> hot_backup.sh

2. Create a table with one row and switch logfile

SQL> drop table system.t;
SQL> create table system.t as select * from all_tables where rownum <=1; SQL> alter system switch logfile;

3. Insert the second row and switch logfile
SQL> insert into system.t select * from all_tables where rownum <=1; SQL> commit;
SQL> alter system switch logfile;

4. Insert the third row and switch logfile
5. Insert the forth row WITHOUT switch logfile

At this point, we should see total 4 rows in the table t:

sys@DBWRKEV1> select count(*) from system.t ;

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

6. Delete all data files to simulate media failure, shutdown instance

rm /db1/u01/oradata/dbwrkev1/system01.dbf
rm /db1/u04/oradata/dbwrkev1/undotbs01.dbf
rm /db1/u02/oradata/dbwrkev1/sysaux01.dbf
rm /db1/u02/oradata/dbwrkev1/users01.dbf

7. Restore data files

#> restore_data.sh

8. Re-create control file

idle> conn / as sysdba
Connected to an idle instance.
idle> startup nomount;
ORACLE instance started.
 
Total System Global Area  473956352 bytes
Fixed Size                  1979520 bytes
Variable Size             314575744 bytes
Database Buffers          150994944 bytes
Redo Buffers                6406144 bytes
idle> @ctl
 
Control file created.

Below is the content of ctl.sql

CREATE CONTROLFILE REUSE DATABASE "DBWRKEV1" NORESETLOGS FORCE LOGGING ARCHIVELOG
    MAXLOGFILES 16
    MAXLOGMEMBERS 3
    MAXDATAFILES 100
    MAXINSTANCES 8
    MAXLOGHISTORY 292
LOGFILE
  GROUP 1 (
    '/db1/u05/archive/dbwrkev1/redo01a.log',
    '/db1/u06/archive/dbwrkev1/redo01b.log'
  ) SIZE 50M,
  GROUP 2 (
    '/db1/u05/archive/dbwrkev1/redo02a.log',
    '/db1/u06/archive/dbwrkev1/redo02b.log'
  ) SIZE 50M,
  GROUP 3 (
    '/db1/u05/archive/dbwrkev1/redo03a.log',
    '/db1/u06/archive/dbwrkev1/redo03b.log'
  ) SIZE 50M
-- STANDBY LOGFILE
DATAFILE
  '/db1/u01/oradata/dbwrkev1/system01.dbf',
  '/db1/u04/oradata/dbwrkev1/undotbs01.dbf',
  '/db1/u02/oradata/dbwrkev1/sysaux01.dbf',
  '/db1/u02/oradata/dbwrkev1/users01.dbf'
CHARACTER SET WE8ISO8859P1
;

Then I did:

idle> recover database;
ORA-00279: change 10467469165231 generated at 01/27/2010 13:36:56 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_7_709302414.arc
ORA-00280: change 10467469165231 for thread 1 is in sequence #7
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469165563 generated at 01/27/2010 13:44:35 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_8_709302414.arc
ORA-00280: change 10467469165563 for thread 1 is in sequence #8
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_7_709302414.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
Log applied.
Media recovery complete.
idle> alter database open;
 
Database altered.
 
idle> select count(*) from system.t;
 
  COUNT(*)
----------
         4

Updated Feb 3, 2010 - It seems RMAN recovery can automatically apply changes in the online redo logs. See: http://oracle-study-notes.blogspot.com/2007/07/exercise-using-control-file-autobackup.html

NetApp Snapshot backup and recovery for Oracle databases

2010-01-26T17:41:00.004-05:00

In my current working environment, we use NetApp Snapshot technology to backup some of our Oracle databases. I have recently participated in a Snapshot backup and recovery test for three production databases that were migrated to new servers. In the tests, the Storage Admin team performed Snapshot backup and restore, the Unix Admin team performed diskgroup deport and import operations, and we, DBAs, were responsible for the database  recovery.

The databases have file layout in such a way that all of data files and control files is in the volumn /db1, online redo log files are in the volumn /db1redo, and archived logs are saved in volumn /db1arch. The Snapshot backups are performed on all three volumns mentioned. We tested two recovery scenarios:

1. Restore /db1 and /db1redo
2. Restore /db1 only

I think if you are an experienced DBA, you will immediately question the practise of backup and restore of online redo logs. You are right. I had doubts at the time. Today, I have done simulations of these two scenarios in a test envrinment. I have been more clear that we should not do that at all.

Below I will describe the test cases in more details, which are the simulations of what we did in the Snapshot backup and recoery test in the production servers a few days ago.

Case 1 - Restore data files, control files and redo log files (e.g. /db1 and /db1redo)

1. Perform hotbackup
    #> hot_backp.sh
    Note: script see Appendix

2. Create a table with one row and switch logfile
    SQL> drop table system.t;
    SQL> create table system.t as select * from all_tables where rownum <=1;
    SQL> alter system switch logfile;

3. Insert the second row and switch logfile
   SQL> insert into system.t select * from all_tables where rownum <=1;
   SQL> commit;
   SQL> alter system switch logfile;

4. Insert the third row and switch logfile

5. Insert the forth row WITHOUT switch logfile
    At this point, we should see total 4 rows in the table t:
    sys@DBWRKEV1> select count(*) from system.t ;
    COUNT(*)
     ---------
     4

6. Delete all data files to simulate media failure, shutdown instance
     rm /db1/u01/oradata/dbwrkev1/system01.dbf
     rm /db1/u04/oradata/dbwrkev1/undotbs01.dbf
     rm /db1/u02/oradata/dbwrkev1/sysaux01.dbf
     rm /db1/u02/oradata/dbwrkev1/users01.dbf

7. Restore data files, control files and redo log file
   #> restore_data.sh
   #> restore_ctl.sh
   #> restore_redo.sh

8. Recover database
   After mount the database, I did:

    idle> recover database;
    Media recovery complete.
    idle> alter database open;
    Database altered.

    So here we observed the same in the real test a few days ago, we thought we did a complete recovery, but really?

     idle> select count(*) from system.t;
              select count(*) from system.t
                *
               ERROR at line 1:
              ORA-00942: table or view does not exist

   We can see the table t does not exist at all.

Case 2 Restore data file and control files (e.g. /db1)

Note: due to our data files and control files are both in /db1, with Snapshot restore we can not restore only one of them. This is one of the disavantages of NetApp Snapshot as I can see compared to RMAN backup and restore.

1-6. same as in case 1

7. Restore data files and control files
    #> restore_data.sh
    #> restore_ctl.sh

8. Recover database
   After mount the database, I did:

idle> recover database until cancel using backup controlfile;
ORA-00279: change 10467469061882 generated at 01/26/2010 10:45:48 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_27_708088679.arc
ORA-00280: change 10467469061882 for thread 1 is in sequence #27
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469062192 generated at 01/26/2010 10:51:40 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_28_708088679.arc
ORA-00280: change 10467469062192 for thread 1 is in sequence #28
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_27_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469064362 generated at 01/26/2010 11:43:01 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_29_708088679.arc
ORA-00280: change 10467469064362 for thread 1 is in sequence #29
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_28_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469064390 generated at 01/26/2010 11:43:54 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_30_708088679.arc
ORA-00280: change 10467469064390 for thread 1 is in sequence #30
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_29_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469064400 generated at 01/26/2010 11:44:17 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_31_708088679.arc
ORA-00280: change 10467469064400 for thread 1 is in sequence #31
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_30_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00308: cannot open archived log '/db1/archive/dbwrkev1/dbwrkev1_1_31_708088679.arc'
ORA-27037: unable to obtain file status
SVR4 Error: 2: No such file or directory
Additional information: 3
 
 
idle> recover database until cancel using backup controlfile;
ORA-00279: change 10467469064400 generated at 01/26/2010 11:44:17 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_31_708088679.arc
ORA-00280: change 10467469064400 for thread 1 is in sequence #31
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
cancel
Media recovery cancelled.
idle> alter database open resetlogs;
 
Database altered.
 
idle> select count(*) from system.t;
 
  COUNT(*)
----------
        3

So, obviously we lost the changes recorded in the online redo log. This is an imcomplete recvoery, corresponding to lost all control files and (some of) data files, but online redo logs are intact. However, if we know the current online redo log at the time of media failure ( We can find it out in the alert log file), we probably can recover more.

For example, in my test, I knew the current online redo logs are those of group 2. So I did:

#> cp redo02a.log /db1/archive/dbwrkev1/dbwrkev1_1_31_708088679.arc

Then I repeated the steps 6,7,8 as in the test case 2, let's see what we got:

idle> recover database until cancel using backup controlfile;
ORA-00279: change 10467469061882 generated at 01/26/2010 10:45:48 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_27_708088679.arc
ORA-00280: change 10467469061882 for thread 1 is in sequence #27
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469062192 generated at 01/26/2010 10:51:40 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_28_708088679.arc
ORA-00280: change 10467469062192 for thread 1 is in sequence #28
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_27_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469064362 generated at 01/26/2010 11:43:01 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_29_708088679.arc
ORA-00280: change 10467469064362 for thread 1 is in sequence #29
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_28_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469064390 generated at 01/26/2010 11:43:54 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_30_708088679.arc
ORA-00280: change 10467469064390 for thread 1 is in sequence #30
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_29_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
ORA-00279: change 10467469064400 generated at 01/26/2010 11:44:17 needed for thread 1
ORA-00289: suggestion : /db1/archive/dbwrkev1/dbwrkev1_1_31_708088679.arc
ORA-00280: change 10467469064400 for thread 1 is in sequence #31
ORA-00278: log file '/db1/archive/dbwrkev1/dbwrkev1_1_30_708088679.arc' no longer needed for this recovery
 
 
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
 
Log applied.
Media recovery complete.
idle> alter database open resetlogs;
 
Database altered.
 
idle> select count(*) from system.t;
 
  COUNT(*)
----------
         4

Bingo! It seemed I did a complete recovery!

[Jan 27,2010 updated: this post shows another way to do a complete revcovery in this situation]

Another thing I want to point out is that if we only lost data files whereas the control files and online redo logs are intact, we can do a complete recovery easily as long as we have archived logs. However, in our envionment when we restore snapshot backup, we also overwrite the current control files. So we must be cautious and it is thus advisable to copy the intact control files to some other location. It is probaly a good idea that we should not place all the control files in the same volumn as data files.

BTW, the information in the following two links gave me some ideas about this topic.

http://freekdhooge.wordpress.com/2007/12/03/disaster-recovery-troubles/
http://download.oracle.com/docs/cd/B10501_01/server.920/a96519/strategy.htm#1004884

Appendix - Scripts used:

#!/bin/ksh
# script:  hot_backup.sh
#
sqlplus "/ as sysdba" <<EOF
alter tablespace UNDOTBS1 begin backup;
alter tablespace USERS    begin backup;
alter tablespace SYSTEM   begin backup;
alter tablespace SYSAUX   begin backup;
EOF
echo " -- tablespace begin backup mode "

cp /db1/u01/oradata/dbwrkev1/system01.dbf    /db1/backup
cp /db1/u04/oradata/dbwrkev1/undotbs01.dbf   /db1/backup
cp /db1/u02/oradata/dbwrkev1/sysaux01.dbf    /db1/backup
cp /db1/u02/oradata/dbwrkev1/users01.dbf     /db1/backup
cp /db1/u05/archive/dbwrkev1/redo03a.log     /db1/backup
cp /db1/u06/archive/dbwrkev1/redo03b.log     /db1/backup
cp /db1/u05/archive/dbwrkev1/redo02a.log     /db1/backup
cp /db1/u06/archive/dbwrkev1/redo02b.log     /db1/backup
cp /db1/u05/archive/dbwrkev1/redo01a.log     /db1/backup
cp /db1/u06/archive/dbwrkev1/redo01b.log     /db1/backup
cp /db1/u01/oradata/dbwrkev1/control01.ctl   /db1/backup 
cp /db1/u02/oradata/dbwrkev1/control02.ctl   /db1/backup 
cp /db1/u03/oradata/dbwrkev1/control03.ctl   /db1/backup


echo " -- data file, control file and redo log backup done "

sqlplus "/ as sysdba" <<EOF
alter tablespace UNDOTBS1 end backup;
alter tablespace USERS    end backup;
alter tablespace SYSTEM   end backup;
alter tablespace SYSAUX   end backup;
EOF

echo " -- tablespace end backup mode "

sqlplus "/ as sysdba" <<EOF
alter system archive log current;
alter database backup controlfile to '/tmp/backupctrl.ctl' reuse;
EOF
echo " -- archive current redo log and backup controlfile done"

#!/bin/ksh
# script: restore_data.sh
#

cp /db1/backup/system01.dbf  /db1/u01/oradata/dbwrkev1 
cp /db1/backup/undotbs01.dbf /db1/u04/oradata/dbwrkev1 
cp /db1/backup/sysaux01.dbf  /db1/u02/oradata/dbwrkev1 
cp /db1/backup/users01.dbf   /db1/u02/oradata/dbwrkev1 

#!/bin/ksh
#   restore_ctl.sh 
#

cp /db1/backup/control01.ctl /db1/u01/oradata/dbwrkev1   
cp /db1/backup/control02.ctl /db1/u02/oradata/dbwrkev1   
cp /db1/backup/control03.ctl /db1/u03/oradata/dbwrkev1   

#!/bin/ksh
# script: restore_redo.sh
#
cp /db1/backup/redo03a.log   /db1/u05/archive/dbwrkev1    
cp /db1/backup/redo03b.log   /db1/u06/archive/dbwrkev1    
cp /db1/backup/redo02a.log   /db1/u05/archive/dbwrkev1    
cp /db1/backup/redo02b.log   /db1/u06/archive/dbwrkev1     
cp /db1/backup/redo01a.log   /db1/u05/archive/dbwrkev1     
cp /db1/backup/redo01b.log   /db1/u06/archive/dbwrkev1

Clone an online database - applying standby feature

2010-01-13T14:08:00.001-05:00

In a previous post, I described how to clone an online database by transferring data files through network. Since the cloned database should not be opened immediately after the copy, instead, it needed to be opened one week later. This was to minimize the maintenance window needed to configure the cloned database. In this scenario, we need to ship the archived logs from source to target, and also apply them in the target during the whole week in order to keep the source and target database in sync. For that purpose, I wrote a shell script and put it in the cron to automatically transfer the archived logs and then manually applying the logs.

Inspired by a fellow DBA recently, I have found that we can take advantage of Oracle standby technology to achieve the log transportation and apply purpose automatically. I thus did a test on a testing 10g database to demonstrate the concept, which consisted of the following steps:

1. Copied selected tablespaces from source to target, using the same method as in the previous post
    Tablespaces: SYSTEM, SYSAUX, USERS and UNDOTBS1

2. Created standby control file in source and copied them to the target.e.g
     a. At source, alter database create standby controlfile as '/tmp/stby.ctl';
     b. scp from source to target server
     c. At target, issue:
        cp /tmp/stby.ctl /db1/u01/oradata/orasid1/control01.ctl
        cp /tmp/stby.ctl /db1/u02/oradata/orasid1/control02.ctl
        cp /tmp/stby.ctl /db1/u03/oradata/orasid1/control03.ctl

3. Added in the init.ora a parameter: standby_file_management = manual
    Note: this is to take into account that data file directory may be different between source and targer server.

4. Mount the target database with the standby controlfile.
     I then did Offline drop all those data files that are not copied
   e.g. alter database datafile 'filename' offline drop;

5. In mount mode, issue:
    SQL> RECOVER STANDBY DATABASE UNTIL CANCEL;
    Note: this is to apply all available archived logs upto the current time manually.

6. Started the managed recovery of the standby database at target server
    SQL> ALTER DATABASE RECOVER MANAGED STANDBY DATABASE DISCONNECT;

7. In the source db issue:
    SQL> ALTER SYSTEM SET log_archive_dest_2='SERVICE=ORASID1_STBY LGWR ASYNC';

8. Verify archived log are shiped and applied automatically.
    for examples:
     SELECT SEQUENCE#,APPLIED FROM V$ARCHIVED_LOG ORDER BY SEQUENCE#;

9. Opened the standby database as a regular operational database
    a. At source issue: ALTER SYSTEM SET log_archive_dest_2=''

    b. At target, cancel Redo Apply:
        ALTER DATABASE RECOVER MANAGED STANDBY DATABASE CANCEL;
    c. At target issue: alter database activate physical standby database
    d. ALTER DATABASE OPEN;
    e. Drop those tablespace not copied and needed in the target server.

Some hige-level concepts about transaction processing

2009-12-17T17:23:00.002-05:00

I once read in a forum someone proposed an interview question for Oracle DBA. The question was like 'What kind of things Oracle do when issuing a 'COMMIT' ?'. I was very vague at that time. Now I am feeling better. I went through a chapter called "Transaction Processing" in an old Oracle University guide - Oracle 9i database: Space and Transaction Management (Student Guide). Here are some high-level concepts about transaction process, including something Oracle will do when it commits a transaction.

Sytem commit number (SCN)
- identifies the committed version of a database

Change vector
- contains the information necessary to change one block from one consistent state to another consistent state

Begin transaction

Undo segment binding
Slot allocation in the transaction table
Undo block allocation

Transaction Commit

Finds an SCN value
Updates the transaction table
Puts the current undo block into the free block pool (under some condition)
Creates a commit record in the redo log buffer
Flushes the redo log buffer to disk (for durability)
Releases locks held on rows and tables

[Dec 26,2009 Ed.]
Tom Kyte wrote a section "What Does a COMMIT Do?" in his book "Expert Oracle Database Architecture" (pp 292-98). There are two points I would like to add based on his book.

1. When Oracle issues a COMMIT, LGWR writes all of the remaining redo log entries to disk. Considering commit after inserting one row into a table compared to after inserting 1M rows, the time for commit in these two cases is almost same, why? Because redo info is being written to the disk during the inserting process batch by batch. At COMMIT, the remaining redo entries be flushed is thus small. The cost of COMMIT is not a function of the transaction size.

2. When COMMIT, some of the blocks the transaction modified will be visited and "cleaned out" in a fast mode if they are still in the buffer cache. Block cleanout refers to the cleaning out the transaction information stored in the database block header.

Modifying a data block

Find an interested transaction list (ITL) available in the block
Lock the row you are modifying
Generate the redo part of data describing the changes to the data block
Generate the undo part of data describing

The inverse operation of data block user changes
The undo block changes in the undo segment
The undo segment block changes (if necessary)

5. Create the redo record and apply the changes to the blocks.

Don't use PL/SQL to Do the Job of SQL

2009-11-25T12:28:00.003-05:00

Several days ago, I was asked to review scripts from development team for an application consolidation effort. There is a particular script that uses PL/SQL, which run more than 3 hours. After I reviewed it, I believed they can be written by SQL statment.

For example, for the following PL/SQL block, it depends on the EXCEPTION condition to update a table. Though I am not an experienced PL/SQL programmer, I am suspicous this could be considered good practice in PL/SQL.

-- PL/SQL block

BEGIN
   FOR bas_rec IN bas_cur LOOP
      v_my_account_id:=bas_rec.my_account_id;

      BEGIN 
  SELECT DISTINCT ms.state_id INTO v_state_id
    FROM
      my_sch.tab_ms ms
    WHERE
      ms.account_id = v_my_account_id AND
      ms.state_id IS NOT NULL AND
      ms.svc_node_type_id  NOT IN (203,204,206,208,218,402) AND
      ms.is_pq ='N' AND
      ms.svc_status_id = 2;
     
  EXCEPTION
    WHEN TOO_MANY_ROWS THEN
      UPDATE my_sch.conv_2 bas
        SET bas.to_be_converted_status=v_exclusion_flag, 
     bas.exclusion_reason = v_exclusion_reason_multi, 
     bas.is_processed = v_processed_flag
        WHERE bas.my_account_id = v_my_account_id;
        v_is_updated:='Y';
      COMMIT;
    WHEN NO_DATA_FOUND THEN NULL; 
    WHEN OTHERS THEN 
    dbms_output.put_line('Multi State block OTHERS - v_ban:'||sqlerrm ); 
  COMMIT;
      END; 
  END LOOP;
END;

Anyway, I know that " Don't use PL/SQL to Do the Job of SQL". So I translated the above PL/SQL to the following SQL.

-- SQL code 

UPDATE my_sch.conv_2 bas
SET bas.to_be_converted_status='N', 
    bas.exclusion_reason = 'SERVICES IN MULTIPLE STATES', 
    bas.is_processed ='Y' 
WHERE bas.is_processed is null
  AND 1 < ( select count( DISTINCT ms.state_id)
      from my_ord.tab_ms ms
       WHERE ms.account_id =  bas.my_account_id
  AND ms.state_id IS NOT NULL 
  AND ms.svc_node_type_id  NOT IN (203,204,206,208,218,402) 
  AND ms.is_pq ='N' 
  AND ms.svc_status_id = 2 )
;

I also re-wrote the other part of the script with SQL. In a small scale test, original PL/SQL took 5 min. My SQL code took about 1.5 min. Sadly, developers are more comfortable with their PL/SQL code and are unwilling to do a thoroug test and verification about SQL method. So I will still use their PL/SQL code in the production implementation - just running 5 threads of them to speed up instead of 1 thread previously.

DDL for CONSTRAINTS and DEFAULTS

2009-11-23T16:12:00.004-05:00

When using a CTAS to create a table from an existing table, the new table won't have all the constraints as the exsiting table except that the NOT NULL constraints are preserved. Below is an example showing a CHECK constraint is not presented in a table created from CTAS:

TESTDB> create table t (id number not null, val number check (val > 5));
 
Table created.
 
 
TESTDB> insert into t values(1,7);
 
1 row created.
 
TESTDB> commit;
 
Commit complete.
 
TESTDB> insert into t values (2,4);
insert into t values (2,4)
*
ERROR at line 1:
ORA-02290: check constraint (OPS$MYUSRID.SYS_C001214102) violated
 
 
TESTDB> desc t;
 Name                  Null?    Type     
 --------------------- -------- --------
 ID                    NOT NULL NUMBER
 VAL                            NUMBER
 
TESTDB> create table t1 as select * from t;
 
Table created.
 
TESTDB> desc t1;
 Name                 Null?    Type
 -------------------- -------- ----------
 ID                   NOT NULL NUMBER
 VAL                           NUMBER
 
TESTDB> insert into t1 values (1, 4);
 
1 row created.
 


TESTDB> ;
  1* select owner, constraint_name, constraint_type, table_name, search_condition from user_constraints
TESTDB> /
 
OWNER        CONSTRAINT_NAME                C TABLE_NAME SEARCH_CONDITION
------------ ------------------------------ - ---------- ------------------------------
OPS$MYUSRID  SYS_C001214102                 C T          val > 5
OPS$MYUSRID  SYS_C001214101                 C T          "ID" IS NOT NULL
OPS$MYUSRID  SYS_C001214103                 C T1         "ID" IS NOT NULL

To create the constraints in the new table, I thus faced a task to extract all the DDL about constraints from the existing table. The approach I adopted after several tests was as follows.

1. First, I created a table my_constraints to have CLOB datatype for search_conditon column since we can not use LIKE operater on a LONG type column.

create table my_constraints ( 
    owner varchar2(30)
   , constraint_name varchar2(30)
   , constraint_type varchar2(1)
   , table_name varchar2(30)
   , search_condition clob
   ) ;

   insert into my_constraints
   select owner, constraint_name, constraint_type, table_name, to_lob(search_condition)
     from dba_constraints 
   where owner =&owner ;

2. For PK, UK and check constraints ( excluding NOT NULL), I used the following command to extract the DDL:

SELECT DBMS_METADATA.GET_DDL('CONSTRAINT', t.constraint_name , t.owner ) ddl_string
  from my_constraints t
 where table_name = upper('&table_name')
  and  owner=upper('&owner')
and constraint_type in ('P', 'U','C')
and ( search_condition is null
      or ( search is not null and search_condition not like '%NOT NULL')
    )
;

3. For FK constraints, I used the following command to extract the DDL

SELECT to_char(DBMS_METADATA.GET_DEPENDENT_DDL('REF_CONSTRAINT', table_name, owner)) DDL
  FROM (SELECT DISTINCT b.table_name, b.owner
           from dba_constraints b
           where b.constraint_type = 'R'
           AND b.owner = upper('&owner')
           AND b.table_name = upper('&table_name')) ;

CTAS also does not preserve DEFAULT values of columns. I used the following to obtain the 'ALTER TABLE' statement for DAFAULTS:

BEGIN
        FOR r IN (
             select owner, table_name, column_name, data_type, data_default
               from dba_tab_columns
             where owner = upper('&owner')
               and table_name = upper('&table_name')
               and data_default is not null
        )
        LOOP
                DBMS_OUTPUT.PUT_LINE
                ( 'ALTER TABLE ' || r.owner || '.' || r.table_name  ||
                 ' modify  ' ||r.column_name ||
                 ' default ' || r.data_default || ';');
        END LOOP;
END;
/

The reason we need to use PL/SQL instead of SQL is that DATA_DEFAULT column is LONG type. We can not use '||' with LONG type column.

Move table to different tablespace through online redefinition

2009-11-20T14:31:00.001-05:00

Some times ago, I tested the steps of moving two tables to different tablespace through online redefiniton. I developed the steps based on the Oracle online documentation.

The background is that we need to do an online copy of a production database with subset data to another data center. These two tables are critical and need to be copied over and would be used to build other tables. However, these two tables reside in a tablespace hosting many other tables. Thus to put them into a separate tablespace would make our copy job much easier.

Below describes the steps and commands involved for reference. TAB_MA and TAB_MS are under schema SCH_SO. The tablespace to which we want to move them is called SCH_SO_DATA_R. (Those are not real production table names)

Step:
~~~~~

1. Verify that the table is a candidate for online redefinition

BEGIN
DBMS_REDEFINITION.CAN_REDEF_TABLE('sch_so','tab_ma',
dbms_redefinition.cons_use_pk);
END;
/

BEGIN
DBMS_REDEFINITION.CAN_REDEF_TABLE('sch_so','tab_ms',
dbms_redefinition.cons_use_pk);
END;
/

2. Create an interim tables

create table sch_so.tab_ma_int
tablespace sch_so_data_r
as
select * from sch_so.tab_ma
where 1=0;

create table sch_so.tab_ms_int
tablespace sch_so_data_r
as
select * from sch_so.tab_ms
where 1=0;

3. Start the redefinition process.

BEGIN
DBMS_REDEFINITION.START_REDEF_TABLE(
'sch_so', 'tab_ma','tab_ma_int',
)
END;
/

BEGIN
DBMS_REDEFINITION.START_REDEF_TABLE(
'sch_so', 'tab_ms','tab_ms_int',
)
END;
/

Note:
After redefinition finished, checked the segment size of interim tables:

1 select owner, segment_name, tablespace_name, bytes/1024/1024/1024 size_G from dba_segments
2* where tablespace_name='SCH_SO_DATA_R'
SQL> /

OWNER SEGMENT_NAME TABLESPACE_NAME SIZE_G
---------------- ----------------------- ----------------- ----------
SCH_SO TAB_MA_INT SCH_SO_DATA_R 4.9375
SCH_SO TAB_MS_INT SCH_SO_DATA_R 9.1875

time: 20 min

4. Create any triggers, indexes and constraints on the interim tables

5. Optionally, synchronize the interim table hr.int_admin_emp.

BEGIN
DBMS_REDEFINITION.SYNC_INTERIM_TABLE('sch_so', 'tab_ms', 'tab_ms_int');
END;
/

6. Complete the redefinition.

BEGIN
DBMS_REDEFINITION.FINISH_REDEF_TABLE('sch_so', 'tab_ms', 'tab_ms_int');
END;
/

BEGIN
DBMS_REDEFINITION.FINISH_REDEF_TABLE('sch_so', 'tab_ma', 'tab_ma_int');
END;
/

Note: The table is locked in the exclusive mode only for a small window toward the end of this step. After this call the table is redefined such that it has all the attributes of the interim table.

7. Drop the interim table.

session_cached_cursors and parse

2009-11-09T09:19:00.016-05:00

The following test case demonstrated the effects of session_cached_cursors on whether and how the PL/SQL caches cursors. I tested with either session_cached_cursors=0 or 20 and with a static SQL or an 'execute immediate' statement in a PL/SQL procedure, in a 9.2.0.8 database and a 10.2.0.1 database, respectively.

create or replace procedure  proc_p
is
obj_no number;
begin
for i in 1..100
loop
execute immediate 'select count(*)  from all_objects where object_id = :1 ' into obj_no using i;
dbms_output.put_line('i='  i  ' count='  obj_no);
end loop;
end;
/


create or replace procedure  proc_p2
is
obj_no number;
begin
for i in 1..100
loop
select count(*) into obj_no from all_objects where object_id = i;
dbms_output.put_line('i='  i  ' count='  obj_no);
end loop;
end;
/

alter session set sql_trace=true;

-- alter session set session_cached_cursors=0;
alter session set session_cached_cursors=20;

exec proc_p;
exec proc_p2;

alter session set sql_trace=false;
exit;

I used TKPROF to analyse the trace files. Below is the summary:

----------------------------------------------------------------------------
version  session_cached_cursors    SQL          # of parse    # of execution
----------------------------------------------------------------------------
9.2.0.8      0                     exe immed    100            100
9.2.0.8      0                     static       100            100
9.2.0.8      20                    exe immed    100            100
9.2.0.8      20                    static       1              100
10.2.0.1     0                     exe immed    100            100
10.2.0.1     0                     static       100            100
10.2.0.1     20                    exe immed    1              100
10.2.0.1     20                    static       1              100
----------------------------------------------------------------------------

It can be seen that with session_cached_cursors=0, no matter in which version and with what kind of SQL, Oracle needs to at least soft parse each SQL for each execution. So session_cached_cursors=0 effectively disable the ability of PL/SQL to cache cursors. With session_cached_cursors=20 (nozero essentially),in 9.2.0.8, for the static SQL it can be achieved "parase once, execute many times"; in 10.2.0.1, for both type of SQL, same effect of "parse once, execute many times" is observed. Whenever possible, we should use static SQL in PL/SQL code; if not, we should try to use 'execute immediate' with bind variables. It seems from 10g, PL/SQL engine can cache cursors from 'execute immediate' statement also.

I continued to experiment about the session_cached_cursors and the number of SQL that is repeatedly executed. The test code looks like:

create or replace procedure  proc_p2
is
obj_no number;
obj_name all_objects.object_name%type;
begin
for i in 1..100
loop
-- sql a
select count(*) into obj_no from all_objects where object_id = i; 
-- sql b
select max(object_name) into obj_name from all_objects where rownum <= i;
-- sql c 
select min(object_name) into obj_name from all_objects where rownum <= i;
end loop;
end;
/

alter session set sql_trace=true;

-- alter session set session_cached_cursors=1;
alter session set session_cached_cursors=3;

exec proc_p2;

alter session set sql_trace=false;
exit;

I tested with session_cached_cursors from 1 to 3 and number of SQL from 1-3 as well. Here is the summary:

-------------------------------------------------------------------------
version  session_cached_    # static SQL      # of parse    # of execution
cursors
-------------------------------------------------------------------------
10.2.0.1     1                      1                1             100
10.2.0.1     1                      2   (a)          100           100
                                        (b)          100           100
10.2.0.1     2                      2   (a)          100           100
10.2.0.1                                (b)          100           100
10.2.0.1     3                      2   (a)          1             100
                                        (b)          1             100
10.2.0.1     3                      3   (a)          100           100
                                        (b)          100           100
                                        (c)          100           100
-------------------------------------------------------------------------

In the case of session_cached_cursors=3 and three static SQLs, in the above test, I repeatedly executed all three SQLs together 100 times. How about repeatedly executing each SQL 100 times, for three SQLs total?. How about picking up the next SQL to be executed randomly? Can increase session_cached_cursors really help?. Below are the test codes and some results.

Test code of excuting each static SQL 100 times, for three SQLs total:

create or replace procedure  proc_p2
is
obj_no number;
obj_name all_objects.object_name%type;
begin
for i in 1..100
loop
-- sql a
select count(*) into obj_no from all_objects where object_id = i; 
end loop;     

for i in 1..100
loop  
-- sql b
select max(object_name) into obj_name from all_objects where rownum <= i;
end loop;

for i in 1..100
loop 
-- sql c 
select min(object_name) into obj_name from all_objects where rownum <= i;
end loop;
end;
/

alter session set sql_trace=true;

-- alter session set session_cached_cursors=1;
alter session set session_cached_cursors=3;

exec proc_p2;

alter session set sql_trace=false;
exit;

Test code of picking next static SQL to be executed randomly:

create or replace procedure  proc_p2
is
obj_no number;
obj_name all_objects.object_name%type;
r number;
begin
for i in 1..300
loop
r := dbms_random.value; 
if ( r <= 0.3333 ) then
select count(*) into obj_no from all_objects where object_id = i; 
elsif ( r >= 0.6667 ) then
select max(object_name) into obj_name from all_objects where rownum <= i;
else 
select min(object_name) into obj_name from all_objects where rownum <= i;
end if;
end loop;     
end;
/
show errors;

alter session set sql_trace=true;

-- alter session set session_cached_cursors=1;
alter session set session_cached_cursors=20;

exec proc_p2;

alter session set sql_trace=false;
-- exit;

Here is the result from TKPROF for above two cases:

------------------------------------------------------------------------
Order      session_cached_    # static SQL    # of parse  # of execution
cursors
------------------------------------------------------------------------
Each SQL
100 times      3                   3   (a)         1          100
                                       (b)         1          100
                                       (c)         1          100
Random         3                   3   (a)        33           90
                                       (b)        33          104
                                       (c)        33          106
Random         20                  3   (a)         1           96
                                       (b)         1          104
                                       (c)         1          100
------------------------------------------------------------------------

DBMS_STATS mistake

2009-10-30T14:59:00.005-04:00

In 10g I know, by default, Oracle will decide if the histogram is needed for a column. If we don't want to collect histogram, we should specify: method_opt=>'FOR ALL COLUMNS SIZE 1'.

I find I have maken a mistake in a pre-production 10g database. I omitted the 'ALL' keyword in the job for gathering table stats. So what could happen?

Here is the demonstration by a test:

SQL>select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bi
PL/SQL Release 10.2.0.1.0 - Production
CORE 10.2.0.1.0 Production
TNS for Solaris: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production

SQL>
SQL>drop table t;
drop table t
*
ERROR at line 1:
ORA-00942: table or view does not exist

SQL>create table t as select * from dba_objects;

Table created.

SQL>
SQL>begin
2 dbms_stats.gather_table_stats(user,'T',
3 estimate_percent =>30,
4 cascade => TRUE,degree => 8,
5 method_opt => 'FOR COLUMNS SIZE 1');
6 end;
7 /

PL/SQL procedure successfully completed.

SQL>
SQL>select table_name, column_name, density,num_buckets, last_analyzed
2 from dba_tab_columns where owner=user and table_name='T';

TABLE_NAME COLUMN_NAME DENSITY NUM_BUCKETS LAST_ANAL
------------------------------ ------------------------------ ---------- ----------- ---------
T OWNER
T OBJECT_NAME
T SUBOBJECT_NAME
T OBJECT_ID
T DATA_OBJECT_ID
T OBJECT_TYPE
T CREATED
T LAST_DDL_TIME
T TIMESTAMP
T STATUS
T TEMPORARY
T GENERATED
T SECONDARY

13 rows selected.

SQL>
SQL>
SQL>begin
2 dbms_stats.gather_table_stats(user,'T',
3 estimate_percent =>30,
4 cascade => TRUE,degree => 8,
5 method_opt => 'FOR ALL COLUMNS SIZE 1');
6 end;
7 /

PL/SQL procedure successfully completed.

SQL>
SQL>
SQL>select table_name, column_name, density,num_buckets, last_analyzed
2 from dba_tab_columns where owner=user and table_name='T';

TABLE_NAME COLUMN_NAME DENSITY NUM_BUCKETS LAST_ANAL
------------------------------ ------------------------------ ---------- ----------- ---------
T OWNER .03125 1 30-OCT-09
T OBJECT_NAME .000035967 1 30-OCT-09
T SUBOBJECT_NAME .005847953 1 30-OCT-09
T OBJECT_ID .000019563 1 30-OCT-09
T DATA_OBJECT_ID .000208203 1 30-OCT-09
T OBJECT_TYPE .027777778 1 30-OCT-09
T CREATED .000393236 1 30-OCT-09
T LAST_DDL_TIME .000394789 1 30-OCT-09
T TIMESTAMP .000388651 1 30-OCT-09
T STATUS .5 1 30-OCT-09
T TEMPORARY .5 1 30-OCT-09
T GENERATED .5 1 30-OCT-09
T SECONDARY .5 1 30-OCT-09

13 rows selected.

We can see that no column stats will be gathered if that 'ALL' is missing, though no errors thrown out. This will cause bad execution plan in some situations.

DBA makes mistake. The question is how to reduce and avoid serious one. Some are due to carelessness and some are due to lack of experinece or knowledge. I should say the above mentioned mistake belongs to the first category. ( Though, I did not realize that all column stats would be missing) . Another example, the other day, I forgot to lift the restricted session mode after I was done a maitenance job. I do have this step in my checklist, the situation was that I was distracted by a production issue and have not come back to verify every steps in my checklist. Chris Foot has written an execent blog: The Art of Being a Successful DBA – Poka-Yoke and Paranoid DBA Best Practices, which I may want to read from time to time.

Truncate a parent table

2009-10-13T08:24:00.003-04:00

I overlooked the operations required to truncate a parent table. I thought I only need to
truncate all of its child tables first, then truncate itself. The following test demonstrated
that constraints have to be taken care of in addition:

SQL> @fk_child
Enter value for 1: z9xxx94
Enter value for 2: p
----- Children of z9xxx94 p -------

Owner Table Name Constraint Name Ref Constraint Name Status
-------------- ----------------- ------------------ ------------------------ --------
Z9xxx94 C C_FK P_PK ENABLED

SQL> truncate table c;

Table truncated.

SQL> truncate table p;
truncate table p
*
ERROR at line 1:
ORA-02266: unique/primary keys in table referenced by enabled foreign keys

We have to disable child table FK constraint first:

SQL> alter table c modify constraint C_FK disable;

Table altered.

SQL> truncate table p;

Table truncated.

SQL> alter table c modify constraint C_FK enable;

Table altered.

SQL> select count(*) from c;

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

SQL> select count(*) from p;

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

A SQL with a hidden error

2009-10-09T00:40:00.006-04:00

This test case is built from a real life DBA task.

SQL> create table t as select rownum id, object_name from dba_objects where rownum <=10;

Table created.

SQL> create table t2 as select rownum id1, object_name from dba_objects where rownum <=5;

Table created.

Our intention was to do the following SQL with a subqeury:

SQL> select * from t where id in ( select id1 from t2);

ID OBJECT_NAME
---------- ------------------------------
1 TAB$
2 I_IND1
3 I_COBJ#
4 USER$
5 I_OBJ1

Instead, we executed the following SQL, which has a typo . However, it got executed without error:

SQL> select * from t where id in ( select id from t2);

ID OBJECT_NAME
---------- ------------------------------
1 TAB$
2 I_IND1
3 I_COBJ#
4 USER$
5 I_OBJ1
6 I_PROXY_ROLE_DATA$_2
7 C_FILE#_BLOCK#
8 C_OBJ#
9 BOOTSTRAP$
10 I_ICOL1

10 rows selected.

Isn't it better Oracle can throw error for this SQL?