OpenSolaris: Bloqueos, mutex y R/W part II
La salida del 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 mas 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: Direccion de memoria del la estructura del lock
- caller: Dirección de memoria desde la que se ha adquirdo 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 mas 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 mas informacion acerca de el.
------------------------------------------------------------------------------- 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 sufrir´n bloqueos breves. Muchos de ellos corresponden a estructuras de datos del kernel como p. ej. las dispatch queues. Los criterios para su analisis 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
segiú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.
Quien 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 al fin y al cabo lo que le interesa a un administrador es poder identificar que PIDs son los que est´an 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 mas 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
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 BB.DD. oracle, en este momento
deberíamos hablar con nuestro DBA para contar con su ayuda para continuar
nuestra investigación.
Hay que tener en cuenta que la existencia de locks en un S.O. es perfectamente
normal, debemos investigar solo aquellos que intuyamos pueden penalizar
excesivamente el rendimiento.
