Olá DBAs, a vida tá boa?
Hoje vou mostrar para voces como fazer um caso interessante que me acometeu esta semana, durante um trabalho de migração entre servers e upgrade de 12c para 19c.
Existem diversos outros artigos em blogs falando sobre migrações e upgrades, então este não será o foco neste artigo, mas sim do problema que enfrentei pós upgrade.
Para referencia, seguem informações básicas sobre origem e destino:
Origem:
| Sistema Operacional | Windows Server 2012 R2 |
| Versão Database | 12.1.0.2.0 |
Destino:
| Sistema Operacional | Windows Server 2022 Standard |
| Versão Database | 19.3 Base Release |
*Sim, existem motivos para não haverem os patches aplicados tanto em origem quanto em destino, e este também não é o foco deste artigo.
Vamos ao que interessa.
Desde que se trata de arquitetura multitenant, o método de migração utilizado foi plugar o database 12c do antigo servidor no database 19c do novo servidor, realizar o upgrade e abrir o mesmo. Para tal, como essa fase era de exercício e não da migração em si, um backup frio foi executado na base de origem, copiado para o novo server, o xml foi restaurado pelo pacote “DBMS_PDB.RECOVER” e então o plugin foi realizado no novo container 19c.
Trabalho executado. Foram 12 horas de trabalho de uma Sexta pra Sábado, incluindo a criação do ambiente de DataGuard para este database em 19c após o plugin do PDB.
Fazendo uma checagem um dia depois, verifiquei o alert do banco de dados novo sendo bombardeado pelo seguinte erro:
2023-10-02T15:31:06.730230-05:00 PDBPROD(3):Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_17088.trc: ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], [] 2023-10-02T15:31:08.237559-05:00 Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_17088.trc (incident=341812) (PDBNAME=CDB$ROOT): ORA-00600: internal error code, arguments: [ktcSetActiveSession:pdb], [3], [1], [], [], [], [], [], [], [], [], [] ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], [] Use ADRCI or Support Workbench to package the incident. See Note 411.1 at My Oracle Support for error and packaging details. Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_17088.trc (incident=362104) (PDBNAME=CDB$ROOT): ORA-00603: ORACLE server session terminated by fatal error ORA-00600: internal error code, arguments: [ktcSetActiveSession:pdb], [3], [1], [], [], [], [], [], [], [], [], [] ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], [] 2023-10-02T15:31:08.331332-05:00 opidrv aborting process RECO ospid (17088) as a result of ORA-603 2023-10-02T15:35:02.761112-05:00 Restarting dead background process RECO Starting background process RECO 2023-10-02T15:35:02.792381-05:00 RECO started with pid=156, OS id=2428 2023-10-02T15:35:05.858349-05:00 Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_2428.trc (incident=362099) (PDBNAME=PDBPROD): ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], [] PDBPROD(3):Use ADRCI or Support Workbench to package the incident. See Note 411.1 at My Oracle Support for error and packaging details. 2023-10-02T15:35:05.873984-05:00
Alert.log relatando este erro de 4 em 4 minutos, aumentando o tamanho do arquivo e enchendo meu diretório de traces com arquivos de trace para o processo *reco*.
Assim que vi estes erros, o MOS(pra quem é velho como eu) virou meu melhor amigo, e as pesquisas começaram. Todos os artigos relatando erros de ORA-0600 [4000] eram assustadores, pois apontavam para um erro interno severo, que poderia causar uma quebra no banco a qualquer momento. Como por exemplo esse trecho do Doc ID 47456.1 (ORA-600 [4000] “trying to get dba of undo segment header block from usn”):
“DESCRIPTION:This has the potential to be a very serious error. It means that Oracle has tried to find an undo segment number in the dictionary cache and failed.
IMPACT: INSTANCE FAILURE – Instance will not restart, STATEMENT FAILURE“
Lendo este DOC, minha primeira suspeita apesar da versão listada no DOC não ser compatível, foi a alteração que fiz durante a migração de undo compartilhada para undo local , mas ao pensar mais um pouco, descartei a ideia pois eu executei um backup frio para a migração e não haveriam informações de transação remanescentes na UNDO tablespace após o shutdown.
Continuei a pesquisa e o que mais se encaixava para o meu caso era o Doc ID 33343993.8 (Bug 33343993 – Convert ORA-600 [4000] to PDB Specific Assert and Crash Only the Affected PDB) contendo as seguintes informações resumidamente:
“Bug 33343993 Convert ORA-600 [4000] to PDB Specific Assert and Crash Only the Affected PDB” Description There have been outages where a fatal background process like PMON/CLMN while trying to perform dead process recovery for a PDB, ORA-600 [4000] assert got fired and the instance was terminated. With this fix, we will force close the affected PDB by converting ORA-600 [4000]into a PDB assert. REDISCOVERY INFORMATION: ORA-600 [4000] in a fatal background in a PDB causes instance crash. WORKAROUND: NONE
Bom, o erro poderia causar crash da instancia e não existia medida de contorno para tal a não ser aplicar o patch (o último patch 19.20 de Julho de 2023 cobria ess bug).
Dica rápida: Utilize o ORAdiff (https://oradiff.oracle.com) para análisar a cobertura dos patches. Ferramenta rápida, com método de localização de bugs e mais.
Neste ponto era hora de falar com o cliente e dizer que apesar de ele não querer, seríamos obrigado a aplicar o patch pois existia o risco do database ter um problema generalizado após levarmos para produção, etc, etc, etc…
* Mais uma vez reforço que eu entendo o valor e a necessidade de aplicarmos os patches, mas nem sempre as coisas são como recomendamos ao cliente.
Daí em diante começaram as reuniões do cliente com o time global, para definirem a ordem de aplicação dos patches nos lower environments, assim como o período de testes e etc, o que com certeza impactaria na data prevista do go-live. Enquanto começaram a se desencadear estas reuniões e definições, decidi deixar um pouco de lado o suporte da Oracle e começar a investigar mais a fundo o problema por mim mesmo, a começar pelos logs gerados pelos erros. Decidi ler um dos *reco* logs (prod_reco_12345.trc) totalmente em busca de pistas, como de costume verifiquei mais atentamente o início e o final do mesmo, e no final encontrei a seguinte informação:
===== Data Guard Broker request completed ===== *** 2023-10-02T14:27:03.407149-05:00 2023-10-02T14:27:03.407149-05:00 Incident 361968 created, dump file: H:\APP\diag\rdbms\prod_22\prod\incident\incdir_361968\prod_reco_18116_i361968.trc ORA-00600: internal error code, arguments: [ktcSetActiveSession:pdb], [3], [1], [], [], [], [], [], [], [], [], [] ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], []
“Data Guard Broker request completed”, era um sinal claro de que havia algo relacionado ao DG. Comecei a olhar mais logs *reco* e encontrei a mesma informação em todos. Voltei ao primeiro deles pra fazer uma varredura, e encontrei as seguintes informações em determinados pontos:
… ObjectName: Name=select us#, inc#, tsn, file#, block#, crscnwrp, crscnbas, drscnwrp, drscnbas, crttime, drptime, name, user#, scnwrp, scnbas, xactsqn, undosqn, inst#, flags1 from undohist$ order by us# asc, inc# asc … ObjectName: Name=select us#, name, file#, block#, status$, user#, undosqn, xactsqn, scnbas, scnwrp, inst#, ts#, spare1 from undo$ … ObjectName: Name=select sub_session_id, interface, dbid, link_owner, dblink, branch_id from pending_sub_sessions$ where local_tran_id = :1 and session_id = :2 … ObjectName: Name=select session_id, branch_id, interface, parent_dbid, type#, db_userid from pending_sessions$ where local_tran_id = :1 … ObjectName: Name=select local_tran_id, global_tran_fmt, global_oracle_id, global_foreign_id, state, status, heuristic_dflt, session_vector, reco_vector, 3600*24*(sysdate-reco_time), 3600*24*(sysdate-nvl(heuristic_time,fail_time)), global_commit#, type# from pending_trans$ where session_vector != '00000000' …
Bom, haviam selects sendo feitos em views referentes a undo e também a transações pendentes.
Interessante!!!
Decidi executar estas consultas eu mesmo no banco de dados e ver o que elas me retornavam, e nas consultas de transações pendentes dentro do PDB, qual não foi minha surpresa ao verificar o seguinte:
SQL> select session_id, branch_id, interface, parent_dbid, type#, db_userid from pending_sessions$ ;
SESSION_ID BRANCH_ID I PARENT_DBID TYPE# DB_USERID
---------- ------------ ---------------- ---------- ----------
1 0000 N 0 136
SQL> select local_tran_id, global_tran_fmt, global_oracle_id, global_foreign_id, state, status, heuristic_dflt, session_vector, reco_vector, 3600*24*(sysdate-reco_time), 3600*24*(sysdate-nvl(heuristic_time,fail_time)), global_commit#, type# from pending_trans$ where session_vector != '00000000' ;
LOCAL_TRAN_ID GLOBAL_TRAN_FMT GLOBAL_ORACLE_ID GLOBAL_FOREIGN_ID STATE S H SESSION_ RECO_VEC 3600*24*(SYSDATE-RECO_TIME) 3600*24*(SYSDATE-NVL(HEURISTIC_TIME,FAIL_TIME)) GLOBAL_COMMIT# TYPE#
---------------------- --------------- ---------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------- ---------------- - - -------- -------- --------------------------- ----------------------------------------------- ---------------- ----------
13.19.6824 306206 PDBPROD.dc4812bc.13.19.6824 collecting P 00000001 00000001 1102458 231962254 92959660978 0
SQL> select
2 local_tran_id,
3 global_tran_id,
4 state,
5 mixed
6 from
7 dba_2pc_pending;
LOCAL_TRAN_ID GLOBAL_TRAN_ID STATE MIX
---------------------- ------------------ ---------------- ---
13.19.6824 PDBPROD.dc4812bc.13.19.6824 collecting no
SQL> select * from dba_2pc_pending;
LOCAL_TRAN_ID GLOBAL_TRAN_ID STATE MIX FAIL_TIME
RETRY_TIME OS_USER OS_TERMINAL HOST DB_USER
---------------------- ------------------- ------ --- -------------------------- ------------------- ------------------- ------------------- ---------------------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------
13.19.6824 PDBPROD.dc4812bc.13.19.6824 collecting no 05/26/2016 21:32:31 09/19/2023 21:15:47 BR\CLIENTPROD22 CLIENTEPROD\PROD22 CLIENTE
Percebam que havia uma remanescencia de transação distribuída(2pc) perdida no PDB, que falhou em 2016 e teve sua ultima tentativa de execução dias antes do meu exercício de migração/upgrade.
Não fazia o menor sentido (e ainda não faz), pois ao realizar um shutdown limpo no database todas as pendencias são resolvidas, principalmente as transações. Pensei em várias possibilidades e conversei com algumas pessoas, e pra nenhuma delas fazia o menor sentido essa transação estar pendente no banco. O banco de origem já foi reiniciado várias vezes desde 2016, e mesmo após shutdown/startup, a transação 13.19.6824 continuou lá, sem nenhuma sessão vinculada, sem nenhuma outra informação vinculada e no caso do banco de origem, sem a geração do erro ORA-0600 no alertlog. Era uma transação totalmente orfã e eu nunca havia visto este comportamento.
Faria todo o sentido esta transação estar pipocando os erros que eu estava recebendo no alert log, afinal, o processo de reco para o Dataguard estava buscando por estas informações para replicar, mesmo sem nenhum vínculo a nenhuma sessão, mas os redolog online já tinham a sinalização de uma transação não finalizada.
Para creditar o erro ORA-0600 a esta sessão orfã, eu deveria limpar essa transação e verificar o comportamento dos logs a partir de então, e fi o que fiz:
SQL> begin 2 dbms_transaction.purge_lost_db_entry(xid => '13.19.6824'); 3 end; 4 / PL/SQL procedure successfully completed. SQL> select * from dba_2pc_pending; no rows selected SQL> select 2 local_tran_id, 3 global_tran_id, 4 state, 5 mixed 6 from 7 dba_2pc_pending; no rows selected
Após fazer o purge da transação, era hora de monitorar o alert log e a geração de trace files para o processo *reco*.
Eu havia pego um erro exatamente as 15:47 como abaixo:
PDBPROD(3):Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_11472.trc: ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], [] 2023-10-02T15:47:09.388607-05:00 Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_11472.trc (incident=362109) (PDBNAME=CDB$ROOT): ORA-00600: internal error code, arguments: [ktcSetActiveSession:pdb], [3], [1], [], [], [], [], [], [], [], [], [] ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], [] Use ADRCI or Support Workbench to package the incident. See Note 411.1 at My Oracle Support for error and packaging details. Errors in file H:\APP\diag\rdbms\prod_22\prod\trace\prod_reco_11472.trc (incident=362122) (PDBNAME=CDB$ROOT): ORA-00603: ORACLE server session terminated by fatal error ORA-00600: internal error code, arguments: [ktcSetActiveSession:pdb], [3], [1], [], [], [], [], [], [], [], [], [] ORA-00600: internal error code, arguments: [4000], [13], [1], [1], [], [], [], [], [], [], [], []
Executei o comando de purge as 15:49 e… Adivinhem… os erros pararam. Realmente esta transação pendente (contra toda e qualquer estatística pois foi herdade de um banco via backup frio) era a causadora do ORA-0600[4000].
Eu havia encontrado informações inicialmente sobre este problema no Doc ID 2309826.1 (ORA-00600: [4097]/ ORA-00600: [4000] on RECO background after converting NON_CDB to PDB) mas também descartei essa informação desde que se tratava de um backup frio, e em teoria não haveria a menor possibilidade de haver uma transação pendente em um cenário como este.
Sendo assim, compartilho aqui minha experiencia de algo que até então para mim era inimaginável em um ambiente pós shutdown, mas que esta situação mostrou que eu estava enganado, e a partir de agora a lição é não ignorar situações e casos mesmo que estes caminhem de encontro a noção geral de arquitetura do BD.
Fiquem a vontade para fazer quaisquer pontuações caso já tenham vivenciado algo do tipo.
Essa é a dica 0800 pra voces desta vez.
“Saber das coisas vale ouro. Compartilhar esse conhecimento não tem preço.”
Seguem referencias:
ORA-600 [4000] “trying to get dba of undo segment header block from usn” (Doc ID 47456.1)
ORA-00600: [4097]/ ORA-00600: [4000] on RECO background after converting NON_CDB to PDB (Doc ID 2309826.1)
