Para melhor visualização, recomendo resolução de no mínimo 1280 x 800 e navegador Mozilla Firefox


terça-feira, 23 de maio de 2017

Monitorando alternâncias do redo log online no Oracle (Redo Log Switch Frequency)

Por Eduardo Legatti

Olá,

Uma situação que pode acontecer em um ambiente de banco de dados Oracle é o aumento expressivo no número de dados de "redo" gerados pelo aumento do número de transações ao longo do tempo ou até mesmo por alguma operação isolada. A consequência imediata no número de transações que afetam grandes quantidades de dados é o número excessivo de "redo log switches" ou alternâncias de log gerados um curto espaço de tempo. Em ambientes Oracle que operam em modo ARCHIVELOG a geração excessiva de archive logs por conta de várias operações de alternâncias de log em um curto espaço de tempo pode ocasionar problemas como: espaço livre em disco, tempo de backup, entre outros. Portanto, é importante monitorar a quantidade de redo log switches ocorridas na última hora. Vale a pena salientar que o tamanho do arquivo de redo log online influencia na quantidade de alternâncias de log realizadas.

O cenário abaixo ocorreu em um ambiente de banco de dados com redo log de tamanho de 50 MB no qual o padrão era gerar em média 23 alternância de log por dia, ou seja, cerca de uma alternância por hora. No entanto, foi detectado que a partir do dia 09/05 às 11:00 hs, conforme resultado da consulta abaixo, as operações de redo log switches aumentaram drasticamente gerando cerca de 770 alternâncias por dia. O impacto disso foi um aumento significativo de archive logs gerados, consumindo espaço extra na flash recovery area. Uma vez detectado o problema, foi averiguado que a aplicação tinha sido configurada para fazer mais coisas do que deveria e que, a partir do dia 21/05 às 16:00 hs, as operações de alternância de redo log foram reduzidas significativamente.

SQL> select to_char(first_time,'DD/MM/YYYY') day,
  2  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'00',1,0)),'999') "00",
  3  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'01',1,0)),'999') "01",
  4  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'02',1,0)),'999') "02",
  5  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'03',1,0)),'999') "03",
  6  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'04',1,0)),'999') "04",
  7  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'05',1,0)),'999') "05",
  8  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'06',1,0)),'999') "06",
  9  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'07',1,0)),'999') "07",
 10  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'08',1,0)),'999') "08",
 11  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'09',1,0)),'999') "09",
 12  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'10',1,0)),'999') "10",
 13  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'11',1,0)),'999') "11",
 14  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'12',1,0)),'999') "12",
 15  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'13',1,0)),'999') "13",
 16  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'14',1,0)),'999') "14",
 17  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'15',1,0)),'999') "15",
 18  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'16',1,0)),'999') "16",
 19  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'17',1,0)),'999') "17",
 20  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'18',1,0)),'999') "18",
 21  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'19',1,0)),'999') "19",
 22  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'20',1,0)),'999') "20",
 23  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'21',1,0)),'999') "21",
 24  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'22',1,0)),'999') "22",
 25  to_char(sum(decode(substr(to_char(first_time,'HH24'),1,2),'23',1,0)),'999') "23",
 26  sum(1) "TOTAL_IN_DAY"
 27  from v$log_history
 28  group by to_char(first_time,'DD/MM/YYYY')
 29  order by to_date(day) desc;

