Bug na feature "Expression Statistics Monitoring" deixando o Banco de Dados extremamente lento

 
Olá pessoal,

     Durante algumas semanas, até o mês 8/2019, tive problemas semanalmente em um dos Bancos de Dados de produção que administro, relacionados a um bug na feature “Expression Statistics Monitoring” (que é habilitada por padrão no 12cR2, versão do BD em questão), cujos detalhes explicarei ao longo deste artigo.

     Tudo começou com uma sobrecarga e lentidão excessiva que ocorria toda semana, normalmente às 2ªs-feiras. Era algo estranho e difícil de entender, pois eu não conseguia encontrar nada de diferente sendo executado naquele BD que justificasse aumentar "brutalmente" o tempo de execução dos SQLs. A máquina virava uma carroça e a única forma "paliativa" de resolver o problema da lentidão, para não deixar os sistemas inoperantes, era restartar a instância. Após o restart tudo voltava ao normal, e isso me dava um pouco de fôlego para investigar com mais calma, em Statspack Reports, sintomas que pudessem indicar a origem do problema: a sobrecarga e lentidão de todos os SQLs, em especial de 2 sistemas que eram os mais utilizados.

     Esse problema se repetiu por umas 3 semanas e eu sempre gerava e analisava Statspack Reports de períodos de horas próximos ao horário em que a lentidão estava maior (procedimento recomendado para encontrar mais facilmente a origem do problema), e durante essas 3 semanas não consegui encontrar nenhum indício do que poderia estar ocorrendo, mas consegui fazer várias constatações, entre as principais:

1- Surgimento na seção "Top 5 Timed Events" de alguns wait events que não ocorriam normalmente (read by other session, db file parallel read), e um grande aumento da qtde. de ocorrências e tempo de outros que eram normais acontecer (db file sequential read e db file scattered read):

Top 5 Timed Events                                       Avg      %Total

~~~~~~~~~~~~~~~~~~                                       wait     Call

Event                            Waits       Time (s)   (ms)     Time

read by other session          6,523,331      37,310      6      19.7

db file sequential read       10,431,862      33,720      3      17.8

db file scattered read         2,820,518      15,053      5       7.9

db file parallel read          1,829,917      11,980      7       6.3

2- Pude notar na seção "IO Stat by Function - summary" um grande volume de dados sendo processado na Buffer Cache (mais de 100 X maior do que o normal):

IO Stat by Function - summary  DB/Inst: CDBINTRA/cdbintra  Snaps: 1335-1339

->Data Volume values suffixed with   M,G,T,P are in multiples of 1024,

  other values suffixed with       K,M,G,T,P are in multiples of 1000

->ordered by Data Volume (Read+Write) desc

               ---------- Read --------- --------- Write -------- --- Wait ----

                 Data  Requests    Data   Data  Requests    Data          Avg

Function        Volume     /sec  Vol/sec Volume     /sec  Vol/sec  Count Tm(ms)

--------------- ------ -------- -------- ------ -------- -------- ------ ------

RMAN              875G   288.5     62.2M  6811M      .6       .5M  3296K    0.0

Buffer Cache Re   504G  2434.8     35.8M                             13M    0.0

Others             20G    11.1      1.4M  8807M     4.0       .6M   167K    0.0

Direct Reads       17G    11.8      1.2M    19M      .2       .0M           0.0

LGWR                2M      .0       .0M    11G    14.5       .8M   255     0.0

DBWR                        .0            7368M    43.7       .5M    27     0.0

Direct Writes               .0             346M     1.7       .0M           0.0

Streams AQ                  .0                                       12     0.0

          -------------------------------------------------------------

3- Uma quantidade de Physical reads quase 100 X maior do que o normal, porém uma qtde. de transações 2.4 X menor:

Load Profile              Per Second    Per Transaction    Per Exec    Per Call

