_
********************************************************************************
SQL ID: fcqbkkryrx6xh Plan Hash: 2798344373
_
SELECT MIN(OBJECT_ID)
FROM
DBA_OBJECTS WHERE OBJECT_ID > :B1
_
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 7088 0.83 2.51 0 0 0 0
Fetch 7088 1396.10 4853.38 0 17149867 0 7088
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14177 1396.94 4855.90 0 17149867 0 7088
_
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
asynch descriptor resize 28176 0.00 0.06
latch: cache buffers chains 7 0.07 0.24
latch: row cache objects 1 0.05 0.05
latch free 1 0.06 0.06
********************************************************************************
_
Neste caso, a query executou durante 4856 segundos, mas gastou apenas 1397 deles em CPU. Isso é comum, porque processos de banco de dados geralmente passam um bom tempo esperando blocos serem trazidos do cache ou do disco. Mas vejam que não houve espera alguma por disco ("db file sequential read" ou "db file scattered read") nem por qualquer outro recurso (Soma de "Total Waited" não dá nem 1s). Então pra onde foram os outros 3459 segundos ?
Resposta: eles foram gastos esperando por CPU. Durante o tempo de execução, outros processos estavam rodando na mesma máquina, e nosso processo só teve acesso aos ciclos da CPU durante 29% do tempo em que rodou. A espera por CPU não é registrada pelo trace do Oracle como um evento de "wait", portanto não aparece.
No exemplo acima eu sei que foi exatamente isso que aconteceu, porque foi um teste controlado: em uma máquina com 4 CPUs foram disparados 4 processos Oracle que executavam operações pesadas, mas praticamente sem acesso a disco. Em seguida, disparei um quinto processo idêntico, mas este sofreu um rebaixamento de prioridade no sistema operacional (comando "renice" em Linux). O trecho acima vem deste último processo.
Então em resumo é isso: quando cair em suas mãos um trace com lapsos de tempo, é porque outra(s) coisa(s) estava(m) rodando junto com seu processo no período registrado pelo trace. Para investigar mais a fundo um caso como esse, é necessário utilizar ferramentas que vejam a instância Oracle como um todo (e.g. AWR Report) ou até ferramentas de análise de carga do servidor, já que os processos que consumiram a CPU podem nem ter sido do Oracle.
Nenhum comentário:
Postar um comentário