DTrace как инструмент администратора Solaris

Павел Анни

Как часто приходится слышать фразы «система глючит», «почему-то тормозит», «не знаю, что происходит, проще перезагрузить»... Кому как, а мне становится очень неуютно, когда я не понимаю, что происходит. Тем более, если речь идет о системе, за которую я несу ответственность. Как найти причину проблем, заглянуть вглубь системы, понять, что происходит? Идея средства мониторинга, которое бы предоставляло бы возможность «заглянуть» в самые дальние уголки системы и позволяло бы получать ответы на самые неожиданные вопросы, давно зрела в умах разработчиков Solaris и наконец воплотилась в видео подсистемы динамической трассировки DTrace.

Введение в DTrace

Исторически в UNIX (и Linux) сформировалась развитая система мониторинга и диагностики. Существует масса команд: все эти vmstat, mpstat, iostat, top и др. Они помогали и продолжают помогать системным администраторам решать повседневные задачи и искать ответы на вопросы: "насколько загружена система?", "что происходит с моими дисками?", "хватает ли виртуальной памяти?". В то же время, любой администратор не понаслышке знает и об ограничениях стандартных средств мониторинга и анализа.

Скажем, посредством команды vmstat легко обнаружить, что система слишком много времени пребывает в состоянии system time (выполняя системные вызовы). С помощью strace (или ee эквивалента truss -- в Solaris) можно определить список этих вызовов. Но как понять, какая из системных функций вызывается наиболее часто и сколько времени тратится на ее выполнение? Как заглянуть «внутрь» системного вызова? Что происходит в ядре ОС, когда туда передается управление? В конце концов, в чем состоит причина «тормозов» при выполнении программы?

Еще пример. С помощью утилиты iostat можно проанализировать состояние подсистемы дискового ввода-вывода и обнаружить, что один из дисков перегружен (большие очереди, большой поток данных). Какой из процессов стал тому причиной? Еще хуже, если вы видите, что кто-то (пользователь или программа) непрерывно пишет данные на диск, «съедая» дисковое пространство. Как понять, что это за процесс? Время идет, дисковое пространство кончается... Хорошо бы иметь под рукой набор утилит для решения такого рода проблем.

Разработчики DTrace, Брайан Кэнтрил (Bryan Cantrill) и Майк Шапиро (Mike Shapiro) вспоминают, что когда-то, когда DTrace был еще только в идеях, они уже «пользовались» им в своих обсуждениях: «В этой ситуации мы введем такую команду с помощью DTrace и увидим, что...» Возможно, именно поэтому DTrace оказался настолько полезен для системных администраторов (более подробно история Dtrace изложена на http://research.sun.com/minds/2005-0929/).

Немного теории

Что можно увидеть с помощью DTrace? Если коротко – все. Подконтрольны все объекты, что существуют в системе, все системные вызовы, все устройства, интерфейсы и процессы. Все они снабжены так называемыми датчиками (probe), каждый из которых можно включить, выключить и опросить. Например, с помощью DTrace легко просмотреть:

• все системные вызовы, запускаемые в системе в данный период времени;
• все системные вызовы, запускаемые конкретным процессом;
• все системные вызовы read(), запускаемые данным процессом;
• размер буфера в момент системного вызова read().

Любой мало-мальски опытный системный администратор скажет, что все это можно увидеть и с помощью стандартных системных средств типа strace или truss. Появился другой набор задач -- администраторы Linux скажут: для этого есть iostat или mdb или vmstat. Но DTrace особенно хорош тем, что унифицирует все эти разрозненные, объединяет их в целостную и логичную систему, а кроме того предоставляет дополнительные возможности. Например, можно увидеть:

• размер дискового блока записи для конкретного процесса;
• прерывания, вызываемые процессом;
• статистику блокировок внутри ядра;
• системные сигналы, посылаемые и принимаемые процессом;
• размеры системного стека для пользовательских процессов;
• и многое, многое другое.

DTrace: практика

Одна из важнейших возможностей DTrace – агрегация. Администратор системы может не только отслеживать запуск системных вызовов, но и просматривать статистические данные (сколько и каких вызовов было за определенный промежуток времени, сколько суммарно времени занимал каждый из вызовов и др.) и сортировать результаты. Таким образом легко выявляются программы, незаметно «съедающие» значительную часть системного времени. Если они несущественны для реальной работы их можно остановить (как правило, это вспомогательные «демоны», различные «украшения» рабочего стола и прочие излишества). Если речь идет о жизненно необходимой прикладной программе, то, возможно, стоит задать вопрос разработчику: «а зачем вот здесь один и тот же файл открывается 27 раз подряд?». Если возможности предъявить претензии разработчикам нет, возможно, остроту проблемы сгладит перемещение этого файла в каталог /tmp (как минимум, это ускорит операции с ним, каталог /tmp в Solaris монтируется в виртуальной памяти и работает значительно быстрее, чем файловая система на диске). Даже простые методы поиска и сокращения ненужных вызовов позволяют иногда добиваться ускорения работы в два--пять раз.

Мониторинг процессов

Одна из наиболее «дорогих» операций (с точки зрения процессорного времени) – формирование и запуск нового процесса. Соответственно, полезно знать, какие процессы и с какой частотой запускаются при работе конкретной программы. Задаем команду:

# dtrace -n 'proc:::exec-success { 
trace(curpsinfo->pr_psargs); }'

