Предположим что вы изучаете вывод mpstat на многопользовательском сервере:
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
12 1 27 3504 338 206 765 27 114 65 1 337 9 19 41 31
13 1 19 5725 98 68 723 22 108 120 0 692 3 17 20 61
14 0 57 3873 224 192 670 22 75 86 1 805 7 10 35 48
15 36 7 1551 42 28 689 6 68 59 0 132 2 9 35 54
16 14 7 7209 504 457 1031 37 125 244 0 459 6 30 4 60
17 5 5 4960 150 108 817 37 98 154 0 375 6 26 6 62
18 5 6 6085 1687 1661 741 60 76 248 0 434 3 33 0 64
19 0 15 10037 72 41 876 23 100 291 1 454 2 19 9 71
20 12 5 5890 746 711 992 32 122 216 2 960 10 33 4 53
21 60 5 1567 729 713 467 15 80 59 0 376 2 35 10 53
22 0 6 4378 315 291 751 17 84 142 1 312 3 16 1 80
23 0 6 12119 33 3 874 20 82 384 1 513 4 24 11 62
Вы вполне можете задаться вопросом - что происходит с цифрами в колонке межпроцессорных вызовов (xcal)?
С помощью DTrace сделаем вот такой снимок системы:
# dtrace -n xcalls'{@[execname] = count()}'
dtrace: description 'xcalls' matched 4 probes
[ Подождем несколько секунд ]
^C
mozilla-bin 1
lockd 1
in.mpathd 2
nsrmmd 5
grep 6
chmod 6
cat 6
nwadmin 13
ls 24
in.tftpd 28
nsrindexd 34
fsflush 38
cut 42
find 42
mkdir 66
rm 76
ipop3d 78
scp 79
inetd 96
dtrace 111
nawk 118
imapd-simmonmt 126
rmdir 132
sshd 138
rpc.rstatd 159
mv 398
save 1292
gzip 1315
get_all2 1678
sched 1712
nfsd 3709
tar 27054
Видно, что наибольшее число запросов вызывает tar. Чтобы проверить запросы, вызываемые непосредственно tar, слегка изменим наш скрипт:
# dtrace -n xcalls'/execname == "tar"/{@[pid] = count()}'
dtrace: description 'xcalls' matched 4 probes
[ Снова дадим скрипту несколько секунд для работы ]
^C
938339 507
938415 784
938229 2438
938390 3282
938363 6464
937067 13984
Но теперь мы замечаем странную вещь: мы не можем найти ни один из этих процессов после возвращения в shell, например:
# pflags 937067
pflags: cannot examine 937067: no such process or core file
Получается, кто-то запускает связку коротких вызовов для tar? Для начала попробуем получать pid всякий раз, когда запускается tar:
# dtrace -n syscall::exec*:return'/execname == "tar"/{trace(pid)}'
CPU ID FUNCTION:NAME
18 112 exece:return 954538
21 112 exece:return 954519
17 112 exece:return 954584
21 112 exece:return 954579
21 112 exece:return 954607
22 112 exece:return 954632
21 112 exece:return 954658
20 112 exece:return 954684
20 112 exece:return 954705
15 112 exece:return 954727
14 112 exece:return 954763
16 112 exece:return 954775
12 112 exece:return 954798
18 112 exece:return 954818
22 112 exece:return 954873
22 112 exece:return 954889
23 112 exece:return 954893
14 112 exece:return 954916
14 112 exece:return 954971
...
Видно что tar запускается с некоторой частотой (приблизительно каждую секунду). Попробуем узнать поподробнее, что за процессы выполняются на машине:
# dtrace -n syscall::exec*:entry'{@[copyinstr(arg0)] = count()}'
[ Дадим скрипту несколько секунд ]
^C
usr/lib/mail.local 1
/usr/bin/true 1
/usr/bin/pgrep 1
/usr/bin/wc 1
/usr/bin/touch 1
/usr/bin/sleep 1
/usr/sbin/modinfo 4
/bin/awk 4
/bin/sh 4
/usr/bin/chmod 14
/usr/bin/cat 14
/usr/bin/tar 14
./do1 14
/usr/bin/cut 15
/usr/bin/grep 15
/usr/bin/find 15
/usr/bin/ls 15
/usr/bin/mv 15
/usr/bin/rm 16
/usr/bin/mkdir 17
/usr/bin/gzip 29
/usr/bin/nawk 44
/usr/bin/rmdir 48
/home/ellenp/rmdir 48
/home1/netscape/rmdir 48
/usr/dt/bin/rmdir 96
/usr/openwin/bin/rmdir 96
Здесь много интересного, но пока мы интересуемся только процессами, имеющими отношение к tar. В частности - когда кто-то запускает tar, мы хотим точно знать кто это. Для этого напишем следующий скрипт DTrace и назовем его "whotar.d":
syscall::exec*:entry
/copyinstr(arg0) == "/usr/bin/tar"/
{
@[execname] = count();
}
Вывод прямо указывает на "преступника":
# dtrace -s whotar.d
[ Снова дадим скрипту несколько секунд для работы ]
^C
get_all2 22
Таким образом проблема заключается в get_all2. Теперь можно использовать традиционные инструменты:
# ptree `pgrep get_all2`
100578 /usr/sbin/inetd -s
900870 in.rlogind
900872 -csh
901382 /bin/sh get_all3
901383 /bin/sh ./get_all2 80/80acc080 90/00fccc90
959045 /bin/sh ./get_all2 80/80acc080 90/00fccc90
959046 tar xvf - explorer.80c23d8e.ptgw02is-2003.10.27.09.35/README
959047 gzip -dc /net/pamer.central/proactive/rawdata/8e/80c23d8e
901384 /bin/sh ./get_all2 90/80bdbb90 a0/1274eda0
959565 /bin/sh ./get_all2 90/80bdbb90 a0/1274eda0
959566 tar xvf - explorer.8089ed9d.curly-2002.05.06.10.00/README exp
959567 gzip -dc /net/pamer.central/proactive/rawdata/9d/8089ed9d
901385 /bin/sh ./get_all2 a0/80aabda0 b0/1d6c05b0
959619 mv disks/diskinfo disks/format.out disks/mount.out etc/release
901386 /bin/sh ./get_all2 b0/80b264b0 c0/335419c0
959612 /bin/sh ./get_all2 b0/80b264b0 c0/335419c0
959613 tar xvf - explorer.82a86abd.seq22-2002.05.31.21.49/README exp
959614 gzip -dc /net/pamer.central/proactive/rawdata/bd/82a86abd
Теперь ясно где находятся процессы tar (и соответственно, откуда меняются показатели xcal). Но как кратковременны эти процессы? Тут нам опять поможет DTrace. Для этого, используя ассоциативный массив и переменную timestamp, постараемся получить линейный вывод в промежутке от 0 секунд до 60. Мы будем также использовать пробу "tick-1sec", для автоматической остановки через минуту. Скрипт (назовем его "longtar.d"):
syscall::exec*:return
/execname == "tar"/
{
start[pid] = timestamp;
}
fbt::exit:entry
/start[pid]/
{
@["tar time, in seconds"] =
lquantize((timestamp - start[pid]) / 1000000000, 0, 60);
start[pid] = 0;
}
tick-1sec
/n++ >= 60/
{
exit(0);
}
Запустим:
# dtrace -s longtar.d
dtrace: script 'longtar.d' matched 4 probes
CPU ID FUNCTION:NAME
23 38110 :tick-1sec
tar time, in seconds
value ------------- Distribution ------------- count
< 0 | 0
0 |@ 1
1 |@@@@@ 4
2 |@@@@@@@@@@@ 8
3 |@@@@@@@ 5
4 |@@@@@@@ 5
5 |@@ 2
6 | 0
7 |@@@@ 3
8 | 0
Вывод показывает как тяжело выявить эту проблему, используя традиционные инструменты: каждый процесс tar живет только в течение примерно двух секунд! Тем не менее, взятые вместе, процессы tar составляют подавляющее большинство xcal-запросов системы. Это хороший пример использования DTrace, потому что проблема здесь не в одном единственном приложении, а в целой армии процессов tar, которые исчезают прежде, чем они могут быть замечены. Действительно, запуск prstat на этой машине не показывает процессы tar или кого-либо из потомков get_all2 как главныx потребителей ресурсов, однако истинных виновников можно быстро найти с помощью DTrace.
(Вольный перевод письма Bryan Cantrill из DTrace Engineering Team в comp.unix.solaris) 
