sábado, 16 de junio de 2012

Buscando al ESX asesino silencioso de discos

Situación

Cluster VMware ESX 4.1 con 25 hosts. Estos hosts no tienen discos locales, arrancan de SAN. Todos arrancan de la misma cabina que aloja también más de 200 máquinas virtuales. La cabina tiene unos 200 discos pero a pesar de que está óptimamente configurada la SAN y el multipath SATP/PSP, no da abasto con las IOPs que generan las máquinas virtuales, el sistema de backup y las service console de los hosts ESX. Por momentos va tan mal que algunos procesos como Storage vMotion fallan por timeout de acceso a disco.

Analizando qué máquinas virtuales y datastores generan más tráfico de disco, veo en el vSphere Client que los datastores de arranque de los hosts tienen una escritura sostenida de unos 700 a 1000 KB/s. Esto despierta mi inquietud, ¿pero qué carajo hacen los hosts ESX escribiendo constantemente en disco semejante cantidad de datos? No es que sea muchísima carga de IO, pero multiplicada por 25 sobre una cabina que ya no da de sí, si nos la podemos sacar de encima ganaremos rendimiento.

Las LUN de arranque de arranque sólo están presentados a su propio host y por lo tanto sus datastores sólo albergan la service console local. Así que estas escrituras las ha de hacer en la service console.

¿Quién es el asesino?

La service console está corriendo sin actividad de swap, con buena cantidad de memoria libre. Así que descartamos la falta de memoria y su consecuente trashing.

En la service console ejecuto mi comando preferido, el nunca bien ponderado vmstat 1
Para mi gran sorpresa, la evolución de la columna "bo" (escritura en disco, en KB) no es mucha en cada segundo. Viéndolo con más detalle, dos o tres veces por minuto hay una gran escritura, digamos de unos 20 MB, pero el resto del tiempo se escribe poco y nada.

El querido esxtop coincide con vmstat: en la LUN correspondiente a este hosts sólo se escribe de vez en cuando, y lo hace el world 4096 (la service console)

¿Por qué esa discrepancia entre las estadísticas del vSphere Client y lo que me dice esxtop y vmstat? La explicación es sencilla, en vmstat y esxtop estoy tomando medidas cada uno y dos segundos, respectivamente. Mientras que en el vSphere Client cada muestra corresponde al promedio de los últimos 20 segundos. Por lo tanto lo que en el vmstat es una escritura de 20 MB en un segundo y ninguna actividad luego, en el vSphere Client se ve como una actividad promedio de 1 MB/s.

¿Hay una diferencia, no? Esto me hace recordar a alguien que alguna vez me dijo: la estadística es la ciencia por la cual si yo me como dos panchos (hot dog) y vos no comés ninguno, los dos nos comimos uno cada uno.

Definitivamente, parece haber un asesino en la service console. Es cuestión de encontrarlo.

Primer sospechoso: generación de logs

Nada de nada, todo lo que hay en /var/log va creciendo pero ni de casualidad a ese ritmo.

Segundo sospechoso: otros archivos

Lamentablemente no hay muy buenas herramientas para ver qué archivos se están escribiendo en cada momento en Linux. El iotop no funciona en la service console pero pude recurrir a analizar el dmesg con la opción de logs de escritura activados. No salió nada muy relevante de él.

Lo que arrojó un poco más de luz fue hacer un find de todo el disco en busca de los archivos escritos durante el último minuto. Al menos reducía el tamaño de la búsqueda, pero no era muy conclusivo. Lo que no había era archivos que crecieran.

¿Qué proceso será?

Para ir delimitando responsabilidades puse el host en modo mantenimiento, detuve todos los agentes de monitorización de hardware, el vpxa (vCenter Agent) y desconecté el host del vCenter. El comportamiento persistía. Ya casi no quedaba duda, la actividad era del hostd. Apago el hostd y voilà, desaparecen las escrituras.

Pensando y pensando, viendo y revisando veo que las ráfagas de escrituras se producen cada 20 segundos. ¿Qué hace el hostd cada 20 segundos aunque el host esté en modo mantenimiento y desconectado del vCenter server? ¡Bingo! Recoge estadísticas. Esa era la sospecha, así que recoger evidencias y probarla en juicio.

La instrucción

Para probar las sospechas habilité el modo de logs trivia en el hostd. Esto se hace editando /etc/vmware/hostd/config.xml tal como se describe en KB1004795 y reiniciando el hostd.



Verifiqué entonces que los momentos en los que se recogían las estadísticas (servicio Statssvc del hostd) según el log coincidian con los picos de escritura y con las actualizaciones de los archivos de estadísticas alojados en /var/lib/vmware/hostd/stats. Es más, el tamaño de estos archivos coincidía aproximadamente con el volúmen de cada ráfaga (en la captura de ejemplo es 1 MB). El asesino estaba rodeado, vamos a juicio.

