Oracle Golden Gate  – Replicat parece travado durante resync

Olá DBAs, a vida tá boa?

E não é que finalmente temos um post não relacionado ao Windows? Pois é! Passei por uma situação estes dias que de início me deixou um pouco confuso, mas depois teve seu desenrolar na normalidade conforme conto a vocês a seguir.

Um dos clientes que trabalho, tem replicação unidirecional de sua base de produção para 3 outros servidores via GoldenGate. Estes 3 servidores ajudam no recebimento de visualizações dos dados, e quando transações são exigidas, a aplicação envia para o servidor de produção e faz a alteração lá. Não vou entrar em detalhes da arquitetura de funcionamento da aplicação, mas do lado dos bancos de dados, temos a seguinte arquitetura no macro:

Neste caso também não vou entrar no mérito de versões e afins, pois não são inerentes ao que quero mostrar no final, mas a título de informação saibam que os bancos são 11G e o GG é 12c.

Após uma falha de disco no GGDB1, disco este onde se encontravam os binários, tivemos a recuperação do mesmo após 14 dias. Não retivemos os trailfiles do período que estivessem fora da política de retenção, que é de 7 dias no nosso caso, sendo assim, foi necessário fazer o resync do database com os dados de produção.

Para tal, procedimento padrão:

1 – Exportação de produção com o SCN do momento;

2 – Transferencia do dump para o servidor destino;

3 – Importação dos dados no database destino;

4 – Início do replicat com o CSN apontando ao SCN usado para a exportação.

Simples e rasteiro. Segui todo o procedimento como de costume. Levamos uns 2 dias para terminar tudo até o passo 3, era o momento então de iniciar o passo 4.

oracle@GGserver01 1> start rep db1, atcsn 7893239546
replicat db1 started...

Excelente!!! Vamos checar como está o lag e o chekpoint neste momento:

GGSCI (GGserver01) 1> info all 
 
Program     Status      Group     Lag at Chkpt     Time Since Chkpt
 
MANAGER     RUNNING
REPLICAT    RUNNING     DB1       168:30:06        00:00:02

Bom, meu lag ainda consta como de 17 dias atrás, mas eu já fiz um checkpoint do processo. Acreditei que logo ao iniciar o processo de replicat, essa informação seria corrigida e eu voltaria a ver o lag normal, que deveria ser de 3 dias (ponto do CSN definido) e não de 17 como demonstrado.

Como de costume, eu havia iniciado um comando tail no log do GoldenGate. Todo o processo de start ocorreu normalmente, mas o log estava simplesmente parado, sem inserção de novas informações. Após uns 5 mins, log parado, mais uma verificação de dentro do GG:

GGSCI (GGserver01) 1> info all 
 
Program     Status      Group     Lag at Chkpt     Time Since Chkpt
 
MANAGER     RUNNING
REPLICAT    RUNNING     DB1       168:36:20        00:00:02

Meu tempo no lag estava aumentando, com o processo rodando com sucesso, mas log inativo e sem informações.

Como poderia não haver nenhum tipo de erro?

O processo estava realmente se movendo?

Havia algum bloqueio?

Comecei checar no database a procura de bloqueios ou algo do tipo e nada me parecia fora do normal. O que me deixou mais confuso ainda. Foi aí que decidi fazer algo básico e simples que eu deveria ter feito desde o começo: Checar pelo próprio console do GoldenGate o replicat, com mais detalhes do que só pelas informações gerais.

E foi o que fiz:

GGSCI (GGserver01) 1> info rep db1

REPLICAT   DB1       Last Started 2024-31-07 07:30   Status RUNNING
COORDINATED          Coordinator                      MAXTHREADS 15
Checkpoint Lag       408:50:20 (updated 00:00:07 ago)
Process ID           11445
Log Read Checkpoint  File ./dirdat/gg003856
                     2024-07-24 07:49:45.975662  RBA 44704

