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

Por Anderson Graf
Postado em Novembro 2016

Revisado por Marcelo Pivovar - Solution Architect

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 12c contamos com mais de 1.500 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).

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 atraves 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 analisado (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".

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:

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 --Aqui você coloca o SNAP_ID capturado na query acima
82           order by PCT desc) a
83   where rownum <= 5 --Quantidade de linhas retornadas, especifique 10 e você tera um TOP 10
84  /

SNAP_ID BEGIN_TIME       END_TIME         INSTANCE EVENT_NAME                         WAITS  TIME(s) AVG_WAIT(ms)
------- ---------------- ---------------- -------- ----------------------------- ---------- -------- ------------ 
21138 	23-07-2013 11:00 23-07-2013 12:00 c0090prd DB CPU                                     66,705                
21138 	23-07-2013 11:00 23-07-2013 12:00 c0090prd log file sync                    868,610   15,564           18
21138 	23-07-2013 11:00 23-07-2013 12:00 c0090prd db file sequential read        7,663,832   15,562            2
21138 	23-07-2013 11:00 23-07-2013 12:00 c0090prd SQL*Net message from dblink      813,766   14,805           18
21138 	23-07-2013 11:00 23-07-2013 12:00 c0090prd SQL*Net break/reset to client    174,240    7,015           40

%PCT   WAIT_CLASS
------ ----------
44.6
10.4   Commit
10.4   User I/O
9.9    Network
4.7    Application

 

Referências:

Wait Event Enhancements in Oracle 10g
http://www.dbspecialists.com/files/presentations/wait_events_10g.html

Oracle Wait Events
http://docs.oracle.com/cd/B28359_01/server.111/b28320/waitevents.htm

Oracle Wait Interface: A Practical Guide to Performance Diagnostics & Tuning
http://my.safaribooksonline.com/book/databases/oracle/9780072227291/2-oracle-wait-interface-components/lev9_html#X2ludGVybmFsX0h0bWxWaWV3P3htbGlkPTk3ODAwNzIyMjcyOTElMkZsZXY0X2h0bWwmcXVlcnk9

Oracle - A query to get the "Wait Events" part of the AWR report.
http://it.toolbox.com/blogs/living-happy-oracle/oracle-a-query-to-get-the-wait-events-part-of-the-awr-report-33420

 


Anderson Graf, Bacharel em Sistemas de Informação e MBA em Gestão de Banco de Dados Oracle. Trabalha com banco de dados Oracle desde 2009, é Oracle OCP 10g/11g/12c, OCS Linux, Database e Cloud Control. OCE Performance Tuning; OPNCS. É um entusiasta da tecnologia Oracle e autor dos blogs andersondba.com.br e oraclehome.com.br.

Este artigo foi revisto pela equipe de produtos Oracle e está em conformidade com as normas e práticas para o uso de produtos Oracle.