В результате запуска, например, команды man ls, можно увидеть какие процессы порождает эта команда:

dtrace: description 'proc:::exec-success ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  13772         exec_common:exec-success   man ls     
  0  13772         exec_common:exec-success   sh -c cd /usr/man; tbl 
/usr/man/man1/ls.1 |neqn /usr/share/lib/pub/eqnchar - |n
  0  13772         exec_common:exec-success   tbl /usr/man/man1/ls.1 
  0  13772         exec_common:exec-success   neqn 
/usr/share/lib/pub/eqnchar -
  0  13772         exec_common:exec-success   nroff -u0 -Tlp -man - 
  0  13772         exec_common:exec-success   col -x          
  0  13772         exec_common:exec-success   sh -c trap  1 15; 
/usr/bin/mv -f /tmp/mpY7aGaF /usr/man/cat1/ls.1 2> /dev/nul
  0  13772         exec_common:exec-success   /usr/bin/mv -f 
/tmp/mpY7aGaF /usr/man/cat1/ls.1
  0  13772         exec_common:exec-success   sh -c more /tmp/mpY7aGaF
  0  13772         exec_common:exec-success   more /tmp/mpY7aGaF
^C

Множество примеров первых шагов по анализу системы можно найти на странице DTrace Quick Wins: http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Quick_Wins

Мониторинг дисковой активности

Работа с дисковой подсистемой -- головная боль многих системных администраторов. Диск занят постоянно, нагрузка большая, очереди длинные. Один способ – реорганизовать дисковую подсистему. Добавить дисков, включить страйпинг и т. п. Но, возможно, этого не требуется? Может быть проблемы вызывает одна-единственная программа, о которой все давно забыли? Как подсчитать объем байтов, передаваемых программами и посмотреть, кто из них «чемпион»? Запускается сценарий DTrace:

# dtrace -n 'io:::start { @[pid, execname] = 
sum(args[0]->b_bcount); }'

А в двух других запустим find и tar. Через некоторое время взглянем на результат:

dtrace: description 'io:::start ' matched 6 probes
^C

        0  sched                               2372608
      971  find                                3014656
      970  tar                                 4530176

Видно, что tar «перекачал» в полтора раза больше байт, чем find.

Выявление источников пиковых нагрузок

Часто встречающаяся ситуация: по данным vmstat система загружена на 100%. Естественная реакция администратора -- запуск prstat (или top) с целью выявления программа, создающей избыточную нагрузку на процессор. Но... в таблице prstat/top видно, что процессы, занимающие верхние строчки занимают не больше 2% процессорного времени. Откуда же взялась 100%-нагрузщка? Очень просто: top опрашивает систему раз в несколько секунд и просто «не замечает» большого количества процессов с временем жизни меньше кванта опроса (например, если это миллисекунды). А ведь они могут выполнять системные вызовы, которые «съедают» значительную часть процессорного времени. Классический пример: простой сценарий оболочки

