Monday, March 14, 2011

Rolling partition and global index coalesce

Resolving one of performance issues I figure out that primary key index is much bigger that it should be. Most of database activity is inserting data into partitioning table using some date field as a partitioning key. Rows can be inserted to every partition not only to most recent one. Daily job is dropping one oldest partition per day. Unfortunately primary key index is not partitioned and is maintained during partition drop as a global index. Correlation of these two things is a root cause of index size explosion.
Short test case below:
  • script test.sql has been used to check index size, number of rows in table and partition drop
  • in second session simple script inserting data into random partition was running continuously
Table definition:
  CREATE TABLE LOGS
   (    "LOG_ID" NUMBER NOT NULL ENABLE,
        "DELDATE" DATE NOT NULL ENABLE,
        "FILL" VARCHAR2(100),
         CONSTRAINT "LOGS_PK" PRIMARY KEY ("LOG_ID")
   )
  TABLESPACE "USERS"
  PARTITION BY RANGE ("DELDATE")
 (PARTITION "PARTITION1"  VALUES LESS THAN (TO_DATE(' 2011-02-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION2"  VALUES LESS THAN (TO_DATE(' 2011-03-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION3"  VALUES LESS THAN (TO_DATE(' 2011-04-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION4"  VALUES LESS THAN (TO_DATE(' 2011-05-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION5"  VALUES LESS THAN (TO_DATE(' 2011-06-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION6"  VALUES LESS THAN (TO_DATE(' 2011-07-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION7"  VALUES LESS THAN (TO_DATE(' 2011-08-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION8"  VALUES LESS THAN (TO_DATE(' 2011-09-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION9"  VALUES LESS THAN (TO_DATE(' 2011-10-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION10"  VALUES LESS THAN (TO_DATE(' 2011-11-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')),
  PARTITION "PARTITION11"  VALUES LESS THAN (TO_DATE(' 2011-12-28 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
 );
Source of test.sql script 
prompt number of rows in table
 select count(*) from pioro.logs;
 
 prompt LOGS_PK index size
 select sum(bytes)/1024/1024 from dba_extents where segment_name = 'LOGS_PK';

 prompt calculating stats
 exec dbms_stats.gather_table_stats('PIORO','LOGS',cascade=>true, estimate_percent=>null);
 
 prompt rows/block without update global indexes
 select blevel, leaf_blocks, distinct_keys, NUM_ROWS, NUM_ROWS/leaf_blocks "rows/block" from dba_indexes 
where owner='PIORO' and table_name='LOGS' and leaf_blocks <> 0;

 prompt number of rows in table partition
 select count(*) from pioro.logs partition(&partname);
 set timing on 

 alter table pioro.logs drop partition &partname update global indexes;
Inserts script running in loop looks like

insert into logs select seq_log_id.nextval, to_date('2011-'|| trunc(dbms_random.value(2,9)) ||'-15','yyyy-mm-dd'),
lpad('x',70,'x') from all_source a, all_source b where rownum <= 3000000;
commit;
Here is a output from test.sql for first partition drop
SQL> @test
number of rows in table COUNT(*)                                                                                                 
----------                                                                                                          
  12000000                                                                                                          

Elapsed: 00:00:13.74
LOGS_PK index size

SUM(BYTES)/1024/1024                                                                                                
--------------------                                                                
242           

Elapsed: 00:00:00.51
calculating stats

PL/SQL procedure successfully completed.

Elapsed: 00:01:11.28
rows/block without update global indexes

    BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS rows/block                                                          
---------- ----------- ------------- ---------- ----------                                                          
         2       30000      12000000   12000000        400         

Elapsed: 00:00:00.03
number of rows in table partition
Enter value for partname: partition1
old   1:  select count(*) from pioro.logs partition(&partname)
new   1:  select count(*) from pioro.logs partition(partition1)

  COUNT(*)                                                                                                          
----------                                                                                                          
   3001361                                                                              
Elapsed: 00:00:00.35
Enter value for partname: partition1
old   1:  alter table pioro.logs drop partition &partname update global indexes
new   1:  alter table pioro.logs drop partition partition1 update global indexes

Table altered.

Elapsed: 00:00:55.37
As you can see before first drop average number of rows in one index leaf for primary key was 400. ( 8 kB database block ) Output from next run looks like:
SQL> @test
number of rows in table

  COUNT(*)   
----------   
  11998639   

Elapsed: 00:00:09.59
LOGS_PK index size

SUM(BYTES)/1024/1024  
--------------------  
                 296  

Elapsed: 00:00:01.12
calculating stats

PL/SQL procedure successfully completed.

Elapsed: 00:01:13.16
rows/block without update global indexes

    BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS rows/block    
---------- ----------- ------------- ---------- ----------    
         2       37500      11998639   11998639 319.963707    

Elapsed: 00:00:00.05
number of rows in table partition
Enter value for partname: partition2
old   1:  select count(*) from pioro.logs partition(&partname)
new   1:  select count(*) from pioro.logs partition(partition2)

  COUNT(*)                  
----------                  
   3749280                  

Elapsed: 00:00:00.43
Enter value for partname: partition2
old   1:  alter table pioro.logs drop partition &partname update global indexes
new   1:  alter table pioro.logs drop partition partition2 update global indexes

Table altered.

Elapsed: 00:01:22.85
Numbers of rows in one leaf block drop from 400 to 320 rows per block. After a few next runs it looks like:
SQL> @test
number of rows in table

  COUNT(*)                                                                                                          
----------                                                                                                          
   9748583                                                                                                          

Elapsed: 00:00:17.67
LOGS_PK index size

SUM(BYTES)/1024/1024      
--------------------      
                 414      

Elapsed: 00:00:00.85
calculating stats

PL/SQL procedure successfully completed.

Elapsed: 00:01:11.78
rows/block without update global indexes

    BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS rows/block        
---------- ----------- ------------- ---------- ----------        
         2       52500       9748583    9748583 185.687295        

Elapsed: 00:00:00.01
Now is really bad - only 186 rows in one leaf block and size of index segment is now 414 MB. It will have huge impact on database performance as much more index blocks have to be read during index range scans. Solution is quite simple and can be done online without huge overhead. It is a index coalesce - this command will consolidate a free space in existing index and provide more free blocks for particular index segment. See example:
SQL> alter index pioro.LOGS_PK coalesce;

Index altered.

Elapsed: 00:03:57.12
SQL> prompt number of rows in table partition
number of rows in table partition
SQL> select count(*) from pioro.logs partition(&partname);
Enter value for partname: partition4
old   1: select count(*) from pioro.logs partition(&partname)
new   1: select count(*) from pioro.logs partition(partition4)

  COUNT(*)                    
----------                    
   5248055                    

Elapsed: 00:00:10.47
SQL> alter table pioro.logs drop partition &partname update global indexes;
Enter value for partname: partition4
old   1: alter table pioro.logs drop partition &partname update global indexes
new   1: alter table pioro.logs drop partition partition4 update global indexes

Table altered.

Elapsed: 00:02:09.65
SQL> @test
number of rows in table

  COUNT(*)                          
----------                          
   7500528                          

Elapsed: 00:00:15.78
LOGS_PK index size

SUM(BYTES)/1024/1024      
--------------------      
                 414      

Elapsed: 00:00:01.47
calculating stats

PL/SQL procedure successfully completed.

Elapsed: 00:00:46.30
rows/block without update global indexes

    BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS rows/block      
---------- ----------- ------------- ---------- ----------      
         2       26682       7500528    7500528 281.108163      

Elapsed: 00:00:00.08
After index coalesce we can see that Oracle is able to allocate space from free block and size of index remain stable and number of rows in one leaf block is now increasing.
This post has been created based on test data and test scenario but after sucesfull implementation in life systems I will blog about real numbers from production databases.

Wednesday, January 12, 2011

Moving standby database or Oracle know limitation story

It has been a long time since I last blogged. There were some changes in my professional live and now I'm again more close with 24/7 databases. 
I really like Oracle approach to know bugs or limitation and dealing with that from version to version. I have hit one of those recently and I want to share it with all my readers. This know limitation/bug appear first time in 10g and still exist in 11g R1.
I had a simple task to do - move standby database managed by DataGuard to new host. According to some bandwidth limitation I couldn't copy files from old host but I need to copy it from production box. In 11g it is not a problem we can use duplication from active database so we don't need to wait until backup solution will be setup on new box. This is what I have chosen  - RMAN and duplicate from active database.
Here is a command line used by me:
$ rman target sys@production auxiliary sys@standby
RMAN> duplicate target database for standby from active database dorecover NOFILENAMECHECK; 
And here is my point - I have specified NOFILENAMECHECK so Oracle allow me to keep same disk layout on production and standby database and will no claim that datafiles have the same names on both boxes. So far so good - duplication process has been finished without any issues.
I have started standby database and there is where I my problem begun.
Here are an example entry from alert.log
Errors in file /logs/diag/rdbms/dbs0_a/dbs0/trace/dbs0_mrp0_23247.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/redo1/dbs0/redo11.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /logs/diag/rdbms/dbs0_a/dbs0/trace/dbs0_mrp0_23247.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/redo1/dbs0/redo11.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Clearing online redo logfile 1 /redo1/dbs0/redo11.log
Clearing online log 1 of thread 1 sequence number 2357
Errors in file /logs/diag/rdbms/dbs0_a/dbs0/trace/dbs0_mrp0_23247.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/redo1/dbs0/redo11.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /logs/diag/rdbms/dbs0_a/dbs0/trace/dbs0_mrp0_23247.trc:
ORA-19527: physical standby redo log must be renamed
ORA-00312: online log 1 thread 1: '/redo1/dbs0/redo11.log'
Clearing online redo logfile 1 complete
Oracle is trying to open redo log file which doesn't exist on standby machine - this is a first error and of course expected one. Than Oracle is trying to clear (in that case recreate) redo log and it failed with error ORA-19527 and of course at the end it is informing DBA that clearing online redo log 1 has been completed.
Unfortunately this files has not been created and this error appear every time standby database has been restarted or recovery process has been restarted. The main issue is ORA-19527 "physical standby redo log must be renamed" even if in that case this is not a standby redo but online redo log. Simplest solution like drop and add a new groups of redo logs failed as Oracle is claiming that all those unexisting files will be used to database recovery. Hmmm - i like that. This is what Oracle support answer for that problem (783113.1) "These are not bug's, they are known limitations" and proposed solution is to set LOG_FILE_NAME_CONVERT to convert old redo log name to new one - even if both are same. As a part of explanation other note (352879.1) has following sentence "It is the equivalent of asking - Are you sure you want the logs to be called this....".
I can agree with that and this can be some protection to prevent overwriting of existing redo logs but why this same error happen if
  • I have specified NOFILENAME checking (ok I could do it by mistake) 
  • There were not online redo logs files nor standby logs files on my new box so I can't imagine how Oracle could overwritten one of those files
This is KNOW limitation so why RMAN is not forcing user to specify LOG_FILE_NAME_CONVERT or not checking if this parameter is set in new instance ?
regards,
Marcin

Tuesday, November 2, 2010

Unsafe deinstall using Oracle Univeral Installer.

Are Oracle Homes totally independent from OUI point of view? This was my impression until yesterday when I hit Oracle OUI de-installer bug in Oracle Real Application Cluster environment. I did 3 simple steps:
  • I have installed new Oracle Home into new directory on both nodes
  • There was timing issue between servers so I need to remove new Oracle Home using OUI de-install functionality.
  • I have corrected timing issue and installed new Oracle Home once again.
All old homes have been used by working Oracle ClusterWare, ASM and database and I believed that there should not be any issues. Unfortunately a few minutes after that work I have got first error message but only for new session:
ORA-27504: IPC error creating OSD context 
ORA-27300: OS system dependent operation: IPC init failed with status:65 
ORA-27301: OS failure message: Package not installed 
ORA-27302: failure occurred at: skgxpcini 
ORA-27303: additional information: libskgxpd.so called
I was surprised and I have checked $ORACLE_HOME/lib/ directory and I have found root cause - libskgxpd.so has very recent modification date and it was date of my installation. I have checked all OUI logs immediately looking for that file and in deinstallation log I found that entry:
INFO: The output of this make operation is also available at: '/opt/app/oracle/product/10.2.0/Db_new/install/make.log'
INFO:
INFO: Start output from spawned process:
INFO: ----------------------------------
INFO:
INFO: rm -f /opt/app/oracle/product/10.2.0/Db_1/lib/libskgxp10.so
INFO: cp /opt/app/oracle/product/10.2.0/Db_1/lib//libskgxpd.so /opt/app/oracle/product/10.2.0/Db_1/lib/libskgxp10.so
But in that same log I have found following message at the end:
INFO: Current Inventory:
        Oracle Home: OraCrs10g_home
                This Oracle Home has not been changed in this session.
        Oracle Home: ASM_HOME
                This Oracle Home has not been changed in this session.
        Oracle Home: RDBMS_HOME
                This Oracle Home has not been changed in this session.
INFO: This deinstallation was successful
So OUI replaced library libskgxp10.so in existing old home (RDBMS_HOME) and at the end of work stated that this home has not been change. There are bugs related to that : 7006848, 5474623.

If you ever hit that error – there is two possible solutions:
  1. Copy backup libskgxp10.so from untouched home if you have home with this same patch level (in my case it was ASM)
  2. Rebuild Oracle using the following steps   
    • cd $ORACLE_HOME/rdbms/lib   
      rename the original library (if exists)
      mv libskgxp10.so libskgxp10.so.old  
    • Relink to configure UDP for IPC    
      make -f ins_rdbms.mk rac_on ipc_udp ioracle   
    • Check whether the library exists    
      ls -l $ORACLE_HOME/lib/libskgxp10.so
    • startup the instance
And good advise at the end – your testing environment should be same as production one. If you are going to do some work on RAC test it on your test RAC too.

Sunday, September 12, 2010

Oracle patchest 11.2.0.2

Hi, 

Some people tweet about new Oracle patch set 11.2.0.2. I decided to check it too but I can't find it on MOS any more. Not only me as Tim Hall  (@oraclebase) tweet about that situation too.
Anyway there is one important note on MOS - 1189783.1 - starting with patch set 11.2.0.2 new Oracle patch sets will be full installations of Oracle Software and patching out-of-place will be preferred one or even mandatory one in case of Grid Infrastructure.
I hope this note doesn't disappear from MOS like patch set and will be still valid after a few days.
Now I'm waiting for 11.2.0.2 to appear once again.

regards,
Marcin

Wednesday, September 8, 2010

New version of Simulating ASH

Hello, 

I have mentioned some time ago about using Simulating ASH to solve performance issue in Oracle 9i database.
According to some restrictions I have to customize it a little bit and than I agreed with Kyle Hailey that I will publish it as a new version of S-ASH. A new project has been created on SourceForge to keep a repository and this new code and installation instruction can be find here.

Please feel free to post any comments or remarks. I have some idea about potential enhancement of that tool but I'm open for any new too.

regards,
Marcin

Wednesday, August 4, 2010

Column names and typing errors

Last few days I have hit myself into Oracle "feature" which was one of my favorite when I was helping developers solve strange Oracle issues. I recall one Oracle ANSI SQL syntax issue when Oracle didn't recognize that column names are duplicated in different tables and use a random one in output. This is why I always told people use column name with table name to avoid confusion. Anyway now I decided to blog about that and show why table.column_name syntax is so important.
Let's go through an example - In this syntax equal ?
select name1 from T1 where id1 in (select id1 from T2 where name2='NAME2');
select T1.name1 from T1 where T1.id1 in (select T2.id1 from T2 where name2='NAME2');
Looks OK isn't it ? But it really depend on how tables are defined. 
SQL> desc T1
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 ID1                                                NUMBER
 NAME1                                              VARCHAR2(100)

SQL> desc T2
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 ID2                                                NUMBER
 NAME2                                              VARCHAR2(100)

SQL> select id1, name1 from T1;

       ID1 NAME1
---------- -------------------------------------------------------
         1 NAME1

SQL> select id2, name2 from T2;

       ID2 NAME2
---------- -------------------------------------------------------
         2 NAME2
 
Now we can see that there is a typo in second query as there is no ID1 column in T2 table. But lets try to execute both. First we start a query with tablename.columnname syntax :
SQL> select T1.name1 from T1 where T1.id1 in (select T2.id1 from T2 where name2='NAME2');
select T1.name1 from T1 where T1.id1 in (select T2.id1 from T2 where name2='NAME2')
                                                *
ERROR at line 1:
ORA-00904: "T2"."ID1": invalid identifier
Looks OK Oracle found our error and query has not been executed. What about first example ?
SQL> select name1 from T1 where id1 in (select id1 from T2 where name2='NAME2');

NAME1
--------------------------------------------------------------------------------
NAME1

SQL>
It return one row and Oracle didn't find our typing error. Even worse IN filter is true for every T1 row but it should not - if you check rows in T1 and T2 where is no common value between  ID1 and ID2.
Why ? We are going to check if ID1 from T1 is included in set of ID1 from T2. But there is no ID1 in T2 so Oracle is using ID1 from T1 as in every correlated subquery. What this subquery return ? It will return ID1 from table T1 for every row in table T2 where name is equal to 'NAME2'. This is not what was excepted.

But is this subquery can be executed as separate query ? Of course not
SQL> select id1 from T2 where name2='NAME2';
select id1 from T2 where name2='NAME2'
       *
ERROR at line 1:
ORA-00904: "ID1": invalid identifier

I'm not sure if that problem can be classified as bug but at least is good to know how Oracle is using columns names and use tablename.columnname syntax to avoid confusion and increase code quality. Especially if there are tables with long column names and there is one letter difference between them.

regards,
Marcin

Thursday, July 29, 2010

Process hung on library cache lock

Customer reported a system slowdown/process hung during small and well defined period of time and it was related to one specific process only. Standard Oracle 9i performance analyze tool - Statspack didn't show anything unusual in that time but shapshots were taking very 30 min and this issue took about 5 minutes.
As we could not replicate issue I thought about SASH (a free simulator of Oracle Active Session History) and I have installed it and configured. From that time I was able to gather and keep information about active sessions.
When next time I got detailed information about similar issue I was able to use collected data and found a problem. After investigation I figured out that process used for that business functionality stuck on “library cache lock” event. When I compared my findings from SASH with Statspack I realize why I didn't spotted it before - "library cache lock" was about 1.8 % of all locks between statspack snapshots. From overall database review there was no problem but from process (and business) perspective that lock hung important process for almost 5 minutes.

Below I described all major steps of my investigation and what was a root cause.
Let's start with SASH output (I just left 3 lines but there was many more similar lines):
SQL> select sample_time,program, session_id, session_state, event, seq#, sql_id, '0' || trim(to_char(p1,'XXXXXXXXXXXXXXXXX')) "p1raw", p3
  2  from v$active_session_history
  3  where 
  4  sample_time >= to_date('18-7-2010 13:50:10','dd-mm-yyyy hh24:mi:ss')
  5  and sample_time <= to_date('18-7-2010 13:54:58','dd-mm-yyyy hh24:mi:ss')
  6  and event like 'library%'
  7  order by sample_time desc
  8  /

SAMPLE_TI PROGRAM        SESSION_ID SESSION_STATE EVENT              SEQ#  SQL_ID     p1raw             P3
--------- -------------- ---------- ------------- ------------------ ----- -------    -----------       ---
18-JUL-10 importantp.exe        472 WAITING       library cache lock  214  1548901218 07000002AC789A98  210
18-JUL-10 otherprogr.exe        436 WAITING       library cache lock    8  2855865705 07000002AC789A98  210
18-JUL-10                       375 WAITING       library cache lock   33   261624711 07000002AC789A98  310

First idea was about parsing problem but when I took a look on SQL it looked OK but it was just entry point to PL/SQL procedure. Next thing was to check event parameters and there was first surprise. According to Oracle documentation and Metalink note 34579.1 that event has following parameters:
  • p1 is an address of required object - in my case 07000002AC789A98
  • p3 is a lock type and namespace type (lock mode * 100 + namespace)  - in my case 310 or 210
In Oracle definitions (metalink or decode in v$librarycache) namespace number 10 is not defined. See whole list below
•    0 SQL Area
•    1 Table / Procedure / Function / Package Header
•    2 Package Body
•    3 Trigger
•    4 Index
•    5 Cluster
•    6 Object
•    7 Pipe
•    13 Java Source
•    14 Java Resource
•    32 Java Data
So what object it is ? P1 had a address and X$KGLOB has a list of all objects (I checked that table next day but there was no restart and it was a chance that there is still that same object in shared pool as session was running 24/7):
SQL> select kglnaown "Owner", kglnaobj "Object" from x$kglob where kglhdadr='07000002AC789A98'; 

Owner  Object
------ --------
SOFT   SNDQ
What type of objects is it ?
SQL> select object_type, object_name from dba_objects where owner='SOFT' and object_name = 'SNDQ';

OBJECT_TYPE OBJECT_NAME
----------- -----------
QUEUE       SNDQ
Bingo - object was a queue there was a dequeue in that PL/SQL code. My process called importantp.exe was waiting for lock on queue. Let's check lock type:
  • 2    - Share mode 
  • 3    - Exclusive mode 
For importantp.exe lock mode in p3 parameter was 210 which mean wait for shared lock. But queuing and dequeueing operations are running with shared locks so reason for waiting had to be related to none of them. I found it in last line of my listing there was another processes waiting for exclusive lock on that same queue. Using SQL_ID (261624711)  I discovered that there was another PL/SQL piece of code and add_subscriber function was called inside. 
That was a explanation of importantp.exe hungs - as dequeue function was called after add_subscriber function it had to wait until DDL command was finished. Add subscriber function had to wait until all previous operations in shared mode will be completed and there was typical chain of locks.

There are bugs in Metalink raised by other people describing similar situations and there is only one workaround do not try any DDL on queues during traffic peaks. This recommendation is well know and most DBAs preventing database from typical DDL operation ( like index rebuild or schema changes) during business hours. The problems starts with hidden  DDL commands used in application.