Performance analysis: A study case (bottleneck)

Como una manera de seguir ilustrando el post anterior "Performance analysis: Understanding the vmstat comand output", vamos a realizar un rápido análisis de un bottleneck producido en un equipo debido a la baja lentitud de la controladora de disco. Si bien en este caso el equipo no es más que una laptop, ejemplifica bien lo que es el estudio de performance que puede aplicarse a una gran variedad de equipos. Como en esta serie de post, solo hemos tratado con vmstat(1), utilizaremos tal herramienta para realizar el análisis.

Síntomas
El equipo, en momentos en los que se sometía a alta carga de trabajo de I/O se volvía extremadamente lento, dejando de responder por momentos, no habiendo otra solución que apagarlo, o esperar un buen rato. Si bien es entendible que el mismo se "quede" sin memoria y swapee, esto no se hacía de una manera tan agresiva, por lo cual se analizara la existencia de otro problema.

Descripción del equipo
El equipo es una laptop HP 420, con una CPU Pentium(R) Dual-Core CPU T4500 @ 2.30GHz, en cuanto a su memoría RAM se encuentra conectado un módulo DDR2 de 2 Gb. además cuenta con un disco rígido Western Digital WDC WD5000BPVT-00HXZT3 utilizando la interfaz SATAII. El sistema operativo que corre en el mismo es Linux (Fedora 16), x86_64, utilizando el kernel 3.3.1-5.fc16.x86_64. Sin entrar en más detalles vemos que dice lspci(1), sobre los dispositivos conectados al mismo:

00:00.0 Host bridge: Intel Corporation Mobile 4 Series Chipset Memory Controller Hub (rev 07)
00:1a.0 USB Controller: Intel Corporation 82801I (ICH9 Family) USB UHCI Controller #4 (rev 03)
00:1a.1 USB Controller: Intel Corporation 82801I (ICH9 Family) USB UHCI Controller #5 (rev 03)
00:1a.2 USB Controller: Intel Corporation 82801I (ICH9 Family) USB UHCI Controller #6 (rev 03)
00:1a.7 USB Controller: Intel Corporation 82801I (ICH9 Family) USB2 EHCI Controller #2 (rev 03)
00:1b.0 Audio device: Intel Corporation 82801I (ICH9 Family) HD Audio Controller (rev 03)
00:1c.0 PCI bridge: Intel Corporation 82801I (ICH9 Family) PCI Express Port 1 (rev 03)
00:1c.1 PCI bridge: Intel Corporation 82801I (ICH9 Family) PCI Express Port 2 (rev 03)
00:1c.2 PCI bridge: Intel Corporation 82801I (ICH9 Family) PCI Express Port 3 (rev 03)
00:1c.4 PCI bridge: Intel Corporation 82801I (ICH9 Family) PCI Express Port 5 (rev 03)
00:1c.5 PCI bridge: Intel Corporation 82801I (ICH9 Family) PCI Express Port 6 (rev 03)
00:1d.0 USB Controller: Intel Corporation 82801I (ICH9 Family) USB UHCI Controller #1 (rev 03)
00:1d.1 USB Controller: Intel Corporation 82801I (ICH9 Family) USB UHCI Controller #2 (rev 03)
00:1d.2 USB Controller: Intel Corporation 82801I (ICH9 Family) USB UHCI Controller #3 (rev 03)
00:1d.7 USB Controller: Intel Corporation 82801I (ICH9 Family) USB2 EHCI Controller #1 (rev 03)
00:1e.0 PCI bridge: Intel Corporation 82801 Mobile PCI Bridge (rev 93)
00:1f.0 ISA bridge: Intel Corporation ICH9M LPC Interface Controller (rev 03)
00:1f.2 SATA controller: Intel Corporation ICH9M/M-E SATA AHCI Controller (rev 03)
02:00.0 Network controller: Ralink corp. RT3090 Wireless 802.11n 1T/1R PCIe

