Oracle Wait Interface (OWI) – Por onde começar?

Embora introduzido no Oracle 7, o Oracle Wait Interface (OWI) continua sendo hoje uma ferramenta inestimável para os DBAs, através dela é possível obter informações que ajudam na solução de problemas e na busca de melhorias na performance de todo o ambiente de banco de dados.

O Oracle Wait Interface nada mais é que uma coleção de visões dinâmicas de performance e arquivo de rastreamento SQL(SQL trace file) que promovem estatísticas de desempenho sobre gargalos de um processo mais conhecidas como eventos de espera(wait events) ou sintomas.

Utilizando o OWI podemos identificar todos os gargalos de espera que incidiram desde o inicio ao termino de um processo, incluindo esperas por operações de I/O, locks, network, dentre outros. Proporcionando um direcionamento para a solução ou redução do impacto causado pelo gargalo de espera.

Atualmente na versão 12.1.0.1 contamos com 1.567 eventos de espera(wait events), diferentemente de seus antecessores. O Oracle 11.2.0.3 por exemplo, conta com 1.152 eventos de espera, na versão 10G pouco mais de 800 enquanto na versão 7.3 contava com apenas 104 eventos de espera. (A quantidade de eventos de espera depende da versão, configuração e opções instaladas no RDBMS).

numero wait events Oracle Wait Interface (OWI)   Por onde começar?

Wait Events são as condições em que uma sessão está esperando que algo aconteça. Elas podem ser a nível de sistema, onde afeta todo o banco de dados ou a nível de sessão em que afeta uma única atividade de usuário no banco de dados.

Conforme documentação Oracle, os wait events são elencados em três visões dinâmicas de performance:

V$SESSION_WAIT exibe os eventos para os quais as sessões acabaram de concluir ou estão esperando.

V$SYSTEM_EVENT exibe o número total de tempo que todas as sessões tem aguardado por eventos de espera.

V$SESSION_EVENT é semelhante ao V$SYSTEM_EVENT, mas mostra todas as esperas para cada sessão.

Todo evento de espera pertence a uma classe de espera(Wait Class). Através da visão V$EVENT_NAME podemos identificar os tipos de classe de espera e os tipos de eventos bem como o que representam os parâmetros(PARAMETER) P1,P2 e P3 da V$SESSION_WAIT igualmente como as colunas P1TEXT, P2TEXT e P3TEXT desta mesma view.

-- Lista das classes de espera

SQL> select distinct wait_class from v$event_name;

WAIT_CLASS
----------------------------------------------------------------
User I/O
Application
Network
Concurrency
Administrative
Configuration
Scheduler
Cluster
Other
Idle
System I/O
Commit

12 rows selected.

-- Detalhes de um evento:

SQL> set lines 190
SQL> col NAME for a40
SQL> col WAIT_CLASS for a20
SQL> col PARAMETER1 for a10
SQL> col PARAMETER2 for a15
SQL> col PARAMETER3 for a15
SQL> select * from v$event_name where name='db file scattered read';

    EVENT#   EVENT_ID NAME                                     PARAMETER1 PARAMETER2      PARAMETER3      WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
---------- ---------- ---------------------------------------- ---------- --------------- --------------- ------------- ----------- --------------------
       118  506183215 db file scattered read                   file#      block#          blocks             1740759767           8 User I/O

A lista abaixo descreve brevemente cada classe:

Administrative

Espera resultante de comandos administrativos (DBA). Por exemplo, um rebuild de índice.

Application

Espera resultante do código da aplicação do usuário. Por exemplo, lock a nível de linha ou comando explícito de lock.

Cluster

Espera relacionada aos recursos do Real Application Clusters (RAC). Por exemplo, ‘gc cr block busy’.

Commit

Esta classe cotém apenas um evento de espera. ‘log file sync’ – espera para o redolog confirmar um commit.

Concurrency

Espera por recursos internos do banco de dados. Por exemplo, latches.

Configuration

