示例
on-cpu 和 off-cpu
可能遇到的一个常见问题是哪些 CPU 在运行线程，将运行多久。此问题可以通过使用 on-cpu 和 off-cpu 探测器在系统范围内轻松回答，如下例所示：
sched:::on-cpu
{
self->ts = timestamp;
}
sched:::off-cpu
/self->ts/
{
@[cpu] = quantize(timestamp - self->ts);
self->ts = 0;
}
运行上面的脚本将会生成与以下示例类似的输出：
# 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
|
以上输出显示，在 CPU 1 中，线程运行的时间小于 100 微秒，或者约 10 毫秒。两组数据之间的显著差异显示在直方图中。或许您还想了解哪些 CPU 在运行某个特定进程。同样可以使用 on-cpu 和 off-cpu 探测器来回答此问题。以下脚本显示哪些 CPU 运行指定的应用程序超过 10 秒：
#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", @);
}
在大型邮件服务器上运行以上脚本并指定 IMAP（Internet Message Access Protocol，Internet 消息访问协议）守护进程将生成与以下示例类似的输出：
# 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 在选择要运行线程的 CPU 时会考虑线程已休眠的时间：休眠时间不足的线程往往不会迁移。可使用 off-cpu 和 on-cpu 探测器来观察此行为：
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;
}
运行以上脚本约 30 秒将会生成与以下示例类似的输出：
# 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
|
示例输出显示非迁移的出现次数大大超过迁移的出现次数。而且，休眠时间越长，发生迁移的可能性越大。100 毫秒子范围中的分布明显不同，但因为休眠时间变长，所以看起来很相似。此结果指示，一但超出特定阈值，在做出调度决策时就不会考虑休眠时间。
使用 off-cpu 和 on-cpu 的最后示例说明如何使用这些探测器和 pr_stype 字段来确定线程休眠的原因和时间：
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;
}
运行以上脚本若干秒将会生成与以下示例类似的输出：
# 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
|
enqueue 和 dequeue
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。可以使用 enqueue 和 dequeue 探测器来回答此问题：
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 上的若干实例，其中线程已进入运行队列若干秒。
您可能不需要查看等待时间，而要检查一段时间内运行队列的长度。通过使用 enqueue 和 dequeue 探测器，可以建立关联数组来跟踪队列长度：
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 启用项可以这样做，也应该避免对内核的内部数据结构产生依赖性。
对于此类型的脚本，应启用 enqueue 和 dequeue 探测器并使用推理和关联数组。每次线程入队时，脚本将递增队列的长度并在由线程控制的关联数组中记录时间标记。由于一个线程可能会让另一个线程入队，所以在此情况下不能使用线程局部变量。于是脚本将检查队列长度是否超出最大值。如果超出最大值，则脚本会启动新的推理操作并记录时间标记和新的最大值。随后，当线程离开队列时，脚本会将入队时间标记与最长长度时间标记进行比较：如果线程在最长长度的时间标记之前入队，则在记录最长长度时线程位于队列中。在此情况下，脚本将推理跟踪线程的信息。一旦内核允许在最长长度的时间标记时入队的最后一个线程离开队列，线程将提交推理数据。此脚本如下所示：
#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 事件处理造成的。
sleep 和 wakeup
在enqueue 和 dequeue中，最后的示例说明因为可运行 xterm 进程而导致运行队列长度剧增。一种猜测是这种现象是因为虚拟桌面中的更改而造成的。要验证此猜测，可使用 wakeup 探测器来确定是谁唤醒了 xterm 进程以及是何时唤醒的，如下例所示：
#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);
}
要验证此猜测，请运行以上脚本，等待大约 5 秒，然后切换一次虚拟桌面。如果 xterm 进程的剧增是因为切换虚拟桌面造成的，则输出应该在 5 秒标记处显示唤醒活动剧增。
# dtrace -s ./xterm.d
Xsun
value -------------- Distribution ------------ count
4 | 0
5 |@ 1
6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32
7 | 0
|
此输出显示 X 服务器正在唤醒切换虚拟桌面时聚集的 xterm 进程。如果要了解 X 服务器与 xterm 进程之间的交互，可在 X 服务器触发 wakeup 探测器时聚集用户栈跟踪。
要了解像 X 窗口系统这样的客户机/服务器系统的性能，您需要了解服务器以其名义运行的客户机。常规性能分析工具很难回答这类问题。但是，如果某个模型中的客户机向服务器发送一条消息并且休眠，而且是在暂挂服务器处理时休眠，则可以使用 wakeup 探测器来确定对其执行请求的客户机，如下例所示：
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;
}
运行上面的脚本将会生成与以下示例类似的输出：
dtrace -s ./xwork.d dtrace: script './xwork.d' matched 14 probes ^C xterm 9522510 soffice.bin 9912594 fvwm2 100423123 MozillaFirebird 312227077 acroread 345901577 |
此输出显示许多 Xsun 工作都是以进程 acroread、MozillaFirebird 的名义完成的，很少以 fvwm2 的名义完成。请注意，此脚本仅检查条件变量同步对象 (SOBJ_CV) 中的唤醒次数。如表 25–4 中所述，条件变量为通常用于同步（出于访问共享数据区域之外的原因）的同步对象类型。如果使用 X 服务器，客户机将通过对条件变量休眠来等待管道中的数据。
而且，您还可使用 sleep 探测器和 wakeup 探测器来了解哪些应用程序在哪些应用程序上阻塞，以及阻塞多长时间，如下例所示：
#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", @);
}
在桌面系统上运行以上示例若干秒生成的输出后半部分与以下示例类似：
# 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
|
您可能需要了解 MozillaFirebird 如何以及为何阻塞自身。可按以下示例中所示修改以上脚本来回答此问题：
#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", @);
}
运行修改后的脚本若干秒将会生成与以下示例类似的输出：
# 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
|
还可使用 sleep 和 wakeup 探测器来了解门服务器的性能（如名称服务高速缓存守护进程），如下例所示：
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;
}
在大型邮件服务器上运行以上脚本生成的输出后半部分与以下示例类似：
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
|
您可能会关心 automountd 的异常数据点或 sendmail 的超过 1 毫秒的持久数据点。可向以上脚本中添加其他谓词以有效查看造成任何异常或反常结果的原因。
preempt、remain-cpu
因为 Solaris 是抢占系统，所以高优先级线程将抢先于低优先级线程。抢占会导致低优先级线程出现明显延迟，所以您可能需要知道哪些线程被另一些线程抢占。以下示例说明如何使用 preempt 和 remain-cpu 探测器来显示此信息：
#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", @);
}
在桌面系统上运行以上脚本若干秒将会生成与以下示例类似的输出：
# 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
|
change-pri
抢占是根据优先级进行的，因此可能需要观察一段时间内优先级的变化。以下示例使用 change-pri 探测器来显示此信息：
sched:::change-pri
{
@[stringof(args[0]->pr_clname)] =
lquantize(args[2] - args[0]->pr_pri, -50, 50, 5);
}
示例脚本捕获优先级升高或降低的程度，并按调度类聚集。运行上面的脚本将会生成与以下示例类似的输出：
# 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
|
输出显示交互 (Interactive, IA) 调度类的优先级处理。您可能不需要查看优先级处理，而只需要查看一段时间内特定进程和线程的优先级值。以下脚本使用 change-pri 探测器来显示此信息：
#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);
}
要查看一段时间内优先级的变化 ，请在一个窗口中键入以下命令：
$ echo $$ 139208 $ while true ; do let i=0 ; done |
在另一个窗口中运行该脚本并将输出重定向到文件：
# dtrace -s ./pritime.d 139208 1 > /tmp/pritime.out # |
可将上面生成的文件 /tmp/pritime.out 用作绘图软件的输入，以图形方式显示一段时间内的优先级。gnuplot 是免费提供的绘图软件包，它包括在 Solaris 免费软件配套 CD 中。缺省情况下，gnuplot 安装在 /opt/sfw/bin 中。
tick
Solaris 使用基于计时单元的 CPU 记帐（其中系统时钟中断会按固定时间间隔触发）并将 CPU 的使用情况归结到计时单元时间运行的线程和进程。以下示例说明如何使用 tick 探测器来观察这一归结情况：
# 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
|
系统时钟频率随操作系统不同而变化，但通常会在 25 赫兹到 1024 赫兹之间。Solaris 系统时钟频率是可调整的，但缺省值为 100 赫兹。
仅当系统时钟检测到可运行线程时，tick 探测器才会触发。要使用 tick 探测器来观察系统时钟的频率，必须具有始终可运行的线程。在一个窗口中创建循环 shell，如下例所示：
$ while true ; do let i=0 ; done |
在另一个窗口中运行以下脚本：
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 |
最短时间间隔为 9.8 毫秒，它指示缺省时钟周期频率为 10 毫秒（100 赫兹）。因为抖动，所以观察到的最短时间间隔略小于 10 毫秒。
基于计时单元的记帐的一个缺点是，执行记帐的系统时钟通常还负责分派任何与时间有关的调度活动。因此，如果线程要在每个时钟周期（即每 10 毫秒）执行一定量的工作，则根据记帐是在与时间有关的分派调度活动之前还是之后完成，系统会对线程的工作量记帐过多或过少。在 Solaris 中，记帐是在与时间有关的分派之前完成的。因此，系统会对定期运行的线程工作量记帐过少。如果这类线程运行的时间小于时钟周期的时间间隔，它们可以有效地“隐藏”在时钟周期中。以下示例显示系统中这类线程的情况：
sched:::tick,
sched:::enqueue
{
@[probename] = lquantize((timestamp / 1000000) % 10, 0, 10);
}
示例脚本的输出在 10 毫秒时间间隔内分为两个毫秒偏移部分，一个对应于 tick 探测器，另一个对应于 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
|
名为 tick 的输出直方图显示时钟周期在 8 毫秒偏移处触发。如果调度与时钟周期完全无关，enqueue 的输出将平均分布在 10 毫秒时间间隔内。但是，输出显示同一 8 毫秒偏移处有一个峰值，指示系统中至少有一些线程是根据时间调度的。
- © 2010, Oracle Corporation and/or its affiliates