Agora eu tinha a informação do qual trailfile stava sendo lido, excelente. Vejam que é um trailfile antigo, de antes da data do meu CSN. Era um dos trailfiles mais antigos que eu tinha no diretório de 7 dias atrás.

Espera! Se ele está lendo um dos trailfiles mais antigos, será que está parado? Vamos esperar mais uns minutos e executar novamente o pedido de informação.

GGSCI (GGserver01) 1> info rep db1

REPLICAT   DB1       Last Started 2024-31-07 07:30   Status RUNNING
COORDINATED          Coordinator                      MAXTHREADS 15
Checkpoint Lag       408:56:10 (updated 00:00:07 ago)
Process ID           11445
Log Read Checkpoint  File ./dirdat/gg003858
                     2024-07-24 09:30:40.912865  RBA 47809

Vejam que neste momento eu estou em um diferente trailfile, adiante do anterior, apesar do meu log ainda estar totalmente parado como se não houvesse atividade.

O que isso significa?

Em resumo, ao iniciar o meu processo do replicat definido por um CSN, meu replicat ainda não sabe onde está este CSN, ou seja, não sabe em qual trailfile eu tenho esse determinado ponto no tempo, sendo assim, ele vai ler todos os trailfiles que eu tenha gravados no respositório até encontrar o certo, que contenha o CSN pedido no momento do start do meu replicat.

O processo não está parado, ele está fazendo a varredura sequencial nos trailfiles, para que possa então iniciar as transações justamente no CSN que foi solicitado.

Se voce continuar acompanhando o processo pelo “info rep”, perceberá algumas características:

– Os trailfiles continuam avançando;

– O tempo de lag continua aumentando.

O tempo de lag continua aumentando, pois o tempo continua passando e o sicronismo continua se distanciando, e isso acontecerá até o momento em que o processo encontrar o trailfile correto e comece então a aplicar as transações devidas.

Continuei monitorando, e algumas horas depois, o log começou a receber informações e o cenário era o seguinte:

GGSCI (GGserver01) 1> info rep db1

REPLICAT   DB1       Last Started 2024-31-07 07:30   Status RUNNING
COORDINATED          Coordinator                      MAXTHREADS 15
Checkpoint Lag       71:02:18 (updated 00:00:03 ago)
Process ID           11445
Log Read Checkpoint  File ./dirdat/gg004025
                     2024-07-28 15:42:40.9178544  RBA 50365

Neste momento o processo já havia encontrado um dos primeiros trailfiles que continham o CSN solicitado, e só então começou a transacionar dentro do banco destino. Percebam que foi então que meu checkpoint avançou e passou a apontar para 3 dias atrás, só então também ele começou a decrescer.

Algumas horas depois meu processo estava concluído e o sincronismo estava feito já aplicando as alterações em tempo real:

GGSCI (GGserver01) 1> info all 
 
Program     Status      Group     Lag at Chkpt     Time Since Chkpt
 
MANAGER     RUNNING
REPLICAT    RUNNING     DB1       00:00:10        00:00:02

Finalizando, sempre que for necessário recuperar o sincronismo após vários dias, o início do processo do replicat fará a varredura em todos os trailfiles existentes no diretório procurando pelo CSN solicitado no start. Durante este processo, seu log do Goldegate estará parado, sem inserção de novas informações, seu checkpoint lag estará ainda em uma crescente, o banco não demonstrará sinais de problema e voce poderá sim ser ludibriado achando que tem algo errado, mas não. Verifique os detalhes do processo utlizando o “info rep” para checar o andamento e saber que ele realmente está trabalhando (Mas em modo furtivo 😊).

Fiquem a vontade para fazer quaisquer pontuações caso já tenham vivenciado algo do tipo.

Essa é a dica 0800 pra vocês desta vez.

“Saber das coisas vale ouro. Compartilhar esse conhecimento não tem preço.”