Espera causada por uma configuração inadequase do banco de dados ou recursos da instance. Por exemplo, mal dimensionamento do tamanho dos
log file, shared pool size.

Idle

Indica que a sessão está inativa, esperando para trabalhar. Por exemplo, ‘SQL*Net message from client’.

Network

Espera relacionada a eventos de rede. Por exemplo, ‘SQL*Net more data to dblink’.

Other

Esperas que normalmente não devem ocorrem em um sistema. Por exemplo, ‘wait for EMON to spawn’)

Scheduler

Espera relacionada ao gerenciamento de recursos. Por exemplo, ‘resmgr: become active’.

System I/O

Espera por background process I/O. Por exemplo, DBWR wait for ‘db file parallel write’)

User I/O

Espera por user I/O. Por exemplo ‘db file sequential read’.

Ao longo das versões, o Oracle database ganhou outras visões de desempenho que oferecem novas informações de espera por várias perspectivas incluindo features de apoio para atender limitações do OWI como:

  • ASH (Active Session History), coleta a todo segundo informações correntes de cada sessão. Seria um join da V$SESSION com a V$SESSION_WAIT porem com dados históricos das sessões ativas.
  • AWR (Automatic Workload Repository), oferece o histórico de todas as atividades das sessões. Seu tempo de retenção default é 8 dias mas pode ser ajustado conforme necessidade. Os dados capturados podem ser acessados através de views (DBA_HIST_*) e pelo AWR report facilmente acessado utilizando o Oracle Enterprise Manager.
  • ADDM (Automatic Database Diagnostic Monitor), faz uma análise automática dos dados capturados(snapshots) dentro do AWR e oferece recomendações de melhorias.

Algumas outras views que complementam o OWI:

V$SYSTEM_WAIT_CLASS
V$SESSION_WAIT_CLASS
V$SESSION_WAIT_HISTORY
V$EVENT_HISTOGRAM
V$EVENTMETRIC
V$SERVICE_EVENT
V$SERVICE_WAIT_CLASS
V$ACTIVE_SESSION_HISTORY
V$WAITCLASSMETRIC
V$SESSTAT
V$STATNAME
V$SYSSTAT
V$SESS_TIME_MODEL
V$SYS_TIME_MODEL
DBA_HIST_EVENT_NAME
DBA_HIST_ACTIVE_SESS_HISTORY
DBA_HIST_BG_EVENT_SUMMARY
DBA_HIST_WAITCLASSMET_SUMMARY

Outro componente que faz parte do OWI (citado anteriormente) é o extended SQL Trace:

De forma simplificada, o rastreamento SQL (trace) é um “monitoramento” que pode ser habilitado sobre uma sessão/processo para identificarmos os comandos executados, tempos e gargalos para cada SQL, o que permite diagnosticar problemas de performance.

É possível habilitar um trace de diversas formas e com diferentes níveis de coleta:

Nível 0   Trace desabilitado. Igual ao SQL_TRACE = FALSE.
Nível 1   Informações de rastreamento SQL padrão (SQL_TRACE = TRUE). Este é o nível default.
Nível 4   Informações de rastreamento SQL + valores das bind variables.
Nível 8   Informações de rastreamento SQL + informações de wait events.
Nível 12 Informações de rastreamento SQL + informações de wait events + valores das bind variables.

Alguns métodos para se habilitar um trace na sua sessão:

--ativa trace nível 1
alter session set sql_trace=true;

--desativa trace
alter session set sql_trace=false;

--ativa o trace nível 8
alter session set events ‘10046 trace name context forever, level 8’;

--desativa o trace
alter session set events ‘10046 trace name context off’;

--Para quem possui o pacote DBMS_SUPPORT instalado:

--ativa trace nível 1
exec sys.dbms_support.start_trace;

--para incluir wait events e bind variables
exec sys.dbms_support.start_trace(waits => TRUE, binds=> TRUE);

--desativa o trace
exec sys.dbms_support.stop_trace;

