Solaris DTrace
DTrace
(дополненный текст отсюда: http://experience.openquality.ru/dtrace-use-cases/)
Технология DTrace и подходящие инструменты для ее использования появились в 2005 году, но, несмотря на это, DTrace еще малоизвестна в широких кругах разработчиков и сисадминов. Это тем более удивительно, что за пять с половиной лет, прошедших с выхода системы Solaris 10, в которой она впервые появилась, так и не было придумано более совершенной технологии наблюдения за операционной системой и приложениями.
DTrace была разработана в компании Sun Microsystems, и открытый код всех ее компонентов был опубликован в том же 2005 году. С тех пор DTrace была перенесена в Mac OS X, QNX и FreeBSD, и появилась также во всех дистрибутивах, унаследовавших код ядра Solaris: Belenix, Korona, Nexenta, OpenIndiana и Milax. Разумеется, в Solaris технология DTrace тоже осталась и даже развилась – датчиков стало больше. В настоящее время DTrace доступна в самой свежей версии Solaris 11 Express, равно как и в Solaris 10.
По сравнению с другими средствами сбора информации о системе и отладки приложений, DTrace обладает рядом уникальных свойств:
- накапливает информацию о системе, работающей под максимальной нагрузкой – с низкими накладными расходами на сбор информации;
- собирает любую информацию из любых уголков системы, позволяя наблюдать как за работой приложений, так и за работой самого ядра системы;
- может показать, какие аргументы передаются от одной функции к другой, независимо от того, доступен ли исходный код функций;
- собирает информацию о том, как долго исполняются вызываемые функции, какой процент времени занимает исполнение каждой из них, сколько раз каждая из них была вызвана;
- фильтрует информацию любым заданным образом – например, позволяет ограничить область наблюдения одним приложением, одним потоком команд, или определенной областью (скажем, измерять время выполнения только конкретного системного вызова, а об остальном не заботиться);
- может реагировать на определенные события (ввод-вывод, вызов заданных функций, завершение программы, запуск нового потока и пр.);
- имеет как средства низкоуровнего наблюдения (можно изучать ход работы драйвера устройства), так и средства высокоуровневые, например, позволяет отслеживать определенные события при исполнении скриптов на PHP или вызов методов в приложении, написанном на Java;
- позволяет выполнять трассировку вызовов, с одновременным отслеживанием любых параметров – времени выполнения, переданных аргументов и пр.
Основным компонентом DTrace является модуль ядра, обеспечивающий функционирование подсистемы DTrace, а основным инструментом – приложение dtrace, которое воспринимает скрипты, написанные на языке D, созданном специально для работы с DTrace. В этой заметке мы не будем вдаваться в детали реализации DTrace; тем, кто в них заинтересован, я могу посоветовать найти их описание в Google, а также в главах 27 и 28 второго издания книги «Операционная система Solaris», написанной мной в соавторстве с Евгением Ильиным в 2009 году. Кроме того, наблюдение, профилирование и трассировка работы приложений с помощью DTrace подробно рассмотрены в одной из лекций по курсу «Системное администрирование ОС Solaris 10».
Cкрипт, выдающий количество функций, написать легко. В качестве затравки рассмотрим несколько вариантов, а затем перейдем к синтаксису скриптов. Например, вот такой скрипт выдает количество вызовов любых функций при работе программы ls (вначале на экран будет выдан результат ее работы, а потом – список функций с количеством вызовов для каждой в порядке возрастания):
pfexec dtrace -n 'pid$target:::entry {@funсtions[probefunc]=count();}' -c ls
А вот таким скриптом можно посчитать количество функций, вызванных конкретным процессом с PID=2355; для получения результата надо прервать выполнение скрипта с помощью Ctrl-C:
pfexec dtrace -n 'pid2355:::entry {@funсtions[probefunc]=count();}'
А вот так можно посчитать количество системных вызовов в том же процессе:
pfexec dtrace -n 'syscall:::entry /pid==2355/ {@funсtions[probefunc]=count();}'
Итак, в скриптах на языке D всегда используется следующий синтаксис:
провайдер:модуль:функция:датчик
/условие/
{
действия
}
Провайдер – это модуль ядра или модуль приложения, обеспечивающий регистрацию своих датчиков DTrace в системе. Например, провайдер syscall регистрирует датчики, расположенные в системных вызовах, провайдер mysql – датчики, встроенные в сервер MySQL.
Модуль – это название модуля или библиотеки, например, libc.
Функция – имя функции, датчик в которой нам интересен, например, fopen.
Датчик – название датчика (во многих случаях датчик называется entry или return).
Условие задает ситуацию, когда следует выполнить действие при срабатывании датчика. Например, надо выполнить его только тогда, когда датчик сработал в приложении top. Тогда условие выглядит так:
/execname == top/
Действия – это то, что обеспечивает сбор информации и вывод ее на экран. Из примеров ниже будет ясно, какими они бывают.
Простой пример того, как я использую DTrace в повседневной жизни: после переноса пользовательских настроек с одного компьютера на другой система на не захотела работать с принтером, как раньше. Было ясно, что какой-то из файлов настроек отчего-то не скопирован. Но какой именно? Их же сотни… Банальные /etc/printers и /etc/lp/* были проверены и разгадки не дали. Тогда пришлось задействовать DTrace. Простой скрипт дает возможность заглянуть в недра программы lpstat (наиболее безвредная программа из тех, что работает с принтером) и посмотреть, какие файлы она пытается открыть:
lpstat -s scheduler is running system default printer: eaqvap21 aqvap21: unknown printer aqvap21: unknown printer
Чтобы запустить программу и подсунуть ее PID скрипту на DTrace надо использовать ключ -c :
dtrace -n 'pid$target::fopen:entry {printf("%s",copyinstr(arg0));}' -c "lpstat -s"
dtrace: description 'pid$target::fopen:entry ' matched 1 probe
scheduler is running
system default printer: eaqvap21
aqvap21: unknown printer
aqvap21: unknown printer
dtrace: pid 11156 has exited
CPU ID FUNCTION:NAME
0 59882 fopen:entry /etc/default/init
0 59882 fopen:entry /etc/lp/ppd/eaqvap21.ppd
0 59882 fopen:entry /export/home/filip/.printers
0 59882 fopen:entry /export/home/filip/.printers
0 59882 fopen:entry /export/home/filip/.printers
0 59882 fopen:entry /etc/printers.conf
0 59882 fopen:entry /export/home/filip/.printers
0 59882 fopen:entry /etc/printers.conf
1 59882 fopen:entry /etc/nsswitch.conf
1 59882 fopen:entry /export/home/filip/.printers
1 59882 fopen:entry /export/home/filip/.printers
1 59882 fopen:entry /etc/printers.conf
Вот и все: я забыл, что надо почистить файл .printers в домашнем каталоге:
rm /export/home/filip/.printers
Замечание: подсовывать PID программы скрипту надо потому, что провайдер pid требует указания PID изучаемого с помощью DTrace процесса, а знакомый нам всем вызов fopen как раз относится к этому провайдеру DTrace.
Вообще, сбор информации о том, какие файлы открываются в системе, часто дает разгадку сисадмину. Поэтому иногда я использую и такую модификацию скрипта:
pfexec dtrace -n 'syscall::open*:entry {printf("%s\n",copyinstr(arg0));}'
Этот скрипт валит в кучу данные от всех системных вызовов, имена которых начинаются на open, что неудобно, но зато его легче всего вспомнить и проще всего применить к уже запущенным приложениям, а полученной информации может хватить для анализа.
Наконец, для тех, кто отлаживает веб-приложения, может пригодиться скрипт, который вылавливает SQL-операторы из сервера БД перед тем, как сервер их запустит. Это позволяет выяснить, какие именно операторы исполняются; такая информация поможет, если кажется, что скрипт, работающий с БД, все делает верно, а база данных возвращает неожиданный результат: может оказаться, что либо SQL-выражение формируется неверно, либо соединние происходит не с той базой данных, что надо, либо какой-то параметр передается СУБД без должного оформления (например, без кавычек или с лишними кавычками).
Вот этот скрипт: (не работает)
#!/usr/sbin/dtrace -s
#pragma D option quiet
dtrace:::BEGIN
{
printf("%-20s %-20s %-40s %-9s\n", "Who", "Database", "Query", "Time(ms)");
}
mysql*:::query-start
{
self->query = copyinstr(arg0);
self->connid = arg1;
self->db = copyinstr(arg2);
self->who = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));
self->querystart = timestamp;
}
mysql*:::query-done
{
printf("%-20s %-20s %-40s %-9d\n",self->who,self->db,self->query,
(timestamp - self->querystart) / 1000000);
}
Запустив его, можно наблюдать картину работы сервера (осторожно! там может быть очень много информации, если сервер сильно нагружен запросами!):
$ pfexec ./mysql.d Who Database Query Time(ms) root@localhost data SELECT DATABASE() 0 root@localhost test show tables 0 root@localhost test SELECT DATABASE() 0 root@localhost mysql select * from users 0 root@localhost mysql select * from host 0
C помощью измерения времени между срабатываниями датчиков query-start и query-done вычисляется время исполнения SQL-оператора, и DTrace позволяет строить графики распределения времени исполнения по операторам. Так можно найти те обращения к базе данных, которые отнимают много времени при выполнении конкретных приложений. Большое преимущество DTrace в том, что все эти измерения можно производить в условиях реальной нагрузки на сервер, так как накладные расходы на работу самого DTrace минимальны и не будут мешать работе сервера.
Замечание: время выполнения запросов меньше 1 ms, а в скрипте выполняется целочисленное деление, поэтому результат получается 0. Можно считать в микросекундах, а не в миллисекундах, тогда будет какое-то небольшое значение.
Из приведенных примеров видно, что датчики DTrace расставлены в системе и приложениях Solaris повсюду. Изучить, какие аргументы, связанные с датчиками, можно использовать так, как показано выше, можно в документации по системе (man) и в документации по конкретным приложениям (например, по серверу MySQL на сайте mysql.com).
Значительно больше примеров скриптов для dtrace можно найти в следующих источниках:
- каталог /opt/DTT/ (Solaris)
- http://blogs.sun.com/brendan/category/DTrace
- http://www.brendangregg.com/DTrace/dtrace_oneliners.txt
Примеры
# dtrace_oneliners.txt - DTrace one liners. Handy commands.
#
# 25-Apr-2005, ver 0.70 (first release)
#
# Standard Disclaimer: This is freeware, use at your own risk.
#
# 25-Apr-2005 Brendan Gregg Created this.
#
# Contents
#
DTrace One Liners,
# New processes with arguments,
dtrace -n 'proc:::exec-success { trace(curpsinfo->pr_psargs); }'
# Files opened by process,
dtrace -n 'syscall::open*:entry { printf("%s %s",execname,copyinstr(arg0)); }'
# Syscall count by program,
dtrace -n 'syscall:::entry { @num[execname] = count(); }'
# Syscall count by syscall,
dtrace -n 'syscall:::entry { @num[probefunc] = count(); }'
# Syscall count by process,
dtrace -n 'syscall:::entry { @num[pid,execname] = count(); }'
# Read bytes by process,
dtrace -n 'sysinfo:::readch { @bytes[execname] = sum(arg0); }'
# Write bytes by process,
dtrace -n 'sysinfo:::writech { @bytes[execname] = sum(arg0); }'
# Read size distribution by process,
dtrace -n 'sysinfo:::readch { @dist[execname] = quantize(arg0); }'
# Write size distribution by process,
dtrace -n 'sysinfo:::writech { @dist[execname] = quantize(arg0); }'
# Disk size by process,
dtrace -n 'io:::start { printf("%d %s %d",pid,execname,args[0]->b_bcount); }'
# Pages paged in by process,
dtrace -n 'vminfo:::pgpgin { @pg[execname] = sum(arg0); }'
# Minor faults by process,
dtrace -n 'vminfo:::as_fault { @mem[execname] = sum(arg0); }'
# Interrupts by CPU,
dtrace -n 'sdt:::interrupt-start { @num[cpu] = count(); }'
DTrace Longer One Liners,
# New processes with arguments and time,
dtrace -qn 'syscall::exec*:return { printf("%Y %s\n",walltimestamp,curpsinfo->pr_psargs); }'
# Successful signal details,
dtrace -n 'proc:::signal-send /pid/ { printf("%s -%d %d",execname,args[2],args[1]->pr_pid); }'
#
# Examples
#
### New processes with arguments,
# dtrace -n 'proc:::exec-success { trace(curpsinfo->pr_psargs); }'
dtrace: description 'proc:::exec-success ' matched 1 probe
CPU ID FUNCTION:NAME
0 3297 exec_common:exec-success man ls
0 3297 exec_common:exec-success sh -c cd /usr/share/man; tbl /usr/share/man/man1/ls.1 |neqn /usr/share/lib/pub/
0 3297 exec_common:exec-success tbl /usr/share/man/man1/ls.1
0 3297 exec_common:exec-success neqn /usr/share/lib/pub/eqnchar -
0 3297 exec_common:exec-success nroff -u0 -Tlp -man -
0 3297 exec_common:exec-success col -x
0 3297 exec_common:exec-success sh -c trap '' 1 15; /usr/bin/mv -f /tmp/mpzIaOZF /usr/share/man/cat1/ls.1 2> /d
0 3297 exec_common:exec-success /usr/bin/mv -f /tmp/mpzIaOZF /usr/share/man/cat1/ls.1
0 3297 exec_common:exec-success sh -c more -s /tmp/mpzIaOZF
0 3297 exec_common:exec-success more -s /tmp/mpzIaOZF
### Files opened by process,
# dtrace -n 'syscall::open*:entry { printf("%s %s",execname,copyinstr(arg0)); }'
dtrace: description 'syscall::open*:entry ' matched 2 probes
CPU ID FUNCTION:NAME
0 14 open:entry gnome-netstatus- /dev/kstat
0 14 open:entry man /var/ld/ld.config
0 14 open:entry man /lib/libc.so.1
0 14 open:entry man /usr/share/man/man.cf
0 14 open:entry man /usr/share/man/windex
0 14 open:entry man /usr/share/man/man1/ls.1
0 14 open:entry man /usr/share/man/man1/ls.1
0 14 open:entry man /tmp/mpqea4RF
0 14 open:entry sh /var/ld/ld.config
0 14 open:entry sh /lib/libc.so.1
0 14 open:entry neqn /var/ld/ld.config
0 14 open:entry neqn /lib/libc.so.1
0 14 open:entry neqn /usr/share/lib/pub/eqnchar
0 14 open:entry tbl /var/ld/ld.config
0 14 open:entry tbl /lib/libc.so.1
0 14 open:entry tbl /usr/share/man/man1/ls.1
0 14 open:entry nroff /var/ld/ld.config
[...]
### Syscall count by program,
# dtrace -n 'syscall:::entry { @num[execname] = count(); }'
dtrace: description 'syscall:::entry ' matched 228 probes
^C
snmpd 1
utmpd 2
inetd 2
nscd 7
svc.startd 11
sendmail 31
poold 133
dtrace 1720
### Syscall count by syscall,
# dtrace -n 'syscall:::entry { @num[probefunc] = count(); }'
dtrace: description 'syscall:::entry ' matched 228 probes
^C
fstat 1
setcontext 1
lwp_park 1
schedctl 1
mmap 1
sigaction 2
pset 2
lwp_sigmask 2
gtime 3
sysconfig 3
write 4
brk 6
pollsys 7
p_online 558
ioctl 579
### Syscall count by process,
# dtrace -n 'syscall:::entry { @num[pid,execname] = count(); }'
dtrace: description 'syscall:::entry ' matched 228 probes
^C
1109 svc.startd 1
4588 svc.startd 2
7 svc.startd 2
3950 svc.startd 2
1626 nscd 2
870 svc.startd 2
82 nscd 6
5011 sendmail 10
6010 poold 74
8707 dtrace 1720
### Read bytes by process,
# dtrace -n 'sysinfo:::readch { @bytes[execname] = sum(arg0); }'
dtrace: description 'sysinfo:::readch ' matched 4 probes
^C
mozilla-bin 16
gnome-smproxy 64
metacity 64
dsdm 64
wnck-applet 64
xscreensaver 96
gnome-terminal 900
ttymon 5952
Xorg 17544
### Write bytes by process,
# dtrace -n 'sysinfo:::writech { @bytes[execname] = sum(arg0); }'
dtrace: description 'sysinfo:::writech ' matched 4 probes
^C
dtrace 1
gnome-settings-d 8
xscreensaver 8
gnome-panel 8
nautilus 8
date 29
wnck-applet 120
bash 210
mozilla-bin 1497
ls 1947
metacity 3172
Xorg 7424
gnome-terminal 51955
### Read size distribution by process,
# dtrace -n 'sysinfo:::readch { @dist[execname] = quantize(arg0); }'
dtrace: description 'sysinfo:::readch ' matched 4 probes
^C
[...]
gnome-terminal
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
64 |@@@ 1
128 | 0
Xorg
value ------------- Distribution ------------- count
-1 | 0
0 |@@@@@@@@@@@@@@@@@@@ 26
1 | 0
2 | 0
4 | 0
8 |@@@@ 6
16 |@ 2
32 |@ 2
64 | 0
128 |@@@@@@@@ 11
256 |@@@ 4
512 | 0
### Write size distribution by process,
# dtrace -n 'sysinfo:::writech { @dist[execname] = quantize(arg0); }'
dtrace: description 'sysinfo:::writech ' matched 4 probes
^C
[...]
Xorg
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 169
64 |@@@ 16
128 |@@ 10
256 | 0
gnome-terminal
value ------------- Distribution ------------- count
0 | 0
1 |@@ 6
2 | 0
4 | 0
8 | 1
16 |@ 2
32 |@@@ 7
64 | 0
128 |@@@@@@@@@@@@@@@@@@@@@@@ 63
256 |@@@@ 10
512 | 1
1024 |@@@@@ 13
2048 |@ 2
4096 |@@@ 7
### Disk size by process,
# dtrace -n 'io:::start { printf("%d %s %d",pid,execname,args[0]->b_bcount); }'
0 3271 bdev_strategy:start 16459 tar 1024
0 3271 bdev_strategy:start 16459 tar 1024
0 3271 bdev_strategy:start 16459 tar 2048
0 3271 bdev_strategy:start 16459 tar 1024
0 3271 bdev_strategy:start 16459 tar 1024
0 3271 bdev_strategy:start 16459 tar 1024
0 3271 bdev_strategy:start 16459 tar 8192
0 3271 bdev_strategy:start 16459 tar 8192
0 3271 bdev_strategy:start 16459 tar 16384
0 3271 bdev_strategy:start 16459 tar 2048
0 3271 bdev_strategy:start 16459 tar 1024
0 3271 bdev_strategy:start 16459 tar 1024
### Pages paged in by process,
# dtrace -n 'vminfo:::pgpgin { @pg[execname] = sum(arg0); }'
dtrace: description 'vminfo:::pgpgin ' matched 1 probe
^C
ttymon 1
bash 1
mozilla-bin 36
tar 6661
### Minor faults by process,
# dtrace -n 'vminfo:::as_fault { @mem[execname] = sum(arg0); }'
dtrace: description 'vminfo:::as_fault ' matched 1 probe
^C
mozilla-bin 18
dtrace 57
find 64
bash 150
tar 501
### Interrupts by CPU,
# dtrace -n 'sdt:::interrupt-start { @num[cpu] = count(); }'
dtrace: description 'sdt:::interrupt-start ' matched 1 probe
^C
513 2
515 4
3 39
2 39
### New processes with arguments and time,
# dtrace -qn 'syscall::exec*:return { printf("%Y %s\n",walltimestamp,curpsinfo->pr_psargs); }'
2005 Apr 25 19:15:09 man ls
2005 Apr 25 19:15:09 sh -c cd /usr/share/man; tbl /usr/share/man/man1/ls.1 |...
2005 Apr 25 19:15:09 neqn /usr/share/lib/pub/eqnchar -
2005 Apr 25 19:15:09 tbl /usr/share/man/man1/ls.1
2005 Apr 25 19:15:09 nroff -u0 -Tlp -man -
2005 Apr 25 19:15:09 col -x
2005 Apr 25 19:15:10 sh -c trap '' 1 15; /usr/bin/mv -f /tmp/mpRZaqTF /usr/s...
2005 Apr 25 19:15:10 /usr/bin/mv -f /tmp/mpRZaqTF /usr/share/man/cat1/ls.1
2005 Apr 25 19:15:10 sh -c more -s /tmp/mpRZaqTF
2005 Apr 25 19:15:10 more -s /tmp/mpRZaqTF
[...]
### Successful signal details,
# dtrace -n 'proc:::signal-send /pid/ { printf("%s -%d %d",execname,args[2],args[1]->pr_pid); }'
dtrace: description 'proc:::signal-send ' matched 1 probe
CPU ID FUNCTION:NAME
0 3303 sigtoproc:signal-send bash -15 16442
0 3303 sigtoproc:signal-send bash -9 16443
^C
