Una pregunta común que probablemente querrá ver respondida es qué CPU están ejecutando subprocesos y durante cuánto tiempo. Puede utilizar los sondeos on-cpu y off-cpu para responder fácilmente a esta pregunta en base a todo un sistema, tal y como se muestra en el siguiente ejemplo:
sched:::on-cpu { self->ts = timestamp; } sched:::off-cpu /self->ts/ { @[cpu] = quantize(timestamp - self->ts); self->ts = 0; }
La ejecución de la secuencia de comandos anterior devuelve una salida similar al siguiente ejemplo:
# dtrace -s ./where.d dtrace: script './where.d' matched 5 probes ^C 0 value ------------- Distribution ------------- count 2048 | 0 4096 |@@ 37 8192 |@@@@@@@@@@@@@ 212 16384 |@ 30 32768 | 10 65536 |@ 17 131072 | 12 262144 | 9 524288 | 6 1048576 | 5 2097152 | 1 4194304 | 3 8388608 |@@@@ 75 16777216 |@@@@@@@@@@@@ 201 33554432 | 6 67108864 | 0 1 value ------------- Distribution ------------- count 2048 | 0 4096 |@ 6 8192 |@@@@ 23 16384 |@@@ 18 32768 |@@@@ 22 65536 |@@@@ 22 131072 |@ 7 262144 | 5 524288 | 2 1048576 | 3 2097152 |@ 9 4194304 | 4 8388608 |@@@ 18 16777216 |@@@ 19 33554432 |@@@ 16 67108864 |@@@@ 21 134217728 |@@ 14 268435456 | 0 |
La salida anterior muestra que los subprocesos de la CPU 1 tienden a ejecutarse por menos de 100 microsegundos seguidos, o durante aproximadamente 10 milisegundos. En el histograma se muestra una importante diferencia entre los dos clústeres de datos. Podría estar también interesado en saber qué CPU están ejecutando un proceso determinado. También puede utilizar los sondeos on-cpu y off-cpu para responder a esta cuestión. La siguiente secuencia de comandos muestra qué CPU ejecutan una aplicación determinada durante un periodo de 10 segundos:
#pragma D option quiet dtrace:::BEGIN { start = timestamp; } sched:::on-cpu /execname == $$1/ { self->ts = timestamp; } sched:::off-cpu /self->ts/ { @[cpu] = sum(timestamp - self->ts); self->ts = 0; } profile:::tick-1sec /++x == 10/ { exit(0); } dtrace:::END { printf("CPU distribution of imapd over %d seconds:\n\n", (timestamp - start) / 1000000000); printf("CPU microseconds\n--- ------------\n"); normalize(@, 1000); printa("%3d %@d\n", @); }
Ejecutando la secuencia de comandos anterior en un gran servidor de correo y especificando el daemon IMAP, devuelve una salida similar al ejemplo siguiente:
# dtrace -s ./whererun.d imapd CPU distribution of imapd over 10 seconds: CPU microseconds --- ------------ 15 10102 12 16377 21 25317 19 25504 17 35653 13 41539 14 46669 20 57753 22 70088 16 115860 23 127775 18 160517 |
Solaris tiene en cuenta el tiempo que ha estado un subproceso en inactividad a la hora de seleccionar la CPU en la que ejecutar el subproceso: un subproceso que ha estado en actividad durante menos tiempo tiende a no migrar. Puede utilizar los sondeos off-cpu y on-cpu para observar esta conducta:
sched:::off-cpu /curlwpsinfo->pr_state == SSLEEP/ { self->cpu = cpu; self->ts = timestamp; } sched:::on-cpu /self->ts/ { @[self->cpu == cpu ? "sleep time, no CPU migration" : "sleep time, CPU migration"] = lquantize((timestamp - self->ts) / 1000000, 0, 500, 25); self->ts = 0; self->cpu = 0; }
La ejecución de la secuencia de comandos anterior durante aproximadamente 30 segundos devuelve una salida similar al siguiente ejemplo:
# dtrace -s ./howlong.d dtrace: script './howlong.d' matched 5 probes ^C sleep time, CPU migration value -------------- Distribution ------------ count < 0 | 0 0 |@@@@@@@ 6838 25 |@@@@@ 4714 50 |@@@ 3108 75 |@ 1304 100 |@ 1557 125 |@ 1425 150 | 894 175 |@ 1526 200 |@@ 2010 225 |@@ 1933 250 |@@ 1982 275 |@@ 2051 300 |@@ 2021 325 |@ 1708 350 |@ 1113 375 | 502 400 | 220 425 | 106 450 | 54 475 | 40 >= 500 |@ 1716 sleep time, no CPU migration value -------------- Distribution ------------ count < 0 | 0 0 |@@@@@@@@@@@@ 58413 25 |@@@ 14793 50 |@@ 10050 75 | 3858 100 |@ 6242 125 |@ 6555 150 | 3980 175 |@ 5987 200 |@ 9024 225 |@ 9070 250 |@@ 10745 275 |@@ 11898 300 |@@ 11704 325 |@@ 10846 350 |@ 6962 375 | 3292 400 | 1713 425 | 585 450 | 201 475 | 96 >= 500 | 3946 |
La salida de ejemplo muestra que hay más ocurrencias de no migración que de migración. Asimismo, cuando los tiempos de inactividad son mayores, la posibilidad de migración es más alta. Las distribuciones son notablemente diferentes en el intervalo inferior a los 100 milisegundos, pero su apariencia es muy similar a medida que aumentan los tiempos de inactividad. Este resultado parecería indicar que el tiempo de inactividad no es un factor decisivo en la planificación una vez que se supera un umbral determinado.
El ejemplo final que utiliza off-cpu y on-cpu muestra cómo utilizar estos sondeos junto con el campo pr_stype para determinar por qué los subprocesos se encuentran en inactividad y durante cuánto tiempo:
sched:::off-cpu /curlwpsinfo->pr_state == SSLEEP/ { /* * We're sleeping. Track our sobj type. */ self->sobj = curlwpsinfo->pr_stype; self->bedtime = timestamp; } sched:::off-cpu /curlwpsinfo->pr_state == SRUN/ { self->bedtime = timestamp; } sched:::on-cpu /self->bedtime && !self->sobj/ { @["preempted"] = quantize(timestamp - self->bedtime); self->bedtime = 0; } sched:::on-cpu /self->sobj/ { @[self->sobj == SOBJ_MUTEX ? "kernel-level lock" : self->sobj == SOBJ_RWLOCK ? "rwlock" : self->sobj == SOBJ_CV ? "condition variable" : self->sobj == SOBJ_SEMA ? "semaphore" : self->sobj == SOBJ_USER ? "user-level lock" : self->sobj == SOBJ_USER_PI ? "user-level prio-inheriting lock" : self->sobj == SOBJ_SHUTTLE ? "shuttle" : "unknown"] = quantize(timestamp - self->bedtime); self->sobj = 0; self->bedtime = 0; }
La ejecución de la secuencia de comandos anterior durante varios segundos devuelve una salida similar al siguiente ejemplo:
# dtrace -s ./whatfor.d dtrace: script './whatfor.d' matched 12 probes ^C kernel-level lock value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@@@@ 3 65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 11 131072 |@@ 1 262144 | 0 preempted value -------------- Distribution ------------ count 16384 | 0 32768 | 4 65536 |@@@@@@@@ 408 131072 |@@@@@@@@@@@@@@@@@@@@@@ 1031 262144 |@@@ 156 524288 |@@ 116 1048576 |@ 51 2097152 | 42 4194304 | 16 8388608 | 15 16777216 | 4 33554432 | 8 67108864 | 0 semaphore value -------------- Distribution ------------ count 32768 | 0 65536 |@@ 61 131072 |@@@@@@@@@@@@@@@@@@@@@@@@ 553 262144 |@@ 63 524288 |@ 36 1048576 | 7 2097152 | 22 4194304 |@ 44 8388608 |@@@ 84 16777216 |@ 36 33554432 | 3 67108864 | 6 134217728 | 0 268435456 | 0 536870912 | 0 1073741824 | 0 2147483648 | 0 4294967296 | 0 8589934592 | 0 17179869184 | 1 34359738368 | 0 shuttle value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@ 2 131072 |@@@@@@@@@@@@@@@@ 6 262144 |@@@@@ 2 524288 | 0 1048576 | 0 2097152 | 0 4194304 |@@@@@ 2 8388608 | 0 16777216 | 0 33554432 | 0 67108864 | 0 134217728 | 0 268435456 | 0 536870912 | 0 1073741824 | 0 2147483648 | 0 4294967296 |@@@@@ 2 8589934592 | 0 17179869184 |@@ 1 34359738368 | 0 condition variable value -------------- Distribution ------------ count 32768 | 0 65536 | 122 131072 |@@@@@ 1579 262144 |@ 340 524288 | 268 1048576 |@@@ 1028 2097152 |@@@ 1007 4194304 |@@@ 1176 8388608 |@@@@ 1257 16777216 |@@@@@@@@@@@@@@ 4385 33554432 | 295 67108864 | 157 134217728 | 96 268435456 | 48 536870912 | 144 1073741824 | 10 2147483648 | 22 4294967296 | 18 8589934592 | 5 17179869184 | 6 34359738368 | 4 68719476736 | 0 |
Cuando una CPU pasa a estado de inactividad, el distribuidor busca trabajos en cola en otras CPU (que no se encuentran en inactividad). El siguiente ejemplo utiliza el sondeo dequeue para comprender la frecuencia con la que se transfieren las aplicaciones y qué CPU lo hace:
#pragma D option quiet sched:::dequeue /args[2]->cpu_id != --1 && cpu != args[2]->cpu_id && (curlwpsinfo->pr_flag & PR_IDLE)/ { @[stringof(args[1]->pr_fname), args[2]->cpu_id] = lquantize(cpu, 0, 100); } END { printa("%s stolen from CPU %d by:\n%@d\n", @); }
La cola de la salida de la ejecución de la secuencia de comandos anterior en un sistema con 4 CPU devuelve una salida similar al siguiente ejemplo:
# dtrace -s ./whosteal.d ^C ... nscd stolen from CPU 1 by: value -------------- Distribution ------------ count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 28 3 | 0 snmpd stolen from CPU 1 by: value -------------- Distribution ------------ count < 0 | 0 0 |@ 1 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 31 3 |@@ 2 4 | 0 sched stolen from CPU 1 by: value -------------- Distribution ------------ count < 0 | 0 0 |@@ 3 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 36 3 |@@@@ 5 4 | 0 |
En lugar de saber qué CPU realizó qué trabajo, puede que desee conocer las CPU en las que los procesos y subprocesos están esperando a ejecutarse. Puede utilizar los sondeos enqueue y dequeue de forma conjunta para resolver esta duda:
sched:::enqueue { self->ts = timestamp; } sched:::dequeue /self->ts/ { @[args[2]->cpu_id] = quantize(timestamp - self->ts); self->ts = 0; }
La ejecución de la secuencia de comandos anterior durante varios segundos devuelve una salida similar al siguiente ejemplo:
# dtrace -s ./qtime.d dtrace: script './qtime.d' matched 5 probes ^C -1 value -------------- Distribution ------------ count 4096 | 0 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 16384 | 0 0 value -------------- Distribution ------------ count 1024 | 0 2048 |@@@@@@@@@@@@@@@ 262 4096 |@@@@@@@@@@@@@ 227 8192 |@@@@@ 87 16384 |@@@ 54 32768 | 7 65536 | 9 131072 | 1 262144 | 5 524288 | 4 1048576 | 2 2097152 | 0 4194304 | 0 8388608 | 0 16777216 | 1 33554432 | 2 67108864 | 2 134217728 | 0 268435456 | 0 536870912 | 0 1073741824 | 1 2147483648 | 1 4294967296 | 0 1 value -------------- Distribution ------------ count 1024 | 0 2048 |@@@@ 49 4096 |@@@@@@@@@@@@@@@@@@@@ 241 8192 |@@@@@@@ 91 16384 |@@@@ 55 32768 | 7 65536 | 3 131072 | 2 262144 | 1 524288 | 0 1048576 | 0 2097152 | 0 4194304 | 0 8388608 | 0 16777216 | 0 33554432 | 3 67108864 | 1 134217728 | 4 268435456 | 2 536870912 | 0 1073741824 | 3 2147483648 | 2 4294967296 | 0 |
Observe los valores que no son cero al final de la salida de ejemplo. Estos puntos de datos revelan diversas instancias en ambas CPU en las que se situó en cola un subproceso para que se ejecutara durante varios segundos.
En lugar de observar los tiempos de espera, puede que desee examinar la longitud de la cola de ejecución a través del tiempo. Mediante los sondeos enqueue y dequeue puede establecer una matriz asociativa para que realice un seguimiento de la longitud de la cola:
sched:::enqueue { this->len = qlen[args[2]->cpu_id]++; @[args[2]->cpu_id] = lquantize(this->len, 0, 100); } sched:::dequeue /qlen[args[2]->cpu_id]/ { qlen[args[2]->cpu_id]—; }
La ejecución de la secuencia de comandos anterior durante aproximadamente 30 segundos en un sistema portátil monoprocesador con un amplio tiempo de inactividad devolvería una salida similar a la del siguiente ejemplo:
# dtrace -s ./qlen.d dtrace: script './qlen.d' matched 5 probes ^C 0 value -------------- Distribution ------------ count < 0 | 0 0 |@@@@@@@@@@@@@@@@@@@@@@@@@ 110626 1 |@@@@@@@@@ 41142 2 |@@ 12655 3 |@ 5074 4 | 1722 5 | 701 6 | 302 7 | 63 8 | 23 9 | 12 10 | 24 11 | 58 12 | 14 13 | 3 14 | 0 |
La salida es básicamente lo que cabría esperar de un sistema en inactividad: la mayor parte del tiempo durante la que se sitúa en cola un subproceso ejecutable, el tamaño de la cola de ejecución era escaso (longitud de tres subprocesos o inferior). Sin embargo, dado que el sistema estuvo en inactividad durante un largo periodo de tiempo, los puntos de datos de la parte inferior de la tabla podrían ser inesperados. Por ejemplo, ¿por qué tenía la cola de ejecución 13 subprocesos ejecutables? Para explorar esta cuestión, podría escribir una secuencia de comandos D que muestre el contenido de la cola de ejecución cuando su longitud sea amplia. Este problema es complicado, dado que la habilitación de D no puede iterar a lo largo de estructuras de datos y, por lo tanto, no puede simplemente iterar a través de toda la cola de ejecución. Incluso si la habilitación de D pudiera hacerlo, debería evitar dependencias con las estructuras de datos internas del núcleo.
Para este tipo de secuencia de comandos, habilitará los sondeos enqueue y dequeue y utilizaría tanto especulaciones como matrices asociativas. Siempre que se sitúa en cola un subproceso, la secuencia de comandos aumenta la longitud de la cola, y registra la marca de hora en una matriz asociativa grabada por el subproceso. En este caso no podrá utilizar una variable thread-local, ya que un subproceso podría situar en cola a otro. La secuencia de comandos comprueba si la longitud de la cola supera el máximo. En caso afirmativo, inicia una nueva especulación y registra la marca horaria y el nuevo máximo. Posteriormente, cuando se quita de cola un subproceso, la secuencia de comandos compara la marca horaria en cola con la marca horaria de mayor longitud: si el proceso se colocó en cola antes que la marca horaria de mayor longitud, el subproceso se encontraba en cola al registrar el subproceso de mayor longitud. En este caso, la secuencia de comandos realiza un seguimiento de forma especulativa de la información del subproceso. Una vez que el núcleo quita de la cola el último subproceso que se encontraba en cola en la marca horaria de mayor longitud, la secuencia de comandos efectúa los datos de especulación. Esta secuencia de comandos se muestra a continuación:
#pragma D option quiet #pragma D option nspec=4 #pragma D option specsize=100k int maxlen; int spec[int]; sched:::enqueue { this->len = ++qlen[this->cpu = args[2]->cpu_id]; in[args[0]->pr_addr] = timestamp; } sched:::enqueue /this->len > maxlen && spec[this->cpu]/ { /* * There is already a speculation for this CPU. We just set a new * record, so we'll discard the old one. */ discard(spec[this->cpu]); } sched:::enqueue /this->len > maxlen/ { /* * We have a winner. Set the new maximum length and set the timestamp * of the longest length. */ maxlen = this->len; longtime[this->cpu] = timestamp; /* * Now start a new speculation, and speculatively trace the length. */ this->spec = spec[this->cpu] = speculation(); speculate(this->spec); printf("Run queue of length %d:\n", this->len); } sched:::dequeue /(this->in = in[args[0]->pr_addr]) && this->in <= longtime[this->cpu = args[2]->cpu_id]/ { speculate(spec[this->cpu]); printf(" %d/%d (%s)\n", args[1]->pr_pid, args[0]->pr_lwpid, stringof(args[1]->pr_fname)); } sched:::dequeue /qlen[args[2]->cpu_id]/ { in[args[0]->pr_addr] = 0; this->len = --qlen[args[2]->cpu_id]; } sched:::dequeue /this->len == 0 && spec[this->cpu]/ { /* * We just processed the last thread that was enqueued at the time * of longest length; commit the speculation, which by now contains * each thread that was enqueued when the queue was longest. */ commit(spec[this->cpu]); spec[this->cpu] = 0; }
La ejecución de la secuencia de comandos anterior en el mismo portátil monoprocesador devuelve una salida similar a la del siguiente ejemplo:
# dtrace -s ./whoqueue.d Run queue of length 3: 0/0 (sched) 0/0 (sched) 101170/1 (dtrace) Run queue of length 4: 0/0 (sched) 100356/1 (Xsun) 100420/1 (xterm) 101170/1 (dtrace) Run queue of length 5: 0/0 (sched) 0/0 (sched) 100356/1 (Xsun) 100420/1 (xterm) 101170/1 (dtrace) Run queue of length 7: 0/0 (sched) 100221/18 (nscd) 100221/17 (nscd) 100221/16 (nscd) 100221/13 (nscd) 100221/14 (nscd) 100221/15 (nscd) Run queue of length 16: 100821/1 (xterm) 100768/1 (xterm) 100365/1 (fvwm2) 101118/1 (xterm) 100577/1 (xterm) 101170/1 (dtrace) 101020/1 (xterm) 101089/1 (xterm) 100795/1 (xterm) 100741/1 (xterm) 100710/1 (xterm) 101048/1 (xterm) 100697/1 (MozillaFirebird-) 100420/1 (xterm) 100394/1 (xterm) 100368/1 (xterm) ^C |
La salida revela que las largas colas de ejecución están motivadas por un alto número de procesos xterm no ejecutables. Este experimento coincidía con un cambio en el escritorio virtual y, por lo tanto, los resultados probablemente están provocados por algún tipo de procesamiento de evento X.
En enqueue y dequeue, el ejemplo final demuestra que la ráfaga en la longitud de la cola de ejecución está motivada por procesos xterm. Una hipótesis es que las observaciones estuvieron provocadas por un cambio en el escritorio virtual. Es posible utilizar el sondeo wakeup para explorar esta hipótesis determinando quién y cuándo está activando los procesos xterm, tal y como se muestra en el ejemplo siguiente:
#pragma D option quiet dtrace:::BEGIN { start = timestamp; } sched:::wakeup /stringof(args[1]->pr_fname) == "xterm"/ { @[execname] = lquantize((timestamp - start) / 1000000000, 0, 10); } profile:::tick-1sec /++x == 10/ { exit(0); }
Para investigar la hipótesis, ejecute la secuencia de comandos anterior, esperando unos cinco segundos, y cambie el escritorio virtual una única vez. Si la ráfaga de procesos no ejecutables xterm está motivada por un cambio de escritorio virtual, la salida debería mostrar una ráfaga de actividad de activación en la marca de cinco segundos.
# dtrace -s ./xterm.d Xsun value -------------- Distribution ------------ count 4 | 0 5 |@ 1 6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32 7 | 0 |
La salida muestra que el servidor X está activando procesos xterm, agrupados en torno al momento en el que cambiaron los escritorios virtuales. Si su intención era comprender la interacción entre el servidor X y los procesos xterm, podrá agregar en la pila de usuario marcas de seguimiento cuando el servidor X active el sondeo wakeup.
La comprensión del rendimiento de sistemas cliente/servidor tales como el sistema de ventanas X requiere comprender a los clientes en nombre de los cuales está realizando el trabajo el servidor. Este tipo de pregunta es difícil de responder con herramientas convencionales de análisis de rendimiento. Sin embargo, si cuenta con un modelo en el que un cliente envía un mensaje al servidor y pasa a inactividad esperando el procesamiento por parte del servidor, podría utilizar el sondeo wakeup para determinar el cliente para el que se está realizando la solicitud, tal y como se muestra en el siguiente ejemplo:
self int last; sched:::wakeup /self->last && args[0]->pr_stype == SOBJ_CV/ { @[stringof(args[1]->pr_fname)] = sum(vtimestamp - self->last); self->last = 0; } sched:::wakeup /execname == "Xsun" && self->last == 0/ { self->last = vtimestamp; }
La ejecución de la secuencia de comandos anterior devuelve una salida similar al siguiente ejemplo:
dtrace -s ./xwork.d dtrace: script './xwork.d' matched 14 probes ^C xterm 9522510 soffice.bin 9912594 fvwm2 100423123 MozillaFirebird 312227077 acroread 345901577 |
Esta salida revela que gran parte del trabajo Xsun se está realizando en nombre de los procesos acroread, MozillaFirebird y, en menor grado, fvwm2. Tenga en cuenta que la secuencia de comandos sólo examinó activaciones desde objetos de sincronización de variables de condición (SOBJ_CV). Tal y como se describe en la Tabla 25–4las variables de condición son el tipo de objeto de sincronización que suele utilizarse para sincronizar por razones diferentes al acceso a una región de datos compartida. En el caso del servidor X, un cliente esperará los datos en un sector de conducción esperando en inactividad en una variable de condición.
Asimismo, puede utilizar el sondeo sleep junto con el sondeo wakeup para saber qué aplicaciones están bloqueando en qué aplicaciones y durante cuánto tiempo, tal y como se muestra en el siguiente ejemplo:
#pragma D option quiet sched:::sleep /!(curlwpsinfo->pr_flag & PR_ISSYS) && curlwpsinfo->pr_stype == SOBJ_CV/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { @[stringof(args[1]->pr_fname), execname] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } END { printa("%s sleeping on %s:\n%@d\n", @); }
La cola de la salida resultante de la ejecución de la secuencia de comandos de ejemplo durante varios segundos en un sistema de escritorio es similar al siguiente ejemplo:
# dtrace -s ./whofor.d ^C ... xterm sleeping on Xsun: value -------------- Distribution ------------ count 131072 | 0 262144 | 12 524288 | 2 1048576 | 0 2097152 | 5 4194304 |@@@ 45 8388608 | 1 16777216 | 9 33554432 |@@@@@ 83 67108864 |@@@@@@@@@@@ 164 134217728 |@@@@@@@@@@ 147 268435456 |@@@@ 56 536870912 |@ 17 1073741824 | 9 2147483648 | 1 4294967296 | 3 8589934592 | 1 17179869184 | 0 fvwm2 sleeping on Xsun: value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@@@@@@@@@@@@@@@@@@ 67 131072 |@@@@@ 16 262144 |@@ 6 524288 |@ 3 1048576 |@@@@@ 15 2097152 | 0 4194304 | 0 8388608 | 1 16777216 | 0 33554432 | 0 67108864 | 1 134217728 | 0 268435456 | 0 536870912 | 1 1073741824 | 1 2147483648 | 2 4294967296 | 2 8589934592 | 2 17179869184 | 0 34359738368 | 2 68719476736 | 0 syslogd sleeping on syslogd: value -------------- Distribution ------------ count 17179869184 | 0 34359738368 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 68719476736 | 0 MozillaFirebird sleeping on MozillaFirebird: value -------------- Distribution ------------ count 65536 | 0 131072 | 3 262144 |@@ 14 524288 | 0 1048576 |@@@ 18 2097152 | 0 4194304 | 0 8388608 | 1 16777216 | 0 33554432 | 1 67108864 | 3 134217728 |@ 7 268435456 |@@@@@@@@@@ 53 536870912 |@@@@@@@@@@@@@@ 78 1073741824 |@@@@ 25 2147483648 | 0 4294967296 | 0 8589934592 |@ 7 17179869184 | 0 |
Puede que desee comprender cómo y por qué razón MozillaFirebird se está bloqueando a sí mismo. Puede modificar la secuencia de comandos anterior del siguiente modo para responder a esta pregunta:
#pragma D option quiet sched:::sleep /execname == "MozillaFirebird" && curlwpsinfo->pr_stype == SOBJ_CV/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /execname == "MozillaFirebird" && bedtime[args[0]->pr_addr]/ { @[args[1]->pr_pid, args[0]->pr_lwpid, pid, curlwpsinfo->pr_lwpid] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { bedtime[args[0]->pr_addr] = 0; } END { printa("%d/%d sleeping on %d/%d:\n%@d\n", @); }
La ejecución de la secuencia de comandos modificada durante varios segundos devolverá una salida similar a la del siguiente ejemplo:
# dtrace -s ./firebird.d ^C 100459/1 sleeping on 100459/13: value -------------- Distribution ------------ count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 1048576 | 0 100459/13 sleeping on 100459/1: value -------------- Distribution ------------ count 16777216 | 0 33554432 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 67108864 | 0 100459/1 sleeping on 100459/2: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@ 5 65536 |@ 2 131072 |@@@@@ 6 262144 | 1 524288 |@ 2 1048576 | 0 2097152 |@@ 3 4194304 |@@@@ 5 8388608 |@@@@@@@@ 9 16777216 |@@@@@ 6 33554432 |@@ 3 67108864 | 0 100459/1 sleeping on 100459/5: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@ 12 65536 |@@ 5 131072 |@@@@@@ 15 262144 | 1 524288 | 1 1048576 | 2 2097152 |@ 4 4194304 |@@@@@ 13 8388608 |@@@ 8 16777216 |@@@@@ 13 33554432 |@@ 6 67108864 |@@ 5 134217728 |@ 4 268435456 | 0 536870912 | 1 1073741824 | 0 100459/2 sleeping on 100459/1: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@@@@@@@@@@ 11 65536 | 0 131072 |@@ 2 262144 | 0 524288 | 0 1048576 |@@@@ 3 2097152 |@ 1 4194304 |@@ 2 8388608 |@@ 2 16777216 |@ 1 33554432 |@@@@@@ 5 67108864 | 0 134217728 | 0 268435456 | 0 536870912 |@ 1 1073741824 |@ 1 2147483648 |@ 1 4294967296 | 0 100459/5 sleeping on 100459/1: value -------------- Distribution ------------ count 16384 | 0 32768 | 1 65536 | 2 131072 | 4 262144 | 7 524288 | 1 1048576 | 5 2097152 | 10 4194304 |@@@@@@ 77 8388608 |@@@@@@@@@@@@@@@@@@@@@@@ 270 16777216 |@@@ 43 33554432 |@ 20 67108864 |@ 14 134217728 | 5 268435456 | 2 536870912 | 1 1073741824 | 0 |
Puede utilizar también los sondeos sleep y wakeup para comprender el rendimiento de servidores puerta, como el daemon name service cache, tal y como se muestra en el siguiente ejemplo:
sched:::sleep /curlwpsinfo->pr_stype == SOBJ_SHUTTLE/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /execname == "nscd" && bedtime[args[0]->pr_addr]/ { @[stringof(curpsinfo->pr_fname), stringof(args[1]->pr_fname)] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { bedtime[args[0]->pr_addr] = 0; }
La cola de la salida al ejecutar la secuencia de comandos anterior en un gran servidor de correo es similar al siguiente ejemplo:
imapd value -------------- Distribution ------------ count 16384 | 0 32768 | 2 65536 |@@@@@@@@@@@@@@@@@ 57 131072 |@@@@@@@@@@@ 37 262144 | 3 524288 |@@@ 11 1048576 |@@@ 10 2097152 |@@ 9 4194304 | 1 8388608 | 0 mountd value -------------- Distribution ------------ count 65536 | 0 131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 49 262144 |@@@ 6 524288 | 1 1048576 | 0 2097152 | 0 4194304 |@@@@ 7 8388608 |@ 3 16777216 | 0 sendmail value -------------- Distribution ------------ count 16384 | 0 32768 |@ 18 65536 |@@@@@@@@@@@@@@@@@ 205 131072 |@@@@@@@@@@@@@ 154 262144 |@ 23 524288 | 5 1048576 |@@@@ 50 2097152 | 7 4194304 | 5 8388608 | 2 16777216 | 0 automountd value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@@@@@@ 22 131072 |@@@@@@@@@@@@@@@@@@@@@@@ 51 262144 |@@ 6 524288 | 1 1048576 | 0 2097152 | 2 4194304 | 2 8388608 | 1 16777216 | 1 33554432 | 1 67108864 | 0 134217728 | 0 268435456 | 1 536870912 | 0 |
Podría estar interesado en los inusuales puntos de datos para automountd o en el punto de datos persistente a más de un milisegundo para sendmail. Asimismo, puede añadir predicados a la secuencia de comandos anterior para conocer detalladamente las causas de cualquier tipo de resultado excepcional o anómalo.
Dado que Solaris es un sistema preemptivo, los subprocesos de mayor prioridad se adelantan a los de una prioridad más baja. La preempción puede provocar una burbuja de latencia significativa en el subproceso de menor prioridad, por lo que puede que desee saber qué subprocesos están adelantándose a cuáles. El siguiente ejemplo muestra cómo utilizar los sondeos preempt y remain-cpu para visualizar esta información:
#pragma D option quiet sched:::preempt { self->preempt = 1; } sched:::remain-cpu /self->preempt/ { self->preempt = 0; } sched:::off-cpu /self->preempt/ { /* * If we were told to preempt ourselves, see who we ended up giving * the CPU to. */ @[stringof(args[1]->pr_fname), args[0]->pr_pri, execname, curlwpsinfo->pr_pri] = count(); self->preempt = 0; } END { printf("%30s %3s %30s %3s %5s\n", "PREEMPTOR", "PRI", "PREEMPTED", "PRI", "#"); printa("%30s %3d %30s %3d %5@d\n", @); }
La ejecución de la secuencia de comandos anterior en un sistema de escritorio devuelve una salida similar a la mostrada en el siguiente ejemplo:
# dtrace -s ./whopreempt.d ^C PREEMPTOR PRI PREEMPTED PRI # sched 60 Xsun 53 1 xterm 59 Xsun 53 1 MozillaFirebird 57 Xsun 53 1 mpstat 100 fvwm2 59 1 sched 99 MozillaFirebird 57 1 sched 60 dtrace 30 1 mpstat 100 Xsun 59 2 sched 60 Xsun 54 2 sched 99 sched 60 2 fvwm2 59 Xsun 44 2 sched 99 Xsun 44 2 sched 60 xterm 59 2 sched 99 Xsun 53 2 sched 99 Xsun 54 3 sched 60 fvwm2 59 3 sched 60 Xsun 59 3 sched 99 Xsun 59 4 fvwm2 59 Xsun 54 8 fvwm2 59 Xsun 53 9 Xsun 59 MozillaFirebird 57 10 sched 60 MozillaFirebird 57 14 MozillaFirebird 57 Xsun 44 16 MozillaFirebird 57 Xsun 54 18 |
La preempción se basa en las prioridades, por lo que puede que desee observar los cambios de prioridad durante un periodo de tiempo. El siguiente ejemplo utiliza el sondeo change-pri para visualizar esta información:
sched:::change-pri { @[stringof(args[0]->pr_clname)] = lquantize(args[2] - args[0]->pr_pri, -50, 50, 5); }
La secuencia de comandos de ejemplo captura el grado de aumento o disminución de la prioridad, y realiza adiciones según la clase de planificación. La ejecución de la secuencia de comandos anterior devuelve una salida similar al siguiente ejemplo:
# dtrace -s ./pri.d dtrace: script './pri.d' matched 10 probes ^C IA value -------------- Distribution ------------ count < -50 | 20 -50 |@ 38 -45 | 4 -40 | 13 -35 | 12 -30 | 18 -25 | 18 -20 | 23 -15 | 6 -10 |@@@@@@@@ 201 -5 |@@@@@@ 160 0 |@@@@@ 138 5 |@ 47 10 |@@ 66 15 |@ 36 20 |@ 26 25 |@ 28 30 | 18 35 | 22 40 | 8 45 | 11 >= 50 |@ 34 TS value -------------- Distribution ------------ count -15 | 0 -10 |@ 1 -5 |@@@@@@@@@@@@ 7 0 |@@@@@@@@@@@@@@@@@@@@ 12 5 | 0 10 |@@@@@ 3 15 | 0 |
El resultado muestra la manipulación de prioridad de la clase de planificación Interactive (IA). En lugar de percibir la manipulación de la prioridad, quizá desee ver los valores de prioridad de un proceso y subproceso determinado a lo largo del tiempo. La siguiente secuencia de comandos utiliza el sondeo change-pri para visualizar esta información:
#pragma D option quiet BEGIN { start = timestamp; } sched:::change-pri /args[1]->pr_pid == $1 && args[0]->pr_lwpid == $2/ { printf("%d %d\n", timestamp - start, args[2]); } tick-1sec /++n == 5/ { exit(0); }
Para ver el cambio sufrido por la prioridad a lo largo del tiempo, escriba el siguiente comando en una ventana:
$ echo $$ 139208 $ while true ; do let i=0 ; done |
En otra ventana, ejecute la secuencia de comandos y redirija la salida a un archivo:
# dtrace -s ./pritime.d 139208 1 > /tmp/pritime.out # |
Puede utilizar el archivo /tmp/pritime.out que se genera como entrada para un software de trazos para visualizar gráficamente la prioridad a lo largo del tiempo. gnuplot es un paquete de trazos gratuito que se incluye en el CD compañero freeware de Solaris. De forma predeterminada, gnuplot está instalado en /opt/sfw/bin.
Solaris utiliza contabilidad de CPU basado en pulsos de reloj, en el que se activa una interrupción del reloj del sistema en un intervalo fijo, y atribuye la utilización de la CPU a los subprocesos y procesos que se ejecutan al mismo tiempo que el pulso. El ejemplo siguiente muestra cómo utilizar el sondeo tick para observar esta atribución:
# dtrace -n sched:::tick'{@[stringof(args[1]->pr_fname)] = count()}' ^C arch 1 sh 1 sed 1 echo 1 ls 1 FvwmAuto 1 pwd 1 awk 2 basename 2 expr 2 resize 2 tput 2 uname 2 fsflush 2 dirname 4 vim 9 fvwm2 10 ksh 19 xterm 21 Xsun 93 MozillaFirebird 260 |
La frecuencia de reloj del sistema varía según el sistema operativo, pero suele estar en el intervalo de los 25 y los 1024 hercios. La frecuencia de reloj del sistema Solaris es ajustable, pero el valor predeterminado es 100 hercios.
El sondeo tick sólo se activa si el reloj del sistema detecta un subproceso que pueda ejecutar. Para utilizar el sondeo tick para observar la frecuencia de reloj del sistema, debe contar con un subproceso que pueda ejecutarse en todo momento. Cree en una ventana una shell en bucle, tal y como se muestra en el ejemplo siguiente:
$ while true ; do let i=0 ; done |
Ejecute en otra ventana la siguiente secuencia de comandos:
uint64_t last[int]; sched:::tick /last[cpu]/ { @[cpu] = min(timestamp - last[cpu]); } sched:::tick { last[cpu] = timestamp; }
# dtrace -s ./ticktime.d dtrace: script './ticktime.d' matched 2 probes ^C 0 9883789 |
El intervalo mínimo es 9,8 milisegundos, que indica que la frecuencia de pulso de reloj predeterminada es 10 milisegundos (100 hercios). El mínimo observado suele ser algo inferior a los 10 milisegundos, debido al movimiento.
Uno de los defectos del registro basado en pulsos de reloj es que el reloj del sistema que realiza el registro suele ser también responsable de distribuir las actividades de planificación relacionadas con el tiempo. Como resultado, si un subproceso va a realizar determinada cantidad de trabajo cada pulso de reloj (es decir, cada 10 milisegundos), el sistema realizará un registro superior o inferior al subproceso, en función de si el registro se realiza antes o después de la actividad de planificación de distribución relacionada con el tiempo. En Solaris, el registro se realiza antes de la distribución relacionada con el tiempo. Como resultado, el sistema realizará un registro inferior de los subprocesos que están en ejecución en un intervalo regular. Si dichos subprocesos se encuentran en ejecución durante un tiempo inferior al intervalo de pulso de reloj, pueden "ocultarse" tras el pulso del reloj. El ejemplo siguiente muestra el punto hasta el que el sistema tiene tales subprocesos:
sched:::tick, sched:::enqueue { @[probename] = lquantize((timestamp / 1000000) % 10, 0, 10); }
La salida de la secuencia de comandos de ejemplo es dos distribuciones del desplazamiento en milisegundos dentro de un intervalo de diez milisegundos, uno para el sondeo tick y otro para el sondeo enqueue:
# dtrace -s ./tick.d dtrace: script './tick.d' matched 4 probes ^C tick value -------------- Distribution ------------ count 6 | 0 7 |@ 3 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 79 9 | 0 enqueue value -------------- Distribution ------------ count < 0 | 0 0 |@@ 267 1 |@@ 300 2 |@@ 259 3 |@@ 291 4 |@@@ 360 5 |@@ 305 6 |@@ 295 7 |@@@@ 522 8 |@@@@@@@@@@@@ 1315 9 |@@@ 337 |
El histograma de salida denominado tick muestra que el pulso de reloj se está activando con un desplazamiento de 8 milisegundos. Si la planificación no estuviera relacionada de ningún modo con el pulso de reloj, la salida de enqueue estaría distribuida de forma uniforme a lo largo del intervalo de diez milisegundos. Sin embargo, la salida muestra un pico en el mismo desplazamiento de 8 milisegundos, que indica que al menos algunos subprocesos del sistema están planificándose en base al tiempo.