Guía de seguimiento dinámico de Solaris

enqueue y dequeue

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.