Comando "Shutdown abort", é mesmo perigoso?

Por Franky Weber e Gabriel Comenale,
Postado em Novembro 2016

Revisado por Marcelo Pivovar - Solution Architect

Objetivo: desmistificar alguns conceitos sobre o shutdown abort e provar as ocorrências ao executá-lo.

Nós viemos aqui para tratar de um assunto polêmico para alguns DBAs: o comando shutdown abort. Do contrário do que muitos pensam, este comando de desligamento do banco de dados é mais seguro do que se imagina e nós, Franky e Gabriel, vamos provar ao longo deste artigo esta afirmação, então leia até o final para entender nossos argumentos. O Oracle possui dois tipos de shutdown: consistente e inconsistente. Num shutdown consistente os arquivos do banco de dados são sincronizados pelo processo CKPT (checkpoint) em conjunto com o LGWR (logwriter) e DBWn (dbwriter) e então a instância é desligada. Num shutdown inconsistente o CKPT não é disparado então os arquivos não são sincronizados e permanecem no estado em que estão até que aconteça o startup, onde os mesmos são sincronizados. Este processo de sincronização no startup é chamado de instance recovery ou crash recovery e acontece automaticamente.

Shutdown consistente:

  • shutdown ou shutdown normal: novas conexões ao banco de dados não são permitidas, o Oracle aguarda que todos se desconectem do banco de dados, força o checkpoint nos arquivos e então faz o desligamento. No startup não é necessário recover.
  • shutdown transactional: novas conexões ao banco de dados não são permitidas, o Oracle aguarda que todas as transações sejam finalizadas, força o checkpoint nos arquivos e então faz o desligamento. No startup não é necessário recover.
  • shutdown immediate: novas conexões ao banco de dados não são permitidas, o Oracle derruba todas as sessões, faz o rollback das transações que não sofreram commit, força o checkpoint nos arquivos e faz o desligamento. No startup não é necessário recover.

Shutdown inconsistente:

  • shutdown abort ou startup force ou instance failure (falha da instância): o Oracle não aguarda nada ser concluído, não faz checkpoint nos arquivos e termina os processos fazendo o desligamento do banco de dados. No startup o processo SMON (system monitor) é responsável por identificar a necessidade de recover. Depois de concluído o recover o banco de dados é aberto para utilização e então o Oracle inicia o rollback das transações que não sofreram commit antes do desligamento. Isso acontece porque o Oracle faz a leitura dos redolog files e aplica todas as alterações que foram feitas nos dados que estavam no database buffer cache, inclusive as que não haviam sofrido commit, pois não é somente quando ocorre um commit que o log buffer é descarregado para os redolog files. (Saiba mais sobre o comportamento do log writer)

Ok, então quer dizer que se eu fizer shutdown abort meu banco de dados não terá problemas depois? Não, não terá, pois o Oracle usa os online redolog files para fazer o recover de todas as alterações e depois disso abre o banco de dados para uso para só então iniciar o rollback das transações que não têm commit. Se os seus arquivos de redolog não forem apagados ou corrompidos não terá problema nenhum. Em muitas situações é mais válido fazer um shutdown abort do que efetuar um shutdown immediate e aguardar o rollback das transações finalizar, porque o Oracle fará rollback só depois que abrir o banco de dados no caso do abort, do contrário se você estivesse executando uma operação que levaria 8 horas e esta só executou 3 horas, em teoria, você teria que aguardar um rollback de 3 horas para o banco desfazer tudo que já havia sido feito e não temos como esperar 3 horas para o shutdown immediate completar, certo?

Outro motivo para não se preocupar com o shutdown abort é que o próprio Oracle faz shutdown abort quando você tem um ambiente em cluster ou com ASM. Ao efetuar os comandos “crsctl stop crs”, “crsctl stop cluster” ou “srvctl stop asm -f” (exceto Flex ASM) o Clusterware faz shutdown abort do banco de dados. Você acha que se até o próprio Oracle faz isso você estaria fazendo algo errado?

Ainda não se convenceu? Ok. Vamos mostrar o que acontece durante um shutdown abort, mas entenda que o shutdown abort é diferente de uma queda de energia, ou desligamento do servidor por falha de hardware, pois esses desligamentos do servidor podem afetar os discos e arquivos neles armazenados. Nos sistemas de arquivos existe um conceito chamado Journaling que ajuda a evitar que os arquivos sejam corrompidos por inconsistência de dados, mas ainda assim isso pode ocorrer.

Vamos ver alguns exemplos de shutdown abort...

Em uma sessão vamos executar os comandos e na outra temos o alert.log do banco de dados aberto:

Exemplo 1

Sessão A:

Sessão A:

