Encontrar procesos que causan bloqueos de IO (iowait)

IOWait es la medida del tiempo que los procesos de la CPU pasan sin hacer nada, en espera de poder hacer una operación de IO, es decir, leer o escribir en el disco.

Generalmente es un indicador claro de un cuello de botella en el sistema, y se produce cuando alguno de los discos (o todos) no dan a basto con operaciones de lectura y/o escritura.

Los síntomas suelen ser bastante claros, en forma de bajada general de rendimiento, largas esperas, etc.

La forma más sencilla y estándar de comprobar la carga de iowait que tenemos es usar el comando top, que tenemos disponible en cualquier sistema GNU / Linux, y en muchos casos no es necesario ni siquiera tener permisos de root. En la primera parte de la salida del top es donde tenemos esta información en la línea de %Cpu(s), marcada como wa.

top - 20:26:25 up 5 days, 22:50,  3 users,  load average: 0,02, 0,31, 0,54
Tasks: 220 total,   1 running, 219 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3,3 us,  1,8 sy,  0,0 ni, 94,3 id,  0,7 wa,  0,0 hi,  0,0 si,  0,0 st
KiB Mem :  7614832 total,   144824 free,  2784012 used,  4685996 buff/cache
KiB Swap:  7815164 total,  7718864 free,    96300 used.  4251800 avail Mem

En este caso, según la salida de top, tenemos 3,3% de procesos de usuario (us), 1,8% un de sistema (sy), 0,0% de procesos de baja prioridad (ni), un 94,3% de CPU sin hacer nada, o en estado idle (id), y solamente un 0,7% de iowait (wa), lo cual está bastante bien. El resto está a cero, y si hacemos la suma sale un 100,1 %. Cosas del redondeo...

Para refrescar, según la información de man del comando top...

us: user cpu time (or) % CPU time spent in user space
sy: system cpu time (or) % CPU time spent in kernel space
ni: user nice cpu time (or) % CPU time spent on low priority processes
id: idle cpu time (or) % CPU time spent idle
wa: io wait cpu time (or) % CPU time spent in wait (on disk)
hi: hardware irq (or) % CPU time spent servicing/handling hardware interrupts
si: software irq (or) % CPU time spent servicing/handling software interrupts
st: steal time - - % CPU time in involuntary wait by virtual cpu while hypervisor is servicing another processor (or) % CPU time stolen from a virtual machine

Ahora veamos un ejemplo de proceso generando esperas de iowait. Lo que voy a hacer es ejecutar un comando sencillo pero que va a generar muchas operaciones de lectura, en este caso, un simple du para comprobar el espacio usado, pero sobre el raiz del sistema de ficheros:

du -h /

Al ejecutar el comando, los resultados del top ya empiezan a mostrar una subida del iowait.

Tasks: 226 total,   3 running, 223 sleeping,   0 stopped,   0 zombie
%Cpu(s): 11,5 us,  6,5 sy,  2,0 ni, 60,8 id, 19,0 wa,  0,0 hi,  0,1 si,  0,0 st
KiB Mem :  7614832 total,    52068 free,  3388748 used,  4174016 buff/cache
KiB Swap:  7815164 total,  7711876 free,   103288 used.  3580684 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                      
 2356 charles   20   0  882788 147036  83488 S  17,6  1,9   0:30.12 chrome                                                       
 2513 charles   20   0    7076   3156   2384 D  14,6  0,0   0:02.09 du                                                           
12156 charles   20   0  564288  62128  43656 S  13,6  0,8   0:36.61 konsole                                                      
 2442 charles   20   0  623544 182416 134288 S   7,0  2,4  26:52.05 chrome     

Aquí podemos ver que el %wa ha subido al 19,0%, con lo que vamos a empezar a notar problemas de rendimiento. En este caso, y solamente usando el comando top, podemos identificar rápidamente el proceso, fijándonos en la columna de estado (S) del top, vemos que hay un proceso du que tiene su estado a D. El estado D significa 'uninterruptible sleep', lo que suele ser indicativo de que el proceso está esperando por una operación de IO.

También para refrescar, esta es la lista de estados que muestra el man del comando top.

D = uninterruptible sleep
R = running
S = sleeping
T = stopped by job control signal
t = stopped by debugger during trace
Z = zombie

Normalmente, los procesos en top estarán en estado S (durmiendo a gusto) o R (corriendo). Si empezamos a ver procesos en D, es señal de que estamos teniendo lo esperas largas de IO.

Para sacar algo más de información de que están haciendo nuestros procesos conflictivos, otro comando muy útil y más específico el top es iotop. Ojo, porque este no viene "de serie" en la mayoría de distribuciones, aunque es muy recomendable tenerlo a mano. En Debian, lo tenemos sencillo:

apt-get install iotop