El juicio

¿Es esto normal? Sí.
Se recogen estadísticas cada 20 segundos y se graban  localmente y se retienen en el host durante una hora. Cada cinco minutos (300 s) estos datos se condensan en nuevas muestras agregadas. Estas muestras agregadas cada cinco minutos se envían al vCenter para que las guarde en la base de datos. A pesar de ello se mantienen durante un día en el host. Esto último se realiza como optimización, para que todas las consultas del último día no tengan que ir a la base de datos del vCenter y puedan ir directamente al host.
Gráfico tomado de PowerCLI & vSphere statistics

El la captura de pantalla anterior se veían dos archivos: hostAgentStats-20.stats y hostAgentStats-300.stats. Todo apunta a que estos archivos guardan la información local de muestras de 20 segundos y 5 minutos. Es en el momento en que se realizan estas escrituras cada 20 segundos donde vemos el tráfico de disco que genera el supuesto problema.

En este momento ya podemos decir que hemos encontrado al asesino. Pero no hemos tenido otro remedio que absolverlo por homicidio culposo: lo que hace es perfectamente normal y explicable. En un pequeño host con pocas CPU y acceso a pocas LUNs las estadísticas a recoger sólo ocupan poco más de 1 MB. Pero cuando uno tiene que recoger estadísticas de 8 NICs, 2 HBAs, 24 CPUs y 80 LUNs, la escritura de todas estas estadísticas cada 20 segundos puede ser sustancial.

Para colmo de males uno tiene un cluster de 25 hosts con relojes perfectamente sincronizados como el monstruo del espagueti volador manda, y el muy bueno del hostd sincroniza la recolección de estadísticas a los segundos 0, 20 y 40 de cada minuto. Así que los 25 hosts van como zombis a escribir a la vez a la cabina unos 500 MB de una.

¿Y el ESXi?

¿Pero no me contaron el cuento de que el ESXi se ejecuta en memoria y no necesita disco físico una vez que arrancó? (salvo para guardar cambios en la configuración). De hecho yo he hecho la guarrada de quitar el disco de arranque al ESXi y él tan contento funcionando. ¿Cómo puede ser que funcionen las estadísticas si no puede escribir como lo hace el ESX?

No nos mintieron, eso se demuestra viendo los filesystems que tiene montado un ESXi.


¡Hostias! Hay un filesystem montado justito en el lugar en donde están los archivos de la discordia. ¿Por qué?

El visorfs es algo así como un RAM disk. Tiene sus características particulares, pero en el fondo lo es. Eso quiere decir en resumidas cuentas que el ESXi sí escribe estos archivos, pero ¡lo hace en memoria! y no en disco físico.

La solución creativa

Visto lo visto, ¿cómo hacer para solucionar la molestia inicial de la generación de escrituras en el disco SAN? La respuesta está en el ESXi: escribirlo en memoria.

La service console de ESX no es el vmkernel, no existe un visorfs, es un Red Hat Linux. ¿Tiene algo parecido el Linux? Sí, se llama tempfs.

Con varias salvedades, el tmpfs es algo parecido al vmvisor: un RAM disk. La parte buena es que es un RAM disk que irá usando memoria a medida que se necesite y la irá liberando, a diferencia de un RAM disk tradicional que reserva espacio en memoria.

Entonces la solución es meter el /var/lib/vmware/hostd/stats en un tmpfs. Lo hacemos agregando una línea al /etc/fstab y reiniciando el host.




Una vez reiniciado el host, vemos cómo han quedado montadas las distintas particiones.



Y los archivos de estadísticas en su lugar.


Sí sí, cuando reinicies estos archivos habrán desaparecido. No es grave, las estadísticas de 5 minutos ya están en el vCenter y si no existen estos archivos los crea desde cero el hostd cuando arranca.

Para más inri, es exáctamene lo que hace ESXi, los tira. En el script de inicio de hostd (/etc/init.d/hostd) crea el RAM disk tomand como base para el cálculo el número de VMs y de resource pools.



Case closed. Colorín colorado, el cuento se ha acabado.

Otrosí digo

Y ya que estamos con la recolección de estadísticas por parte del hostd, en su archivo de configuración /etc/vmware/hostd/config.xml hay una seccion para el statssvc que nos permite especificar varios parámetros. Entre ellos cada cuánto tiempo recolectar estadísticas o en qué directorio guardarlas.

Deslinde de responsabilidades: seguro que esto no lo debe "soportar" VMware, así que esta información va "as is". En todo caso se aplica el deslinde genérico de este blog.