# while :; do date; done

Приведет к полной загрузке системы, причем, с помощью стандартных средств понять чем же именно она занята -- почти невозможно. Использование программы execsnoop из упоминавшегося набора DTrace Toolkit покажет со всей наглядностью, что в системе постоянно запускаются процессы:

-bash-3.00# execsnoop -v
STRTIME                UID    PID   PPID ARGS
2007 Apr 14 03:14:55 116755   2167   1251 date
2007 Apr 14 03:14:56 116755   2168   1251 date
2007 Apr 14 03:14:56 116755   2169   1251 date 
2007 Apr 14 03:14:57 116755   2170   1251 date
2007 Apr 14 03:14:57 116755   2171   1251 date
2007 Apr 14 03:14:57 116755   2172   1251 date
2007 Apr 14 03:14:57 116755   2173   1251 date
2007 Apr 14 03:14:57 116755   2174   1251 date 
2007 Apr 14 03:14:57 116755   2175   1251 date
2007 Apr 14 03:14:57 116755   2176   1251 date
2007 Apr 14 03:14:58 116755   2177   1251 date
2007 Apr 14 03:14:58 116755   2178   1251 date
2007 Apr 14 03:14:58 116755   2179   1251 date 
2007 Apr 14 03:14:58 116755   2180   1251 date
2007 Apr 14 03:14:58 116755   2181   1251 date
2007 Apr 14 03:14:58 116755   2182   1251 date
2007 Apr 14 03:14:59 116755   2183   1251 date
2007 Apr 14 03:15:00 116755   2184   1251 date 
2007 Apr 14 03:15:00 116755   2185   1251 date

DTrace и Java?

И DTrace, и Java разработаны в Sun -- а значит могут работать вместе. Один из компонентов DTrace (так называемый провайдер), jstack() может показать содержимое стека Java-программы в какой-то определенный момент (например, при системном вызове read()):

# dtrace -n 'syscall::read:entry /execname == "java"/ { jstack(); }'
dtrace: description 'syscall::read:entry ' matched 1 probe
[...]
CPU     ID                    FUNCTION:NAME
  0  75943                       read:entry 
              libc.so.1`_read+0x7
              libX11.so.4`_X11TransSocketRead+0x25
              libX11.so.4`_X11TransRead+0x17
              libX11.so.4`_XRead+0x58
              libX11.so.4`_XEventsQueued+0x29e
              libX11.so.4`XEventsQueued+0x4f
              libmawt.so`Java_sun_awt_X11_XlibWrapper_XEventsQueued+0x1f
              sun/awt/X11/XlibWrapper.XEventsQueued(JI)I
              sun/awt/X11/XToolkit.run(Z)V
              sun/awt/X11/XToolkit.run()V
              java/lang/Thread.run()V
              StubRoutines (1)
              libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue
_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x1a3
              libjvm.so`__1cCosUos_exception_wrapper6FpFpnJJavaValue
_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x27
              libjvm.so`__1cJJavaCallsEcall6FpnJJavaValue
_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x2f
              libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue
_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_+0xc1
              libjvm.so`__1cJJavaCallsMcall_virtual6FpnJJavaValue
_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_+0x7e
              libjvm.so`__1cMthread_entry6FpnKJavaThread_pnGThread
__v_+0xd2
              libjvm.so`__1cKJavaThreadRthread_main_inner6M
_v_+0x4c
              libjvm.so`__1cKJavaThreadDrun6M_v_+0x196
              libjvm.so`java_start+0xd3
              libc.so.1`_thr_setup+0x52
              libc.so.1`_lwp_start

Сразу видны все взаимосвязи между методами Java и системными вызовами Solaris и легко понять, , что именно происходит в системе, когда выполняется тот или иной метод.

Скачать (pdf, 132 KB)

PC Magazine #05, май 2007