quarta-feira, 15 de fevereiro de 2012

Starvation ou "Meu Trace Sofreu um Lapso de Tempo"

Durante a análise de arquivos trace do Oracle, às vezes nos deparamos com a seguinte situação: o tempo de CPU foi X, o tempo decorrido (elapsed) foi bem maior que X, mas não aparece nenhum evento de espera que justifique a diferença. Por exemplo:
_
********************************************************************************
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