El primer paso del análisis consintió en reproducir el síntoma haciendo simplemente un yum update. Los paquetes a actualizar eran cuatro y no representaban más de 8 megas, la descarga de los mismos se produjo de manera adecuada y en tiempos aceptables. Por lo cual, se instrumento vmstat(1) tomar muestras cada 1 segundo y así conocer la utilización de los distintos componentes del equipo y si se producía en algún caso saturación. Bajo un funcionamiento normal, vmstat(1) en el equipo reporta lo siguiente:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0 643000 125868  17100 308404    0    0     0     0 1759 2977 21  5 74  0  0        
 0  0 643000 125744  17100 308448    0    0     0     0 1866 2442 28  3 69  0  0        
 1  0 643000 125744  17100 308448    0    0     0    40 1774 1935 31  4 66  0  0        
 1  0 643000 125868  17108 308376    0    0     0    16 1837 1765 36  3 58  3  0        
 0  0 643000 124876  17108 308772    0    0     0     0 1621 1949 23  3 74  0  0        
 0  0 643000 124844  17108 308772    0    0     0     0 1252 1057 12  1 87  0  0        
 2  0 643000 125092  17116 308364    0    0     0    24 1555 2377 17  4 76  3  0        
 0  0 642988 125496  17128 308396    0    0     0   156 1593 1578 22  3 71  4  0        
 1  0 642988 125496  17136 308400    0    0     0    32 1781 2525 21  4 71  4  0        
 0  0 642988 125496  17136 308400    0    0     0     0 2012 3000 32  4 64  0  0        
 1  1 642988 125404  17144 308392    0    0     0    72 1887 3008 25  4 71  1  0        
 0  0 642988 126044  17144 308404    0    0     0     4 1918 2502 28  5 65  3  0        
 0  0 642988 126572  17152 308396    0    0     0    88 2083 3117 32  4 62  2  0        
 1  0 642988 125952  17152 308404    0    0     4     0 1511 1519 19  3 78  0  0        
 0  0 642988 129832  17160 308404    0    0     0    20 2193 3602 34  4 58  4  0        
 2  0 642988 129756  17160 308444    0    0     0     0 1620 1719 21  3 77  0  0        
 1  0 642988 129848  17160 308444    0    0     0    64 1817 2590 21  4 75  0  0        
 0  0 642988 129784  17168 308320    0    0     0    28 1673 1748 19  2 75  4  0        
 1  0 642988 130004  17168 308380    0    0    28     0 1893 2270 27  4 68  2  0        
 0  0 642988 129816  17176 308396    0    0     0    20 1630 1895 21  3 74  2  0        
 0  0 642976 129756  17184 308424   28    0    28   172 1727 1828 27  4 66  3  0 

Podemos ver que la run queue, en ningún momento sobrepasa la cantidad de cores del equipo (2), si bien el consumo de memoria esta un poco elevado tampoco es excesivo. En las columnas relacionadas a los discos (bi/bo), podemos observar que se están leyendo algunos bloques (cada bloque tiene un tamaño de 1024 kb), por lo cual una lectura de 50 bloques representa 5120 kb. Las interrupciones se mantienen dentro de los parámetros de la normalidad, como así también los context switch. En cuanto al consumo de CPU y su utilización el idle es relativamente bueno, teniendo en cuenta que el equipo es una laptop, y la mayor cantidad de tiempo de CPU se esta consumiendo en userspace (aproximadamente un 25%).
En el post anterior, hablé sobre la relación de la columna "b" y la columna "wa" (Waiting for I/O), si bien aquí el tiempo de Waiting for I/O que se muestra es muy bajo vale la pena recordar que los procesos o threads pueden estar sleeping en dos formas diferentes:

Interruptible sleep: Aquellos procesos que están esperando alguna señal para despertar y volver a ejecutarse (por ejemplo que se les notifique que X tarea fue completada).

Uninterruptible sleep: Aquellos procesos los cuales se encuentran aguardando algún tipo de evento externo para poder continuar, por ejemplo esperando I/O.

Esto puede ser indicio de un cuello de botella en una controladora de disco, o en el propio arreglo de discos que utiliza el equipo (sea local, o mediante un storage externo).
Durante momentos de carga más elevada, se llegaron a ver muestras como la siguiente:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  1 647756  72388   1332 318084    0   80 11432    80 2143 2507 22 12 28 38  0        
 0  1 648276  75008   1324 313328    0  520  7432   520 1907 2451 18  8 39 35  0        
 0  2 648276  76248   1328 311652    0    0  2636     0 1381 2049  6  4 41 50  0        
 0  2 648276  71660   2728 314488    0    0  3732     0 1237 1939  8  4 40 48  0        
 0  1 648356  75132   4248 309420    0   80  5068    80 1935 2770 15  8 23 54  0        
 0  1 648404  75132   4660 308220    0   48  2772    48 1591 2363  8  4 41 47  0        
 1  2 648388  89116   4660 312252  108    0  4120     0 1084 2003  3  4 38 56  0        
 0  2 648372  83164   5376 316324   40    0  4624     0 1109 1836  6  4 43 47  0        
 0  2 648364  85388   5668 313564   20    0  3028   160  893 1422  4  4 31 62  0        
 1  4 648328  75032   5816 322396   56    0  2712    92 1556 2504 14  6 30 51  0        
 2  2 648292  73484   5816 323456   96    0  2900    48 1565 3009 14  5 33 48  0        
 0  2 648292  68928   5816 326612   44    0  3744     0 2349 3104 41  8 18 32  0        
 0  2 648292  64464   5816 330776   20    0  4300     0 2084 4249 20  7 27 46  0        
 0  4 648488  68228   6004 327264   56  208  3884   216 1682 2576 10  5 17 68  0        
 2  6 648500  68640   6272 324992  112   72  4648   360 1439 2003  9  5  1 85  0        
 0  4 648684  65912   5864 328392   64  208  5680   268 1923 2577 10  7 12 72  0        
 0  6 648776  63272   5868 333172    0  108  6932   108 1959 2491 14  8 11 68  0        
 0  2 648836  67172   5884 329808   32   64  1388    72 1798 3385 11  5 17 68  0        
 1  3 648940  73000   5912 324516    0  104  1072   196 1581 2322  5  3  6 86  0        
 0  4 648908  70464   6060 329648    0   40  3008   132 2183 2948 12  6  3 79  0        
 3  3 649068  73316   6096 326456    4  168  1072   372 2106 3319 25  6  3 66  0   

