Rendimiento/Tuning Solaris: Introducción

OpenSolaris, Solaris, Tuning Dejar un comentario

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@huelva)# 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@huelva)# 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@huelva)# 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@huelva)#

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@huelva)# 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@huelva)# 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@huelva)#

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@huelva)# 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@huelva)#

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@huelva)# 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@huelva)#

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@huelva)#  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@huelva)#

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.

Nota - Si tiene alguna pregunta o sugerencia sobre este artículo, por favor, no dude en ponerse en contacto conmigo mediante email en jjmora AT arrakis DOT es

<< | >>Rendimiento/Tuning Solaris: Memoria

Technorati Tag(s) :

Los comentarios están cerrados.

My name is null, /dev/null
Algunos derechos reservados. Licencia Creative Commons