5.- Compitiendo por los recursos.
Por muy evolucionado que esté el hardware los recursos siempre son limitados, es decir, el sistema operativo debe gestionarlos para que los distintos procesos puedan ejecutarse. Como medida de protección cuando un recurso está siendo usado por un hilo el kernel lo bloquea para que no pueda ser usado por otro a la vez. La perogrullada anterior es para que se entienda que los bloqueos en un sistema son normales, es más, son necesarios para asegurar la integridad de los datos. También hay que tener en cuenta que "los recursos" no es solamente hardware, existen las run queues, la memoria virtual, las distintas cachés, etc. Todo ello debe ser accedido de forma controlada, la coordinación se realiza principalmente por bloqueos. Es decir, el próximo DBA, administrador de weblogic, etc ... que mencione los bloqueos del sistema para justificar una perdida repentina de rendimiento, le mandáis a paseo. Si encima pretende que reiniciéis el equipo sacrificadlo a los dioses del binario para aplacar su ira.Si los bloqueos son normales, por que deberemos prestar atención a ellos ?
Hay que tener siempre claro que los bloqueos son síntomas y como tales nos ayudan a diagnosticar, pero se producen como consecuencia de la actividad del sistema y esta es la responsable de la degradación del rendimiento. Los bloqueos no degradan el rendimiento por si mismos. Hay dos ocasiones en las cuales un análisis del comportamiento de los bloqueos puede ser de ayuda en el diagnóstico de una perdida de rendimiento: 1.- Exceso de carga del sistema.2.- Una aplicación escala mal. En el primer caso pueden darte una pista adicional acerca del origen del problema. Por ejemplo si detectas que el driver de la tarjeta de red sufre muchos mutex es probable que la carga de red esté saturando el equipo. Profundizaremos un poco más a continuación cuando veamos como diagnosticar. El segundo caso es mucho más preocupante, si la aplicación es comprada a un tercero por mucho que detectes el problema poco puedes hacer para solventarlo, la segunda opción es casi peor, puede ser que esté desarrollada en tu propia empresa, con lo que te tocará pelearte con la gente de desarrollo que, en general, negarán que el problema sea suyo. Hoy en día si en una aplicación pulsas un botón y obtienes el resultado que esperas en la pantalla, está bien. Da igual si por el camino has consumido chorro cientos ciclos de CPU y zampado 3 gigas de memoria. Sangrante es el caso de algunas aplicaciones java, en muchos caso nada más arrancarlas lanzan más de un centenar de threads que no paran de desalojarse mutuamente de las distintas CPUs.
Síntomas
Las aplicaciones se ejecutan lentamente, a pesar de que el sistema cuenta con recursos de sobra.Blocks a nivel de Kernel.
Cambios de contexto
En un mundo ideal los procesos se ejecutarían hasta que su quantum se agotara, sin embargo es frecuente que sean desalojados de los procesadores por varias causas, cuando un proceso se encuentra en espera por que trata de acceder a un recurso bloqueado se le envía a dormir, esto provoca un cambio de contexto voluntario. Podemos usar el comando mpstat para monitorizar la cantidad de estos que se han producido en el sistema (columna csw).root@box # mpstat 5 CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl 0 254 0 1374 455 7 1773 475 485 127 40 4795 46 14 0 40 1 266 0 1724 554 25 2145 549 552 162 40 4999 40 14 0 46 2 316 0 1432 725 296 1730 457 441 134 39 4730 46 15 0 39 3 252 0 1854 1905 1499 1435 383 416 197 36 4043 40 21 0 39
El comando lockstat
Con el comando lockstat podemos ver los bloqueos que se han producido a nivel de kernel en un intervalo de tiempo. La salida se divide en bloques dependiendo del tipo de bloqueo. Para recopilar datos durante 5 segundos ejecutaremosbox#lockstat sleep 5El primer bloque de información nos muestra los mutex adaptivies en los que el thread propietario del bloqueo se estaba ejecutando en una cpu en el momento que otro thread ha intentado tomar posesión de este.
Adaptive mutex spin: 14204 events in 5.106 seconds (2782 events/sec) Count indv cuml rcnt spin Lock Caller ------------------------------------------------------------------------------- 2974 21% 21% 0.00 4 0x6000aa6ef80 fifo_write+0x5c 1087 8% 29% 0.00 5 0x6000cff5960 fifo_write+0x2ac 901 6% 35% 0.00 3 0x6000aa6ef80 fifo_read+0x28 566 4% 39% 0.00 5 0x6000cff5960 fifo_write+0x5c 523 4% 43% 0.00 5 0x6000aa6ef80 fifo_write+0x2ac 143 1% 44% 0.00 3 0x60010420060 aionotify+0x18 111 1% 44% 0.00 3 0x60010420060 aio_cleanup+0x30 99 1% 45% 0.00 3 0x60002889658 ssdintr+0x268 65 0% 46% 0.00 2 0x60002889658 ssdintr+0x18 61 0% 46% 0.00 3 0x3003f9c0060 aio_cleanup+0x30 59 0% 46% 0.00 2 0x30000009008 mod_hold_dev_by_major+0x60 [...]Veamos el significado de las columnas más importantes:
- Count: Número de veces que se ha producido el bloqueo.
- indv: Este es el el % de ocasiones en las que la muestra que vemos en la pantalla se corresponde con el total de eventos.
- spin: El número de veces que el thread a tenido que realizar un spin (bucle en espera que el block se libere) antes de conseguir adueñarse de el.
- Lock: Direccón de memoria de la estructura del lock
- caller: Dirección de memoria desde la que se ha adquirido el block, generalmente expresada de forma funcion+offset
-------------------------------------------------------------------------------
Adaptive mutex block: 334 events in 5.106 seconds (65 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
25 7% 7% 0.00 1495276 0x600104f8068 aio_cleanup+0x28
23 7% 14% 0.00 75221 0x6000aa6ef80 fifo_write+0x5c
22 7% 21% 0.00 54495 0x6000cff5960 cv_wait_sig_swap_core+0x158
14 4% 25% 0.00 231178 0x60001728c40 post_syscall+0x2fc
12 4% 29% 0.00 53233 0x6000aa6ef80 cv_wait_sig_swap_core+0x158
9 3% 31% 0.00 59322 0x60010420060 cv_timedwait_sig+0x188
7 2% 34% 0.00 37771 0x60001725900 issig_forreal+0x20
5 1% 35% 0.00 82760 0x60010420060 aio_cleanup+0x30
5 1% 37% 0.00 48300 0x3003f9c0060 cv_timedwait_sig+0x188
4 1% 38% 0.00 58625 0x6000cff5960 fifo_write+0x2ac
4 1% 39% 0.00 66850 0x6000cff5960 fifo_write+0x5c
4 1% 40% 0.00 232650 0x6000aa6ef80 fifo_write+0x2ac
[...]
El siguiente bloque nos da estadísticas acerca de los bloqueos tipo mutex que
cuando el thread ha tratado de adquirirlo estaba ocupado por otro thread que
no se estaba ejecutando actualmente. Como resultado hemos enviado nuestro hilo
a dormir. Obviamente el impacto desde el punto de vista de la performance
es más acusado.
Los campos son los mismos que en el anterior bloque con la salvedad que la
columna spin ha sido sustituida por la nsec. Esto es el numero de
nanosegundos que el thread a tenido que permanecer el la sleep queue antes de
que se liberara el lock.
La interpretación de los datos es parecida que en el caso anterior, si el
evento se produce muchas veces o tiene un coste de tiempo muy elevado
deberemos tratar de obtener más información acerca de él.
------------------------------------------------------------------------------- Spin lock spin: 59660 events in 5.106 seconds (11683 events/sec) Count indv cuml rcnt spin Lock Caller ------------------------------------------------------------------------------- 10349 17% 17% 0.00 6 cp_default disp_getbest+0x4 4119 7% 24% 0.00 6 0x60001a37cb0 disp_getbest+0x4 3987 7% 31% 0.00 6 0x60001a37980 disp_getbest+0x4 3888 7% 37% 0.00 6 0x60001a378c0 disp_getbest+0x4 3450 6% 43% 0.00 6 0x60001a37800 disp_getbest+0x4 3334 6% 49% 0.00 6 0x60001a37aa0 disp_getbest+0x4 3330 6% 54% 0.00 6 cpu0_disp disp_getbest+0x4 2895 5% 59% 0.00 4 0x60001a37aa0 disp+0x84 [...]El tercer bloque nos presenta información acerca de los bloqueos mutex spin. En estos casos el thread que quiere adueñarse del lock siempre se quedara haciendo un spining (bucle) y nunca se mandara a dormir. Este tipo de locks se usa para sincronizar el acceso a estructuras de datos que suelen sufrir bloqueos breves. Muchos de ellos corresponden a estructuras de datos del kernel como por ejemplo las dispatch queues. Los criterios para su análisis deben ser parecidos al primer bloque.
R/W writer blocked by writer: 42 events in 5.106 seconds (8 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
6 14% 14% 0.00 216083 0x6000f7ea168 sam_proc_get_lease+0x1f0
6 14% 29% 0.00 91800 0x6000f7ddc90 sam_proc_get_lease+0x1f0
6 14% 43% 0.00 167066 0x6000f7a2460 sam_proc_get_lease+0x1f0
4 10% 52% 0.00 205875 0x6000f7ea168 sam_dk_direct_io+0xb6c
4 10% 62% 0.00 298950 0x6000f7ea168 sam_write_vn+0x13c
4 10% 71% 0.00 419550 0x6000f7a2460 sam_write_vn+0x13c
3 7% 79% 0.00 183866 0x6000f7ddc90 sam_write_vn+0x13c
2 5% 83% 0.00 123250 0x6000f7e9ca0 sam_proc_get_lease+0x1f0
2 5% 88% 0.00 104450 0x6000f7de620 sam_proc_get_lease+0x1f0
1 2% 90% 0.00 74100 0x6000f7e9ca0 sam_write_vn+0x13c
1 2% 93% 0.00 28700 0x6000f7e9ca0 sam_dk_direct_io+0xb6c
1 2% 95% 0.00 128500 0x6000f7e37d0 sam_proc_get_lease+0x1f0
1 2% 98% 0.00 95600 0x6000f7de620 sam_write_vn+0x13c
1 2% 100% 0.00 59100 0x6000f7de158 sam_proc_get_lease+0x1f0
-------------------------------------------------------------------------------
R/W writer blocked by readers: 23 events in 5.106 seconds (5 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
4 17% 17% 0.00 118800 0x6000f7ddc90 sam_write_vn+0x13c
3 13% 30% 0.00 299133 0x6000f7ea168 sam_write_vn+0x13c
3 13% 43% 0.00 283566 0x6000f7a2460 sam_write_vn+0x13c
2 9% 52% 0.00 144900 0x6000f7ea168 sam_dk_direct_io+0xb6c
2 9% 61% 0.00 78600 0x6000f7ea168 sam_proc_get_lease+0x1f0
1 4% 65% 0.00 100000 0x6000f7e9ca0 sam_write_vn+0x13c
1 4% 70% 0.00 53300 0x6000f7e37d0 sam_write_vn+0x13c
1 4% 74% 0.00 160700 0x6000f7de620 sam_write_vn+0x13c
1 4% 78% 0.00 79900 0x6000f7de158 sam_write_vn+0x13c
1 4% 83% 0.00 201100 0x6000f7ddc90 sam_dk_direct_io+0xb6c
1 4% 87% 0.00 36600 0x6000f7ddc90 sam_proc_get_lease+0x1f0
1 4% 91% 0.00 65100 0x6000f7a2460 sam_dk_direct_io+0xb6c
1 4% 96% 0.00 86100 0x3001ba97c58 as_map+0x38
1 4% 100% 0.00 339800 0x6000f7a2460 sam_proc_get_lease+0x1f0
-------------------------------------------------------------------------------
R/W reader blocked by writer: 23 events in 5.106 seconds (5 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
6 26% 26% 0.00 61300 0x6000f7ea168 sam_dk_direct_io+0x5d8
5 22% 48% 0.00 59180 0x6000f7ddc90 sam_dk_direct_io+0x5d8
4 17% 65% 0.00 70900 0x6000f7a2460 sam_dk_direct_io+0x5d8
3 13% 78% 0.00 72333 0x6000f7de620 sam_dk_direct_io+0x5d8
2 9% 87% 0.00 99850 0x6000f7e9ca0 sam_dk_direct_io+0x5d8
1 4% 91% 0.00 54600 0x6000f7e37d0 sam_dk_direct_io+0xb6c
1 4% 96% 0.00 141200 0x6000f7e37d0 sam_dk_direct_io+0x5d8
1 4% 100% 0.00 82400 0x6000f7de158 sam_dk_direct_io+0x5d8
-------------------------------------------------------------------------------
R/W reader blocked by write wanted: 8 events in 5.106 seconds (2 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
3 38% 38% 0.00 124533 0x6000f7ea168 sam_dk_direct_io+0x5d8
3 38% 75% 0.00 104266 0x6000f7a2460 sam_dk_direct_io+0x5d8
2 25% 100% 0.00 129600 0x6000f7ddc90 sam_dk_direct_io+0x5d8
-------------------------------------------------------------------------------
El último grupo de bloques se refiere a los lock R/W, divididos en grupos
según la actividad que estén realizando los threads involucrados (
lectura o escritura).
Como en los casos anteriores nos fijaremos en el número de eventos y el coste en
nanosegundos para estimar cuales pueden ser los que estén penalizando el rendimiento
del sistema.
Quién es el responsable de todos estos bloqueos.
Después de leer todo lo anterior os estaréis preguntando que utilidad tiene, al fin y al cabo solo hemos podido recopilar un montón de direcciones de memoria, funciones, y estadísticas ... pero lo que le interesa a un administrador es poder identificar que PIDs son los que están generando todos esos bloqueos. En nuestro ejemplo vemos que la siguiente función esta siendo ejecutada un montón de veces y esta teniendo problemas para adueñarse de algunos locks.25 7% 7% 0.00 1495276 0x600104f8068 aio_cleanup+0x28 111 1% 44% 0.00 3 0x60010420060 aio_cleanup+0x30 61 0% 46% 0.00 3 0x3003f9c0060 aio_cleanup+0x30A quien esta afectando. dtrace es nuestro amigo. Lo primero es localizar la prueba que nos interesa para monitorizar nuestra función.
root@box # dtrace -l | grep aio_cleanup 2023 fbt unix dr_aio_cleanup_thread entry 2024 fbt unix dr_aio_cleanup_thread return 5196 fbt genunix aio_cleanup_cleanupq entry 5197 fbt genunix aio_cleanup_cleanupq return [...] 13875 fbt genunix aio_cleanup entry 13876 fbt genunix aio_cleanup return [...]Después ejecutamos dtrace para que nos informe de todos los pids que están ejecutando dicha función.
root@box # dtrace -n 'fbt::aio_cleanup: { printf("%6d %s\n", pid, execname); }'
dtrace: description 'fbt::aio_cleanup: ' matched 2 probes
CPU ID FUNCTION:NAME
16 13875 aio_cleanup:entry 21939 oracle
16 13876 aio_cleanup:return 21939 oracle
0 13875 aio_cleanup:entry 21939 oracle
0 13876 aio_cleanup:return 21939 oracle
0 13875 aio_cleanup:entry 21939 oracle
0 13876 aio_cleanup:return 21939 oracle
Lo siguiente es un poco de la "magia" de la shell, redirigimos a un fichero,
ordenamos y contamos para ver los pids que más frecuentemente llaman a la
función. La primera columna es el número de ocurrencias, la segunda el pid.
root@box # cat /tmp/aio.txt | awk ' { print $4 }' | sort | uniq -c
4 13846
4 14950
22 18856
2 18872
4 21659
2366 21939
194 24669
8 27434
4 27581
18 27585
130 27632
52 27634
1250 27636
402 27638
4 27677
4 28103
2 29590
4 3759
594 7966
8 8172
Podemos observar que un gran % de eventos los generan únicamente dos
pids (21939 y 27636).
Finalmente combinamos ese resultado con un grep para ver que es cada uno de
los pids.
root@box # for i in `cat /tmp/aio.txt | awk ' { print $4 }' | sort | uniq`; do ps -ef | grep $i | grep -v grep; done;
oracle 13846 1 0 Sep 27 ? 7248:54 ora_j003_BBDD2
oracle 14950 1 0 Nov 08 ? 410:33 ora_j005_BBDD2
oracle 18856 1 0 09:26:24 ? 0:35 oracleBBDD2 (LOCAL=NO)
oracle 18872 1 0 09:26:24 ? 0:33 oracleBBDD2 (LOCAL=NO)
oracle 21659 1 0 09:28:01 ? 0:26 oracleBBDD2 (LOCAL=NO)
oracle 21939 21931 4 22:00:03 ? 185:39 oracleBBDD2 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle 24669 1 0 07:46:59 ? 1:52 oracleBBDD2 (LOCAL=NO)
oracle 27434 1 0 Nov 02 ? 741:49 ora_j006_BBDD2
oracle 27581 1 0 Apr 22 ? 362:22 ora_diag_BBDD2
oracle 27585 1 0 Apr 22 ? 2917:07 ora_lmon_BBDD2
oracle 27632 1 0 Apr 22 ? 8275:19 ora_dbw0_BBDD2
oracle 27634 1 0 Apr 22 ? 9106:27 ora_dbw1_BBDD2
oracle 27636 1 1 Apr 22 ? 5161:12 ora_lgwr_BBDD2
oracle 27638 1 0 Apr 22 ? 551:26 ora_ckpt_BBDD2
oracle 27677 1 0 Apr 22 ? 224:17 ora_mmon_BBDD2
oracle 28103 1 0 Apr 22 ? 133:56 ora_arc1_BBDD2
oracle 29590 1 0 Jun 04 ? 175:06 ora_j007_BBDD2
oracle 3759 1 0 Nov 09 ? 7:39 ora_j008_BBDD2
oracle 7966 1 1 19:52:26 ? 99:50 ora_j000_BBDD2
oracle 8172 1 0 09:20:22 ? 0:37 oracleBBDD2 (LOCAL=NO)
Como vemos los procesos pertenecen a una B.D. oracle, en este momento
deberíamos hablar con nuestro DBA para contar con su ayuda para continuar
nuestra investigación.
Bloqueos a nivel de usuario
El comando plockstat
Nuestra aplicación también puede sufrir bloqueos a nivel de usuario. Estos se crean desde el código de una aplicación usando las llamadas mutex_init() o rwlock_init(). Lógicamente su función es sincronizar el acceso de los distintos threads a determinados recursos.OpenSolaris nos permite tracear dichos bloqueos con el comando plockstat, usa dtrace internamente, de forma que podemos medir el impacto en la performance. En la página man encontraremos explicadas las distintas opciones, nosotros usamos las opciones -A para que nos reporte todos los eventos, con la opción -p podemos monitorizar a un pid existente.
plockstat -A cat /etc/passwd [...] Mutex hold Count nsec Lock Caller 1 70200 libc.so.1`_uberdata+0xfc0 cat`_start+0x110 1 40900 libc.so.1`__sbrk_lock libc.so.1`_smalloc+0x4c 1 39400 libc.so.1`_uberdata+0x40 LM1`ld.so.1`call_init+0x70 1 34300 libc.so.1`_uberdata+0x40 LM1`ld.so.1`call_init+0x70 1 27600 libc.so.1`_uberdata+0xfc0 cat`_start+0xac 1 24700 libc.so.1`_uberdata+0x40 cat`main+0x24 1 23100 libc.so.1`_uberdata+0x40 cat`main+0x24 1 4900 libc.so.1`_uberdata+0xfc0 cat`_start+0xb8
La salida es casi autoexplicativa:
- Count: Número de veces que se ha producido el evento
- nsec: Duración media en nanosegundos del bloqueo
- Lock: Nombre del bloqueo
- Caller: Función más offset que ha llamado al bloqueo.