DAY        00   01   02   03   04   05   06   07   08   09   10   11   12   13   14   15   16   17   18   19   20   21   22   23   TOTAL_IN_DAY
---------- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ------------
21/05/2017   32   32   33   32   34   33   34   32   33   32   32   32   33   31   32   33    5    4    2    0    0    0    0    0          531
20/05/2017   32   32   32   33   33   33   34   33   32   32   35   32   32   33   32   33   32   33   32   32   32   32   33   32          781
19/05/2017   33   32   33   32   32   32   34   33   32   32   34   32   32   32   31   33   32   32   32   34   33   32   33   32          779
18/05/2017   33   32   32   32   32   32   34   33   32   32   33   33   32   33   33   31   32   32   32   33   33   32   32   32          777
17/05/2017   33   32   33   32   33   32   34   32   32   33   32   32   33   32   32   33   32   32   33   32   32   32   33   32          778
16/05/2017   32   32   31   32   32   32   33   32   32   31   32   32   31   32   32   32   32   32   32   33   33   32   33   32          769
15/05/2017   31   32   30   32   33   32   34   31   32   31   33   31   31   32   31   33   32   32   31   32   32   31   34   31          764
14/05/2017   31   32   32   31   33   31   33   31   31   31   33   31   32   31   32   31   32   32   32   32   31   31   33   32          761
13/05/2017   31   31   31   32   31   32   33   32   31   32   32   32   32   31   31   32   32   30   32   31   32   32   33   31          759
12/05/2017   31   31   32   32   31   32   33   31   32   32   32   31   31   32   30   31   32   32   31   33   31   32   32   32          759
11/05/2017   32   31   32   31   32   31   35   31   31   31   34   31   30   31   33   31   32   31   32   32   31   32   33   31          761
10/05/2017   31   31   31   31   34   31   33   32   31   31   32   31   32   31   31   31   31   32   32   32   31   32   32   32          758
09/05/2017    0    1    0    1    2    1    2    1    1    0    2   30   32   32   32   32   32   31   32   32   31   32   34   31          424
08/05/2017    0    1    1    0    3    1    3    0    1    1    1    1    1    1    1    1    1    1    1    2    1    1    2    1           27
07/05/2017    0    1    1    0    3    1    3    0    1    1    1    1    1    1    1    1    1    1    1    2    0    1    2    1           26
06/05/2017    0    1    0    1    1    1    3    0    1    1    2    1    1    1    1    1    1    1    1    2    1    1    2    1           26
05/05/2017    0    1    0    1    0    1    3    1    0    1    2    0    1    0    1    0    1    1    0    3    0    1    1    2           21
04/05/2017    1    0    1    0    1    1    4    1    0    1    2    1    0    1    0    1    1    0    1    2    0    1    2    1           23
03/05/2017    0    1    1    0    3    1    3    1    0    1    2    1    1    1    1    1    1    1    0    2    1    1    2    1           27
02/05/2017    1    1    0    1    3    1    2    1    1    1    2    1    1    1    1    1    2    1    1    1    1    1    2    1           29
01/05/2017    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    1    1    2    1            5

21 linhas selecionadas.

Durante a análise, foi detectado que havia uma sessão no banco de dados que estava gerando mais dados de UNDO/REDO que as demais, conforme resultado da consulta abaixo.

SQL>   SELECT s.sid,
  2           s.serial#,
  3           s.username,
  4           s.program,
  5           t.used_ublk,
  6           t.used_urec
  7      FROM v$session s, v$transaction t
  8     WHERE s.taddr = t.addr
  9  ORDER BY 5 DESC, 6 DESC, 1, 2, 3, 4;

       SID    SERIAL# USERNAME            PROGRAM                USED_UBLK  USED_UREC
---------- ---------- ------------------- --------------------- ---------- ----------
       930      49433 SCOTT               JDBC Thin Client              88       6177
       633      53173 SCOTT               JDBC Thin Client              10        693
       250      58501 ADAM                JDBC Thin Client               9        692
        99      11223 ADAM                JDBC Thin Client               5        340
       851      51835 SCOTT               JDBC Thin Client               0          0

5 linhas selecionadas.

Outra consulta bastante útil é verificar a quantidade de "redo size" gerada para cada sessão no banco de dados.

SQL> SELECT s.sid,
  2         sn.SERIAL#,
  3         sn.username,
  4         n.name,
  5         ROUND (VALUE / 1024 / 1024, 2) redo_mb,
  6         sn.status,
  7         sn.TYPE
  8    FROM v$sesstat s
  9         JOIN v$statname n ON n.statistic# = s.statistic#
 10         JOIN v$session sn ON sn.sid = s.sid
 11   WHERE n.name LIKE 'redo size' AND s.VALUE <> 0
 12  ORDER BY redo_mb DESC;

       SID    SERIAL# USERNAME            NAME                    REDO_MB STATUS   TYPE
