Translation

The oldest posts, are written in Italian. If you are interested and you want read the post in English, please use Google Translator. You can find it on the right side. If the translation is wrong, please email me: I'll try to translate for you.

mercoledì, agosto 31, 2016

Instance Needs Recovery: Introduction (3/3)

Part 1
Part 2

If an instance is dirty closed (SHUTDOWN ABORT, reboot of the server, kill -9, etc), you have two scenario:
  1. Data blocks modified aren't yet written to disk into datafiles and the informations are only into the Redo Log File online 
  2. Some data blocks into datafile contains data not yet committed 
  • In the first case, changes need to re-applied to the database (roll-forward)
  • In the second case, the changes have to disappear (roll-back) 

The V$DATABASE view, hase two columns that we are interested
  • V$DATAFILE.CHECKPOINT_CHANGE#
  • V$DATAFILE.LAST_CHANGE#

When an instance is opened, V$DATAFILE.CHECKPOINT_CHANGE# is the SCN at last checkpoint (1) while V$DATAFILE.LAST_CHANGE# is NULL. Oracle set to NULL V$DATAFILE.LAST_CHANGE# so it know that the database is working.

If the database is clean closed, Oracle update the V$DATAFILE.LAST_CHANGE# column to the last SCN. But if the close is dirty, Oracle can't to do this update and the V$DATAFILE.LAST_CHANGE# column remain NULL, so at the next startup Oracle knows that last close was not clean and the instance recovery is necessary.

So, when an issue force a shutdown abort (for example), the db is closed before V$DATAFILE.LAST_CHANGE# can be updated to V$DATAFILE.CHECKPOINT_CHANGE#.