Tenemos una salida más que interesante para analizar. Si prestan atención, la run queue, en ningún momento excede el número de CPU's conectadas al equipo, por lo cual de manera grotesca podríamos descartar un problema de saturación de las CPUs, también y como era esperable, podemos notar que nuestra memoria RAM libre, se redujo en un 20%, y por lo tanto algunas páginas de memoria fueron swappeadas a disco, lo que representa un aumento en las operaciones de I/O para la controladora de discos SATA, y el disco conectado al equipo propiamente dicho. Las interrupciones se mantienen dentro de los parámetros de la normalidad, como así también los cambios de contexto. Pero si prestamos atención con un poco de detenimiento nuestro Waiting for I/O (columna wa), esta bastante elevada, pero sin lograr saturar, manteniendose en valores rondando el 60% en una gran parte del tiempo. Los procesos con estado initerrumpible sleep, se mantienen en una constante comprendida entre 1 y 6, lo que representa una ocupación un poco alta del dispositivo. Estos procesos, están a la espera de algún tipo de evento externo para poder continuar con su ejecución normal, en este caso esperando I/O. Lo cual es un indicio clave de un pequeño bottleneck posiblemente ocasionado en la controladora de discos o en el propio disco (5400 rpm).
Este tipo de datos es interesante graficarlos utilizando en mi caso gnuplot, de esta manera es posible realizar un análisis mas detallado de la información brindada y conocer el momento en que se alcanza el througput máximo de utilización.

En el primer caso veremos la utilización de la CPU:
(System time (%sy), User time (%us), Waiting for I/O (%wa) e Idle time (%id)).

En el gráfico podemos observar que el tiempo empleado en Waiting for I/O tiene picos que llegan al 86%, lo cual es altísimo, mientras que por su parte el User time y el System time se mantienen bajos.
Veamos ahora un gráfico de los procesos:
(run queue y procesos bajo uninterruptible sleep)

A simple vista podemos notar un pico bastante importante de procesos en el estado uninterrumpible sleep, a la espera de I/O para poder continuar, también podemos notar un mantenimiento constante de el tiempo de CPU empleado esperando I/O.
Veamos a continuación la utilización de la memoria, la swap y el I/O:
(swap, free, cache, buffers - si, so - bi, bo)

En el análisis de estas tres variables, podemos ver que el consumo de swap se mantiene constante, con una leve curva ascendente que rondando los 600 mb., además existe una disminución de la memoria en ciertos momentos, lo que fuerza al equipo a mandar páginas de memoria virtual no utilizada por los procesos a disco, esta tendencia a swappear fuerza a operaciones de I/O que llegan a picos máximos de 1600 kilobytes por segundo, lo cual puede combinarse estadísticamente con nuestro elevado Waiting for I/O y los procesos en estado ininterrumpible sleep.

Pasos siguientes:
Determinar la existencia o no de errores en los discos (hdparm, SMART), comprobar la existencia de errores de filesystem en los del sistema, comprobar las opciones de montaje de los distintos filesystems. Hacer diagnósticos mas extensivos con herramientas tales como iostat(1).

Conclusión:
En este caso, no se reportaron errores de disco ni filesystems, las opciones de montaje se encontraban correctas.
El problema es una combinación de tres factores, un disco de baja velocidad, una controladora de disco de baja performance, además de tener una baja cantidad de memoria RAM física instalada en el equipo lo que fuerza a una utilización aún mayor de los subsistemas de I/O.