4. Análisis CPU-I/O

Pregunta motivadora: Si dos procesos toman normalmente dos horas en ejecutarse, y un buen día adquirimos un CPU (quizá con la memoria respectiva) que proporciona el DOBLE de velocidad de procesamiento, ¿cuánto tardarán ahora estos procesos?

La respuesta, evidentemente, NO es una hora.

4.1. Recursos consumidos por los procesos

Los procesos que se ejecutan en los computadores hacen uso de diversos subsistemas del computador, tales como el CPU, la Memoria, los discos, y quizá la red. Normalmente se asume que la memoria tiene una velocidad "compatible" con la del CPU[1], por lo que los tiempos consumidos en ambos se combinan en uno sólo: el "tiempo de CPU".

Si un proceso no está ejecutando instrucciones del CPU en un momento dado, normalmente es porque está accediendo al disco o a la red (coloquialmente, se dice que está efectuando I/O.) Existe una tercera posibilidad que corresponde a procesos que "pausan" o "esperan eventos" sin hacer nada más (estado "idle" u "ocioso".)

4.2. Repartición CPU-I/O-Idle

A partir de lo anterior, para cualquier proceso se puede plantear que el tiempo de su ejecución se divide en tres componentes:

Tiempo Total = Tiempo CPU + Tiempo I/O + Tiempo Idle
Esta relación se puede acumular a todos los procesos del sistema y expresarla porcentualmente para un lapso de tiempo determinado:
% CPU sistema + % I/O sistema + % Idle sistema = 100%
El comando vmstat en sus últimas columnas nos proporciona estos valores. Por ejemplo:
$ vmstat 5
procs ------ ---swap-- -----io---- --system-- ----cpu----
 r  b  cache   si   so    bi    bo   in    cs us sy id wa
 2  0 110144    0    0    20     7 1013   237  4  1 94  1
 0  1 120520    0    0  2166    21 1160  1424 12  4 40 45
 6  0 133916    0    0  2573   133 1168  1311 31  4 27 38
 0  1 201372    0    0 13646   197 1155  1227 18  6 22 53
 0  1 210380    0    0  1870   201 1096  1305 62  4  0 33
 0  0 212548    0    0   437   163 1162  1049 16  2 77  5
La primera fila generada por vmstat debe ser descartada para este análisis pues corresponde a un acumulado desde que el sistema fue encendido.

Nuestro %CPU del sistema corresponde a la suma de las columnas 'us' y 'sy' (que se comentan luego.) El %I/O se encuentra en la columna 'wa', y por último, el %Idle corresponde a la columna 'id'.

NOTA: El manual de vmstat indica que para kernels Linux de versión menor a 2.5.41, la columna 'wa' siempre reporta cero, y la columna 'id' contiene la suma de %Idle+%I/O[2].

El comando vmstat acepta, entre otros, un argumento numérico que corresponde al intervalo de muestreo (en segundos.) Si deseamos conocer la distribución de los tiempos del sistema durante la ejecución de ciertos procesos, debemos lanzar vmstat en paralelo con los mismos y promediar los valores obtenidos mientras éstos se ejecutan. A modo de ilustración, asumiremos que pretendo analizar la distribución de tiempos de un proceso que tarda aproximadamente dos horas; vmstat se lanza con intervalo de muestreo de 20 minutos (1200 segundos):

$ vmstat 1200
procs ------- ---swap-- -----io---- --system-- ----cpu----
 r  b   cache   si   so    bi    bo   in    cs us sy id wa
 2  0  212640    0    0    31     7 1013   235  4  1 94  1
 2  0  220324    0    0  3844   296 1021  2360 82 10  0  9
 0  0  223900    0    0  1800     0 1087  1692 38  4 45 13
 4  0  224144    0    0     0     0 1205  3511 74 12 13  0
 1  0  226120    0    0   972   950 1223  2169 34  6 26 33
 1  0  229008    0    0  1490     0 1070  2471 52  8 19 21
 0  0  229916    0    0   564   320 1243  3014 52 10  6 31
Descartando la primera fila, los tiempos obtenidos son:

Tabla 1.

%CPU %I/O %IDLE %TOTAL
92 9 0 101
42 13 45 100
86 0 13 99
40 33 26 99
60 21 19 100
62 31 6 99
No es necesario preocuparse porque el total no suma exactamente 100%. A continuación el promedio de las columnas relevantes[3]:

Tabla 2.

%CPU %I/O %IDLE
63.7 17.8 18.2
Esta distribución es extremadamente útil para averiguar en dónde está concentrada la "lentitud". En este ejemplo, claramente se aprecia que el %CPU es el factor principal, pero tanto el %I/O como el %Idle son significativos. Por lo tanto, el diagnóstico es: Mejorar todos los subsistemas, pero especialmente el CPU.

Asumiendo que el proceso ha tomado dos horas (120 minutos) en total, de acuerdo a la tabla anterior los tiempos absolutos han sido:

Tabla 3.