---------- ---------- ------------------- -------------------- ---------- -------- ----------
       848          1                     redo size               4397,06 ACTIVE   BACKGROUND
       771          1                     redo size               4367,24 ACTIVE   BACKGROUND
      1079          1                     redo size               2689,53 ACTIVE   BACKGROUND
       930      49433 SCOTT               redo size                838,87 INACTIVE USER
         8      18777 SCOTT               redo size                115,77 INACTIVE USER
       166      59825 SCOTT               redo size                172,59 INACTIVE USER
       707      52285 ADAM                redo size                141,95 INACTIVE USER
       622      34283 ADAM                redo size                139,28 INACTIVE USER
      1004      43893 ADAM                redo size                112,61 INACTIVE USER
      1009      39717 SCOTT               redo size                111,41 INACTIVE USER
       249      10097 ADAM                redo size                106,07 INACTIVE USER
       237      44045 SCOTT               redo size                181,37 INACTIVE USER
       699      40115 ADAM                redo size                174,25 INACTIVE USER
       391      58243 ADAM                redo size                154,91 INACTIVE USER

14 linhas selecionadas.

Por fim, segue abaixo uma consulta que retorna a porcentagem utilizada do arquivo de redo log online corrente antes de realizar uma operação de alternância de log.

SQL> SELECT le.lenum "Group#",
  2       le.leseq "Current log sequence No",
  3       ROUND (100 * cp.cpodr_bno / (le.lesiz - 28770), 2) "Percent Full",
  4       cp.cpodr_bno "Current Block No",
  5       le.lesiz * le.lebsz / 1024 / 1024 "Size of Log in MB"
  6  FROM x$kcccp cp, x$kccle le
  7  WHERE le.leseq = CP.cpodr_seq AND BITAND (le.leflg, 24) = 8;

    Group# Current log sequence No Percent Full Current Block No Size of Log in MB
---------- ----------------------- ------------ ---------------- -----------------
        13                  253996         37,4           372194                50

1 linha selecionada.

No mais, é recomendável que uma operação de alternância de log ocorra no mínimo a cada 20 ou 25 minutos, ou seja de 4 a 5 redo log switches por hora, caso contrário talvez seja necessário rever o tamanho dos arquivos de redo log online.




6 comentários:

Paulo Werneck disse...

Legatti,
muito bacana o post!

Seguindo a finalidade do post, qual a Redo Log Switch Frequency você acha ideal, 1 por hora, conforme mencionou no caso do post ?

Abs,
Paulo

Eduardo Legatti disse...

Olá Paulo,

Uma operação de log switch a cada 20 min ou 25 min é aceitável o que equivale a 4 ou 5 switches por hora. Mais do que isso talvez já seja necessário avaliar o tamanho dos redo log files.


Abraços,

Legatti

Agnus Tecnologia disse...

Olá Legatti,

Vou começar a monitorar as sessões para detectar o porque do aumento excessivo de archivelog. Nestes dias a empresa migou o protheus da versão 11 para 12 e os archives simplemente deram um salto enorme. Antes gerava cerca de 1,2 Gigas por dia de Archives e agora esta gerando quase 800 Gigas de archives por dia, mesmo o banco tento no maximo 100 Gigas dados e 50 gigas de indices.

Eduardo Legatti disse...

Olá Alessandro,

Realmente tem algo estranho aí ;-)

Abraços

Legatti

Anônimo disse...

Caro Eduardo,
Aqui Eduardo também!!!
Duas são minhas observações:
1- O usuário Scott está inativo, mas mesmo assim é o responsável pelo crescimento do log?? Fiquei sem entender!!

2- Estou com problema parecido: Uma instalação ora12c com um banco em produção suportando toda uma solução rodando: WebLogic, Portal, SOA, BPM, BAM,etc. De um tempo para cá cresce de forma explosiva. Está derrubando o banco e, o pior, sem que consigamos identificar a causa, pois ocorre em momento diferentes(dias ou horas), primeiro associamos ao uso, mas ontem ocorreu na madrugada(?).
Alguma dica??? Estamos aumentando os espaços, mas sabemos que há algo errado e lutando para resolver!! Assim, qualquer ajuda, é muito bem vinda!!!
Atenciosamente,
Eduardo Lamarca - RJ

Eduardo Legatti disse...

Olá Eduardo,

Uma sessão no Oracle armazena as informações de forma cumulativa enquanto ela estiver conectada, independente dela estar ACTIVE ou INACTIVE. O desafio aí é tentar identificar qual sessão de usuário que está gerando essa massa grande de redos. Caso a sessão conecte faça as transações e desconecte logo em seguida, aí realmente é mais difícil de identificar. Talvez vai ter que criar algum monitoramento específico das sessões no banco e dados.

Abraços,

Legatti

Postagens populares