Con iotop tenemos un listado del uso de operaciones de IO por procesos. La primera información que nos muestra son los totales de lectura y escritura del sistema, y después las de cada proceso ordenados por actividad. Y aquí sí que podremos ver de forma muy clara cuáles son los procesos que más recursos están utilizando.

Total DISK READ :    1265.11 K/s | Total DISK WRITE :       0.00 B/s
Actual DISK READ:     875.85 K/s | Actual DISK WRITE:       0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND                                                                  
14344 be/4 charles  1265.11 K/s    0.00 B/s  0.00 % 64.06 % du -h /
    1 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % init
    2 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [kthreadd]
    3 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [ksoftirqd/0]
    5 be/0 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [kworker/0:0H]

Ahora si podemos ver sin duda que el proceso du es el que está leyendo del disco como si no hubiese mañana, y bueno, en este caso la solución es sencilla: podemos matarlo con un kill, con el PID que nos da el iotop.

kill 14344

Si queremos seguir investigando un poco más, podemos usar el comando lsof, que nos va a mostrar un listado de los archivos que está utilizando un proceso, con su PID:

lsof -p 14344

La salida mostrará algo parecido a lo que vemos a continuación, y en muchos casos también nos puede dar pistas de lo que está sucediendo.

COMMAND   PID    USER   FD   TYPE DEVICE SIZE/OFF     NODE NAME
du      14883 charles  rtd    DIR  252,0     4096        2 /
du      14883 charles  txt    REG  252,0   113576  5796815 /usr/bin/du
du      14883 charles  mem    REG  252,0   341146 10477596 /usr/share/locale/es/LC_MESSAGES/coreutils.mo
du      14883 charles  mem    REG  252,0  1729984 13221996 /lib/x86_64-linux-gnu/libc-2.19.so
du      14883 charles  mem    REG  252,0   140928 13221991 /lib/x86_64-linux-gnu/ld-2.19.so
du      14883 charles  mem    REG  252,0  1607632  4309902 /usr/lib/locale/locale-archive
du      14883 charles  mem    REG  252,0   151111 16318536 /usr/share/locale/es/LC_MESSAGES/libc.mo
du      14883 charles  mem    REG  252,0    26258  4322370 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
du      14883 charles    0u   CHR  136,1      0t0        4 /dev/pts/1
du      14883 charles    1u   CHR  136,1      0t0        4 /dev/pts/1
du      14883 charles    2u   CHR  136,1      0t0        4 /dev/pts/1

Otro comando útil para estos casos es iostat, que nos muestra estadísticas de operaciones de IO sobre los discos. En este caso, no tenemos información de los procesos que las causan, solamente las operaciones globales que se están realizando, y principalmente nos va a permitir descubrir, o confirmar, en cuál de nuestros discos es en el que se están produciendo los bloqueos.

Al igual que con iotop, normalmente tendremos que instalarlo a parte. En Debian:

apt-get install iostat

La primera muestra de iostat nos muestra el resumen total desde que levantó la máquina, y en las siguientes iteraciones se muestra la estadística desde el informe anterior, y es donde podremos ver que está pasando.

iostat 2

La salida de iostat, con iteraciones cada 2 segundos:

Linux 4.2.0-1-amd64 (totoro2)    20/10/15        _x86_64_        (4 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2,38    0,32    1,15    2,69    0,00   93,45

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sda              31,91        84,58       725,86    7867640   67517095
dm-0             37,82        83,47       723,61    7764404   67308108
dm-1              0,64         0,59         2,00      54648     185684

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           4,79    0,00    2,52   24,34    0,00   68,35

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sda             573,50      2304,00        18,00       4608         36
dm-0            580,50      2304,00        18,00       4608         36
dm-1              0,00         0,00         0,00          0          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5,51    0,00    2,38   23,53    0,00   68,59

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sda             197,00       780,00        10,00       1560         20
dm-0            197,00       780,00        10,00       1560         20
dm-1              0,00         0,00         0,00          0          0

En este caso, vemos que tenemos un iowait de alrededor de un 24%, que se está produciendo en el disco sda. Este comando es muy útil cuando tenemos varios, por ejemplo, y podemos combinar con lsof para indagar más sobre los ficheros que están causando el problema.

A partir de aquí, las soluciones dependen del tipo de problema que tengamos entre mano, y eso ya daría no para otro artículo, sino para un libro entero, pero siempre podremos recurrir a nuestro querido kill, al menos para quedarnos agusto.

Para ampliar un poco de información, y como fuentes que he utilizado para consulta, recomiendo varias lecturas interesantes, aunque todas en inglés.

http://serverfault.com/questions/12679/can-anyone-explain-precisely-wha…

http://stackoverflow.com/questions/666783/how-to-find-out-which-process…

http://bencane.com/2012/08/06/troubleshooting-high-io-wait-in-linux/