Exemples
on-cpu et off-cpu
Une question commune que vous pourriez vous poser est de connaître les CPU exécutant des threads ainsi que la durée du processus. Vous pouvez utiliser les sondes on-cpu et off-cpu pour répondre facilement à cette question sur l'ensemble d'un système, tel qu'illustré dans l'exemple suivant :
sched:::on-cpu
{
self->ts = timestamp;
}
sched:::off-cpu
/self->ts/
{
@[cpu] = quantize(timestamp - self->ts);
self->ts = 0;
}
Exécuter le script ci-dessus engendre une sortie similaire à l'exemple suivant :
# 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 sortie ci-dessus indique que les threads de la CPU 1 tendent à être exécutés moins de 100 microsecondes d'affilée ou pendant 10 millisecondes environ. Un écart considérable entre deux clusters de données est illustré dans l'histogramme. Vous pouvez également être intéressé de connaître les CPU exécutant un processus particulier. Vous pouvez également utiliser les sondes on-cpu et off-cpu pour répondre à cette question. Le script suivant affiche les CPU exécutant une application spécifiée pendant dix secondes :
#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", @);
}
L'exécution du script ci-dessus sur un serveur de messagerie d'envergure et la spécification du démon IMAP donnent une sortie similaire à l'exemple suivant :
# 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 prend en compte la durée de sommeil d'un thread lors de la sélection d'une CPU sur laquelle exécuter le thread : un thread en sommeil moins longtemps n'est généralement pas migré. Vous pouvez utiliser les sondes off-cpu et on-cpu pour observer ce comportement :
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;
}
L'exécution du script ci-dessus pendant 30 secondes environ donne une sortie similaire à l'exemple suivant :
# 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
|
L'exemple de sortie indique qu'il existe bien plus de cas de non migrations que de migrations. De plus, plus la durée de sommeil est longue, plus la migration est probable. Les répartitions sont considérablement différentes dans la plage inférieure aux 100 millisecondes, mais semblent très similaires à mesure que les durées de sommeil augmentent. Ce résultat semblerait indiquer que la durée de sommeil n'est pas un facteur dans la prise de décision de planification lorsqu'un seuil donné est dépassé.
Le dernier exemple utilisant off-cpu et on-cpu illustre l'utilisation de ces sondes avec le champ pr_stype pour déterminer pourquoi des threads sommeillent et pendant combien de temps :
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;
}
L'exécution du script ci-dessus pendant plusieurs secondes donne une sortie similaire à l'exemple suivant :
# 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 et dequeue
Lorsqu'une CPU passe au repos, le dispatcheur recherche des tâches mises en file d'attente sur d'autres CPU (pas au repos). L'exemple suivant utilise la sonde dequeue pour connaître la fréquence de transfert des applications et par quelle 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", @);
}
La fin de la sortie de l'exécution du script ci-dessus sur un système à 4 CPU donne une sortie similaire à l'exemple suivant :
# 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
|
Plutôt que de connaître les CPU actives, vous pouvez souhaiter connaître les CPU sur lesquelles des processus et des threads sont en attente d'exécution. Vous pouvez utiliser les sondes enqueue et dequeue ensemble pour répondre à cette question :
sched:::enqueue
{
self->ts = timestamp;
}
sched:::dequeue
/self->ts/
{
@[args[2]->cpu_id] = quantize(timestamp - self->ts);
self->ts = 0;
}
L'exécution du script ci-dessus pendant plusieurs secondes donne une sortie similaire à l'exemple suivant :
# 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
|
Notez les valeurs différentes de zéro au bas de la sortie. Ces points de données représentent plusieurs instances sur les CPU où un thread a été placé en file d'attente d'exécution pendant plusieurs secondes.
Plutôt que de rechercher les délais d'attente, vous pouvez souhaiter observer la longueur de la file d'attente dans le temps. Grâce aux sondes enqueue et dequeue, vous pouvez définir un ensemble associatif pour suivre la longueur de la file d'attente :
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]—;
}
L'exécution du script ci-dessus pendant 30 secondes environ sur un système portable à un processeur au repos donne une sortie similaire à l'exemple suivant :
# 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 sortie est grossièrement ce que vous auriez pu attendre d'un système au repos : le thread exécutable est placé en file d'attente quasiment tout le temps et la file d'attente d'exécution est très courte (trois threads maximum). Cependant, étant donné que le système était au repos, les points de données exceptionnels au bas du tableau peuvent être inattendus. Par exemple, pourquoi la file d'attente comportait-elle 13 threads exécutables ? Pour répondre à cette question, vous pourriez rédiger un script D affichant le contenu de la file d'attente lorsque celle-ci est longue. Ce problème est complexe car les activations D ne peuvent pas être itérées sur des structures de données, et donc pas sur l'ensemble de la file d'attente. Même si des activations D le pouvaient, vous devez éviter toute dépendance aux structures de données internes du noyau.
Pour ce type de script, vous devriez activer les sondes enqueue et dequeue et utiliser des spéculations et des ensembles associatifs. Lorsqu'un thread est placé en file d'attente, le script incrémente la longueur de la file d'attente et enregistre l'horodatage dans un ensemble associatif affecté au thread. Vous ne pouvez pas utiliser une variable locale de thread dans ce cas car un thread peut être placé en file d'attente par un autre thread. Le script vérifie alors si la longueur de la file d'attente est supérieure à la valeur maximale. Si c'est le cas, le script entame une nouvelle spéculation, et enregistre l'horodatage et la nouvelle valeur maximale. Ensuite, lorsqu'un thread est retiré de la file d'attente, le script compare l'horotadage de mise en file d'attente avec celui de la longueur la plus importante : si le thread a été placé en file d'attente avant l'horodatage de la longueur la plus importante, le thread se trouvait en file d'attente au moment de l'enregistrement de la longueur la plus importante. Dans ce cas, le script suit de manière spéculative les informations du thread. Lorsque le noyau retire de la file d'attente le dernier thread placé au niveau de l'horodatage de la longueur la plus importante, le script fournit les données de spéculation. Ce script est illustré ci-dessous :
#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;
}
L'exécution du script ci-dessus sur le même système portable à un processeur donne une sortie similaire à l'exemple suivant :
# 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 sortie indique que les longues files d'attente d'exécution sont dues à de nombreux processus xterm exécutables. Cette expérimentation coïncide avec un changement de bureau virtuel et les résultats sont donc probablement dus à une sorte de traitement d'événement X.
sleep et wakeup
Dans la section enqueue et dequeue, le dernier exemple démontrait qu'une augmentation de la longueur de la file d'attente était due aux processus xterm exécutables. Une hypothèse est que les observations résultaient d'un changement de bureau virtuel. Vous pouvez utiliser la sonde wakeup pour étudier cette hypothèse en déterminant l'origine et le moment du réveil des processus xterm, tel qu'illustré dans l'exemple suivant :
#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);
}
Pour étudier cette hypothèse, exécutez le script ci-dessus, patientez cinq secondes environ, puis changez une fois votre bureau virtuel. Si l'augmentation de processus xterm exécutables est due au changement de bureau virtuel, la sortie doit indiquer une activité de réveil à la cinquième seconde.
# dtrace -s ./xterm.d
Xsun
value -------------- Distribution ------------ count
4 | 0
5 |@ 1
6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32
7 | 0
|
La sortie n'indique pas que le serveur X réveille des processus xterm, mis en cluster au moment du changement de bureau virtuel. Pour comprendre l'interaction entre le serveur X et les processus xterm, vous pourriez effectuer un groupement dans une pile utilisateur au moment où le serveur X déclenche la sonde wakeup.
La compréhension de la performance des systèmes client/serveur comme le système de fenêtrage X nécessite de connaître les clients pour lesquels le serveur travaille. La réponse à ce type de question n'est pas simple avec les outils d'analyse de performance conventionnels. Cependant, si vous disposez d'un modèle dans lequel un client envoie un message au serveur puis sommeille dans l'attente du traitement du serveur, vous pouvez utiliser la sonde wakeup pour déterminer le client à l'origine de la demande, tel qu'illustré dans l'exemple suivant :
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;
}
Exécuter le script ci-dessus engendre une sortie similaire à l'exemple suivant :
dtrace -s ./xwork.d dtrace: script './xwork.d' matched 14 probes ^C xterm 9522510 soffice.bin 9912594 fvwm2 100423123 MozillaFirebird 312227077 acroread 345901577 |
Cette sortie révèle que la plupart des tâches Xsun sont exécutées pour les processus acroread, MozillaFirebird et, dans une moindre mesure, fvwm2. Notez que le script n'a abordé que les réveils à partir d'objets de synchronisation de variable de condition (SOBJ_CV). Tel que décrit dans le Tableau 25–4, les variables de condition représentent le type d'objet de synchronisation généralement utilisé pour une synchronisation dans un but autre que l'accès à une zone de données partagées. Dans le cas du serveur X, un client attend les données d'une file en sommeillant sur une variable de condition.
Vous pouvez également utiliser la sonde sleep avec la sonde wakeup pour connaître les applications bloquantes sur d'autres applications, ainsi que la durée, tel qu'illustré dans l'exemple suivant :
#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", @);
}
La fin de la sortie de l'exécution de l'exemple de script pendant plusieurs secondes sur un système de bureau est similaire à l'exemple suivant :
# 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
|
Vous pouvez souhaiter comprendre comment et pourquoi MozillaFirebird se bloque de lui-même. Vous pourriez modifier le script ci-dessus tel qu'illustré dans l'exemple suivant pour répondre à cette question :
#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", @);
}
L'exécution du script modifié pendant plusieurs secondes donne une sortie similaire à l'exemple suivant :
# 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
|
Vous pouvez également utiliser les sondes sleep et wakeup pour connaître la performance de serveurs à portes comme le démon de cache de service de nom, tel qu'illustré dans l'exemple suivant :
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;
}
La fin de la sortie de l'exécution du script ci-dessus sur un serveur de messagerie d'envergure est similaire à l'exemple suivant :
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
|
Vous pouvez être intéressé par les points de données inhabituels pour automountd ou le point de données persistent de plus d'une milliseconde pour sendmail. Vous pouvez ajouter d'autres prédicats au script ci-dessus pour comprendre les causes de résultats exceptionnels ou anormaux.
preempt, remain-cpu
Solaris étant un système préemptif, les threads à priorité supérieure déplacent ceux à priorité inférieure. La préemption peut entraîner une bulle de latence importante dans un thread à priorité inférieure. Vous pouvez ainsi souhaiter connaître les threads déplacés, et par quels threads. L'exemple suivant illustre comment utiliser les sondes preempt et remain-cpu pour afficher ces informations :
#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", @);
}
L'exécution du script ci-dessus pendant plusieurs secondes sur un système de bureau donne une sortie similaire à l'exemple suivant :
# 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
La préemption est basée sur des priorités. Vous pouvez ainsi souhaiter observer les changements de priorité dans le temps. L'exemple suivant utilise la sonde change-pri pour afficher ces informations :
sched:::change-pri
{
@[stringof(args[0]->pr_clname)] =
lquantize(args[2] - args[0]->pr_pri, -50, 50, 5);
}
L'exemple de script capture le degré auquel la priorité est augmentée ou réduite, et regroupe par classe de planification. Exécuter le script ci-dessus engendre une sortie similaire à l'exemple suivant :
# 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
|
La sortie illustre la manipulation de priorité de la classe de planification Interactive (IA). Plutôt que d'observer la manipulation de priorité, vous pouvez souhaiter observer les valeurs de priorité d'un processus et d'un thread particuliers dans le temps. Le script suivant utilise la sonde change-pri pour afficher ces informations :
#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);
}
Pour observer le changement de priorité dans le temps, entrez la commande suivante dans une fenêtre :
$ echo $$ 139208 $ while true ; do let i=0 ; done |
Dans une autre fenêtre, exécutez le script et redirigez la sortie vers un fichier :
# dtrace -s ./pritime.d 139208 1 > /tmp/pritime.out # |
Vous pouvez utiliser le fichier /tmp/pritime.out généré ci-dessus en entrée pour tracer le logiciel afin d'afficher sous forme graphique la priorité dans le temps. gnuplot est un package de traçage gratuit inclus sur le CD d'accompagnement du freeware Solaris. Par défaut, gnuplot est installé dans /opt/sfw/bin.
tick
Solaris utilise la comptabilisation de CPU sur top, dans laquelle une interruption d'horloge système se déclenche à intervalle fixe et attribue une utilisation de la CPU aux threads et aux processus exécutés au moment du top. L'exemple suivant illustre comment utiliser la sonde tick pour observer cette attribution :
# 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
|
La fréquence de l'horloge système varie d'un système d'exploitation à un autre, mais est généralement comprise entre 25 et 1 024 hertz. La fréquence de l'horloge système Solaris peut être réglée et est par défaut de 100 hertz.
La sonde tick ne se déclenche que si l'horloge système détecte un thread exécutable. Pour utiliser la sonde tick afin d'observer la fréquence de l'horloge système, vous devez disposer d'un thread exécutable en permanence. Dans une fenêtre, créez un shell de bouclage tel qu'illustré dans l'exemple suivant :
$ while true ; do let i=0 ; done |
Dans une autre fenêtre, exécutez le script suivant :
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 |
L'intervalle minimum est de 9,8 millisecondes, qui indique que la fréquence de top d'horloge est par défaut de 10 millisecondes (100 hertz). Le minimum observé est quelque peu inférieur à 10 millisecondes en raison d'une gigue.
Une déficience de la comptabilisation sur top est telle que l'horloge système exécutant la comptabilisation est également souvent chargée de répartir les activités de planification temporelle. Par conséquent, si un thread travaille à chaque top (c'est-à-dire toutes les 10 millisecondes), le système sur- ou sous-comptabilisera le thread, si la comptabilisation est effectuée avant ou après une activité de planification de répartition temporelle. Dans Solaris, la comptabilisation est effectuée avant la répartition temporelle. Par conséquent, le système sous-comptabilisera les threads exécutés à intervalle régulier. Si de tels threads sont exécutés pendant moins longtemps que l'intervalle de top d'horloge, ils peuvent en réalité “se cacher” derrière le top. L'exemple suivant illustre le degré auquel le système comporte de tels threads :
sched:::tick,
sched:::enqueue
{
@[probename] = lquantize((timestamp / 1000000) % 10, 0, 10);
}
La sortie de l'exemple de script est deux distributions du décalage de milliseconde dans un intervalle de dix millisecondes, une pour la sonde tick et l'autre pour 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
|
L'histogramme obtenu nommé tick indique que le top d'horloge se déclenche selon un décalage de 8 millisecondes. Si la planification n'était pas associée au top d'horloge, la sortie de enqueue serait répartie de manière égale pendant l'intervalle de dix millisecondes. La sortie illustre cependant un pic au même décalage de 8 millisecondes, indiquant qu'au moins certains threads du système sont planifiés sur une base temporelle.
- © 2010, Oracle Corporation and/or its affiliates