Tuning Solaris: Introducción
Este es el primero de una serie de artículos sobre la forma de medir el rendimiento de nuestro sistema Solaris. Existe mucha documentación relacionada con este tema, esta serie de artículo solo pretende ser una sencilla guía que nos permita por un lado, conocer las herramientas de las que disponemos en Solaris y por otro lado, conocer cómo podemos utilizar estas herramientas para que nos ayuden a diagnosticar problemas de rendimiento.
El objetivo de esta serie de artículo, como se ha comentado antes, es que sirvan como guía para comenzar el estudio de un
posible problema en el rendimiento del sistema, se ha organizado el contenido en 3 bloques:
- Procesos y procesadores
- Entrada/Salida
- Memoria
No solo se tratarán los distintos comandos para medir el rendimiento, sino que se explicaran algunos de los parámetros que podremos cambiar en nuestro sistema para mejorar el rendimiento, ya sea de memoria, procesador, entrada/salida, etc. De todas formas es importante conocer como pueden afectar los cambios propuestos en cada uno de nuestros sistemas y el objetivo no es dar una serie de axiomas o parámetro, los cuales deben aplicarse ciegamente, sino el que, como administradores, conozcamos
las posibilidades que tenemos para evitar problemas en el rendimiento.
Rendimiento/Tuning Solaris: Procesos y procesadores
Ahora veremos algunas de las herramientas que nos permitan identificar posibles cuellos de botella, tanto en los procesos que se están ejecutando en el sistema como en las operaciones que estén realizando los procesadores. Para ellos vamos a comenzar haciendo una aclaración sobre lo que parece, para mucha gente, un axioma indiscutible sobre el rendimiento de un sistema.“Mucho uso de CPU está directamente relacionado con un problema de rendimiento”
Aunque muchas veces esto puede ser cierto, existen casos en los que no se cumple y otros casos en los que una solución al problema, como sería aumentar el número de CPUs del sistema, no conseguiría aumentar el rendimiento. Por lo tanto no debemos alarmarnos frente a un aumento del uso de CPU, tendremos que analizar la causa para intentar dar una solución. Podemos decir, y lo comprobaremos mas adelante, que “frente a un uso alto de CPU, comprar más procesadores no garantiza que se solucione el problema.” es importante que tengamos claro este principio, ya que normalmente, cuando existe un problema de rendimiento, se suele optar por la solución rápida, comprar HW y podemos llevarnos una desagradable sorpresa, cuando descubrimos que el haber gastado una suma importante de dinero para conseguir únicamente, el el porcentaje de uso de CPU se ha reducido, pero el rendimiento del sistema es igual de malo.
El rendimiento de un procesos no se puede medir simplemente con el porcentaje de uso de CPU, existen una serie de parámetros que nos ayudarán a conocer no solo qué está haciendo el proceso, sino la causa de un posible problema de degradación en nuestro sistema.
NOTA – No podemos basar nuestro análisis del problema de rendimiento, únicamente en el uso de CPU.
Como hemos comentado, existen otros factores que puede generar un cuello de botella y no tiene por qué ser el uso de CPU, en sistemas multitareas y multithreads como es Solaris, el que un proceso decremente su rendimiento se debe principalmente a dos posibles causas:
-Externa, la lentitud en el proceso se produce por un elemento externo al proceso, como puede ser el acceso a la memoria, lentitud en los dispositivos de E/S, pésima asignación de tiempo de CPU, etc.
-Interna, en los procesos con múltiples threads, normalmente existen una serie de sincronizaciones entre los distintos threads, estas sincronizaciones, pueden provocar bloqueos entre varios de los threads, produciendo una pérdida del rendimiento del proceso.
Tendremos que analizar si la causa de que el rendimiento del proceso no es el esperado está en el propio proceso, que a su vez está afectando al rendimiento del resto de procesos del sistema o por el contrario, la razón de la pérdida de rendimiento se debe un causa externa al proceso.
Nuestro análisis debe comenzar desde un punto de vista global, hasta desembocar en un foco concreto, no es buena idea centrarnos, a priori, en un elemento particular, ya que esto, nos podría evitar ver la causa del problema en otro elemento que no esté relacionado con el que nosotros pensamos que es la causa de todo el problema.
Estado del sistema
El primer paso para el diagnóstico de un problema en el sistema, es ver de forma global el estado en el que se encuentra. Tenemos que conocer qué se está ejecutando en el sistema, para ello, utilizaremos el comando prstat.
# prstat
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
23288 app01 1592M 1255M sleep 29 10 7:13:46 34.8% java/129
9302 app01 1322M 911M sleep 29 10 7:49:56 3.7% java/76
23647 app01 8920K 8504K sleep 49 0 0:00:00 0.6% perl/1
23681 app01 56M 12M cpu0 0 10 0:00:00 0.4% java/8
23672 app01 5552K 5000K sleep 0 0 0:00:00 0.3% perl/1
1425 root 13M 5704K sleep 59 0 46:41:35 0.2% scopeux/1
13 root 12M 9128K sleep 59 0 17:09:01 0.1% vxconfigd/1
18985 app01 734M 562M sleep 29 10 0:10:15 0.1% java/100
22690 jjmora 2456K 2168K cpu3 59 0 0:00:00 0.1% prstat/1
26948 root 57M 11M sleep 59 0 0:26:15 0.1% java/9
442 root 4720K 4024K sleep 59 0 14:57:55 0.0% picld/6
1465 root 2648K 2216K sleep 59 0 3:42:50 0.0% vold/2
23287 app01 1639M 1180M sleep 29 10 2:42:39 0.0% java/131
29782 root 5248K 3448K sleep 59 0 0:46:40 0.0% NICAgent/13
1 root 1320K 768K sleep 59 0 2:02:59 0.0% init/1
23648 app01 1008K 776K sleep 59 0 0:00:00 0.0% grep/1
29784 root 5192K 3240K sleep 59 0 0:16:13 0.0% Notifier/13
12556 app01 63M 57M sleep 59 0 0:01:20 0.0% adr3/57
19640 app01 119M 62M sleep 29 10 0:00:16 0.0% java/20
3363 app01 98M 39M sleep 29 10 0:00:18 0.0% java/20
Total: 167 processes, 1854 lwps, load averages: 4.61, 4.30, 3.71
Como podemos comprobar, el comando prstat nos permite disponer de una primera visión de qué se está ejecutando en nuestros sistema. En el ejemplo, lo primero que nos llama la atención es el proceso con PID 23288, es un proceso java con 129 threads, a priori y sin ningún diagnóstico previo, podemos pensar que la causa del problema es este proceso, pero no podemos parar aquí nuestro análisis, ya que puede que la causa de lentitud del sistema no se deba solo a este proceso y sea un elemento ajeno a él la razón de la lentitud.
Lo que si nos debe llamar la atención, es el crecimiento que se está produciendo en la carga media del sistema load averages: 4.61, 4.30, 3.71, que podemos ver que está creciendo.
mpstat
Como segundo paso vamos a ver qué está ocurriendo con los procesadores del sistema, es decir, en qué están empleando su tiempo, esto nos ayudará a que nos aproximemos al diagnostico. Para ver qué están haciendo los procesadores de nuestro sistema utilizaremos el comando mpstat. La salida del comando muestra una fila por cada uno de los procesadores presentes en el sistema y una serie de columnas con estadísticas sobre distintos elementos, cada una de las columnas vienen explicadas en la documentación del man, por lo tanto no vamos a perder tiempo explicándolas y solo vamos a ver las que pueden ser más intersante para nosotros en estos momentos.
# mpstat 1
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 737 0 172 229 3 2429 143 500 72 0 3903 40 10 0 50
1 627 0 185 235 7 2461 152 519 95 0 4429 42 12 0 46
2 342 0 414 222 4 2872 140 608 109 0 3818 23 8 0 69
3 492 0 691 2252 2139 2258 52 447 191 1 3815 31 9 0 60
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 1046 0 556 234 2 2494 155 504 95 0 10747 44 11 0 46
1 844 0 882 225 7 2327 162 556 114 0 10418 43 15 0 43
2 619 0 842 236 3 3055 164 693 126 0 4954 32 9 0 59
3 816 0 913 2053 1933 1795 96 449 203 0 10199 54 11 0 35
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 795 0 255 361 3 3249 290 772 81 0 5503 60 6 0 34
1 868 0 556 353 11 2789 307 745 72 0 5091 54 20 0 26
2 654 0 1049 358 2 3131 320 847 95 0 5175 55 14 0 31
3 1161 0 1187 2673 2543 2319 203 646 210 0 5291 59 20 0 21
De todas las columnas vamos a centrar nuestro análisis únicamente en las siguientes:
minf, fallos menores de memoria, estos fallos afectan a los accesos a memoria y se tratan de fallos de cache, por lo tanto no afectan, de forma directa, al rendimiento del sistema. Este tipo de fallos nos pueden servir de indicativo sobre el comportamiento de la aplicación. Los fallos de memoria se deben analizar dentro del contexto de uso de memoria.
xcall, refleja el número de cross-call de cada procesador. Las cross-call son llamadas que realiza un procesador a otro, a modo de interrupciones, para indicarle que debe realizar alguna operación. Las cross-call las suelen utilizar los procesadores para informar de cambios en las caches de la MMU. Un número elevado de cross-call
puede indicarnos un problema de rendimiento en las caches, de todas formas, el que se produzacan muchas llamadas de este tipo provocará que los procesadores consuman mucho tiempo atendiendo dichas interrupciones y por lo tanto afecten al rendimiento.
csw y icsw, cambio de contexto voluntario y cambio de contexto involuntario. El número de cambios de contexto dependerá, principalmente del número de procesos que se estén ejecutando en el sistema, recordemos que un cambio de contexto consiste en el proceso por el cual el kernel detiene un proceso que se está ejecutando en un procesador, elije otro proceso de la cola de ejecución, actualiza los registros del procesador con la información del nuevo proceso y el procesador continua ejecutando el nuevo proceso en el punto donde fue parado previamente por otro cambio de contexto. Cuando el Kernel tiene que elegir un proceso para sacarlo de un procesador, tiene 2 opciones, elegir uno que esté esperando un dato de E/S, por ejemplo leyendo de disco, a esto se le llama un cambio de contexto voluntario, es el proceso el que anuncia que no está haciendo nada en ese instante o elegir uno de los que no están esperando E/S, esto se conoce como cambio de contexto involuntario. Si el valor de icsw se bastante superior a csw, podemos decir, que el Kernel está sacando de los procesadores a procesos que están ejecutando código que no está en un estado de espera, sino que está ejecutando código y que es el propio kernel el que está ralentizando la ejecución de esos procesos en concreto. Por otra parte no debemos entender esto como un problema del Kernel, sino más bien, un problema con el número de procesos que se están ejecutando, debería intentar reducir el factor procesos/CPU, bien bajando el número de procesos, bien aumentando el número de CPUs.
smtx, presenta el número de veces que se ha intentado acceder a un mutex y no se ha conseguido en el primer intento. Podemos considerar que existe un problema de contención con los mutex, si el valor de smtx es superior a 300 intentos por CPU y el valor de sys > usr, esto significaría que el Kernel está consumiendo CPU intentando acceder a una serie de mutex sin conseguirlo.
srw, presenta el número de veces que se ha intentado acceder a un lock de tipo lectura/escritura y no se ha conseguido en el primer intento.
syscl, número de llamadas ejecutadas por cada CPU.
kstat
Este comando nos permite visualizar una serie de datos estadísticos del Kernel. Mediante kstat podemos obtener la misma información que obtendremos con los comandos mpstat, vmstat, etc. Los valores que devuelve el comando kstat son contadores, por lo tanto, tendremos que ser nosotros los que calculemos los valores realizando una sencilla resta. Las estadísticas del Kernel están organizadas de la siguiente forma módulo:instancia:nombre:estadistica
si ejecutamos el comando kstat tal cual, la salida será parecida a la siguiente.
(root@camtrunet)# kstat
...
module: cpu_info instance: 0
name: cpu_info0 class: misc
chip_id 0
clock_MHz 1062
cpu_type sparcv9
crtime 147.6276642
device_ID 209202519330
fpu_type sparcv9
implementation UltraSPARC-IIIi
snaptime 25738067.4963142
state on-line
state_begin 1154200415
module: cpu_info instance: 1
name: cpu_info1 class: misc
chip_id 1
clock_MHz 1062
...
De toda la información que podemos obtener con kstat, nos interesa la que se almacena en el módulo unix:*:sysinfo, es algo parecido a la siguiente salida.
(root@camtrunet)# kstat -p unix:*:sysinfo
unix:0:sysinfo:class misc
unix:0:sysinfo:crtime 85.4492862
unix:0:sysinfo:runocc 1600644
unix:0:sysinfo:runque 15857131
unix:0:sysinfo:snaptime 25738291.5173894
unix:0:sysinfo:swpocc 0
unix:0:sysinfo:swpque 0
unix:0:sysinfo:updates 25737884
unix:0:sysinfo:waiting 346454
#
Donde las estadisticas almacenan los siguientes datos.
Estadística Descripción
runque Procesos en la cola de ejecución
swpquea Procesos en la SWAP
waiting Procesos esperando E/S
Estos 3 datos, también los podemos obtener del comando vmstat pero esto lo veremos más adelante. De la información obtenida, debemos tener en cuenta que, el número de procesos en la cola de ejecución no debe ser alto, ya que un número alto de procesos en esta cola, significa que hay procesos esperando para que se les asigne un procesador, podemos considerar como número alto el que en la cola haya más de 5 procesos por cada CPU del sistema. Un número elevado de
procesos en swap nos avisará de un posible problema con la memoria del sistema, ya que el Kernel ha tenido que pasar algunos procesos al área de swap, previsiblemente por falta de espacio en la memoria del sistema. Y un número elevado de procesos en waiting nos indicará un problema de accesos en la E/S a algún dispositivo.
truss
Hasta la aparición en escena de Dtrace con Solaris 10, el comando truss ha sido herramienta esencial para la identificación de problemas en el rendimiento del sistema. Con el comando truss podremos ver, las llamadas a sistema que esté realizando un proceso en ejecución, los valores de los distintos parámetros de las llamadas, los valores devueltos, los errores devueltos por las llamadas, etc. Cuando tenemos un problema en el rendimiento del sistema, verificar si los procesos, que pensamos son la causa de la degradación, están haciendo lo que creemos que deben estar haciendo, es una tarea importante, ya que mucha gente (yo diría demasiada), cuando crean software no se preocupan de gestionar los errores que o bien puede generar la aplicación, o bien la aplicación se encuentra, como por ejemplo el intentar acceder a un fichero que no existe, el enviar datos utilizando un socket que se ha cerrado, etc. Estos errores frecuentemente está directamente relacionadas con la caida del rendimiento en las aplicaciones.
truss nos puede ayudar a localizar todos los errores o causas de la pérdida del rendimiento. Por ejemplo, nos puede ayudar a descubrir posible contención en el acceso a un fichero o los fallos generados al intentar acceder a un mutex. Las posibilidades de truss van mucho más allá de lo que podemos ver en este sencillo artículo, de todas formas, para que nos sirva como ejemplo y sin entrar en excesivos detalles, vamos a utilizar el comando truss con el el parámetro -c, para que nos muestre una serie de estadísticas sobre las distintas llamadas a sistema que está ejecutando un proceso.
(root@camtrunet)# truss -c -p 14178
^Csyscall seconds calls errors
read .119 5252 36
write .002 41
close .000 19
fcntl .003 19
poll .016 310
lwp_mutex_wakeup .001 7034
lwp_mutex_lock .002 6128
lwp_cond_wait .002 5327 26
lwp_cond_signal .000 121
lwp_cond_broadcast .000 300
accept .006 19
send .119 2689
setsockopt .003 38
-------- ------ ----
sys totals: .278 8617 62
usr time: 1.337
elapsed: 11.940
(root@camtrunet)#
Para poder interpretar los datos que devuelve truss, debemos conocer algunas de las llamadas a sistema, todas las llamadas a sistema están documentadas perfectamente en el man del sistema. Con la salida obtenida del ejemplo anterior, podemos decir, que quizás exista un problema de acceso a un mutex por parte de algunos LWP (Lightweight process) del proceso. Que un proceso tenga una gran cantidad de operaciones sobre un mutex puede significar, dependiendo de si dichas operaciones son todas sobre un mismo mutex o sobre varios, que los LWP del proceso están luchando por obtener acceso al mutex y por lo tanto, que existe un recurso compartido que está provocando una reducción del rendimiento de la aplicación.
La columna de errores nos puede dar una pista de la causa de la pérdida de rendimiento, por ejemplo que se deba a un número excesivos de intentos de acceso a un elemento que no existe o de una forma que no es la correcta, en el siguiente ejemplo, tenemos la salida del comando truss, la cual nos muestra un posible problema con las llamadas read.
(root@camtrunet)# truss -c -p 21182
^Csyscall seconds calls errors
read .214 2336 1754
time .000 26
poll .000 11
sigprocmask .000 2
waitid .000 1
fork1 .000 1
lwp_suspend .000 2
lwp_continue .000 2
nanosleep .000 10
lwp_schedctl .000 3
-------- ------ ----
sys totals: .002 64 1754
En la columna de errores de la llamada read(), de 2336 llamadas, 1754 son errores, está claro que tenemos un problema con las llamadas de lectura de este proceso, ahora tendremos que averiguar, si los errores afectan a todos los LWP del proceso, si el problema se reproduce en todos los descriptores de ficheros o está localizados en uno en concreto, etc. Dependiendo del resultado de este análisis podremos identificar la causa.
lockstat
En el man de este comando podemos leer que nos facilita información sobre los candados (locks) en el kernel. Antes de continuar debemos hacer una aclaración sobre uno de los tipos de objetos que se utilizan para la sincronización entre threads en Solaris, los mutex. Un mutex es un objeto de exclusión mutua, que solo permite que un thread acceda al recurso controlado por dicho mutex, por lo tanto una de las causas que pueden producir una reducción en el rendimiento de nuestro sistema, es que varios threads intenten hacerse a un mismo mutex. Con lockstat podemos identificar qué está intentando bloquear un mutex.
En Solaris encontramos dos tipos de candados, los spin locks y los block locks. Los candados de tipo spin son aquellos en los que los threads no dejan de intentar acceder a él, independientemente de que el candado esté bloqueado o no, este tipo de candado se implementa cuando queremos que los threads estén continuamente ejecutándose
intentando acceder al candado y sin perder tiempo en esperar algún timeout. Sencillamente el thread más rápido en solicitar el candado, justo después de que el candado se ha liberado, será el afortunado. Los candados de tipo block no utilizan un método tan agresivo como los spin, sino que los threads que intentan acceder a un candado de tipo block que esté bloqueado, sencillamente se bloquean a la espera de que el candado vuelva a ser liberado, estos candado son más lentos con respecto a los anteriores, ya que los procesos deben ser avisados de que el candado se ha liberado. Los candados de tipo block se suelen utilizar para acceder a recursos de E/S.
Por lo tanto en Solaris podemos encontrar candados de tipo spin o mutex spin y candados de tipo block o mutex block, además de estos dos tipos existe un tercer tipo de candado, el cual será de tipo spin o de tipo block, dependiendo del estado en el que esté el thread que lo tiene bloqueado, este tipo de candado se conoce con el nombre de adaptative lock. Si el thread que tiene bloqueado el candado al que queremos acceder está corriendo, todos los threads que están intentando acceder a dicho candado se comportarán como si fuese un spin lock, si por el contrario, el thread que está utilizando el candado, está en un estado bloqueado, por ejemplo, porque esté esperado datos de E/S, todos los threads que estén intentando acceder al cando, se comportarán como si el candado fuese de tipo block locks.
Una vez que tenemos claro los distintos tipos de candados que nos podemos encontrar, vamos a continuar con el comando lockstat para ver algunas de las posibilidades que nos ofrece. Ejecutamos lockstat y le pasamos como parámetro -b para que devuelva una salida básica y el comando sleep 1 para que no devuelva la información de los candados durante la ejecución del comando sleep. La salida devuelta será parecida a la siguiente:
(root@camtrunet)# lockstat -b sleep 1
Adaptive mutex spin: 600 events in 1.000 seconds (600 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
95 16% 16% 1.00 0x30000306000 callout_execute+0x98
89 15% 31% 1.00 0x3000599a420 qfestart+0x294
54 9% 40% 1.00 0x3000030f000 callout_execute+0x98
51 8% 48% 1.00 0x30000306000 untimeout+0x18
45 8% 56% 1.00 0x30000309000 callout_execute+0x98
38 6% 62% 1.00 0x30000306000 timeout_common+0x4
31 5% 67% 1.00 0x30000309000 untimeout+0x18
25 4% 71% 1.00 0x3000030f000 untimeout+0x18
19 3% 75% 1.00 0x3000030c000 untimeout+0x18
...
1 0% 99% 1.00 0x30092298670 putnext+0x54
1 0% 99% 1.00 0x3008228a418 putnext+0x54
1 0% 99% 1.00 0x300002cdaf8 taskq_d_thread+0x78
1 0% 99% 1.00 0x30003561d00 trap_cleanup+0xe8
1 0% 100% 1.00 0x300002cda08 taskq_d_thread+0x78
1 0% 100% 1.00 0x300002cda08 taskq_bucket_dispatch+0x4
1 0% 100% 1.00 0x30003561d00 post_syscall+0x2f4
1 0% 100% 1.00 0x30003561d00 syslwp_continue+0x8
-------------------------------------------------------------------------------
Adaptive mutex block: 9 events in 1.000 seconds (9 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
2 22% 22% 1.00 0x30000309000 timeout_common+0x4
2 22% 44% 1.00 0x3000030f000 untimeout+0x18
1 11% 56% 1.00 0x3008228a418 cv_wait_sig+0x1a4
1 11% 67% 1.00 0x30000309000 untimeout+0x18
1 11% 78% 1.00 0x30092298670 cv_wait_sig+0x1a4
1 11% 89% 1.00 0x30000303000 timeout_common+0x4
1 11% 100% 1.00 0x3000001fa00 kmem_cache_free+0x50
-------------------------------------------------------------------------------
Spin lock spin: 246 events in 1.000 seconds (246 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
78 32% 32% 1.00 cpu[2]+0x90 setbackdq+0x29c
51 21% 52% 1.00 cpu[1]+0x90 setbackdq+0x29c
46 19% 71% 1.00 cpu[0]+0x90 setbackdq+0x29c
17 7% 78% 1.00 cpu[2]+0x90 disp+0x90
15 6% 84% 1.00 cpu[0]+0x90 disp+0x90
9 4% 88% 1.00 cp_default disp_getbest+0x4
8 3% 91% 1.00 cpu[1]+0x90 disp+0x90
6 2% 93% 1.00 cpu[1]+0x90 setfrontdq+0x108
6 2% 96% 1.00 cpu[0]+0x90 setfrontdq+0x108
5 2% 98% 1.00 cpu[2]+0x90 setfrontdq+0x108
2 1% 99% 1.00 sleepq_head+0x1ae8 cv_block+0x98
1 0% 99% 1.00 cpu[1]+0x90 setkpdq+0x148
1 0% 100% 1.00 cpu[3]+0x90 disp+0x90
1 0% 100% 1.00 cpu[3]+0x90 setbackdq+0x29c
-------------------------------------------------------------------------------
Thread lock spin: 5 events in 1.000 seconds (5 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
1 20% 20% 1.00 sleepq_head+0x848 ts_update_list+0x6c
1 20% 40% 1.00 sleepq_head+0x828 setrun+0x4
1 20% 60% 1.00 cpu[1]+0xd0 preempt+0x1c
1 20% 80% 1.00 sleepq_head+0x1118 setrun+0x4
1 20% 100% 1.00 cpu[1]+0xd0 ts_tick+0x8
-------------------------------------------------------------------------------
R/W writer blocked by readers: 1 events in 1.000 seconds (1 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
1 100% 100% 1.00 0x30011f01df8 as_map+0x40
-------------------------------------------------------------------------------
(root@camtrunet)#
Podemos ver en la salida anterior, que hay una sección por cada tipo de candado al que se intenta acceder, por lo tanto, podemos obtener el número de peticiones a candados de tipo Spin lock spin, en nuestro ejemplo,
se producen 246 eventos en 1 segundo. De la salida podemos destacar las siguiente columnas, Count con el
número de intentos para acceder a un candado, Lock con los nombres del los candados
y Caller con las direcciones de los objetos que han intentado el acceso al candado. Estas 3 columnas nos
pueden ayudar a identificar un posible problema de contención en algún candado y si este problema de acceso
a un candado está produciendo una degradación del rendimiento de nuestro sistema.
Spin lock spin y Adaptive mutex spin
Tener un número alto de intentos sobre candados de estos dos tipos, puede provocar que la cantidad de tiempo asignada
al sistema SYS aumente, obligando al sistema a reducir la cantidad de tiempo que se asigna al usuario y por lo
tanto, se producirá una pérdida de rendimiento es todos los procesos de usuario, al recibir menos tiempo de CPU por parte
del Kernel.
Adaptive mutex block
Si en la salida del comando lockstat vemos que el número de este tipo de candados es considerablemente mayor
que cualquiera de los otros tipos, quizás tengamos un problema con el acceso a un recurso, el cual está bloqueando, tanto
al thread que lo está utilizando como a todos aquellos que están intentando acceder a él. Como este
tipo de bloqueos no produce un aumento del uso de CPU, el problema de rendimiento no se detectará a simple vista
mediante el valor de uso de CPU, por lo que es aconsejable, siempre que tengamos dudas del rendimiento de nuestro
sistema, aunque el uso de CPU no sea alto, que realicemos un pequeño análisis de los candados mediante el
comando lockstat.
cpustat y cputrack
Los procesadores SPARC disponen de una serie de contadores, lo cuales podemos consultar para medir el rendimiento de
ciertas operaciones a nivel de los procesadores. Estos contadores nos permitirán descubrir posibles cuellos de
botellas en los procesadores, bien por el número de instrucciones que se estén ejecutando, bien por el nivel de aciertos en las distintas caches.
La información almacenada en los contadores, dependerá del tipo de procesador que tenga nuestro sistema, por lo tanto,
antes de utilizar este comando, debemos comprobar cuales son los contadores disponibles, para ello solo tendremos
que ejecutar cpustat con el parámetro -h.
(root@camtrunet)# cpustat -h
Usage:
cpustat [-c events] [-nhD] [interval [count]]
-c events specify processor events to be monitored
-n suppress titles
-t include %tick register
-D enable debug mode
-h print extended usage information
Use cputrack(1) to monitor per-process statistics.
CPU performance counter interface: UltraSPARC IIIi & IIIi+
events pic0=,pic1=[,sys][,nouser]
event0: Cycle_cnt Instr_cnt Dispatch0_IC_miss IC_ref DC_rd DC_wr
EC_ref EC_snoop_inv Dispatch0_br_target Dispatch0_2nd_br
Rstall_storeQ Rstall_IU_use EC_write_hit_RTO EC_rd_miss
PC_port0_rd SI_snoop SI_ciq_flow SI_owned SW_count_0
IU_Stat_Br_miss_taken IU_Stat_Br_count_taken
Dispatch_rs_mispred FA_pipe_completion MC_read_dispatched
MC_write_dispatched MC_read_returned_to_JBU
MC_msl_busy_stall MC_mdb_overflow_stall MC_miu_spec_request
event1: Cycle_cnt Instr_cnt Dispatch0_mispred EC_wb EC_snoop_cb
IC_miss_cancelled Re_FPU_bypass Re_DC_miss Re_EC_miss
IC_miss DC_rd_miss DC_wr_miss Rstall_FP_use EC_misses
EC_ic_miss Re_PC_miss ITLB_miss DTLB_miss WC_miss
WC_snoop_cb WC_scrubbed WC_wb_wo_read PC_soft_hit
PC_snoop_inv PC_hard_hit PC_port1_rd SW_count_1
IU_Stat_Br_miss_untaken IU_Stat_Br_count_untaken
PC_MS_misses Re_RAW_miss FM_pipe_completion
MC_open_bank_cmds MC_reads MC_writes MC_page_close_stall
Re_DC_missovhd
See the "SPARC V9 JPS1 Implementation Supplement: Sun
UltraSPARC-IIIi"
(root@camtrunet)#
La utilización del comando es bastante sencilla, acepta un evento en cada contador, solo le tenemos que decir qué eventos
queremos monitorizar, el intervalo en segundos y el número de repeticiones. Vamos a ejecutar el comando cpustat, cada segundo, 5 veces, para que nos devuelva el contador Cycle_cnt, el cual almacena el número de ciclos de CPU y Instr_cnt que nos dice cuantas instrucciones se han ejecutando, el comando devuelve una línea por cada CPU.
(root@camtrunet)# cpustat -c pic0=Cycle_cnt,pic1=Instr_cnt 1 5
time cpu event pic0 pic1
1.006 1 tick 5253507 2214596
1.006 0 tick 5906614 1840943
2.006 1 tick 751843 173146
2.006 0 tick 694595 118216
3.006 1 tick 557997 194365
3.006 0 tick 1166984 271610
4.006 1 tick 5253396 2321969
4.006 0 tick 4473184 1284188
5.006 1 tick 781913 223580
5.006 0 tick 474001 70561
5.006 2 total 25314034 8713174
(root@camtrunet)#
Como ya hemos comentado, los contadores que se pueden monitorizar con el comando cpustat dependen del tipo de procesador que tenga nuestro sistema, por lo tanto, tendremos que recurrir a la documentación especifica de cada procesador. En nuestro ejemplo, el procesador que está utilizando la máquina es un UltraSPARC-IIIi y algunos de los contadores son los siguientes:
Contador Descripción
Cycle_cnt Contador de cilclos
Instr_cnt Instrucciones ejecutadas
IC_miss Fallos en la cache de instrucciones
DC_rd_miss Fallos de lectura en la cache
DC_rw_miss Fallos de escritura en la cache
ITLB_miss Fallos de instrucciones en la TLB
DTLB_miss Fallos de datos en la TLB
EC_misses Fallos en la cache externa
La mayoría de los contadores, los veremos más adelante, cuando hablemos de la memoria, ya que los más relevantes hacen referencia a estadísticas sobre elementos como las caches.
El comando cputrack tiene la misma finalidad que cpustat, pero con la diferencia que podemos analizar los distintos eventos referidos únicamente a un proceso, ya sea en ejecución o que lo lancemos con el propio comando cputrack.
(root@camtrunet)# cputrack -T 1 -N 10 -c pic0=Cycle_cnt,pic1=Instr_cnt sleep 5
time lwp event pic0 pic1
1.012 1 tick 908377 302623
2.012 1 tick 0 0
3.012 1 tick 0 0
4.012 1 tick 0 0
5.002 1 exit 991739 314472
(root@camtrunet)#
En el ejemplo anterior, hemos visto el contador de cliclo y el de instrucciones mientras se ejecuta el comando sleep 5, le hemos pasado los párametro -T, para decirle el intervalo en segundos y -N para el número de repeticiones, como el comando sleep 5 solo dura 5 segundos, cputrack solo saca 5 líneas. Este comando nos puede ayudar a conocer cuantas instrucciones ejecuta un proceso, en caso de un problema con el acceso a las caches, podemos comprobar si es un proceso determinado el que provoca la gran mayoría de los fallos de cache, etc.
Tanto cpustat como cputrack son herramientas bastante útiles a la hora de intentar encontrar la causa de una reducción del rendimiento en nuestro sistema.
El objetivo de esta serie de artículo, como se ha comentado antes, es que sirvan como guía para comenzar el estudio de un
posible problema en el rendimiento del sistema, se ha organizado el contenido en 3 bloques:
- Procesos y procesadores
- Entrada/Salida
- Memoria
No solo se tratarán los distintos comandos para medir el rendimiento, sino que se explicaran algunos de los parámetros que podremos cambiar en nuestro sistema para mejorar el rendimiento, ya sea de memoria, procesador, entrada/salida, etc. De todas formas es importante conocer como pueden afectar los cambios propuestos en cada uno de nuestros sistemas y el objetivo no es dar una serie de axiomas o parámetro, los cuales deben aplicarse ciegamente, sino el que, como administradores, conozcamos
las posibilidades que tenemos para evitar problemas en el rendimiento.
Rendimiento/Tuning Solaris: Procesos y procesadores
Ahora veremos algunas de las herramientas que nos permitan identificar posibles cuellos de botella, tanto en los procesos que se están ejecutando en el sistema como en las operaciones que estén realizando los procesadores. Para ellos vamos a comenzar haciendo una aclaración sobre lo que parece, para mucha gente, un axioma indiscutible sobre el rendimiento de un sistema.“Mucho uso de CPU está directamente relacionado con un problema de rendimiento”
Aunque muchas veces esto puede ser cierto, existen casos en los que no se cumple y otros casos en los que una solución al problema, como sería aumentar el número de CPUs del sistema, no conseguiría aumentar el rendimiento. Por lo tanto no debemos alarmarnos frente a un aumento del uso de CPU, tendremos que analizar la causa para intentar dar una solución. Podemos decir, y lo comprobaremos mas adelante, que “frente a un uso alto de CPU, comprar más procesadores no garantiza que se solucione el problema.” es importante que tengamos claro este principio, ya que normalmente, cuando existe un problema de rendimiento, se suele optar por la solución rápida, comprar HW y podemos llevarnos una desagradable sorpresa, cuando descubrimos que el haber gastado una suma importante de dinero para conseguir únicamente, el el porcentaje de uso de CPU se ha reducido, pero el rendimiento del sistema es igual de malo.
El rendimiento de un procesos no se puede medir simplemente con el porcentaje de uso de CPU, existen una serie de parámetros que nos ayudarán a conocer no solo qué está haciendo el proceso, sino la causa de un posible problema de degradación en nuestro sistema.
NOTA – No podemos basar nuestro análisis del problema de rendimiento, únicamente en el uso de CPU.
Como hemos comentado, existen otros factores que puede generar un cuello de botella y no tiene por qué ser el uso de CPU, en sistemas multitareas y multithreads como es Solaris, el que un proceso decremente su rendimiento se debe principalmente a dos posibles causas:
-Externa, la lentitud en el proceso se produce por un elemento externo al proceso, como puede ser el acceso a la memoria, lentitud en los dispositivos de E/S, pésima asignación de tiempo de CPU, etc.
-Interna, en los procesos con múltiples threads, normalmente existen una serie de sincronizaciones entre los distintos threads, estas sincronizaciones, pueden provocar bloqueos entre varios de los threads, produciendo una pérdida del rendimiento del proceso.
Tendremos que analizar si la causa de que el rendimiento del proceso no es el esperado está en el propio proceso, que a su vez está afectando al rendimiento del resto de procesos del sistema o por el contrario, la razón de la pérdida de rendimiento se debe un causa externa al proceso.
Nuestro análisis debe comenzar desde un punto de vista global, hasta desembocar en un foco concreto, no es buena idea centrarnos, a priori, en un elemento particular, ya que esto, nos podría evitar ver la causa del problema en otro elemento que no esté relacionado con el que nosotros pensamos que es la causa de todo el problema.
Estado del sistema
El primer paso para el diagnóstico de un problema en el sistema, es ver de forma global el estado en el que se encuentra. Tenemos que conocer qué se está ejecutando en el sistema, para ello, utilizaremos el comando prstat.
# prstat
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
23288 app01 1592M 1255M sleep 29 10 7:13:46 34.8% java/129
9302 app01 1322M 911M sleep 29 10 7:49:56 3.7% java/76
23647 app01 8920K 8504K sleep 49 0 0:00:00 0.6% perl/1
23681 app01 56M 12M cpu0 0 10 0:00:00 0.4% java/8
23672 app01 5552K 5000K sleep 0 0 0:00:00 0.3% perl/1
1425 root 13M 5704K sleep 59 0 46:41:35 0.2% scopeux/1
13 root 12M 9128K sleep 59 0 17:09:01 0.1% vxconfigd/1
18985 app01 734M 562M sleep 29 10 0:10:15 0.1% java/100
22690 jjmora 2456K 2168K cpu3 59 0 0:00:00 0.1% prstat/1
26948 root 57M 11M sleep 59 0 0:26:15 0.1% java/9
442 root 4720K 4024K sleep 59 0 14:57:55 0.0% picld/6
1465 root 2648K 2216K sleep 59 0 3:42:50 0.0% vold/2
23287 app01 1639M 1180M sleep 29 10 2:42:39 0.0% java/131
29782 root 5248K 3448K sleep 59 0 0:46:40 0.0% NICAgent/13
1 root 1320K 768K sleep 59 0 2:02:59 0.0% init/1
23648 app01 1008K 776K sleep 59 0 0:00:00 0.0% grep/1
29784 root 5192K 3240K sleep 59 0 0:16:13 0.0% Notifier/13
12556 app01 63M 57M sleep 59 0 0:01:20 0.0% adr3/57
19640 app01 119M 62M sleep 29 10 0:00:16 0.0% java/20
3363 app01 98M 39M sleep 29 10 0:00:18 0.0% java/20
Total: 167 processes, 1854 lwps, load averages: 4.61, 4.30, 3.71
Como podemos comprobar, el comando prstat nos permite disponer de una primera visión de qué se está ejecutando en nuestros sistema. En el ejemplo, lo primero que nos llama la atención es el proceso con PID 23288, es un proceso java con 129 threads, a priori y sin ningún diagnóstico previo, podemos pensar que la causa del problema es este proceso, pero no podemos parar aquí nuestro análisis, ya que puede que la causa de lentitud del sistema no se deba solo a este proceso y sea un elemento ajeno a él la razón de la lentitud.
Lo que si nos debe llamar la atención, es el crecimiento que se está produciendo en la carga media del sistema load averages: 4.61, 4.30, 3.71, que podemos ver que está creciendo.
mpstat
Como segundo paso vamos a ver qué está ocurriendo con los procesadores del sistema, es decir, en qué están empleando su tiempo, esto nos ayudará a que nos aproximemos al diagnostico. Para ver qué están haciendo los procesadores de nuestro sistema utilizaremos el comando mpstat. La salida del comando muestra una fila por cada uno de los procesadores presentes en el sistema y una serie de columnas con estadísticas sobre distintos elementos, cada una de las columnas vienen explicadas en la documentación del man, por lo tanto no vamos a perder tiempo explicándolas y solo vamos a ver las que pueden ser más intersante para nosotros en estos momentos.
# mpstat 1
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 737 0 172 229 3 2429 143 500 72 0 3903 40 10 0 50
1 627 0 185 235 7 2461 152 519 95 0 4429 42 12 0 46
2 342 0 414 222 4 2872 140 608 109 0 3818 23 8 0 69
3 492 0 691 2252 2139 2258 52 447 191 1 3815 31 9 0 60
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 1046 0 556 234 2 2494 155 504 95 0 10747 44 11 0 46
1 844 0 882 225 7 2327 162 556 114 0 10418 43 15 0 43
2 619 0 842 236 3 3055 164 693 126 0 4954 32 9 0 59
3 816 0 913 2053 1933 1795 96 449 203 0 10199 54 11 0 35
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 795 0 255 361 3 3249 290 772 81 0 5503 60 6 0 34
1 868 0 556 353 11 2789 307 745 72 0 5091 54 20 0 26
2 654 0 1049 358 2 3131 320 847 95 0 5175 55 14 0 31
3 1161 0 1187 2673 2543 2319 203 646 210 0 5291 59 20 0 21
De todas las columnas vamos a centrar nuestro análisis únicamente en las siguientes:
minf, fallos menores de memoria, estos fallos afectan a los accesos a memoria y se tratan de fallos de cache, por lo tanto no afectan, de forma directa, al rendimiento del sistema. Este tipo de fallos nos pueden servir de indicativo sobre el comportamiento de la aplicación. Los fallos de memoria se deben analizar dentro del contexto de uso de memoria.
xcall, refleja el número de cross-call de cada procesador. Las cross-call son llamadas que realiza un procesador a otro, a modo de interrupciones, para indicarle que debe realizar alguna operación. Las cross-call las suelen utilizar los procesadores para informar de cambios en las caches de la MMU. Un número elevado de cross-call
puede indicarnos un problema de rendimiento en las caches, de todas formas, el que se produzacan muchas llamadas de este tipo provocará que los procesadores consuman mucho tiempo atendiendo dichas interrupciones y por lo tanto afecten al rendimiento.
csw y icsw, cambio de contexto voluntario y cambio de contexto involuntario. El número de cambios de contexto dependerá, principalmente del número de procesos que se estén ejecutando en el sistema, recordemos que un cambio de contexto consiste en el proceso por el cual el kernel detiene un proceso que se está ejecutando en un procesador, elije otro proceso de la cola de ejecución, actualiza los registros del procesador con la información del nuevo proceso y el procesador continua ejecutando el nuevo proceso en el punto donde fue parado previamente por otro cambio de contexto. Cuando el Kernel tiene que elegir un proceso para sacarlo de un procesador, tiene 2 opciones, elegir uno que esté esperando un dato de E/S, por ejemplo leyendo de disco, a esto se le llama un cambio de contexto voluntario, es el proceso el que anuncia que no está haciendo nada en ese instante o elegir uno de los que no están esperando E/S, esto se conoce como cambio de contexto involuntario. Si el valor de icsw se bastante superior a csw, podemos decir, que el Kernel está sacando de los procesadores a procesos que están ejecutando código que no está en un estado de espera, sino que está ejecutando código y que es el propio kernel el que está ralentizando la ejecución de esos procesos en concreto. Por otra parte no debemos entender esto como un problema del Kernel, sino más bien, un problema con el número de procesos que se están ejecutando, debería intentar reducir el factor procesos/CPU, bien bajando el número de procesos, bien aumentando el número de CPUs.
smtx, presenta el número de veces que se ha intentado acceder a un mutex y no se ha conseguido en el primer intento. Podemos considerar que existe un problema de contención con los mutex, si el valor de smtx es superior a 300 intentos por CPU y el valor de sys > usr, esto significaría que el Kernel está consumiendo CPU intentando acceder a una serie de mutex sin conseguirlo.
srw, presenta el número de veces que se ha intentado acceder a un lock de tipo lectura/escritura y no se ha conseguido en el primer intento.
syscl, número de llamadas ejecutadas por cada CPU.
kstat
Este comando nos permite visualizar una serie de datos estadísticos del Kernel. Mediante kstat podemos obtener la misma información que obtendremos con los comandos mpstat, vmstat, etc. Los valores que devuelve el comando kstat son contadores, por lo tanto, tendremos que ser nosotros los que calculemos los valores realizando una sencilla resta. Las estadísticas del Kernel están organizadas de la siguiente forma módulo:instancia:nombre:estadistica
si ejecutamos el comando kstat tal cual, la salida será parecida a la siguiente.
(root@camtrunet)# kstat
...
module: cpu_info instance: 0
name: cpu_info0 class: misc
chip_id 0
clock_MHz 1062
cpu_type sparcv9
crtime 147.6276642
device_ID 209202519330
fpu_type sparcv9
implementation UltraSPARC-IIIi
snaptime 25738067.4963142
state on-line
state_begin 1154200415
module: cpu_info instance: 1
name: cpu_info1 class: misc
chip_id 1
clock_MHz 1062
...
De toda la información que podemos obtener con kstat, nos interesa la que se almacena en el módulo unix:*:sysinfo, es algo parecido a la siguiente salida.
(root@camtrunet)# kstat -p unix:*:sysinfo
unix:0:sysinfo:class misc
unix:0:sysinfo:crtime 85.4492862
unix:0:sysinfo:runocc 1600644
unix:0:sysinfo:runque 15857131
unix:0:sysinfo:snaptime 25738291.5173894
unix:0:sysinfo:swpocc 0
unix:0:sysinfo:swpque 0
unix:0:sysinfo:updates 25737884
unix:0:sysinfo:waiting 346454
#
Donde las estadisticas almacenan los siguientes datos.
Estadística Descripción
runque Procesos en la cola de ejecución
swpquea Procesos en la SWAP
waiting Procesos esperando E/S
Estos 3 datos, también los podemos obtener del comando vmstat pero esto lo veremos más adelante. De la información obtenida, debemos tener en cuenta que, el número de procesos en la cola de ejecución no debe ser alto, ya que un número alto de procesos en esta cola, significa que hay procesos esperando para que se les asigne un procesador, podemos considerar como número alto el que en la cola haya más de 5 procesos por cada CPU del sistema. Un número elevado de
procesos en swap nos avisará de un posible problema con la memoria del sistema, ya que el Kernel ha tenido que pasar algunos procesos al área de swap, previsiblemente por falta de espacio en la memoria del sistema. Y un número elevado de procesos en waiting nos indicará un problema de accesos en la E/S a algún dispositivo.
truss
Hasta la aparición en escena de Dtrace con Solaris 10, el comando truss ha sido herramienta esencial para la identificación de problemas en el rendimiento del sistema. Con el comando truss podremos ver, las llamadas a sistema que esté realizando un proceso en ejecución, los valores de los distintos parámetros de las llamadas, los valores devueltos, los errores devueltos por las llamadas, etc. Cuando tenemos un problema en el rendimiento del sistema, verificar si los procesos, que pensamos son la causa de la degradación, están haciendo lo que creemos que deben estar haciendo, es una tarea importante, ya que mucha gente (yo diría demasiada), cuando crean software no se preocupan de gestionar los errores que o bien puede generar la aplicación, o bien la aplicación se encuentra, como por ejemplo el intentar acceder a un fichero que no existe, el enviar datos utilizando un socket que se ha cerrado, etc. Estos errores frecuentemente está directamente relacionadas con la caida del rendimiento en las aplicaciones.
truss nos puede ayudar a localizar todos los errores o causas de la pérdida del rendimiento. Por ejemplo, nos puede ayudar a descubrir posible contención en el acceso a un fichero o los fallos generados al intentar acceder a un mutex. Las posibilidades de truss van mucho más allá de lo que podemos ver en este sencillo artículo, de todas formas, para que nos sirva como ejemplo y sin entrar en excesivos detalles, vamos a utilizar el comando truss con el el parámetro -c, para que nos muestre una serie de estadísticas sobre las distintas llamadas a sistema que está ejecutando un proceso.
(root@camtrunet)# truss -c -p 14178
^Csyscall seconds calls errors
read .119 5252 36
write .002 41
close .000 19
fcntl .003 19
poll .016 310
lwp_mutex_wakeup .001 7034
lwp_mutex_lock .002 6128
lwp_cond_wait .002 5327 26
lwp_cond_signal .000 121
lwp_cond_broadcast .000 300
accept .006 19
send .119 2689
setsockopt .003 38
-------- ------ ----
sys totals: .278 8617 62
usr time: 1.337
elapsed: 11.940
(root@camtrunet)#
Para poder interpretar los datos que devuelve truss, debemos conocer algunas de las llamadas a sistema, todas las llamadas a sistema están documentadas perfectamente en el man del sistema. Con la salida obtenida del ejemplo anterior, podemos decir, que quizás exista un problema de acceso a un mutex por parte de algunos LWP (Lightweight process) del proceso. Que un proceso tenga una gran cantidad de operaciones sobre un mutex puede significar, dependiendo de si dichas operaciones son todas sobre un mismo mutex o sobre varios, que los LWP del proceso están luchando por obtener acceso al mutex y por lo tanto, que existe un recurso compartido que está provocando una reducción del rendimiento de la aplicación.
La columna de errores nos puede dar una pista de la causa de la pérdida de rendimiento, por ejemplo que se deba a un número excesivos de intentos de acceso a un elemento que no existe o de una forma que no es la correcta, en el siguiente ejemplo, tenemos la salida del comando truss, la cual nos muestra un posible problema con las llamadas read.
(root@camtrunet)# truss -c -p 21182
^Csyscall seconds calls errors
read .214 2336 1754
time .000 26
poll .000 11
sigprocmask .000 2
waitid .000 1
fork1 .000 1
lwp_suspend .000 2
lwp_continue .000 2
nanosleep .000 10
lwp_schedctl .000 3
-------- ------ ----
sys totals: .002 64 1754
En la columna de errores de la llamada read(), de 2336 llamadas, 1754 son errores, está claro que tenemos un problema con las llamadas de lectura de este proceso, ahora tendremos que averiguar, si los errores afectan a todos los LWP del proceso, si el problema se reproduce en todos los descriptores de ficheros o está localizados en uno en concreto, etc. Dependiendo del resultado de este análisis podremos identificar la causa.
lockstat
En el man de este comando podemos leer que nos facilita información sobre los candados (locks) en el kernel. Antes de continuar debemos hacer una aclaración sobre uno de los tipos de objetos que se utilizan para la sincronización entre threads en Solaris, los mutex. Un mutex es un objeto de exclusión mutua, que solo permite que un thread acceda al recurso controlado por dicho mutex, por lo tanto una de las causas que pueden producir una reducción en el rendimiento de nuestro sistema, es que varios threads intenten hacerse a un mismo mutex. Con lockstat podemos identificar qué está intentando bloquear un mutex.
En Solaris encontramos dos tipos de candados, los spin locks y los block locks. Los candados de tipo spin son aquellos en los que los threads no dejan de intentar acceder a él, independientemente de que el candado esté bloqueado o no, este tipo de candado se implementa cuando queremos que los threads estén continuamente ejecutándose
intentando acceder al candado y sin perder tiempo en esperar algún timeout. Sencillamente el thread más rápido en solicitar el candado, justo después de que el candado se ha liberado, será el afortunado. Los candados de tipo block no utilizan un método tan agresivo como los spin, sino que los threads que intentan acceder a un candado de tipo block que esté bloqueado, sencillamente se bloquean a la espera de que el candado vuelva a ser liberado, estos candado son más lentos con respecto a los anteriores, ya que los procesos deben ser avisados de que el candado se ha liberado. Los candados de tipo block se suelen utilizar para acceder a recursos de E/S.
Por lo tanto en Solaris podemos encontrar candados de tipo spin o mutex spin y candados de tipo block o mutex block, además de estos dos tipos existe un tercer tipo de candado, el cual será de tipo spin o de tipo block, dependiendo del estado en el que esté el thread que lo tiene bloqueado, este tipo de candado se conoce con el nombre de adaptative lock. Si el thread que tiene bloqueado el candado al que queremos acceder está corriendo, todos los threads que están intentando acceder a dicho candado se comportarán como si fuese un spin lock, si por el contrario, el thread que está utilizando el candado, está en un estado bloqueado, por ejemplo, porque esté esperado datos de E/S, todos los threads que estén intentando acceder al cando, se comportarán como si el candado fuese de tipo block locks.
Una vez que tenemos claro los distintos tipos de candados que nos podemos encontrar, vamos a continuar con el comando lockstat para ver algunas de las posibilidades que nos ofrece. Ejecutamos lockstat y le pasamos como parámetro -b para que devuelva una salida básica y el comando sleep 1 para que no devuelva la información de los candados durante la ejecución del comando sleep. La salida devuelta será parecida a la siguiente:
(root@camtrunet)# lockstat -b sleep 1
Adaptive mutex spin: 600 events in 1.000 seconds (600 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
95 16% 16% 1.00 0x30000306000 callout_execute+0x98
89 15% 31% 1.00 0x3000599a420 qfestart+0x294
54 9% 40% 1.00 0x3000030f000 callout_execute+0x98
51 8% 48% 1.00 0x30000306000 untimeout+0x18
45 8% 56% 1.00 0x30000309000 callout_execute+0x98
38 6% 62% 1.00 0x30000306000 timeout_common+0x4
31 5% 67% 1.00 0x30000309000 untimeout+0x18
25 4% 71% 1.00 0x3000030f000 untimeout+0x18
19 3% 75% 1.00 0x3000030c000 untimeout+0x18
...
1 0% 99% 1.00 0x30092298670 putnext+0x54
1 0% 99% 1.00 0x3008228a418 putnext+0x54
1 0% 99% 1.00 0x300002cdaf8 taskq_d_thread+0x78
1 0% 99% 1.00 0x30003561d00 trap_cleanup+0xe8
1 0% 100% 1.00 0x300002cda08 taskq_d_thread+0x78
1 0% 100% 1.00 0x300002cda08 taskq_bucket_dispatch+0x4
1 0% 100% 1.00 0x30003561d00 post_syscall+0x2f4
1 0% 100% 1.00 0x30003561d00 syslwp_continue+0x8
-------------------------------------------------------------------------------
Adaptive mutex block: 9 events in 1.000 seconds (9 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
2 22% 22% 1.00 0x30000309000 timeout_common+0x4
2 22% 44% 1.00 0x3000030f000 untimeout+0x18
1 11% 56% 1.00 0x3008228a418 cv_wait_sig+0x1a4
1 11% 67% 1.00 0x30000309000 untimeout+0x18
1 11% 78% 1.00 0x30092298670 cv_wait_sig+0x1a4
1 11% 89% 1.00 0x30000303000 timeout_common+0x4
1 11% 100% 1.00 0x3000001fa00 kmem_cache_free+0x50
-------------------------------------------------------------------------------
Spin lock spin: 246 events in 1.000 seconds (246 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
78 32% 32% 1.00 cpu[2]+0x90 setbackdq+0x29c
51 21% 52% 1.00 cpu[1]+0x90 setbackdq+0x29c
46 19% 71% 1.00 cpu[0]+0x90 setbackdq+0x29c
17 7% 78% 1.00 cpu[2]+0x90 disp+0x90
15 6% 84% 1.00 cpu[0]+0x90 disp+0x90
9 4% 88% 1.00 cp_default disp_getbest+0x4
8 3% 91% 1.00 cpu[1]+0x90 disp+0x90
6 2% 93% 1.00 cpu[1]+0x90 setfrontdq+0x108
6 2% 96% 1.00 cpu[0]+0x90 setfrontdq+0x108
5 2% 98% 1.00 cpu[2]+0x90 setfrontdq+0x108
2 1% 99% 1.00 sleepq_head+0x1ae8 cv_block+0x98
1 0% 99% 1.00 cpu[1]+0x90 setkpdq+0x148
1 0% 100% 1.00 cpu[3]+0x90 disp+0x90
1 0% 100% 1.00 cpu[3]+0x90 setbackdq+0x29c
-------------------------------------------------------------------------------
Thread lock spin: 5 events in 1.000 seconds (5 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
1 20% 20% 1.00 sleepq_head+0x848 ts_update_list+0x6c
1 20% 40% 1.00 sleepq_head+0x828 setrun+0x4
1 20% 60% 1.00 cpu[1]+0xd0 preempt+0x1c
1 20% 80% 1.00 sleepq_head+0x1118 setrun+0x4
1 20% 100% 1.00 cpu[1]+0xd0 ts_tick+0x8
-------------------------------------------------------------------------------
R/W writer blocked by readers: 1 events in 1.000 seconds (1 events/sec)
Count indv cuml rcnt Lock Caller
-------------------------------------------------------------------------------
1 100% 100% 1.00 0x30011f01df8 as_map+0x40
-------------------------------------------------------------------------------
(root@camtrunet)#
Podemos ver en la salida anterior, que hay una sección por cada tipo de candado al que se intenta acceder, por lo tanto, podemos obtener el número de peticiones a candados de tipo Spin lock spin, en nuestro ejemplo,
se producen 246 eventos en 1 segundo. De la salida podemos destacar las siguiente columnas, Count con el
número de intentos para acceder a un candado, Lock con los nombres del los candados
y Caller con las direcciones de los objetos que han intentado el acceso al candado. Estas 3 columnas nos
pueden ayudar a identificar un posible problema de contención en algún candado y si este problema de acceso
a un candado está produciendo una degradación del rendimiento de nuestro sistema.
Spin lock spin y Adaptive mutex spin
Tener un número alto de intentos sobre candados de estos dos tipos, puede provocar que la cantidad de tiempo asignada
al sistema SYS aumente, obligando al sistema a reducir la cantidad de tiempo que se asigna al usuario y por lo
tanto, se producirá una pérdida de rendimiento es todos los procesos de usuario, al recibir menos tiempo de CPU por parte
del Kernel.
Adaptive mutex block
Si en la salida del comando lockstat vemos que el número de este tipo de candados es considerablemente mayor
que cualquiera de los otros tipos, quizás tengamos un problema con el acceso a un recurso, el cual está bloqueando, tanto
al thread que lo está utilizando como a todos aquellos que están intentando acceder a él. Como este
tipo de bloqueos no produce un aumento del uso de CPU, el problema de rendimiento no se detectará a simple vista
mediante el valor de uso de CPU, por lo que es aconsejable, siempre que tengamos dudas del rendimiento de nuestro
sistema, aunque el uso de CPU no sea alto, que realicemos un pequeño análisis de los candados mediante el
comando lockstat.
cpustat y cputrack
Los procesadores SPARC disponen de una serie de contadores, lo cuales podemos consultar para medir el rendimiento de
ciertas operaciones a nivel de los procesadores. Estos contadores nos permitirán descubrir posibles cuellos de
botellas en los procesadores, bien por el número de instrucciones que se estén ejecutando, bien por el nivel de aciertos en las distintas caches.
La información almacenada en los contadores, dependerá del tipo de procesador que tenga nuestro sistema, por lo tanto,
antes de utilizar este comando, debemos comprobar cuales son los contadores disponibles, para ello solo tendremos
que ejecutar cpustat con el parámetro -h.
(root@camtrunet)# cpustat -h
Usage:
cpustat [-c events] [-nhD] [interval [count]]
-c events specify processor events to be monitored
-n suppress titles
-t include %tick register
-D enable debug mode
-h print extended usage information
Use cputrack(1) to monitor per-process statistics.
CPU performance counter interface: UltraSPARC IIIi & IIIi+
events pic0=,pic1=[,sys][,nouser]
event0: Cycle_cnt Instr_cnt Dispatch0_IC_miss IC_ref DC_rd DC_wr
EC_ref EC_snoop_inv Dispatch0_br_target Dispatch0_2nd_br
Rstall_storeQ Rstall_IU_use EC_write_hit_RTO EC_rd_miss
PC_port0_rd SI_snoop SI_ciq_flow SI_owned SW_count_0
IU_Stat_Br_miss_taken IU_Stat_Br_count_taken
Dispatch_rs_mispred FA_pipe_completion MC_read_dispatched
MC_write_dispatched MC_read_returned_to_JBU
MC_msl_busy_stall MC_mdb_overflow_stall MC_miu_spec_request
event1: Cycle_cnt Instr_cnt Dispatch0_mispred EC_wb EC_snoop_cb
IC_miss_cancelled Re_FPU_bypass Re_DC_miss Re_EC_miss
IC_miss DC_rd_miss DC_wr_miss Rstall_FP_use EC_misses
EC_ic_miss Re_PC_miss ITLB_miss DTLB_miss WC_miss
WC_snoop_cb WC_scrubbed WC_wb_wo_read PC_soft_hit
PC_snoop_inv PC_hard_hit PC_port1_rd SW_count_1
IU_Stat_Br_miss_untaken IU_Stat_Br_count_untaken
PC_MS_misses Re_RAW_miss FM_pipe_completion
MC_open_bank_cmds MC_reads MC_writes MC_page_close_stall
Re_DC_missovhd
See the "SPARC V9 JPS1 Implementation Supplement: Sun
UltraSPARC-IIIi"
(root@camtrunet)#
La utilización del comando es bastante sencilla, acepta un evento en cada contador, solo le tenemos que decir qué eventos
queremos monitorizar, el intervalo en segundos y el número de repeticiones. Vamos a ejecutar el comando cpustat, cada segundo, 5 veces, para que nos devuelva el contador Cycle_cnt, el cual almacena el número de ciclos de CPU y Instr_cnt que nos dice cuantas instrucciones se han ejecutando, el comando devuelve una línea por cada CPU.
(root@camtrunet)# cpustat -c pic0=Cycle_cnt,pic1=Instr_cnt 1 5
time cpu event pic0 pic1
1.006 1 tick 5253507 2214596
1.006 0 tick 5906614 1840943
2.006 1 tick 751843 173146
2.006 0 tick 694595 118216
3.006 1 tick 557997 194365
3.006 0 tick 1166984 271610
4.006 1 tick 5253396 2321969
4.006 0 tick 4473184 1284188
5.006 1 tick 781913 223580
5.006 0 tick 474001 70561
5.006 2 total 25314034 8713174
(root@camtrunet)#
Como ya hemos comentado, los contadores que se pueden monitorizar con el comando cpustat dependen del tipo de procesador que tenga nuestro sistema, por lo tanto, tendremos que recurrir a la documentación especifica de cada procesador. En nuestro ejemplo, el procesador que está utilizando la máquina es un UltraSPARC-IIIi y algunos de los contadores son los siguientes:
Contador Descripción
Cycle_cnt Contador de cilclos
Instr_cnt Instrucciones ejecutadas
IC_miss Fallos en la cache de instrucciones
DC_rd_miss Fallos de lectura en la cache
DC_rw_miss Fallos de escritura en la cache
ITLB_miss Fallos de instrucciones en la TLB
DTLB_miss Fallos de datos en la TLB
EC_misses Fallos en la cache externa
La mayoría de los contadores, los veremos más adelante, cuando hablemos de la memoria, ya que los más relevantes hacen referencia a estadísticas sobre elementos como las caches.
El comando cputrack tiene la misma finalidad que cpustat, pero con la diferencia que podemos analizar los distintos eventos referidos únicamente a un proceso, ya sea en ejecución o que lo lancemos con el propio comando cputrack.
(root@camtrunet)# cputrack -T 1 -N 10 -c pic0=Cycle_cnt,pic1=Instr_cnt sleep 5
time lwp event pic0 pic1
1.012 1 tick 908377 302623
2.012 1 tick 0 0
3.012 1 tick 0 0
4.012 1 tick 0 0
5.002 1 exit 991739 314472
(root@camtrunet)#
En el ejemplo anterior, hemos visto el contador de cliclo y el de instrucciones mientras se ejecuta el comando sleep 5, le hemos pasado los párametro -T, para decirle el intervalo en segundos y -N para el número de repeticiones, como el comando sleep 5 solo dura 5 segundos, cputrack solo saca 5 líneas. Este comando nos puede ayudar a conocer cuantas instrucciones ejecuta un proceso, en caso de un problema con el acceso a las caches, podemos comprobar si es un proceso determinado el que provoca la gran mayoría de los fallos de cache, etc.
Tanto cpustat como cputrack son herramientas bastante útiles a la hora de intentar encontrar la causa de una reducción del rendimiento en nuestro sistema.
Comentarios