Alguns métodos para se habilitar um trace em outra sessão:

--ativa o trace nível 8
execute sys.dbms_system.set_ev(SID,SERIAL#,10046,8,'');

--desativa o trace
execute sys.dbms_system.set_ev(SID,SERIAL#,10046,0,'');

--Para quem possui o pacote DBMS_SUPPORT instalado:

--ativa o trace nível 12
exec dbms_support.start_trace_in_session(
     sid => sid,
     serial# => serial,
     waits => true,
     binds => true);

--desativa o trace
exec dbms_support.stop_trace_in_session(
     sid => sid,
     serial# => serial);

--Utilizando o pacote DBMS_MONITOR:

--ativa o trace nível 12
exec dbms_monitor.session_trace_enable(
     session_id => sid,
     serial_num => serial,
     waits => true,
     binds => true);

--desativa o trace
exec dbms_monitor.session_trace_disable(
     session_id => sid,
     serial_num => serial);

Os arquivos de trace recebem a extensão .trc e podem ser encontrados na versão 10g em 2 diretórios dependendo da sessão em que o trace foi habilitado:

Sessão de usuário = USER_DUMP_DEST

SQL> show parameter USER_DUMP_DEST

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest                       string      /oratst01/app/oracle/admin/tes
                                                 te/udump

Processos background = BACKGROUND_DUMP_DEST

SQL> show parameter BACKGROUND_DUMP_DEST

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
background_dump_dest                 string      /oratst01/app/oracle/admin/tes
                                                 te/bdump

Nas versões 11g e 12c os traces (.trc) podem ser encontrados abaixo do ADR (Automatic Diagnostic Repository) tanto para processos background como de usuários: (Diag Trace)

SQL> show parameter diagnostic_dest

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
diagnostic_dest                      string      /oratst02/app/oracle

SQL> col name for a20
SQL> col value for a70
SQL> select * from v$diag_info;

   INST_ID NAME                 VALUE
---------- -------------------- ----------------------------------------------------------------------
         1 Diag Enabled         TRUE
         1 ADR Base             /oratst02/app/oracle
         1 ADR Home             /oratst02/app/oracle/diag/rdbms/teste2/teste2
         1 Diag Trace           /oratst02/app/oracle/diag/rdbms/teste2/teste2/trace
         1 Diag Alert           /oratst02/app/oracle/diag/rdbms/teste2/teste2/alert
         1 Diag Incident        /oratst02/app/oracle/diag/rdbms/teste2/teste2/incident
         1 Diag Cdump           /oratst02/app/oracle/admin/teste2/cdump
         1 Health Monitor       /oratst02/app/oracle/diag/rdbms/teste2/teste2/hm
         1 Default Trace File   /oratst02/app/oracle/diag/rdbms/teste2/teste2/trace/teste2_ora_263.trc
         1 Active Problem Count 0
         1 Active IncidentCount 0

O nome do arquivo será:

[ ORACLE_SID ]_ora_[ SPID ].trc

SQL> select spid
  2    from v$process p, v$session s
  3   where p.addr = s.paddr
  4     and sid = 2371;

SPID
------------
12603
srvtst:oracle:oratst2> ls -lrt *12603*
-rw-r--r--   1 oracle     dba           6032 Aug  8 17:02 oratst2_ora_12603.trc

Uma facilidade presente desde a versão 8.1.7 foi o TRACEFILE_IDENTIFIER que permite atribuir um “NOME” ao arquivo trace. Quando você esta realizando um trace da sua sessão:

SQL> alter session set tracefile_identifier=anderson;

Session altered.
srvtst:oracle:oratst2> ls -lrt *ANDERSON*
-rw-r--r--   1 oracle     dba             73 Aug  8 17:08 oratst2_ora_4796_ANDERSON.trc

Após identificar o seu arquivo trace você executa o utilitário TKPROF (Transient Kernel Profiler) para gerar e sumarizar todos os dados coletados no arquivo .trc

srvtst:oracle:oratst2> tkprof oratst2_ora_4796_ANDERSON.trc trace.txt

TKPROF: Release 10.2.0.5.0 - Production on Thu Aug 8 17:13:35 2013

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Agora é só visualizar o arquivo analizado (trace.txt)

SELECT COUNT(*)
FROM
 TESTE WHERE TIMESTAMP < (SYSDATE  - 365)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.03       0.03          1         30          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     47.08     289.13    1118319    1138160          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     47.11     289.16    1118320    1138190          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 20844

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=1138160 pr=1118319 pw=0 time=289132678 us)
      0   TABLE ACCESS FULL TESTE (cr=1138160 pr=1118319 pw=0 time=289132666 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file scattered read                      35022        0.63        249.26
  latch: object queue header operation           20        0.00          0.00
  db file sequential read                         1        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00
********************************************************************************
  •  Identificando um evento de espera a nível de sessão:
SQL> set lines 190
SQL> col EVENT for a40
SQL> col P1TEXT for a10
SQL> col P2TEXT for a10
SQL> col P3TEXT for a10
SQL> col WAIT_CLASS for a20
SQL> select sw.event,
  2         sw.state,
  3         sw.p1text,
  4         sw.p1,
  5         sw.p2text,
  6         sw.p2,
  7         sw.p3text,
  8         sw.p3,
  9         sw.wait_class
 10    from v$session_wait sw
 11   where sid = 255
 12  /

EVENT                                    STATE               P1TEXT             P1 P2TEXT             P2 P3TEXT             P3 WAIT_CLASS
---------------------------------------- ------------------- ---------- ---------- ---------- ---------- ---------- ---------- --------------------
db file scattered read                   WAITING             file#             448 block#          52425 blocks             16 User I/O

Conhecendo o evento(sintoma) de espera da sessão você pode agir sobre o mesmo. Neste exemplo, o evento ‘db file scattered read’ representa que a sessão esta realizando um acesso FULL sobre uma tabela – FTS (FULL TABLE SCAN) ou sobre um índice – FFS (FAST FULL SCAN).

Identificando o comando SQL da sessão 255:

SQL> SELECT A.SQL_TEXT
  2    FROM V$SQLTEXT A, V$SESSION B
  3   WHERE A.ADDRESS = B.SQL_ADDRESS
  4     AND A.HASH_VALUE = B.SQL_HASH_VALUE
  5     AND B.SID = 255
  6   ORDER BY PIECE;

SQL_TEXT
----------------------------------------------------------------
select * from lancamentos where cd_empresa=5

Plano de execução do SQL. Observe o TABLE ACCESS FULL na coluna Operation. (representa um acesso full sobre uma tabela)

SQL> explain plan for
  2  select * from lancamentos where cd_empresa=5;

Explained.

SQL> SELECT * FROM TABLE(dbms_xplan.display);

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------
Plan hash value: 2518875852

---------------------------------------------------------------------------------
| Id  | Operation         | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |             |  9759K|  1237M|  1108K  (2)| 03:41:40 |
|*  1 |  TABLE ACCESS FULL| LANCAMENTOS |  9759K|  1237M|  1108K  (2)| 03:41:40 |
---------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("CD_EMPRESA"=5)

13 rows selected.

Agora é só agir sobre o problema! sintoma, evento de espera…

  • Identificando os TOP wait events do sistema:

Se você já gerou algum report do AWR(Automatic Workload Repository) deve conhecer a imagem abaixo dos “Top 5 Timed Events”. Caso não conheça você pode ler o artigo, Como gerar Relatório AWR para verificação de Estatística do Banco de Dados Oracle.

top 5 events Oracle Wait Interface (OWI)   Por onde começar?

Este report mostra os wait events que mais afetaram o banco de dados no intervalo de snapshot selecionado, mas não é preciso gerar um AWR para coletá-los, posso pegar as informações utilizando as próprias views do AWR. Exemplo:

Selecionando o horário desejado: ( snap_id = 21138 )

SQL> select a.snap_id,
  2         to_char(a.begin_interval_time, 'dd/mm/yyyy hh24:mi:ss') begin_interval_time,
  3         to_char(a.end_interval_time, 'dd/mm/yyyy hh24:mi:ss') end_interval_time
  4    from dba_hist_snapshot a
  5   order by 1 desc;

   SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME
---------- ------------------- -------------------
     21145 23/07/2013 18:00:53 23/07/2013 19:00:05
     21144 23/07/2013 17:01:11 23/07/2013 18:00:53
     21143 23/07/2013 16:00:27 23/07/2013 17:01:11
     21142 23/07/2013 15:00:15 23/07/2013 16:00:27
     21141 23/07/2013 14:00:02 23/07/2013 15:00:15
     21140 23/07/2013 13:00:50 23/07/2013 14:00:02
     21139 23/07/2013 12:00:37 23/07/2013 13:00:50
     21138 23/07/2013 11:00:24 23/07/2013 12:00:37
     21137 23/07/2013 10:00:11 23/07/2013 11:00:24
     21136 23/07/2013 09:00:59 23/07/2013 10:00:11
     21135 23/07/2013 08:00:46 23/07/2013 09:00:59
     21134 23/07/2013 07:00:33 23/07/2013 08:00:46
     21133 23/07/2013 06:01:09 23/07/2013 07:00:33
     21132 23/07/2013 05:00:08 23/07/2013 06:01:09

Executando a query para coletar os TOP events: (para baixat um txt com a query formatada clique AQUI)

SQL> select snap_id,
  2         begin_time,
  3         end_time,
  4         (select i.instance_name
  5            from gv$instance i
  6           where i.INSTANCE_NUMBER = a.instance_number) as "INSTANCE",
  7         event_name,
  8         total_waits as "WAITS",
  9         event_time_waited as "TIME(s)",
 10         avg_wait as "AVG_WAIT(ms)",
 11         pct as "%PCT",
 12         wait_class
 13    from (select to_char(s.begin_interval_time, 'DD-MM-YYYY HH24:MI') as BEGIN_TIME,
 14                 to_char(s.end_interval_time, 'DD-MM-YYYY HH24:MI') as END_TIME,
 15                 m.*
 16            from (select ee.instance_number,
 17                         ee.snap_id,
 18                         ee.event_name,
 19                         round(ee.event_time_waited / 1000000) event_time_waited,
 20                         ee.total_waits,
 21                         round((ee.event_time_waited * 100) /
 22                               et.total_time_waited,
 23                               1) pct,
 24                         round((ee.event_time_waited / ee.total_waits) / 1000) avg_wait,
 25                         ee.wait_class
 26                    from (select ee1.instance_number,
 27                                 ee1.snap_id,
 28                                 ee1.event_name,
 29                                 ee1.time_waited_micro - ee2.time_waited_micro event_time_waited,
 30                                 ee1.total_waits - ee2.total_waits total_waits,
 31                                 ee1.wait_class
 32                            from dba_hist_system_event ee1
 33                            join dba_hist_system_event ee2 on ee1.snap_id =
 34                                                              ee2.snap_id + 1
 35                                                          and ee1.instance_number =
 36                                                              ee2.instance_number
 37                                                          and ee1.event_id =
 38                                                              ee2.event_id
 39                                                          and ee1.wait_class_id <>
 40                                                              2723168908
 41                                                          and ee1.time_waited_micro -
 42                                                              ee2.time_waited_micro > 0
 43                          union
 44                          select st1.instance_number,
 45                                 st1.snap_id,
 46                                 st1.stat_name event_name,
 47                                 st1.value - st2.value event_time_waited,
 48                                 null total_waits,
 49                                 null wait_class
 50                            from dba_hist_sys_time_model st1
 51                            join dba_hist_sys_time_model st2 on st1.instance_number =
 52                                                                st2.instance_number
 53                                                            and st1.snap_id =
 54                                                                st2.snap_id + 1
 55                                                            and st1.stat_id =
 56                                                                st2.stat_id
 57                                                            and st1.stat_name =
 58                                                                'DB CPU'
 59                                                            and st1.value -
 60                                                                st2.value > 0) ee
 61                    join (select et1.instance_number,
 62                                et1.snap_id,
 63                                et1.value - et2.value total_time_waited,
 64                                null wait_class
 65                           from dba_hist_sys_time_model et1
 66                           join dba_hist_sys_time_model et2 on et1.snap_id =
 67                                                               et2.snap_id + 1
 68                                                           and et1.instance_number =
 69                                                               et2.instance_number
 70                                                           and et1.stat_id =
 71                                                               et2.stat_id
 72                                                           and et1.stat_name =
 73                                                               'DB time'
 74                                                           and et1.value -
 75                                                               et2.value > 0) et on ee.instance_number =
 76                                                                                    et.instance_number
 77                                                                                and ee.snap_id =
 78                                                                                    et.snap_id) m
 79            join dba_hist_snapshot s on m.snap_id = s.snap_id
 80           where m.instance_number = 1
 81             and m.snap_id = 21138 --SNAP_ID capturado na query acima
 82           order by PCT desc) a
 83   where rownum <= 5 --Quantidade de linhas retornadas, especifique 10 para ter um TOP 10
 84  /

   SNAP_ID BEGIN_TIME       END_TIME         INSTANCE         EVENT_NAME                            WAITS      TIME(s) AVG_WAIT(ms)       %PCT WAIT_CLASS
---------- ---------------- ---------------- ---------------- ------------------------------ ------------ ------------ ------------ ---------- --------------------
     21138 23-07-2013 11:00 23-07-2013 12:00 c0090prd         DB CPU                                            66,705                    44.6
     21138 23-07-2013 11:00 23-07-2013 12:00 c0090prd         log file sync                       868,610       15,564           18       10.4 Commit
     21138 23-07-2013 11:00 23-07-2013 12:00 c0090prd         db file sequential read           7,663,832       15,562            2       10.4 User I/O
     21138 23-07-2013 11:00 23-07-2013 12:00 c0090prd         SQL*Net message from dblink         813,766       14,805           18        9.9 Network
     21138 23-07-2013 11:00 23-07-2013 12:00 c0090prd         SQL*Net break/reset to client       174,240        7,015           40        4.7 Application
 Referências:http://docs.oracle.com/cd/B28359_01/server.111/b28320/waitevents.htm
http://it.toolbox.com/blogs/living-happy-oracle/oracle-a-query-to-get-the-wait-events-part-of-the-awr-report-33420
http://vapvarun.com/study/oracle/mcgraw.hill.osborne.oracle.wait.interface.a.practical.guide.to.performance.diagnostics.and.tuning/8174final/lib0010.html
%name Oracle Wait Interface (OWI)   Por onde começar?

Autor: Anderson Graf

Bacharel em Sistemas de Informação e MBA em Gestão de Banco de Dados Oracle. Entusiasta da tecnologia Oracle, ACE Associate ♠, autor em vários blogs e OTN. Consultor Oracle Senior na Exímio Soluções em TI

Envolvido em soluções de:
– Implementação, migração, gerenciamento e suporte a produtos Oracle, multiplataforma
– Monitoramento de ambientes 24×7
– Backup e Recovery
– Performance e Tuning
– Alta disponibilidade (HA) – RAC, Data Guard
– EM database/grid/cloud control
– Particionamento & Advanced Compression
– Oracle Engineered Systems – ODA, Exadata

Blog pessoal: http://www.andersondba.com.br
Articulista na Oracle Technology Network (OTN) – https://goo.gl/99R6yW
ACE Associate – https://goo.gl/MBB51b
Articulista GPO – http://profissionaloracle.com.br