[root@srv1  ~]# crsctl stop cluster -all
CRS-2673:  Attempting to stop 'ora.crsd' on 'srv1'
CRS-2673:  Attempting to stop 'ora.crsd' on 'srv2'
CRS-2790:  Starting shutdown of Cluster Ready Services-managed resources on 'srv1'
.
.
.
CRS-2677:  Stop of 'ora.DATA.dg' on 'srv1' succeeded
CRS-2677:  Stop of 'ora.orcl.oltp2.svc' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.LISTENER.lsnr' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.srv1.vip' on 'srv1'
CRS-2677:  Stop of 'ora.orcl.oltp1.svc' on 'srv2' succeeded
CRS-2673:  Attempting to stop 'ora.srv2.vip' on 'srv2'
CRS-2673:  Attempting to stop 'ora.orcl.db' on 'srv2'
CRS-2677:  Stop of 'ora.scan3.vip' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.srv1.vip' on 'srv1' succeeded
CRS-2677:  Stop of 'ora.orcl.db' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.srv2.vip' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.mgmtdb' on 'srv2' succeeded
CRS-2673:  Attempting to stop 'ora.MGMTLSNR' on 'srv2'
CRS-2673:  Attempting to stop 'ora.CONFIG.dg' on 'srv2'
CRS-2677:  Stop of 'ora.CONFIG.dg' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.MGMTLSNR' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.proxy_advm' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.proxy_advm' on 'srv1' succeeded
.
.
.
CRS-2677:  Stop of 'ora.asm' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.ASMNET1LSNR_ASM.lsnr' on 'srv1'
CRS-2677:  Stop of 'ora.ASMNET1LSNR_ASM.lsnr' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.ons' on 'srv1'
CRS-2673:  Attempting to stop 'ora.ons' on 'srv2'
CRS-2677:  Stop of 'ora.ons' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.net1.network' on 'srv1'
CRS-2677:  Stop of 'ora.net1.network' on 'srv1' succeeded
CRS-2792:  Shutdown of Cluster Ready Services-managed resources on 'srv1' has completed
CRS-2677:  Stop of 'ora.ons' on 'srv2' succeeded
CRS-2673:  Attempting to stop 'ora.net1.network' on 'srv2'
CRS-2677:  Stop of 'ora.net1.network' on 'srv2' succeeded
CRS-2792:  Shutdown of Cluster Ready Services-managed resources on 'srv2' has completed
CRS-2677:  Stop of 'ora.crsd' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.ctssd' on 'srv1'
.
.
.
CRS-2673:  Attempting to stop 'ora.asm' on 'srv2'
CRS-2677:  Stop of 'ora.ctssd' on 'srv1' succeeded
CRS-2677:  Stop of 'ora.evmd' on 'srv1' succeeded
CRS-2677:  Stop of 'ora.ctssd' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.evmd' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.asm' on 'srv2' succeeded
CRS-2673:  Attempting to stop 'ora.cluster_interconnect.haip' on 'srv2'
CRS-2677:  Stop of 'ora.cluster_interconnect.haip' on 'srv2' succeeded
CRS-2673:  Attempting to stop 'ora.cssd' on 'srv2'
CRS-2677:  Stop of 'ora.cssd' on 'srv2' succeeded
CRS-2677:  Stop of 'ora.asm' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.cluster_interconnect.haip' on 'srv1'
CRS-2677:  Stop of 'ora.cluster_interconnect.haip' on 'srv1' succeeded
CRS-2673:  Attempting to stop 'ora.cssd' on 'srv1'
CRS-2677:  Stop of 'ora.cssd' on 'srv1' succeeded

Sessão B:

Wed Oct 19 18:48:10 2016
Shutting down instance (abort)
License high water mark = 7
Wed Oct 19 18:48:10 2016
USER (ospid: 20293): terminating the instance
Wed Oct 19 18:48:11 2016
Instance terminated by USER, pid = 20293
Wed Oct 19 18:48:11 2016
Instance shutdown complete

Exemplo 2

Sessão A:

[oracle@srv1 ~]$ sqlplus / as sysdba
SQL*Plus: Release 12.1.0.2.0 Production on  Wed Oct 19 19:08:18 2016
Copyright (c) 1982, 2014, Oracle.  All rights reserved.
 
Connected to:
Oracle Database 12c Enterprise Edition  Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application  Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application  Testing options
SQL> shutdown abort;  
ORACLE instance shut down. 
 SQL>

Sessão B:

Wed Oct 19 19:08:25 2016
Shutting down instance (abort)
License high water mark = 7
Wed Oct 19 19:08:25 2016
USER (ospid: 8014): terminating the instance
Wed Oct 19 19:08:26 2016
Instance terminated by USER, pid = 8014
Wed Oct 19 19:08:26  2016
Instance shutdown  complete

Obs: Apesar do procedimento do exemplo 2 ter sido executado num banco de dados em cluster o cenário apresentado é exatamente o mesmo num banco de dados single instance.

Agora que vimos alguns exemplos de shutdown vamos ver o que acontece por trás do shutdown abort habilitando um trace do sistema operacional (strace) em alguns processos do Oracle e também um trace com o oradebug nos mesmos processos através do próprio banco de dados.