T. CPU T. I/O T. IDLE
76.4 min 21.4 min 21.8 min

4.2.1. La pregunta inicial

Con los valores de la última tabla, podemos responder a la pregunta con que se inició esta sección: ¿Cuánto tardarán en total los procesos si el CPU es el doble de veloz?

Evidentemente, si el CPU es el doble de veloz, el tiempo en que éste es empleado se reducirá a la mitad. Para nuestro caso:

T. CPU = 76.4 min / 2 = 38.2 min
Con lo que nuestros tiempos resultan siendo:

Tabla 4.

T. CPU T. I/O T. IDLE
38.2 min 21.4 min 21.8 min
Finalmente, el tiempo total de los procesos será:
T. Total = 38.2 min + 21.4 min + 21.8 min = 1h 21min
En general, si el tiempo normal que tardan los procesos es To, y el CPU mejora en un factor F (en nuestro ejemplo, F=2), entonces el nuevo tiempo total Tn será:
Tn = To [1-(%CPU/100).(1-1/F)]
Para nuestro ejemplo:
Tn = 120 [1-(63.7/100).(1-1/2)] = 81.78 min = 1h 21min

Evidentemente este mismo análisis se puede aplicar para el subsistema de I/O, correspondiendo al incremento (o disminución) de la velocidad de los discos, o en ocasiones al incremento de la memoria física que permite el crecimiento del caché de disco.

Finalmente, téngase en cuenta que en Linux, el tiempo de espera con la red se considera tiempo Idle.

4.2.2. User Time y System Time

Anteriormente (en la salida de vmstat) se explicó que el %CPU estaba constituido por la adición de los valores 'us' (User Time) y 'sy' (System Time.) Estos valores pueden ser útiles cuando se pretende optimizar el código de un programa a fin de que consuma menos tiempo de CPU.

El "User Time" corresponde al tiempo que el CPU invierte en ejecutar el texto de los programas en cuestión (cálculos, toma de decisiones, acceso a memoria), mientras que el "System Time" es el tiempo que el CPU invierte en ejecutar código del kernel en función de las solicitudes que el programa le hace (system calls.)

La observación de estos valores puede hacerse para un proceso particular (pues vmstat obtiene el promedio de todo el sistema) mediante el comando time. Por ejemplo:

$ time find /etc > /dev/null
find: /etc/rcS.d: Permission denied
find: /etc/ssl/private: Permission denied
find: /etc/amanda: Permission denied

real    0m4.077s
user    0m0.003s
sys     0m0.050s
$
$ time find /etc > /dev/null
find: /etc/rcS.d: Permission denied
find: /etc/ssl/private: Permission denied
find: /etc/amanda: Permission denied

real    0m0.047s
user    0m0.006s
sys     0m0.018s
Este ejemplo muestra que el comando especificado (find) en su primera ejecución tardó en total 4.077 segundos en completarse. Durante este tiempo, sólo tres milésimas correspondieron a la ejecución del código del programa (pues find no hace mucho procesamiento de información), y cincuenta milésimas fueron dedicadas al código del kernel (en el caso de find, este código del kernel se encarga de navegar en una estructura de directorios.) Nótese que el tiempo total de CPU corresponde a sólo 53 milésimas: muy lejos de los cuatro segundos totales. Esto se debe a 1) otros procesos también se están ejecutando, y 2) el proceso tiene que esperar a que el disco entregue la información solicitada, lo cual es varios órdenes de magnitud más lento que las operaciones de CPU.

En la segunda ejecución el tiempo total se reduce radicalmente a 47 milésimas (ochenta y seis veces más rápido), lo cual se debe sin duda a que los datos de la primera ejecución están ahora en el caché de disco y ya no hay necesidad de ir al disco físico. Nótese que los tiempos de CPU también han cambiado, quizá por el efecto de otros procesos simultáneos, y (para el caso del Kernel/System Time) porque el mecanismo de acceso a la información de la memoria caché resulta más sencillo que el de un acceso real al disco físico[4].

El conocimiento de esto nos puede dar pistas con respecto a la estrategia de optimización de un proceso pesado. Por ejemplo, para el caso anterior, es evidente que no sirve de mucho tratar de optimizar el (escazo) procesamiento que lleva a cabo find, sino enfocar los esfuerzos a emplear menos tiempo en el Kernel. Si bien no trataremos de reprogramar el Kernel, al menos sí podemos tratar de reducir las llamadas que hacemos al mismo desde nuestro programa, o buscar otras llamadas más eficientes.

A modo de ejemplo, el siguiente programa ejecuta un cálculo (inútil) durante cinco segundos, y reporta cuantos millones de iteraciones se ha realizado dicho cálculo:

#include <stdio.h>
#include <sys/time.h>
#include <time.h>

