Introducción
Podemos definir las llamadas a sistema como una interfaz entre el área de usuario y la de kernel, si un proceso necesita realizar una tarea que implique acceder a la área de kernel, posiblemente por que no tenga privilegios para hacerlo el directamente, debe hacerlo a través de una llamada al sistema. Ejemplos típicos seria acceder a un dispositivo de i/o, crear un proceso hijo, esperar a que se cumpla una condición, ... El listado completo de llamadas al sistema que existen lo encontramos en el fichero /usr/include/sys/syscall.h.Rastreando las llamadas de sistema en nuestro equipo
La información acerca de que llamadas a sistema se están ejecutando nos puede dar pistas de la actividad de los distintos procesos en nuestro equipo. Lógicamente procesar una llamada tiene un coste a nivel de recursos, sin embargo dependiendo de la tarea que deba realizar su coste es distinto. El tiempo empleado en dicha tarea es computado como tiempo de sistema, por ello la columna sy en el apartado faults (system calls) y sy en el apartado cpu (tiempo de sistema) de la salida del vmstat están intimamente relacionadas.kthr memory page disk faults cpu r b w swap free re mf pi po fr de sr m0 m1 m2 m1 in sy cs us sy id 0 0 0 30903712 1172696 363 2757 157 14 23 0 20 1 1 1 0 6102 18791 3598 15 5 90 0 0 0 29096840 316968 269 3076 0 0 0 0 0 0 0 0 0 13197 36097 5972 37 8 55 0 0 0 29094864 317632 406 3235 0 2 2 0 0 0 0 0 0 10963 31861 5276 29 7 64Un % elevado de tiempo de sistema puede significar que nuestros procesos están requiriendo llamadas a sistema muy costosas.
¿ pero que procesos son los que generan mas llamadas al sistema y que coste tienen ?
Con el comando prstat -m podemos ver cuantas llamadas ha esta realizando cada proceso. En este ejemplo he ejecutado el top en otra terminal, podemos ver que esta generando 1000 llamadas por tiempo de muestreo, aunque son los procesos de oracle quienes se llevan la palma.PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 9720 root 14 63 3,1 0,0 0,0 0,0 20 0,1 123 185 54K 0 prstat/1 9498 oracle 6,2 3,3 0,0 0,0 2,0 78 11 0,1 123 75 6K 0 java/11 21975 oracle 5,6 0,4 0,0 0,0 0,0 0,0 94 0,0 136 33 2K 0 oracle/1 9943 oracle 5,5 0,3 0,0 0,0 0,0 0,0 94 0,0 138 27 2K 0 oracle/1 13377 oracle 5,4 0,4 0,0 0,0 0,0 0,0 94 0,0 139 34 2K 0 oracle/1 3170 oracle 5,4 0,3 0,0 0,0 0,0 0,0 94 0,0 141 29 2K 0 oracle/1 21977 oracle 5,3 0,3 0,0 0,0 0,0 0,0 94 0,0 139 31 2K 0 oracle/1 1189 oracle 5,3 0,3 0,0 0,0 0,0 0,0 94 0,0 135 29 2K 0 oracle/1 13379 oracle 5,1 0,3 0,0 0,0 0,0 0,0 95 0,0 136 27 2K 0 oracle/1 28043 oracle 5,0 0,3 0,0 0,0 0,0 0,0 95 0,0 136 22 2K 0 oracle/1 6112 oracle 4,8 0,3 0,0 0,0 0,0 0,0 95 0,0 139 25 2K 0 oracle/1 1442 oracle 4,5 0,3 0,0 0,0 0,0 0,0 95 0,0 120 23 2K 0 oracle/1 19048 oracle 4,5 0,3 0,0 0,0 0,0 0,0 95 0,1 126 29 2K 0 oracle/1 19041 oracle 4,4 0,3 0,0 0,0 0,0 0,0 95 0,0 109 28 2K 0 oracle/1 29647 oracle 4,3 0,3 0,0 0,0 0,0 0,0 95 0,0 121 19 2K 0 oracle/1 Total: 416 processes, 4687 lwps, load averages: 3,03, 2,86, 2,79La información del prstat en muy completa, el número de llamadas al sistema esta relacionado con los demás valores, p. ej. como decía antes la columna sys nos dará una idea del coste de procesarlas, si la columna SLP tiene un valor alto puede significar que el proceso esta realizando mucha i/o, los valores de cambios de contexto voluntarios también está relacionado con las ellas ya que puede significar que el proceso esta solicitando continuamente ir a dormir con su correspondiente llamada a sistema ... Como vemos los distintos valores de las columnas solo nos permiten hacer una idea del coste que supone para el equipo ese proceso y de su actividad, sin embargo seria deseable saber exactamente que es lo que esta haciendo. Para ello podemos ejecutar el comando truss. Con la opción -c nos dará el total de cada una de las llamadas ejecutadas y su resultado.
root@myhost # truss -faelid -c -p 26095
psargs: top
^C
syscall seconds calls errors
read .152 829
write .000 2
open .036 830 1
close .027 829
time .000 2
lseek .000 4
ioctl .000 20
uadmin .000 2
getdents .006 6
sysconfig .000 2
pread .000 4
pollsys .000 2
-------- ------ ----
sys totals: .224 2532 1
usr time: .022
elapsed: 6.880
Como podemos ver nos lista las distintas llamadas realizadas por el top
durante
la muestra, la cantidad de cada una de ellas y el tiempo empleado en
procesarlas. También si ha terminado correctamente o en error.
Podemos ir aun mas lejos y ver directamente el flujo de llamadas que va
realizando el proceso en tiempo real.
truss -faelid -o /tmp/truss2 -p 26095
se time stamp: 1188377543.2551 [ Wed Aug 29 10:52:23 CEST 2007 ]
23650/1: psargs: top
23650/1: 0.3558 pollsys(0xFFFFFFFF7FFFD6A0, 1, 0xFFFFFFFF7FFFD860,
0x00000000) = 0
23650/1: 0.3564 ioctl(6, KSTAT_IOC_CHAIN_ID, 0x00000000) =
15654
23650/1: 0.3566 ioctl(6, KSTAT_IOC_READ, "system_misc") =
15654
23650/1: 0.3571 ioctl(6, KSTAT_IOC_READ, "cpu_stat3") =
15654
23650/1: 0.3573 ioctl(6, KSTAT_IOC_READ, "cpu_stat0") =
15654
23650/1: 0.3577 ioctl(6, KSTAT_IOC_READ, "cpu_stat1") =
15654
23650/1: 0.3581 ioctl(6, KSTAT_IOC_READ, "cpu_stat2") =
15654
23650/1: 0.3582 ioctl(6, KSTAT_IOC_READ, "cpu_stat16") =
15654
23650/1: 0.3584 ioctl(6, KSTAT_IOC_READ, "cpu_stat17") =
15654
23650/1: 0.3586 ioctl(6, KSTAT_IOC_READ, "cpu_stat18") =
15654
23650/1: 0.3590 ioctl(6, KSTAT_IOC_READ, "cpu_stat19") =
15654
23650/1: 0.3592 pread(3, "\0\0 a R", 4, 0x0186EAC8) = 4
23650/1: 0.3595 sysconfig(_CONFIG_PHYS_PAGES) =
2097152
23650/1: 0.3597 pread(3, "\0\0\0\0\0\099 ~", 8, 0x018B1750) = 8
23650/1: 0.3598 uadmin(16, 5, -2147494064) = 0
23650/1: 0.3600 lseek(5, 0, SEEK_CUR) = 9856
23650/1: 0.3601 lseek(5, 0, SEEK_SET) = 0
23650/1: 0.3609 getdents(5, 0xFFFFFFFF7F404000, 8192) = 8184
23650/1: 0.3611 open("0/psinfo", O_RDONLY) = 8
23650/1: 0.3613 read(8, "\0\0\001\0\0\001\0\0\0\0".., 416) = 416
23650/1: 0.3615 close(8) = 0
23650/1: 0.3616 open("1/psinfo", O_RDONLY) = 8
23650/1: 0.3618 read(8, "02\0\0\0\0\0\001\0\0\001".., 416) = 416
23650/1: 0.3621 close(8) = 0
/write
... omitiendo
23650/1: 0.6331 getdents(5, 0xFFFFFFFF7F404000, 8192) = 0
23650/1: 0.6340 time() =
1188377543
23650/1: 0.6346 write(1, "1B [ 1 ; 1 1 H 2 4 9 1 4".., 500) = 500
En el código fuente de OpenSolaris encontraremos documentadas la mayoría de
ellas en sus correspondiente ficheros, también se lo están en la
sección 2 de las páginas man. Sin embargo algunas son muy
intuitivas, ioctl, open, read, lseek, ... todos están relacionadas con la
lectura de datos, teniendo en cuenta que estamos ejecutando un top
posiblemente estos sean de /proc, el write que muestro podría corresponder a
la salida por pantalla.
El comando pfiles nos devuelve los file descriptors que tiene abiertos ese
proceso, lógicamente estos corresponden a los de la salida del truss. Por
ejemplo aqui vemos como el FD la llamada ioctl apunto al pseudodispositivo
kstat, lseek y getdents apuntan a /proc.
23650: top
Current rlimit: 256 file descriptors
0: S_IFCHR mode:0620 dev:292,0 ino:12582922 uid:500 gid:7 rdev:24,3
O_RDWR|O_NOCTTY|O_LARGEFILE
/devices/pseudo/pts@0:3
1: S_IFCHR mode:0620 dev:292,0 ino:12582922 uid:500 gid:7 rdev:24,3
O_RDWR|O_NOCTTY|O_LARGEFILE
/devices/pseudo/pts@0:3
2: S_IFCHR mode:0620 dev:292,0 ino:12582922 uid:500 gid:7 rdev:24,3
O_RDWR|O_NOCTTY|O_LARGEFILE
/devices/pseudo/pts@0:3
3: S_IFCHR mode:0640 dev:292,0 ino:6815750 uid:0 gid:3 rdev:13,1
O_RDONLY|O_LARGEFILE
/devices/pseudo/mm@0:kmem
4: S_IFCHR mode:0640 dev:292,0 ino:6815748 uid:0 gid:3 rdev:13,0
O_RDONLY|O_LARGEFILE
/devices/pseudo/mm@0:mem
5: S_IFDIR mode:0555 dev:294,0 ino:2 uid:0 gid:0 size:480032
O_RDONLY|O_NDELAY|O_LARGEFILE FD_CLOEXEC
/proc
6: S_IFCHR mode:0666 dev:292,0 ino:47185924 uid:0 gid:3 rdev:90,0
O_RDONLY|O_LARGEFILE
/devices/pseudo/kstat@0:kstat
7: S_IFREG mode:0644 dev:85,0 ino:2878 uid:0 gid:3 size:1127
O_RDONLY|O_LARGEFILE
/etc/passwd
23650/1: 0.3571 ioctl(6, KSTAT_IOC_READ, "cpu_stat3")A = 15654 6: S_IFCHR mode:0666 dev:292,0 ino:47185924 uid:0 gid:3 rdev:90,0 O_RDONLY|O_LARGEFILE /devices/pseudo/kstat@0:kstatTambién podemos confirmar que el write corresponde a la salida por pantalla:
23650/1: 0.6346 write(1, "1B [ 1 ; 1 1 H 2 4 9 1 4".., 500) = 500 1: S_IFCHR mode:0620 dev:292,0 ino:12582922 uid:500 gid:7 rdev:24,3 O_RDWR|O_NOCTTY|O_LARGEFILE /devices/pseudo/pts@0:3Resumiendo un examen detallado de las llamadas a sistema de nuestro equipo nos puede dar una foto detallada de que esta haciendo cada proceso lo cual es una ayuda inestimable para diagnosticar problemas de performance.
Por favor envía cualquier comentario a roger.jordan gmail com