~~~~~~~~~~~~      ------------------  ----------------- ----------- -----------

      DB time(s):               33.4                4.4        0.25        0.15

       DB CPU(s):               10.5                1.4        0.08        0.05

       Redo size:          945,450.6          123,807.4

   Logical reads:           41,331.3            5,412.4

   Block changes:              246.6               32.3

  Physical reads:           14,521.5            1,901.6   

Physical writes:                3.5                0.5

      User calls:              221.7               29.0

          Parses:              121.6               15.9

     Hard parses:                0.8                0.1

W/A MB processed:               13.8                1.8

          Logons:                3.1                0.4

        Executes:              134.5               17.6

       Rollbacks:                0.1                0.0

    Transactions:                7.6                  

     Tudo isso (e muitas outras estatísticas que analisei) gerou evidências de que tinha algo muito errado, mas nada que eu via indicava a causa do problema, foi então que, conversando com um Desenvolvedor, ele me deu uma ideia que, na correria da rotina, eu não havia pensado antes: porque não analisar dados de um Statspack Report de um período mais cedo, antes de percebermos o problema? Foi então o que eu fiz, gerei um Report do horário das 5h às 9h, do dia em que havia ocorrido o último problema, e para a minha surpresa encontrei algo muito suspeito, um SQL estranho, do próprio Oracle, que eu nunca tinha visto:

Elapsed               Elap per CPU Old
Time (s) Executions   Exec (s)%Total  Time (s) Physical Reads  Hash Value
-------- ------------ ------- ------  -------- --------------- ---------
26956.23 30           898.54  15.2    26366.36 1,011,532       276052168

select /* QOSD */ exp_id, objn from exp_head$ e where ((select m
ax(nvl(es.last_modified, es.ctime)) from exp_stat$ es where es.o
bjn = e.objn and es.exp_id = e.exp_id) < sysdate - 367 or not e
xists (select 1 from sys.obj$ o where o.obj# = e.objn)) and rown

     Este SQL era o Top 1 em tempo de execução e estava sendo executado com um tempo absurdamente alto, fazendo muitas operações de Buffer Gets, então comecei a desconfiar que ele fosse a origem de tudo. Pelo que analisei no Report conclui que este SQL estava sobrecarregando a Buffer Cache,  e desse modo, faltava cache para os demais SQLs, que passavam a fazer “Physical Reads”, gerando muito I/O, e consequentemente, uma grande lentidão no Banco de Dados. O SQL era executado pelo usuário SYS, e conforme feedback de um SR que abri no MOS, a Oracle informou que ele faz parte da nova “feature” de coleta de Estatísticas de Expressão Automática, habilitada por padrão a partir do Oracle 12.2. Antes de abrir o SR no MOS (em 23/8/19) encontrei o DOC ID 2354960.1, que informava existir um bug na nova feature referente ao espaço em disco exagerado que ela consumia. Essa descrição não tinha relação com o meu problema, porém executei o mesmo procedimento proposto no doc para desabilitá-la, e constatei depois que isso resolveu o meu problema.

     Seguem abaixo os comandos que executei para desabilitar a feature e "contornar" o problema:

     Fiquei contente de ter solucionado o problema com um "workaround", mas a forma mais efetiva de resolvê-lo, segundo a Oracle, era aplicar o patch de correção do "Bug 29240759 MMON OPTIMIZER WORKLOAD CLEANUP ACTION IS NOT FINISHED. (Doc ID 29240759.8)", cujo doc havia sido publicado 1 mês antes. Até hoje não apliquei o patch (forças maiores ainda não me deixaram fazê-lo), mas a situação agora está normalizada. Pretendo aplicá-lo assim que possível, e reabilitar em seguida a feature "Expression statistics monitoring" (executando o comando alter system set "_column_tracking_level"=21 scope=both).

     Qualquer dúvida sobre o assunto deste artigo, é só deixar um comentário que eu lhe responderei o mais breve possível!

[]s