Guía de seguimiento dinámico de Solaris

on-cpu y off-cpu

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