int main(void)
{
int x=1, y=2, z=3;
long iter1=0,iter2=0;
struct timeval tv1,tv2;

gettimeofday(&tv1,NULL);
for(;;)
	{
	x=(x*3+y*7+z*9)%11;
	y=(x*9+y*11+z*3)%29;
	z=(x*17+y*13+z*11)%37;
	iter1++;
	if(iter1==1000000)
		{
		iter2++;
		iter1=0;
		}
	gettimeofday(&tv2,NULL);
	if(tv2.tv_sec==tv1.tv_sec+5 && tv2.tv_usec>=tv1.tv_usec ||
	tv2.tv_sec>tv1.tv_sec+5)
		break;
	}
printf("Iteraciones: %ldM Resultado: %d %d %d\n",iter2,x,y,z);
return 0;
}
Por ejemplo, en mi computador obtuve:
$ time ./calculo1
Iteraciones: 12M Resultado: 6 4 5

real    0m5.002s
user    0m2.379s
sys     0m2.461s
Claramente se aprecia que el "system time" es similar al "cpu time". Los 2.379 segundos de "user time" sólo alcanzaron para 12 millones de iteraciones.

Este programa tiene evidentemente el inconveniente de obtener la hora en cada iteración, lo que deriva en múltiples solicitudes al kernel. Esto se puede mejorar, por ejemplo, preguntando la hora cada millón de iteraciones:

#include <stdio.h>
#include <sys/time.h>
#include <time.h>

int main(void)
{
int x=1, y=2, z=3;
long iter1=0,iter2=0;
struct timeval tv1,tv2;

gettimeofday(&tv1,NULL);
for(;;)
	{
	x=(x*3+y*7+z*9)%11;
	y=(x*9+y*11+z*3)%29;
	z=(x*17+y*13+z*11)%37;
	iter1++;
	if(iter1==1000000)
		{
		iter2++;
		iter1=0;
		gettimeofday(&tv2,NULL);
		if(tv2.tv_sec==tv1.tv_sec+5 && tv2.tv_usec>=tv1.tv_usec ||
		   tv2.tv_sec>tv1.tv_sec+5)
			break;
		}
	}
printf("Iteraciones: %ldM Resultado: %d %d %d\n",iter2,x,y,z);
return 0;
}
Con esto, el tiempo del proceso ha sido casi exclusivamente "User Time", lo cual alcanzó para 65 millones de iteraciones:
$ time ./calculo2
Iteraciones: 65M Resultado: 1 23 5

real    0m5.055s
user    0m5.030s
sys     0m0.001s
El único inconveniente de esta implementación es que se pierde cierta precisión en el tiempo de corte (se pasó por 55 milésimas) debido a que no verifica el tiempo con mucha regularidad. Una solución que aprovecha más recursos del sistema operativo se muestra a continuación:
#include <stdio.h>
#include <unistd.h>
#include <signal.h>

void handler(int);

int timeout=0;

int main(void)
{
int x=1, y=2, z=3;
long iter1=0,iter2=0;

signal(SIGALRM,handler);
alarm(5);
for(;;)
	{
	x=(x*3+y*7+z*9)%11;
	y=(x*9+y*11+z*3)%29;
	z=(x*17+y*13+z*11)%37;
	iter1++;
	if(iter1==1000000)
		{
		iter2++;
		iter1=0;
		}
	if(timeout)
		break;
	}
printf("Iteraciones: %ldM Resultado: %d %d %d\n",iter2,x,y,z);
return 0;
}

void handler(int s)
{
timeout=1;
}
El resultado es óptimo:
$ time ./calculo3
Iteraciones: 65M Resultado: 8 17 19

real    0m5.002s
user    0m4.977s
sys     0m0.001s
El último programa falla cuando se compila con máxima optimización en gcc (opción -O3.) Esto se debe a que el optimizador descubre que la variable timeout no es cambiada en ningún lugar de main() y asume (erroneamente) que nadie más la altera, por lo que genera un código que no la verifica y el loop for() se torna infinito. Una forma estándar de evitar esto consiste en declarar la variable timeout como volatile a fin de que el optimizador no haga asunciones con respecto a la misma. El código de calculo3.c cambia exactamente en una línea:
$ diff calculo3.c calculo4.c
7c7
< int timeout=0;
---
> volatile int timeout=0;
Tras compilar con optimización, el resultado es aún mejor: ciento tres millones de iteraciones.
$ gcc -O3 -o calculo4 calculo4.c
$ time ./calculo4
Iteraciones: 103M Resultado: 2 23 3

real    0m5.002s
user    0m4.977s
sys     0m0.001s

Notas

[1]

En ocasiones, por errores de configuración de partes de hardware, se emplean memorias muy lentas que obligan al CPU a "esperarlas", ocasionando que éste opere efectivamente a menor velocidad.

[2]

Para averiguar qué kernel Linux se está empleando, usar el comando "uname -r".

[3]

Si se conoce aproximadamente el tiempo total de los procesos que se analizan, se puede lanzar vmstat indicando este tiempo a fin de obtener una única muestra que ya no requerirá de este promediado.

[4]

En realidad, los tiempos para este ejemplo son demasiado breves como para tomarlos como base de análisis. Normalmente se utilizan tiempos de al menos varios minutos.