Exemplos
on-cpu e off-cpu
Uma pergunta comum que você pode fazer é quais CPUs estão executando segmentos e por quanto tempo. Você pode usar os testes on-cpu e off-cpu para responder facilmente a essa questão considerando todo o sistema, conforme mostrado no exemplo a seguir:
sched:::on-cpu
{
self->ts = timestamp;
}
sched:::off-cpu
/self->ts/
{
@[cpu] = quantize(timestamp - self->ts);
self->ts = 0;
}
Executar o script acima resultará numa saída semelhante ao exemplo seguinte:
# 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
|
O resultado acima mostra que na CPU 1 os segmentos tendem a ser executados por menos de 100 microssegundos em um período, ou por aproximadamente 10 milissegundos. Um intervalo evidente entre os dois clusters de dados mostrados no histograma. Talvez você também esteja interessado em saber quais CPUs estão executando um processo em particular. Você também pode usar os testes on-cpu e off-cpu para responder a essa pergunta. O script a seguir exibe quais CPUs executam um aplicativo específico durante um período de dez segundos:
#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", @);
}
A execução do script acima em um grande servidor de correio e a especificação do daemon IMAP produz um resultado similar ao exemplo a seguir:
# 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 |
O Solaris leva em consideração quanto tempo um segmento está em espera ao selecionar uma CPU na qual executar o segmento: um segmento que esteja em espera por menos tempo tende a não migrar. Você pode usar os testes off-cpu e on-cpu para observar esse comportamento:
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;
}
A execução do script acima por aproximadamente 30 segundos produz um resultado similar ao seguinte exemplo:
# 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
|
O resultado de exemplo mostra que há muito mais ocorrências de não-migração do que de migração. Além disso, quando os períodos de espera são maiores, as migrações são mais prováveis. As distribuições são evidentemente diferentes no sub-intervalo de 100 milissegundos, mas tornam-se muito similares à medida que os tempos de espera aumentam. Esse resultado poderia indicar que o tempo de espera não é calculado na decisão de agendamento quando um determinado limite é excedido.
O exemplo final usando off-cpu e on-cpu mostra como usar estes testes com o campo pr_stype para determinar por que os segmentos estão em espera e por quanto tempo:
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;
}
A execução do script acima por vários segundos produz um resultado similar ao seguinte exemplo:
# 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 e dequeue
Quando uma CPU fica inativa, o distribuidor procura trabalhos enfileirados em outras CPUs (ativas). O exemplo a seguir usa o teste dequeue para entender com que freqüência os aplicativos são transferidos e por qual 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", @);
}
A parte final do resultado da execução do script acima em um sistema de 4 CPUs produz um resultado similar ao seguinte exemplo:
# 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
|
Em vez de saber quais CPUs pegaram qual tarefa, talvez você queira saber as CPUs nas quais os processos e segmentos estão aguardando para ser executados. Você pode usar os testes enqueue e dequeue juntos para responder a essa questão:
sched:::enqueue
{
self->ts = timestamp;
}
sched:::dequeue
/self->ts/
{
@[args[2]->cpu_id] = quantize(timestamp - self->ts);
self->ts = 0;
}
A execução do script acima por vários segundos produz um resultado similar ao seguinte exemplo:
# 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 os valores diferentes de zero na parte inferior do resultado de exemplo. Esses pontos de dados revelam várias instâncias em ambas as CPUs nas quais um segmento foi enfileirado para ser executado por vários segundos.
Em vez de procurar por tempos de espera, talvez você queira examinar o tamanho da fila de execução ao longo do tempo. Ao usar os testes enqueue e dequeue, você pode definir uma matriz de associação para controlar o tamanho da fila:
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]—;
}
A execução do script acima por aproximadamente 30 segundos em um sistema de laptop com um processador totalmente inativo produz um resultado similar ao seguinte exemplo:
# 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
|
O resultado é aproximadamente o que você esperaria de um sistema inativo: na maior parte do tempo que um segmento executável estava enfileirado, a fila de execução estava muito curta (com três ou menos segmentos). Entretanto, como o sistema estava totalmente inativo, os pontos de dados excepcionais na parte inferior da tabela poderiam ser inesperados. Por exemplo, por que a fila de execução tinha 13 segmentos executáveis? Para explorar essa questão, você pode escrever um script em D que exiba o conteúdo da fila de execução quando a fila de execução for longa. Esse problema é complicado porque as habilitações em D não podem ser repetidas em estruturas de dados, e, portanto, não podem simplesmente ser repetidas em toda a fila de execução. Mesmo que as habilitações em D pudessem fazer isso, você deve evitar dependências nas estruturas internas de dados do kernel.
Para esse tipo de script, você ativaria os testes enqueue e dequeue e usaria matrizes de associação e de especulação. Sempre que um segmento é enfileirado, o script incrementa o tamanho da fila e registra o carimbo de data/hora em uma matriz de associação inserida pelo segmento. Você não pode usar uma variável de segmento local neste caso porque um segmento pode ser enfileirado por outro segmento. O script depois verifica se o tamanho da fila excede o máximo permitido. Caso exceda, o script iniciará uma nova especulação, e registrará o carimbo de data/hora e o novo máximo. Em seguida, quando um segmento é desenfileirado, o script compara o carimbo de data/hora do enfileiramento com o carimbo de data/hora do maior tamanho: se o segmento tiver sido enfileirado antes do carimbo de data/hora do maior tamanho, o segmento estava na fila quando o maior tamanho foi registrado. Nesse caso, o script especulativamente rastreia as informações do segmento. Depois que o kernel desenfileira o último segmento que estava enfileirado no carimbo de data/hora do maior tamanho, o script compromete os dados de especulação. Esse script é mostrado abaixo:
#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;
}
A execução do script acima no mesmo laptop com um processador produz um resultado similar ao seguinte exemplo:
# 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 |
O resultado revela que as filas de execução longas são devido a muitos processos xterm executáveis. Esse experimento coincidiu com uma alteração na área de trabalho virtual, e, portanto, os resultados provavelmente são devido a algum tipo de processamento de evento X.
sleep e wakeup
Em enqueue e dequeue, o exemplo final demonstrou que um crescimento súbito da fila de execução foi devido a processos xterm executáveis. Uma hipótese é que as observações resultaram de uma alteração na área de trabalho virtual. Você pode usar o teste wakeup para explorar essa hipótese determinando quem está ativando os processos xterm, e quando, conforme mostrado no exemplo a seguir:
#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);
}
Para investigar a hipótese, execute o script acima, aguardando aproximadamente cinco segundos, e alterne a área de trabalho virtual exatamente uma vez. Se o crescimento súbito de processos xterm executáveis for devido à alternância da área de trabalho virtual, o resultado deveria mostrar um crescimento súbito de atividade de ativação na marca de cinco segundos.
# dtrace -s ./xterm.d
Xsun
value -------------- Distribution ------------ count
4 | 0
5 |@ 1
6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32
7 | 0
|
O resultado mostra que o servidor X está ativando processos xterm, agrupados por volta da hora que você alternou as áreas de trabalho virtuais. Se você desejasse compreender a interação entre o servidor X e os processos xterm, poderia agregar rastreios de pilha do usuário quando o servidor X acionasse o teste wakeup.
Para se compreender o desempenho dos sistemas cliente/servidor como o sistema de janelas X, deve-se compreender os clientes em nome dos quais o servidor está realizando trabalho. Esse tipo de pergunta é difícil de ser respondida com ferramentas de análise de desempenho convencionais. Entretanto, se você tiver um modelo no qual um cliente envie uma mensagem para o servidor e entre em espera com o processamento do servidor pendente, você poderá usar o teste wakeup para determinar o cliente para o qual a solicitação está sendo realizada, conforme mostrado no exemplo a seguir:
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;
}
Executar o script acima resultará numa saída semelhante ao exemplo seguinte:
dtrace -s ./xwork.d dtrace: script './xwork.d' matched 14 probes ^C xterm 9522510 soffice.bin 9912594 fvwm2 100423123 MozillaFirebird 312227077 acroread 345901577 |
Este resultado revela que a maior parte do trabalho de Xsun está sendo feita em nome dos processos acroread, MozillaFirebird e, em menor grau, fvwm2. Observe que o script só examinou ativações de objetos de sincronização de variável de condição (SOBJ_CV). Conforme descrito na Tabela 25–4, as variáveis de condição são o tipo de objeto de sincronização geralmente usado para sincronizar por razões diferentes do acesso a uma região de dados compartilhados. No caso do servidor X, um cliente irá aguardar por dados em um pipe entrando em espera em uma variável de condição.
Você pode adicionalmente usar o teste sleep junto com o teste wakeup para compreender quais aplicativos estão bloqueando quais aplicativos, e por quanto tempo, conforme mostrado no seguinte exemplo:
#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", @);
}
A parte final do resultado da execução do script de exemplo por vários segundos em um sistema de área de trabalho parece com o seguinte exemplo:
# 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
|
Talvez você queira entender como e por que o MozillaFirebird está se bloqueando. Você pode modificar o script acima como mostrado no exemplo a seguir para responder a essa pergunta:
#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", @);
}
A execução do script modificado por vários segundos produz um resultado similar ao seguinte exemplo:
# 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
|
Você também pode usar os testes sleep e wakeup para compreender o desempenho dos servidores de porta como o daemon do cache de serviço de nome, conforme mostrado no exemplo a seguir:
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;
}
A parte final do resultado da execução do script acima em um servidor de correio grande parece com o seguinte exemplo:
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
|
Você pode estar interessado nos pontos de dados incomuns de automountd ou os pontos de dados persistentes de mais de um milissegundo de sendmail. Você pode incluir predicados adicionais no script acima para focalizar nas causas de quaisquer resultados excepcionais ou anormais.
preempt, remain-cpu
Como o Solaris é um sistema preemptivo, os segmentos de prioridade mais alta têm precedência sobre os de prioridade mais baixa. A preempção pode induzir a uma bolha de latência significativa no segmento de prioridade mais baixa. Por isso, talvez você queira saber quais segmentos estão sendo superados por quais segmentos. O exemplo a seguir mostra como usar os testes preempt e remain-cpu para exibir estas informações:
#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", @);
}
A execução do script acima por vários segundos em um sistema de área de trabalho produz um resultado similar ao seguinte exemplo:
# 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
A preempção é baseada em prioridades, por isso, talvez você queira observar alterações na prioridade ao longo do tempo. O exemplo a seguir usa o teste change-pri para exibir estas informações:
sched:::change-pri
{
@[stringof(args[0]->pr_clname)] =
lquantize(args[2] - args[0]->pr_pri, -50, 50, 5);
}
O script de exemplo captura o grau para o qual a prioridade é elevada ou diminuída e agrega por classe de agendamento. Executar o script acima resultará numa saída semelhante ao exemplo seguinte:
# 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
|
O resultado mostra a manipulação de prioridade da classe de agendamento Interactive (IA). Em vez de ver a manipulação de prioridade, talvez você queira ver os valores de prioridade de um determinado processo e segmento ao longo do tempo. O script a seguir usa o teste change-pri para exibir estas informações:
#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);
}
Para ver as alterações em prioridades ao longo do tempo, digite o seguinte comando em uma janela:
$ echo $$ 139208 $ while true ; do let i=0 ; done |
Em outra janela, execute o script e redirecione o resultado para um arquivo:
# dtrace -s ./pritime.d 139208 1 > /tmp/pritime.out # |
Você pode usar o arquivo /tmp/pritime.out que é gerado acima como entrada para um software de plotagem para exibir a prioridade graficamente ao longo do tempo. O gnuplot é um pacote de plotagem disponível livremente que está incluído no CD complementar do Solaris Freeware. Por padrão, o gnuplot é instalado em /opt/sfw/bin.
tick
O Solaris usa uma contagem de CPU baseada em tique-taque, na qual uma interrupção do relógio do sistema é acionada em um intervalo fixo e atribui a utilização da CPU aos segmentos e processos em execução no momento do tique-taque. O exemplo a seguir mostra como usar o teste tick para observar essa atribuição:
# 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
|
A freqüência do relógio do sistema varia de acordo com o sistema operacional, mas geralmente vai de 25 hertz a 1024 hertz. A freqüência do relógio do sistema é ajustável, mas o padrão é 100 hertz.
O teste tick só é acionado se o relógio do sistema detecta um segmento executável. Para usar o teste tick para observar a freqüência do relógio do sistema, você deve ter um segmento que seja sempre executável. Em uma janela, crie um shell de looping conforme mostrado no exemplo a seguir:
$ while true ; do let i=0 ; done |
Em outra janela, execute o seguinte script:
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 |
O intervalo mínimo é de 9,8 milissegundos, o que indica que a freqüência de tique-taque padrão do relógio é de 10 milissegundos (100 hertz). O mínimo observado é algo menos que 10 milissegundos devido à variação.
Uma deficiência da contagem baseada em tique-taque é que o relógio do sistema que realiza a contagem é, freqüentemente, também responsável por distribuir atividades de agendamento relacionadas ao tempo. Como resultado, se um segmento tiver que realizar alguma quantidade de trabalho a cada tique-taque do relógio (ou seja, a cada 10 milissegundos), o sistema irá contar a mais ou a menos no segmento, dependendo se a contagem for feita antes ou depois de uma atividade de agendamento de distribuição relacionada ao tempo. No Solaris, a contagem é realizada antes da distribuição relacionada ao tempo. Como resultado, o sistema irá contar a menos nos segmentos executados em intervalo regular. Se tais segmentos forem executados por menos tempo que o intervalo do tique-taque do relógio, eles podem se "esconder" eficientemente por trás do tique-taque. O exemplo a seguir mostra o grau para o qual o sistema possui tais segmentos:
sched:::tick,
sched:::enqueue
{
@[probename] = lquantize((timestamp / 1000000) % 10, 0, 10);
}
O script de exemplo resulta em duas distribuições do deslocamento de milissegundo em um intervalo de dez milissegundos: uma para o teste tick e outra para 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
|
O histograma de resultado chamado tick mostra que o tique-taque do relógio está sendo acionado em um deslocamento de 8 milissegundos. Se o agendamento não fosse associado ao tique-taque do relógio, o resultado de enqueue seria distribuído uniformemente no intervalo de dez milissegundos. Entretanto, o resultado mostra um pico no mesmo deslocamento de 8 milissegundos, indicando que pelo menos alguns segmentos no sistema estão sendo agendados de acordo com o tempo.
- © 2010, Oracle Corporation and/or its affiliates