on-cpu und off-cpu
Welche CPUs führen Threads aus und wie lange? Dies ist eine der Fragen, auf die man häufig gerne eine Antwort hätte. Mit den Prüfpunkten on-cpu und off-cpu lässt sich diese Frage, wie das folgende Beispiel zeigt, auf systemweiter Basis einfach beantworten:
sched:::on-cpu
{
self->ts = timestamp;
}
sched:::off-cpu
/self->ts/
{
@[cpu] = quantize(timestamp - self->ts);
self->ts = 0;
}
Die Ausführung des obigen Skripts erzeugt eine Ausgabe wie in folgendem Beispiel:
# 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
|
Die obige Ausgabe zeigt, dass auf CPU 1 Threads über einen Zeitraum von weniger als 100 Mikrosekunden oder für ca. 10 Millisekunden laufen. Zwischen den zwei Datengruppen ist im Histogramm eine deutliche Lücke zu erkennen. Sie möchten vielleicht auch wissen, welche CPUs einen bestimmten Prozess ausführen. Auch diese Frage können Sie mit den Prüfpunkten on-cpu und off-cpu beantworten. Das folgende Skript zeigt, welche CPUs eine angegebene Anwendung über einen Zeitraum von zehn Sekunden ausführen:
#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", @);
}
Wenn Sie dieses Skript auf einem großen Mail-Server ausführen und den IMAP-Dämon angeben, erhalten Sie eine ähnliche Ausgabe wie diese:
# 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 |
In Solaris wird bei der Auswahl einer CPU, auf der Threads ausgeführt werden sollen, die Schlafzeit der Threads berücksichtigt: Threads, die seit kürzerer Zeit schlafen, migrieren in der Regel eher nicht. Mit den Prüfpunkten on-cpu und off-cpu lässt sich dieses Verhalten beobachten:
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;
}
Wenn Sie das obige Skript ungefähr 30 Sekunden lang ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# 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
|
Aus der Beispielausgabe geht hervor, dass sehr viel häufiger keine Migration stattfindet. Auch zeigt sie, dass eine Migration bei längeren Schlafzeiten wahrscheinlicher ist. Die Verteilungen im Bereich unter 100 Millisekunden fallen deutlich unterschiedlich aus, gleichen sich aber mit zunehmender Schlafdauer immer näher an. Dieses Ergebnis könnte man dahin gehend interpretieren, dass die Schlafzeit bei der Scheduling-Entscheidung keine Rolle mehr spielt, sobald ein bestimmter Schwellwert überschritten ist.
Unser letztes Beispiel für die Prüfpunkte off-cpu und on-cpu demonstriert deren Einsatz gemeinsam mit dem Feld pr_stype, um festzustellen, weshalb und wie lange Threads schlafen:
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;
}
Wenn Sie das obige Skript einige Sekunden lang ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# 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
|
- © 2010, Oracle Corporation and/or its affiliates