Solaris 动态跟踪指南

enqueuedequeue

CPU 空闲时,分发程序会查找其他(非空闲)CPU 中已进入队列的工作。以下示例使用 dequeue 探测器来了解传送应用程序的频率以及传送应用程序的 CPU:

#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", @);
}

在 4 CPU 系统上运行以上脚本生成的输出后半部分与以下示例类似:


# 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

您可能不需要了解 CPU 的工作内容,而只想了解进程和线程正在等待运行的 CPU。可以使用 enqueuedequeue 探测器来回答此问题:

sched:::enqueue
{
	self->ts = timestamp;
}

sched:::dequeue
/self->ts/
{
	@[args[2]->cpu_id] = quantize(timestamp - self->ts);
	self->ts = 0;
}

运行以上脚本若干秒将会生成与以下示例类似的输出:


# 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

请注意示例输出底部的非零值。这些数据点显示两个 CPU 上的若干实例,其中线程已进入运行队列若干

您可能不需要查看等待时间,而要检查一段时间内运行队列的长度。通过使用 enqueuedequeue 探测器,可以建立关联数组来跟踪队列长度:

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]—;
}

在基本空闲的单处理器便携式系统上运行以上脚本约 30 秒将会生成与以下示例类似的输出:


# 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

此输出能大体上反映出预期在空闲系统上看到的内容:可运行线程入队占用了大部分时间,运行队列非常短(三个或更少的线程)。但是,如果系统基本空闲,则表底部的异常数据点可能不会出现。例如,为什么运行队列有 13 个可运行线程?要研究此问题,可编写 D 脚本以在运行队列过长时显示运行队列的内容。因为 D 启用项不能在数据结构上迭加,因此不能在整个运行队列上简单迭加,所以此问题非常复杂。即使 D 启用项可以这样做,也应该避免对内核的内部数据结构产生依赖性。

对于此类型的脚本,应启用 enqueuedequeue 探测器并使用推理和关联数组。每次线程入队时,脚本将递增队列的长度并在由线程控制的关联数组中记录时间标记。由于一个线程可能会让另一个线程入队,所以在此情况下不能使用线程局部变量。于是脚本将检查队列长度是否超出最大值。如果超出最大值,则脚本会启动新的推理操作并记录时间标记和新的最大值。随后,当线程离开队列时,脚本会将入队时间标记与最长长度时间标记进行比较:如果线程在最长长度的时间标记之前入队,则在记录最长长度时线程位于队列中。在此情况下,脚本将推理跟踪线程的信息。一旦内核允许在最长长度的时间标记时入队的最后一个线程离开队列,线程将提交推理数据。此脚本如下所示:

#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;
}

在同一单处理器膝上型计算机上运行以上脚本将生成与以下示例类似的输出:


# 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

此输出显示出现最长的运行队列是因为有许多可运行 xterm 进程。此实验与虚拟桌面中的更改有冲突,这些结果可能是因为某种 X 事件处理造成的。