Strange bufwaits / bufwaits estranhos

This article is written in English and Portuguese (original article is here)
Este artigo está escrito em Inglês e Português (artigo original aqui)


English version:

Another recent customer situation triggered an investigation that may be helpful to others. We had a system with two instances, but only one was working. Database configuration was almost equal to other system, but the query performance was horrible in comparison. Sessions status had lots of "IO Wait", but also lots of "yield bufwait". All the monitoring with OS tools showed that we were facing severe IO performance issues (disks showed up at 100% utilization and data throughput was much lower than on similar systems).

So, the DBA team interacted with the system administration team and they identified several hardware and configuration issues that caused severe IO bottleneck. But even considering that those issues were being addressed by the system admin team, the DBA team was still concerned with the fact that we were seeing bufwaits. Accordingly to the manual, bufwaits means our session was trying to access a buffer which was locked by other session. But we could get those bufwaits even when only one query was running. So it was a bit strange.
As usual, if something doesn't look obvious we have to follow the details. First step was to run "onstat -b" during the query execution and try to find who is the owner of the buffer that we want to access. The output was similar to this:

IBM Informix Dynamic Server Version 11.50.UC9W2X1 -- On-Line -- Up 00:04:28 -- 111240 Kbytes

address  userthread flgs pagenum          memaddr  nslots pgflgs xflgs owner    waitlist

4421ec80 0          84   3:230791         4440e000 87     801    80    ffffffff 44d0bc90

The pagenum was constantly changing, but the owner was always "fffffff". Needless to say we don't have any thread with a rstcb address equal to "ffffffff". So we were stuck. But a bit of internal IBM investigation thought me that this means we're waiting for an IO (AIO or KAIO) thread. This didn't answer our question: If we're waiting on IO why doesn't it always show "IO Wait" but instead shows "yield bufwait"?

Well it appears the answer is pretty simple and it's related to the read ahead functionality. After some trial, I noticed that if I reduce the RA_PAGES and RA_THRESHOLD parameters, the thread will show much more "IO Wait" than "yield bufwait". If I increase it I get the opposite. Apparently the engine considers read ahead for the query. And because the disk access is slow, some buffers are consumed by the sqlexec before the IO request completes. So when the sqlexec thread identifies the buffer slot that it needs, it's already in the process of being read from the disk.
Later one of the DBAs used this to make some benchmarking about the best RA_PAGES and RA_THRESHOLD values to use. It was around 128 and 100 respectively. But beginning with 11.70 you should be better using AUTOREADAHED functionality instead.


Versão Portuguesa:
Uma situação recente num cliente despoletou uma investigação que se pode revelar interessante para outros. Tínhamos um sistema com duas instâncias mas apenas uma a correr. As configurações eram quase iguais a outro sistema, mas a velocidade de execução de uma query era péssima em comparação com o outro sistema. O estado das sessões mostrava constantemente "IO Wait", mas também muitos "yield bufwait". Toda a monitorização usando as ferramentas de sistema operativo indicavam que estávamos a ter problemas sérios de I/O (discos com 100% de utilização e métricas de transferência muito abaixo de sistemas semelhantes)

No seguimento, o DBA interagiu com a equipa de gestão de sistemas e foram identificados alguns problemas de hardware e configurações que causavam o problema de I/O. Mas mesmo considerando que esses temas iam ser resolvidos pela equipa de sistemas, a equipa de DBAs ainda estava preocupada com o facto de aparecerem bufwaits. Segundo o manual, bufwaits implica que a nossa sessão está a tentar aceder a um buffer que já está bloqueado por outra sessão. Mas os nossos bufwaits apareciam mesmo quando apenas esta query estava a correr no motor. Por isso parecia um pouco estranho.
Como é hábito, quando algo não parece bem, temos de verificar os detalhes. O primeiro passo foi executar um "onstat -b" durante a execução da query, e tentar quem é o dono dos buffers a que estamos a tentar aceder. O resultado era semelhante a isto:

IBM Informix Dynamic Server Version 11.50.UC9W2X1 -- On-Line -- Up 00:04:28 -- 111240 Kbytes

address  userthread flgs pagenum          memaddr  nslots pgflgs xflgs owner    waitlist

4421ec80 0          84   3:230791         4440e000 87     801    80    ffffffff 44d0bc90

O número da página estava naturalmente sempre a mudar, mas o owner era sempre "fffffff". Escusado será dizer que não temos nenhuma thread cujo rstcb seja ifual a "ffffffff". Por isso esávamos bloqueados. Um pouco mais de investigação na IBM disse-nos que o significado disto é que estávamos à espera de uma thread de I/O (AIO ou KAIO). Isto não respondia à nossa questão: "Se estamos à espera de I/O porque é que não mostra IO Wait em vez de "yield bufwait"?

Bom, aparentemente a resposta é bastante simples e está relacionada com a funcionalidade de read ahead. Após algumas tentativas verifiquei que se reduzir os parâmetros RA_PAGES e RA_THRESHOLD, a thread irá mostrar muito mais IO Wait que yield bufwait. Se os aumentar tenho o contrário. O motor estava a considerar que a query beneficiaria de read ahead. E porque o sistema de discos estava muito lento, alguns buffers eram consumidos pela thread sqlexec (que executa o SQL) antes que os pedidos de I/O se concluíssem. Assim, quando a thread sqlexec identifica o próximo buffer a usar, já existe um pedido de leitura para ele.
Mais tarde um dos DBAs utilizou esta situação para efetuar benchmark sobre os parâmetros RA_PAGES e RA_THRESHOLD. Os melhores valores seriam por volta dos 128 e 100 respetivamente. Mas a partir da 11.70 não deve ter de se preocupar, devendo deixar isto a cargo da funcionalidade de AUTOREADAHED.