Elapsed:  00:00:00.02  
12:45:28  SQL> ORADEBUG SETORAPID 2; 
 Oracle  pid: 2, Unix process pid: 4549, image: oracle@manchester.localdomain (PMON) 
 12:52:38  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
  Statement  processed.  
  12:52:42  SQL> ORADEBUG TRACEFILE_NAME; 
  /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_pmon_4549.trc  
  12:52:46  SQL> ORADEBUG SETORAPID 12;  
  Oracle  pid: 12, Unix process pid: 4571, image: oracle@manchester.localdomain (DBW0) 
  12:52:49  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12; 
  Statement  processed. 
  12:52:52  SQL> ORADEBUG TRACEFILE_NAME;
  /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_dbw0_4571.trc  
  12:52:56  SQL> ORADEBUG SETORAPID 13; 
  Oracle  pid: 13, Unix process pid: 4573, image: oracle@manchester.localdomain (LGWR) 
  12:52:59  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;  
  Statement  processed.  
  12:53:02  SQL> ORADEBUG TRACEFILE_NAME; 
  /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_lgwr_4573.trc  
  12:53:05  SQL> ORADEBUG SETORAPID 14;  
  Oracle  pid: 14, Unix process pid: 4575, image: oracle@manchester.localdomain (CKPT) 
  12:53:08  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12; 
  Statement  processed.  12:53:11  
  SQL> ORADEBUG TRACEFILE_NAME; 
  /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_ckpt_4575.trc 
  12:53:14 SQL> ORADEBUG SETORAPID 15;  
  Oracle  pid: 15, Unix process pid: 4577, image: oracle@manchester.localdomain (SMON) 
  12:53:17  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
  Statement  processed.  12:53:20  SQL> ORADEBUG TRACEFILE_NAME;
  /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_smon_4577.trc 
  12:53:24 SQL>

Vamos habilitar o strace nos background process no Linux.

strace  -t -p 4549 -o pmon_trace.txt
strace  -t -p 4577 -o smon_trace.txt
strace  -t -p 4571 -o dbwr_trace.txt
strace  -t -p 4573 -o lgwr_trace.txt
strace  -t -p 4575 -o ckpt_trace.txt
12:54:30  SQL>  
12:54:30  SQL> 
 shutdown abort;  
 ORACLE  instance shut down. 
 12:54:35 SQL>

Ok, agora que nossa instância foi derrubada às 12:54:35, vamos olhar os logs e verificar o que ocorreu de fato entre 12:54:30 e 12:54:35, que foi o tempo da execução do comando até o retorno do prompt.

