Showing posts with label mistake. Show all posts
Showing posts with label mistake. Show all posts

Friday, October 30, 2009

DBMS_STATS mistake

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.

Monday, May 18, 2009

Check the content of the script before executing in production database

Last weekend, I supported the code release in a production database. There were 39 scripts to be executed. When I executed the 9th script, strange thing happened. Lots of scripts got executed which should not at that stage. This caused extra time to fix the mess. Checking the content of this script, I found that there are strange characters and some other scripts's content. I recalled that I tarred the whole scripts before I uploaded to the server. When I did the tar at the first time I issued the wrong syntax without providing the target file name. That was probably the reason that caused the 9th script garbged.

Bottom line is I should check the content of every script that is going to be dropped in the prodcution database. This is a big lesson.

Friday, August 15, 2008

Lost of a redo log group due to DBA's mistake

Just few days before I joined the current DBA team, there was a serious incident that lead to a production database hung due to a DBA's mistake. I dig into the alert log of that database, trying to understand the sequence of event occurred for the incident. Here are my findings (actual database name changed to PRODDB):

(1) At this moment, the DBA issued a statement to add a redo log group consisting of one member.

----------------
Sat Aug 2 03:50:24 2008
alter database add logfile group 12 '/opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc' size 3G
----------------

Note: The DBA used the archive log file name format and location for the online redo log file. He obviously confused online redo log files with archived log files. The following query shows that at 03:30, the real archive log file "PRODDB0000124998_1_589897528.arc" corresponding to sequence# 124998 did not exist at the location before he issued the statement.

SQL> select sequence#, completion_time from v$archived_log where completion_time between sysdate-12 and sysdate -10


SEQUENCE# COMPLETION_TIME
---------- --------------------
124984 2008-AUG-02 00:50:32
124985 2008-AUG-02 02:12:26
124986 2008-AUG-02 03:02:46
124987 2008-AUG-02 03:43:32
124992 2008-AUG-02 04:06:38
124988 2008-AUG-02 04:07:19
124991 2008-AUG-02 04:08:19
124989 2008-AUG-02 04:35:42
124990 2008-AUG-02 04:38:58
124993 2008-AUG-02 04:50:42
124994 2008-AUG-02 04:51:13
124995 2008-AUG-02 04:51:41
124996 2008-AUG-02 04:54:50
124997 2008-AUG-02 05:17:21
124999 2008-AUG-02 05:35:23
124998 2008-AUG-02 05:39:57
125001 2008-AUG-02 05:49:09
125002 2008-AUG-02 05:50:44
125003 2008-AUG-02 05:51:48

(2) At this moment, all online logs needed archiving, swiching logfile can not proceed, so database was hung.

------
Sat Aug 2 03:55:49 2008
Thread 1 cannot allocate new log, sequence 124999
All online logs needed archiving
Current log# 6 seq# 124998 mem# 0: /opt/app/prddbserv/oracle/PRODDB/NEW_redo2/redoPRODDB_F1.dbf
Current log# 6 seq# 124998 mem# 1: /opt/app/prddbserv/oracle/PRODDB/NEW_redo4/redoPRODDB_F2.dbf
------
Note: This is why the DBA wanted to add new online redo log groups at the first place.

(3) At this moment, log switch occurred
------
Sat Aug 2 04:06:39 2008
Beginning log switch checkpoint up to RBA [0x1e847.2.10], SCN: 10077378246296
Thread 1 advanced to log sequence 124999
Current log# 9 seq# 124999 mem# 0: /opt/app/prddbserv/oracle/PRODDB/NEW_redo1/redoPRODDB_I1.dbf
Current log# 9 seq# 124999 mem# 1: /opt/app/prddbserv/oracle/PRODDB/NEW_redo3/redoPRODDB_I2.dbf
------
(4) At this moment, adding logfile completed:
------
Sat Aug 2 04:11:13 2008
Completed: alter database add logfile group 12 '/opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc'
size 3G
------

(5) At this moment, log switch occurred and the newly added logfile became the current log
------
Sat Aug 2 04:16:59 2008
Beginning log switch checkpoint up to RBA [0x1e848.2.10], SCN: 10077390512906
Thread 1 advanced to log sequence 125000
Current log# 12 seq# 125000 mem# 0: /opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc
------