In other words, when both SCN are the same (V$DATAFILE.LAST_CHANGE# and V$DATAFILE.CHECKPOINT_CHANGE#) we have no problem, but if V$DATAFILE.LAST_CHANGE# is NULL then the instance need recovery.

Question.

If  V$DATAFILE.LAST_CHANGE# and V$DATAFILE.CHECKPOINT_CHANGE# have the same value, are we out of any issue?
The answer is no. Not entirely. This is because Oracle do another check on the datafiles. He verify that V$DATAFILE_HEADER.CHECKPOINT_CHANGE# (2) and V$DATABASE.CHECKPOINT_CHANGE# (3) are the same. If not, than media recovery is needed.

(1) https://docs.oracle.com/cd/E11882_01/server.112/e40402/dynviews_1100.htm#REFRN30050
(2) https://docs.oracle.com/cd/E11882_01/server.112/e40402/dynviews_1102.htm#REFRN30052
(3) https://docs.oracle.com/cd/E11882_01/server.112/e40402/dynviews_1097.htm#REFRN30047

Part 1
Part 2

martedì, agosto 30, 2016

Visualizing the alert.log

Usually an alert.log file has a date at first line followed by some several messages.

Mon Aug 08 09:29:49 2016 
Thread 1 advanced to log sequence 2348 (LGWR switch)
Current log# 7 seq# 2348 mem# 0: +DGCUSDB01/redolog/cusctip_01_07_01.dbf
Current log# 7 seq# 2348 mem# 1: +DGCUSDB02/redolog/cusctip_01_07_02.dbf

With this python script you can visualize an alert.log in a different way: each line is made of a date + message

Sat Aug 06 15:58:12 2016 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
Sat Aug 06 15:58:12 2016 With the Partitioning, Real Application Clusters, Oracle Label Security and Oracle Database Vault options.
Sat Aug 06 15:58:12 2016 ORACLE_HOME = /sbRdbms/app/oracle/product/11.2.0.4/dbh01Rac
Sat Aug 06 15:58:12 2016 System name: Linux
Sat Aug 06 15:58:12 2016 Node name: mdapora1d01
Sat Aug 06 15:58:12 2016 Release: 3.10.0-123.el7.x86_64
Sat Aug 06 15:58:12 2016 Version: #1 SMP Mon May 5 11:16:57 EDT 2014
Sat Aug 06 15:58:12 2016 Machine: x86_64
Sat Aug 06 15:58:12 2016 Using parameter settings in server-side pfile /sbRdbms/app/oracle/product/11.2.0.4/dbh01Rac/dbs/initCUSCTIp1.ora
Sat Aug 06 15:58:12 2016 System parameters with non-default values:
Sat Aug 06 15:58:12 2016 processes = 2500
Sat Aug 06 15:58:12 2016 sessions = 3840
Sat Aug 06 15:58:12 2016 spfile = "+DGCUSDB01/cusctip/pfile/spfilecusctip.ora"
Sat Aug 06 15:58:12 2016 sga_target = 8G
Sat Aug 06 15:58:12 2016 control_files = "+DGCUSDB01/cusctip/cntl/cusctip_control_01.ctl"
Sat Aug 06 15:58:12 2016 control_files = "+DGCUSDB02/cusctip/cntl/cusctip_control_02.ctl"
Sat Aug 06 15:58:12 2016 db_block_size = 8192
Sat Aug 06 15:58:12 2016 compatible = "11.2.0.4.0" 
Sat Aug 06 15:58:12 2016 log_archive_dest_1 = "LOCATION=/dbCUSCTIp/akCUSCTIp01/CUSCTIp/"
Sat Aug 06 15:58:12 2016 log_archive_format = "archive_DBID%d_CUSCTIp%t_%s_%r.dbf"
Sat Aug 06 15:58:12 2016 cluster_database = TRUE


or this

Mon Aug 08 09:29:49 2016 Thread 1 advanced to log sequence 2348 (LGWR switch)
Mon Aug 08 09:29:49 2016 Current log# 7 seq# 2348 mem# 0: +DGCUSDB01/redolog/cusctip_01_07_01.dbf
Mon Aug 08 09:29:49 2016 Current log# 7 seq# 2348 mem# 1: +DGCUSDB02/redolog/cusctip_01_07_02.dbf
Mon Aug 08 09:29:53 2016 Archived Log entry 5093 added for thread 1 sequence 2347 ID 0x4cb57b94 dest 1:
Mon Aug 08 09:31:25 2016 Thread 1 advanced to log sequence 2349 (LGWR switch)
Mon Aug 08 09:31:25 2016 Current log# 1 seq# 2349 mem# 0: +DGCUSDB01/redolog/cusctip_01_01_01.dbf
Mon Aug 08 09:31:25 2016 Current log# 1 seq# 2349 mem# 1: +DGCUSDB02/redolog/cusctip_01_01_02.dbf
Mon Aug 08 09:31:26 2016 Archived Log entry 5095 added for thread 1 sequence 2348 ID 0x4cb57b94 dest 1:

If you want to use my script then
  • download the file
  • copy the the script on your db machine
  • change the first line with the correct python path
    • run which python command, to find where is the interpreter
  • if you use python3, comment (with # symbol) or delete this line
    • from __future__ import print_function

 

Update 2016/Aug/31

I wrote the script so you can run it on a "tail" or "cat" command. For example, you can run

[oracle]# tail -21 alert_+ASM1.log |formatAlertLogX.py
Day Mon DD HH:MI:SS YYYY NOTE: assigning ARB0 to group 45/0xcd5a0bd8 (DGVSAPDB01) with 2 parallel I/Os
Thu Aug 25 09:26:58 2016 NOTE: header on disk 0 advanced to format #2 using fcn 0.525
Thu Aug 25 09:27:02 2016 NOTE: Attempting voting file refresh on diskgroup DGVSAPDB01
Thu Aug 25 09:27:02 2016 NOTE: Refresh completed on diskgroup DGVSAPDB01. No voting file found.
Thu Aug 25 09:28:00 2016 NOTE: GroupBlock outside rolling migration privileged region
Thu Aug 25 09:28:00 2016 NOTE: requesting all-instance membership refresh for group=45
Thu Aug 25 09:28:00 2016 NOTE: membership refresh pending for group 45/0xcd5a0bd8 (DGVSAPDB01)
Thu Aug 25 09:28:00 2016 GMON querying group 45 at 79717 for pid 22, osid 20432
Thu Aug 25 09:28:00 2016 SUCCESS: refreshed membership for 45/0xcd5a0bd8 (DGVSAPDB01)
Thu Aug 25 09:28:00 2016 NOTE: Attempting voting file refresh on diskgroup DGVSAPDB01
Thu Aug 25 09:28:00 2016 NOTE: Refresh completed on diskgroup DGVSAPDB01. No voting file found.
Thu Aug 25 09:28:33 2016 NOTE: stopping process ARB0
Thu Aug 25 09:28:33 2016 SUCCESS: rebalance completed for group 45/0xcd5a0bd8 (DGVSAPDB01)