[root@manchester  ~]# tail lgwr_trace.txt
12:54:30  write(9, "\n", 1)               = 1
12:54:30  semctl(1146882, 43, SETVAL, 0x1) = 0
12:54:30  times(NULL)                    =  429979045
12:54:30  semtimedop(1146882, {{17, -1, 0}}, 1, {0, 540000000}) = 0
12:54:31  nanosleep({1, 0}, NULL)        = ?  ERESTART_RESTARTBLOCK (Interrupted by signal)
12:54:31 --- SIGTERM {si_signo=SIGTERM,  si_code=SI_TKILL, si_pid=4601, si_uid=54321} ---
12:54:31  rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:54:31  rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
12:54:31 exit_group(0)                  = ?
12:54:31 +++ exited with 0 +++
[root@manchester  ~]# tail smon_trace.txt
12:54:21  semtimedop(1146882, {{19, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily  unavailable)
12:54:24  semtimedop(1146882, {{19, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily  unavailable)
12:54:27  semtimedop(1146882, {{19, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily  unavailable)
12:54:30  semtimedop(1146882, {{19, -1, 0}}, 1, {3, 0}) = 0
12:54:31  nanosleep({1, 0}, NULL)        = ?  ERESTART_RESTARTBLOCK (Interrupted by signal)
12:54:31 --- SIGTERM {si_signo=SIGTERM,  si_code=SI_TKILL, si_pid=4601, si_uid=54321} ---
12:54:31  rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:54:31  rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
12:54:31 exit_group(0)                  = ?
12:54:31 +++ exited with 0 +++
[root@manchester  ~]# tail ckpt_trace.txt
12:54:29  write(7, "WAIT #0: nam='control file seque"..., 102) = 102
12:54:29  write(7, "\n", 1)               = 1
12:54:29  times(NULL)                    =  429978905
12:54:29  semtimedop(1146882, {{18, -1, 0}}, 1, {3, 0}) = 0
12:54:31  nanosleep({1, 0}, NULL)        = ?  ERESTART_RESTARTBLOCK (Interrupted by signal)
12:54:31 --- SIGTERM {si_signo=SIGTERM,  si_code=SI_TKILL, si_pid=4601, si_uid=54321} ---
12:54:31  rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:54:31  rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
12:54:31 exit_group(0)                  = ?
12:54:31 +++ exited with 0 +++
[root@manchester  ~]# tail pmon_trace.txt
12:54:30  read(11, "4553 (ora_vktm_lab158) S 1 4553 "..., 999) = 355
12:54:30  close(11)                      = 0
12:54:30  times(NULL)                    =  429978995
12:54:30  semtimedop(1146882, {{6, -1, 0}}, 1, {3, 0}) = 0
12:54:31  nanosleep({1, 0}, NULL)        = ?  ERESTART_RESTARTBLOCK (Interrupted by signal)
12:54:31 --- SIGTERM {si_signo=SIGTERM,  si_code=SI_TKILL, si_pid=4601, si_uid=54321} ---
12:54:31  rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:54:31  rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
12:54:31 exit_group(0)                  = ?
12:54:31 +++ exited with 0 +++
[root@manchester  ~]# tail dbwr_trace.txt
12:54:28  getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 29000}, ru_stime={0, 27000},  ...}) = 0
12:54:28  times(NULL)                    =  429978801
12:54:28  times(NULL)                    =  429978801
12:54:28  semtimedop(1146882, {{16, -1, 0}}, 1, {3, 0}) = 0
12:54:31  nanosleep({1, 0}, NULL)        = ?  ERESTART_RESTARTBLOCK (Interrupted by signal)
12:54:31 --- SIGTERM {si_signo=SIGTERM,  si_code=SI_TKILL, si_pid=4601, si_uid=54321} ---
12:54:31  rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:54:31  rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
12:54:31 exit_group(0)                  = ?
12:54:31 +++ exited with 0 +++

Ok, percebemos que o shutdown abort foi iniciado às 12:54:30 e tivemos background process trabalhando até 12:54:31. Porém, o que eles estavam fazendo?

Observamos system calls de escrita (write) nos processos lgwr e ckpt e tivemos uma system call de leitura (read) no processo pmon. Outro fato, que inclusive é comum a todos estes processos analisados, é que houve uma saída normal e sem erros de todos os processos em suas finalizações (exited with 0).

PMON

root@manchester  ~]# tail /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_pmon_4549.trc
WAIT  #0: nam='pmon timer' ela= 2998821 duration=300 p2=0 p3=0 obj#=-1 tim=5113660106
***  2016-10-20 12:54:24.343
WAIT  #0: nam='pmon timer' ela= 2999683 duration=300 p2=0 p3=0 obj#=-1 tim=5116660113
***  2016-10-20 12:54:27.342
WAIT  #0: nam='pmon timer' ela= 2999517 duration=300 p2=0 p3=0 obj#=-1 tim=5119660110
*** 2016-10-20 12:54:30.342
WAIT  #0: nam='pmon timer' ela= 2999498 duration=300 p2=0 p3=0 obj#=-1 tim=5122660120

DBWR

[root@manchester  ~]# tail /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_dbw0_4571.trc
WAIT  #0: nam='rdbms ipc message' ela= 2999512 timeout=300 p2=0 p3=0 obj#=-1  tim=5111720098
***  2016-10-20 12:54:22.403
WAIT  #0: nam='rdbms ipc message' ela= 3000348 timeout=300 p2=0 p3=0 obj#=-1  tim=5114720869
***  2016-10-20 12:54:25.402
WAIT  #0: nam='rdbms ipc message' ela= 2998848 timeout=300 p2=0 p3=0 obj#=-1  tim=5117720103
***  2016-10-20 12:54:28.403
WAIT  #0: nam='rdbms ipc message' ela= 2999956 timeout=300 p2=0 p3=0 obj#=-1  tim=5120720443

LGWR

[root@manchester  ~]# tail /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_lgwr_4573.trc
WAIT  #0: nam='rdbms ipc message' ela= 2999898 timeout=300 p2=0 p3=0 obj#=-1  tim=5117702539
***  2016-10-20 12:54:28.384
WAIT  #0: nam='rdbms ipc message' ela= 2999128 timeout=300 p2=0 p3=0 obj#=-1  tim=5120702105
***  2016-10-20 12:54:30.836
WAIT  #0: nam='rdbms ipc message' ela= 2450695 timeout=300 p2=0 p3=0 obj#=-1  tim=5123153221
WAIT  #0: nam='log file parallel write' ela= 2158 files=1 blocks=3 requests=1 obj#=-1  tim=5123155588
WAIT  #0: nam='rdbms ipc message' ela= 6449 timeout=54 p2=0 p3=0 obj#=-1  tim=5123162224
WAIT  #0: nam='log file parallel write' ela= 1439 files=1 blocks=6 requests=1 obj#=-1  tim=5123163905

CKPT

[root@manchester  ~]# tail   /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_ckpt_4575.trc
***  2016-10-20 12:54:29.434
WAIT  #0: nam='rdbms ipc message' ela= 2999593 timeout=300 p2=0 p3=0 obj#=-1  tim=5121752108
WAIT  #0: nam='control file sequential read' ela= 59 file#=0 block#=1 blocks=1  obj#=-1 tim=5121752697
WAIT  #0: nam='control file sequential read' ela= 28 file#=0 block#=16 blocks=1  obj#=-1 tim=5121752840
WAIT  #0: nam='control file sequential read' ela= 27 file#=0 block#=18 blocks=1 obj#=-1  tim=5121752923
WAIT  #0: nam='control file sequential read' ela= 28 file#=0 block#=19 blocks=1  obj#=-1 tim=5121753007
WAIT  #0: nam='control file parallel write' ela= 3637 files=2 block#=3 requests=2  obj#=-1 tim=5121756754
WAIT  #0: nam='control file sequential read' ela= 48 file#=0 block#=1 blocks=1  obj#=-1 tim=5121757034
WAIT  #0: nam='control file sequential read' ela= 35 file#=0 block#=16 blocks=1  obj#=-1 tim=5121757191
WAIT  #0: nam='control file sequential read' ela= 33 file#=0 block#=18 blocks=1  obj#=-1 tim=5121757292
WAIT  #0: nam='control file sequential read' ela= 35 file#=0 block#=283 blocks=1  obj#=-1 tim=5121757396

SMON

[root@manchester  ~]# tail /u01/app/oracle/diag/rdbms/lab158/lab158/trace/lab158_smon_4577.trc
***  2016-10-20 12:53:24.092
Received  ORADEBUG command (#2) 'TRACEFILE_NAME' from process '4601'
***  2016-10-20 12:53:24.092
Finished  processing ORADEBUG command (#2) 'TRACEFILE_NAME'
WAIT  #0: nam='smon timer' ela= 3149187 sleep time=300 failed=0 p3=0 obj#=1391  tim=5056411314
***  2016-10-20 12:53:45.112
WAIT  #0: nam='smon timer' ela= 21018297 sleep time=300 failed=0 p3=0 obj#=1391  tim=5077429662

Nos traces gerados pelo oradebug observamos que o PMON e o LGWR têm atividades, o que mostra que durante o shutdown abort ainda existe atividade dos background processes. Observe sempre o horário 12:54:30 em diante, que foi o horário do nosso shutdown abort.

Vamos ver o que aconteceria se o mesmo cenário se repetisse, mas ao invés de um shutdown abort, a máquina sofresse um init 0 no sistema operacional.

Habilitamos os traces nos processos ckpt, pmon, lgwr, dbw0 e smon, tanto pelo banco de dados como pelo sistema operacional:

SQL> ORADEBUG SETORAPID 2;
Oracle pid: 2, Unix process pid: 1006, image:  oracle@oracle-srv.localdomain (PMON)
SQL> ORADEBUG EVENT 10046 TRACE NAME  CONTEXT FOREVER, LEVEL 12;
Statement processed.
SQL> ORADEBUG TRACEFILE_NAME;
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_pmon_1006.trc
SQL> ORADEBUG SETORAPID 12;
Oracle pid: 12, Unix process pid: 1028,  image: oracle@oracle-srv.localdomain (DBW0)
SQL> ORADEBUG EVENT 10046 TRACE NAME  CONTEXT FOREVER, LEVEL 12;
Statement processed.
SQL> ORADEBUG TRACEFILE_NAME;
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_dbw0_1028.trc
SQL> ORADEBUG SETORAPID 13;
Oracle pid: 13, Unix process pid: 1030,  image: oracle@oracle-srv.localdomain (LGWR)
SQL> ORADEBUG EVENT 10046 TRACE NAME  CONTEXT FOREVER, LEVEL 12;
Statement processed.
SQL>   ORADEBUG TRACEFILE_NAME;
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_lgwr_1030.trc
SQL> ORADEBUG SETORAPID 14;
Oracle pid: 14, Unix process pid: 1032,  image: oracle@oracle-srv.localdomain (CKPT)
SQL> ORADEBUG EVENT 10046 TRACE NAME  CONTEXT FOREVER, LEVEL 12;
Statement processed.
SQL> ORADEBUG TRACEFILE_NAME;
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ckpt_1032.trc
SQL> ORADEBUG SETORAPID 16
Oracle pid: 16, Unix process pid: 1036,  image: oracle@oracle-srv.localdomain (SMON)
SQL> ORADEBUG EVENT 10046 TRACE NAME  CONTEXT FOREVER, LEVEL 12;
Statement processed.
SQL> ORADEBUG TRACEFILE_NAME;
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_smon_1036.trc
[oracle@oracle-srv ~]$ su -
Password:
Last login: Tue Oct 18 21:33:58 BRST 2016 on  pts/0
[root@oracle-srv ~]# strace -t -p 1006 -o  pmon_trace.txt &
[1] 1787
[root@oracle-srv ~]# strace -t -p 1036 -o  smon_trace.txt &
[2] 1788
[root@oracle-srv ~]# strace -t -p 1028 -o  dbwr_trace.txt &
[3] 1791
[root@oracle-srv ~]# strace -t -p 1030 -o  lgwr_trace.txt &
[4] 1792
[root@oracle-srv ~]# strace -t -p 1032 -o  ckpt_trace.txt &
[5] 1793
[root@oracle-srv ~]# Process 1036 attached
Process 1032 attached
Process 1030 attached
Process 1028 attached
Process 1006 attached
[root@oracle-srv ~]# jobs
[1]    Running                 strace -t  -p 1006 -o pmon_trace.txt &
[2]    Running                 strace -t -p 1036 -o  smon_trace.txt &
[3]    Running                 strace -t  -p 1028 -o dbwr_trace.txt &
[4]-   Running                 strace -t  -p 1030 -o lgwr_trace.txt &
[5]+   Running                 strace -t  -p 1032 -o ckpt_trace.txt &
[root@oracle-srv ~]# init 0
Connection to 192.168.2.128 closed by remote  host.
Connection to  192.168.2.128 closed.

Vamos ver o que acontece no startup da máquina olhando pelo /var/log/messages:

Oct 25 20:01:30 oracle-srv fprintd: **  Message: No devices in use, exit
Oct 25 20:03:21 oracle-srv systemd: Stopping  user-0.slice.
Oct 25 20:03:21 oracle-srv systemd: Removed  slice user-0.slice.
Oct 25 20:03:21 oracle-srv systemd: Stopping  Session 2 of user oracle.
Oct 25 20:03:21 oracle-srv systemd: Stopped  Session 2 of user oracle.
Oct 25 20:03:21 oracle-srv systemd: Stopping  Session 1 of user oracle.
Oct 25 20:03:21 oracle-srv systemd: Stopped  Session 1 of user oracle.
Oct 25 20:03:21 oracle-srv systemd: Stopping  user-54321.slice.
Oct 25 20:03:21 oracle-srv systemd: Removed  slice user-54321.slice.
Oct 25 20:03:21 oracle-srv systemd: Stopping  Manage Sound Card State (restore and store)...
Oct 25 20:03:21 oracle-srv systemd: Stopping  Dump dmesg to /var/log/dmesg...
Oct 25 20:03:21 oracle-srv systemd: Stopped  Dump dmesg to /var/log/dmesg.
Oct 25 20:03:21 oracle-srv systemd: Stopping  Multi-User System.
Oct 25 20:03:21 oracle-srv systemd: Stopped  target Multi-User System.
Oct 25 20:03:21 oracle-srv systemd: Stopping  ABRT kernel log watcher...
Oct 25 20:03:21 oracle-srv systemd: Stopping  Command Scheduler...
Oct 25 20:03:21 oracle-srv systemd: Stopping  ABRT Xorg log watcher...
Oct 25 20:03:21 oracle-srv systemd: Stopping  Install ABRT coredump hook...
Oct 25 20:03:21 oracle-srv systemd: Stopping  libstoragemgmt plug-in server daemon...
Oct 25 20:03:21 oracle-srv systemd: Stopping  Virtualization daemon...
Oct 25 20:03:21 oracle-srv rsyslogd: [origin  software="rsyslogd" swVersion="7.4.7" x-pid="503"  
x-info="http://www.rsyslog.com"] exiting on signal 15.
Oct 25 20:05:14 oracle-srv rsyslogd: [origin  software="rsyslogd" swVersion="7.4.7" x-pid="500"  
x-info="http://www.rsyslog.com"] start
Oct 25 20:05:06 oracle-srv journal: Runtime  journal is using 8.0M 
(max 100.1M, leaving 150.1M of free 993.2M, current limit  100.1M).
Oct 25 20:05:06 oracle-srv kernel:  Initializing cgroup subsys cpuset
Oct 25 20:05:06 oracle-srv kernel:  Initializing cgroup subsys cpu
Oct 25 20:05:06 oracle-srv kernel: Linux  version 3.8.13-55.1.6.el7uek.x86_64 (mockbuild@ca-build56.us.oracle.com) 
(gcc  version 4.8.3 20140911 (Red Hat 4.8.3-9) (GCC) ) #2 SMP Wed Feb 11 14:18:22 PST  2015

Observamos que a máquina foi desligada às 20:03:21 e foi religada às 20:05:14, então vamos ver o que foi gerado nos traces que fizemos:

strace

[root@oracle-srv ~]# tail pmon_trace.txt
20:03:18 semtimedop(98304, {{6, -1, 0}}, 1,  {3, 0}) = -1 EAGAIN (Resource temporarily unavailable)
20:03:21 times(NULL)                    = 429631669
20:03:21 write(9, "\n*** 2016-10-25  20:03:21.392\n", 29) = 29
20:03:21 lseek(9, 0, SEEK_CUR)          = 24199
20:03:21 write(9, "WAIT #0: nam='pmon  timer' ela= 2"..., 84) = 84
20:03:21 write(10, "J?+WqB~UK1\n",  11)  = 11
20:03:21 write(9, "\n", 1)              = 1
20:03:21 getrusage(0x1 /* RUSAGE_??? */,  {ru_utime={0, 79000}, ru_stime={0, 72000}, ...}) = 0
20:03:21 getrusage(0x1 /* RUSAGE_??? */,  {ru_utime={0, 79000}, ru_stime={0, 72000}, ...}) = 0
20:03:21 open("/proc/1010/stat",  O_RDONLY) = 11
20:03:21 read(11, "1010 (ora_vktm_orcl)  S 1 1010 10"..., 999) = 347
20:03:21 close(11)                      = 0
20:03:21 times(NULL)                    = 429631669
20:03:21 semtimedop(98304, {{6, -1, 0}}, 1,  {3, 0} <detached ...>
[root@oracle-srv ~]# tail smon_trace.txt
20:03:18 semtimedop(98304, {{20, -1, 0}}, 1,  {3, 0}) = -1 EAGAIN (Resource temporarily unavailable)
20:03:21 semtimedop(98304, {{20, -1, 0}}, 1,  {3, 0} <detached ...>
[root@oracle-srv ~]# tail dbwr_trace.txt
20:03:19 times(NULL)                    = 429631444
20:03:19 semtimedop(98304, {{16, -1, 0}}, 1,  {3, 0} <detached ...>
[root@oracle-srv ~]# tail lgwr_trace.txt
20:03:18 semtimedop(98304, {{17, -1, 0}}, 1,  {3, 0}) = -1 EAGAIN (Resource temporarily unavailable)
20:03:21 times(NULL)                    = 429631669
20:03:21 write(7, "\n*** 2016-10-25  20:03:21.392\n", 29) = 29
20:03:21 lseek(7, 0, SEEK_CUR)          = 25499
20:03:21 write(7, "WAIT #0: nam='rdbms  ipc message'"..., 90) = 90
20:03:21 write(8, "J?+WqB~UQ1\n",  11)   = 11
20:03:21 write(7, "\n", 1)              = 1
20:03:21 getrusage(0x1 /* RUSAGE_??? */,  {ru_utime={0, 97000}, ru_stime={0, 95000}, ...}) = 0
20:03:21 getrusage(0x1 /* RUSAGE_??? */,  {ru_utime={0, 97000}, ru_stime={0, 95000}, ...}) = 0
20:03:21 times(NULL)                    = 429631669
20:03:21 times(NULL)                    = 429631669
20:03:21 times(NULL)                    = 429631669
20:03:21 times(NULL)                    = 429631669
20:03:21 semtimedop(98304, {{17, -1, 0}}, 1,  {3, 0} <detached ...>
[root@oracle-srv ~]# tail ckpt_trace.txt

20:03:19 write(7, "\n", 1)              = 1

20:03:19 times(NULL)                    = 429631479

20:03:19 semtimedop(98304, {{18, -1, 0}}, 1,  {3, 0} <detached ...>

oradebug

[oracle@oracle-srv trace]$ tail  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_pmon_1006.trc
WAIT #0: nam='pmon timer' ela= 3000573  duration=300 p2=0 p3=0 obj#=-1 tim=1640181641
*** 2016-10-25 20:03:15.383
WAIT #0: nam='pmon timer' ela= 3210568  duration=300 p2=0 p3=0 obj#=-1 tim=1643392773
*** 2016-10-25 20:03:18.390
WAIT #0: nam='pmon timer' ela= 3006526  duration=300 p2=0 p3=0 obj#=-1 tim=1646400492
*** 2016-10-25 20:03:21.392
 WAIT #0: nam='pmon timer' ela= 2999759  duration=300 p2=0 p3=0 obj#=-1 tim=1649402113
[oracle@oracle-srv trace]$ tail  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_dbw0_1028.trc
WAIT #0: nam='rdbms ipc message' ela= 2999013  timeout=300 p2=0 p3=0 obj#=-1 tim=1638144432
*** 2016-10-25 20:03:13.136
WAIT #0: nam='rdbms ipc message' ela= 3001588  timeout=300 p2=0 p3=0 obj#=-1 tim=1641146485
*** 2016-10-25 20:03:16.138
WAIT #0: nam='rdbms ipc message' ela= 3000258  timeout=300 p2=0 p3=0 obj#=-1 tim=1644147187
*** 2016-10-25 20:03:19.139
WAIT #0: nam='rdbms ipc message' ela= 2999834  timeout=300 p2=0 p3=0 obj#=-1 tim=1647148949
[oracle@oracle-srv trace]$ tail  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_lgwr_1030.trc
WAIT #0: nam='rdbms ipc message' ela= 3001481  timeout=300 p2=0 p3=0 obj#=-1 tim=1640369222
*** 2016-10-25 20:03:15.383
WAIT #0: nam='rdbms ipc message' ela= 3022839  timeout=300 p2=0 p3=0 obj#=-1 tim=1643392697
*** 2016-10-25 20:03:18.391
WAIT #0: nam='rdbms ipc message' ela= 3006585  timeout=300 p2=0 p3=0 obj#=-1 tim=1646400527
*** 2016-10-25 20:03:21.392
WAIT #0: nam='rdbms ipc message' ela= 2999956  timeout=300 p2=0 p3=0 obj#=-1 tim=1649402140
[oracle@oracle-srv trace]$ tail  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ckpt_1032.trc
*** 2016-10-25 20:03:19.215
WAIT #0: nam='rdbms ipc message' ela= 3000321  timeout=300 p2=0 p3=0 obj#=-1 tim=1647225218
WAIT #0: nam='control file sequential read'  ela= 43 file#=0 block#=1 blocks=1 obj#=-1 tim=1647225700
WAIT #0: nam='control file sequential read'  ela= 32 file#=0 block#=15 blocks=1 obj#=-1 tim=1647225848
WAIT #0: nam='control file sequential read'  ela= 31 file#=0 block#=17 blocks=1 obj#=-1 tim=1647225940
WAIT #0: nam='control file sequential read'  ela= 30 file#=0 block#=19 blocks=1 obj#=-1 tim=1647226032
WAIT #0: nam='control file parallel write'  ela= 276560 files=2 block#=3 requests=2 obj#=-1 tim=1647502667
WAIT #0: nam='control file sequential read'  ela= 44 file#=0 block#=1 blocks=1 obj#=-1 tim=1647502925
WAIT #0: nam='control file sequential read'  ela= 31 file#=0 block#=15 blocks=1 obj#=-1 tim=1647503071
WAIT #0: nam='control file sequential read'  ela= 32 file#=0 block#=17 blocks=1 obj#=-1 tim=1647503215
WAIT #0: nam='control file sequential read'  ela= 31 file#=0 block#=284 blocks=1 obj#=-1 tim=1647503311
[oracle@oracle-srv trace]$ tail  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_smon_1036.trc
*** 2016-10-25 19:59:11.405
Received ORADEBUG command (#2)  'TRACEFILE_NAME' from process '1582'
*** 2016-10-25 19:59:11.405
Finished processing ORADEBUG command (#2)  'TRACEFILE_NAME'
WAIT #0: nam='smon timer' ela= 5303665 sleep  time=300 failed=0 p3=0 obj#=1391 tim=1399416743
*** 2016-10-25 20:01:27.013
WAIT #0: nam='smon timer' ela= 135605936  sleep time=300 failed=0 p3=0 obj#=1391 tim=1535022745

Através dos traces dos processos do sistema operacional usando o strace conseguimos observar um comportamento diferente em relação ao shutdown abort. Desta vez os processos não se encerraram e sim abandonaram a execução sem gerar nada nos traces. Num desligamento por falta de energia seria ainda pior, pois o sistema operacional nem seria avisado da queda.

Com estes cenários pudemos observar que o shutdown abort é realmente mais seguro do que desligar o servidor da tomada e tão seguro quanto um shutdown immediate e em alguns cenários é até mais eficiente. Quando ocorre, o banco de dados é desligado de maneira inconsistente, portanto, lembre-se de que ele precisará fazer o recovery quando iniciar, então para minimizar o tempo de recovery você pode configurar o parâmetro fast_start_mttr_target, mas antes de sair configurando estude a respeito.

Esperamos ter esclarecido alguns pontos e que este artigo seja realmente útil para a comunidade.

Referências http://docs.oracle.com/database/121/ADMIN/start.htm#ADMIN004

Franky Weber Faust, atua como administrador de banco de dados Oracle e MySQL no PagSeguro, tem 26 anos, é graduado em Tecnologia em Bancos de Dados e iniciou sua carreira trabalhando num projeto internacional da Volkswagen com os bancos de dados DB2 da IBM, SQL Server da Microsoft e também com o Oracle e desde o início direcionou seus estudos para as tecnologias Oracle. É especialista em tecnologias de Alta Disponibilidade como RAC, Dataguard e GoldenGate e compartilha seus conhecimentos no blog loredata.com.br. Possui as certificações OCE SQL, OCA 11g, OCP 12c, OCS RAC 12c e OCS Linux 6.

Gabriel Comenale, formado em banco de dados pela FIAP possui 6 anos de experiência na área de tecnologia trabalhando com ambientes de pequeno, médio e grande porte nas plataformas Linux e Windows de segmentos variados de clientes como Odebrecht, Livraria Cultura, AES Eletropaulo, Renner, Sindicato dos Comerciários, Tigre – Tubos e Conexões, Unimed Seguros, Fidelity Investments, Alelo, AIG Seguros entre outros. Possui as certificações OCA 11g e ITIL V3 além de já ter ministrado treinamentos em banco de dados Oracle.

Este artigo foi revisto pela equipe de produtos Oracle e está em conformidade com as normas e práticas para o uso de produtos Oracle.