Note: From the seq# 125000, we can know when Oracle archives this online redo log with the wrong name, the
generated archived log will be "/opt/app/prddbserv/oracle/PRODDB/arc/PRODDB000012500_1_589897528.arc"

(6) At this moment, log switch again
------
Sat Aug 2 05:10:20 2008
Beginning log switch checkpoint up to RBA [0x1e849.2.10], SCN: 10077430464587
Thread 1 advanced to log sequence 125001
Current log# 7 seq# 125001 mem# 0: /opt/app/prddbserv/oracle/PRODDB/NEW_redo1/redoPRODDB_G1.dbf
Current log# 7 seq# 125001 mem# 1: /opt/app/prddbserv/oracle/PRODDB/NEW_redo3/redoPRODDB_G2.dbf
------

(7) At this moment, after server log switch, Oracle advanced to log sequence 125003.
And more importantly, from the query in (1), we know Oracle completed an archive log with the name
"/opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc" at 05:39:57.
The real archive log overwrote the online redo log with the same name created by the DBA


Note: 124998 2008-AUG-02 05:39:57


(8)ARC1 throw error at this time, notice log 12 sequence# 125000 cannot be archived,

------
Sat Aug 2 05:28:54 2008
ARC1: Log corruption near block 632833 change 10077402450354 time ?
Sat Aug 2 05:28:54 2008
Errors in file /opt/app/prddbserv/oracle/PRODDB/logs/bdump/p6nbertg_arc1_354.trc:
ORA-00354: corrupt redo log block header
ORA-00353: log corruption near block 632833 change 10077402450354 time 08/02/2008 04:16:58
ORA-00312: online log 12 thread 1: '/opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc'
ARC1: All Archive destinations made inactive due to error 354
------

Note: because at this time '/opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc' was no longer online log, instead it was a real archived log.


(9) From this point on, the Database essentially was not funtioning and throw errors into alert log reaptedly.

Below prensented some alert log messages during the the fixing process:

(1) Shutdown the archive processes

-----
Sat Aug 2 10:02:51 2008
Shutting down archive processes
-----

(2) Modify # of archive processes
-----
Sat Aug 2 10:02:51 2008
ALTER SYSTEM SET log_archive_max_processes=1 SCOPE=MEMORY;
-----

Note: from the timestamp (1) and (2) occurs at the same time, should be from one command

(3) Oracle gives WARNING message

-----
Sat Aug 2 10:02:54 2008
WARNING! CLEARING REDO LOG WHICH HAS NOT BEEN ARCHIVED. BACKUPS TAKEN
BEFORE 08/02/2008 05:10:19 (CHANGE 10077430464587) CANNOT BE USED FOR RECOVERY.
Clearing online log 12 of thread 1 sequence number 125000
-----

(4)
Sat Aug 2 10:03:48 2008
ARCH shutting down
ARC1: Archival stopped

Sat Aug 2 10:04:14 2008
Beginning log switch checkpoint up to RBA [0x1e857.2.10], SCN: 10077532552587
Thread 1 advanced to log sequence 125015
Current log# 12 seq# 125015 mem# 0: /opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc

(5)
Sat Aug 2 10:04:14 2008
Completed: alter database clear unarchived logfile group 12

Sat Aug 2 10:05:09 2008
archivelog header validation failure for file /opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc
archivelog header validation failure for file /opt/app/prddbserv/oracle/PRODDB/arc/PRODDB0000124998_1_589897528.arc

(6)
Sat Aug 2 10:05:24 2008
ARCH: STARTING ARCH PROCESSES
ARC1: Archival started
ARC2: Archival started
ARC3: Archival started
ARCH: STARTING ARCH PROCESSES COMPLETE


Sat Aug 2 10:05:25 2008
ALTER SYSTEM SET log_archive_max_processes=6 SCOPE=MEMORY;
ARC3 started with pid=51, OS id=11043

(7)
Sat Aug 2 10:15:48 2008
alter database drop logfile group 12
Sat Aug 2 10:15:48 2008
Completed: alter database drop logfile group 12