Один француз, Julien Gabel, приводит еще один пример того, как с помощью DTrace можно найти причины повышенной нагрузки на сервере (запущен Nagios, Solaris 10).
Запуская
uptime, он постоянно наблюдал значения
load average 4 или 5 на однопроцессорной системе:
# uptime
11:48am up 85 day(s), 23:27, 2 users, load average: 4.53, 4.44, 4.48
#
# vmstat 1
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr m0 m1 m3 m4 in sy cs us sy id
3 0 0 9286536 1484928 1029 8643 42 156 161 0 203 1 2 0 0 676 78530 949 47 44 8
1 0 0 9263880 1467936 1123 10536 0 0 0 0 0 0 0 0 0 673 37455 1241 52 48 0
1 0 0 9262232 1455472 1097 10656 0 0 0 0 0 0 0 0 0 771 35824 1496 52 48 0
0 0 0 9302168 1484760 1236 11513 0 0 0 0 0 0 0 0 0 592 32530 864 50 50 0
3 0 0 9260872 1458072 967 9788 0 1616 1616 0 0 0 0 0 0 1141 30488 1280 51 48 1
3 0 0 9224896 1434208 1229 11008 0 0 0 0 0 0 0 0 0 638 36756 1198 53 47 0
Чтобы отыскать виновного в расходовании процессорного времени, француз обратился к DTrace:
# dtrace -n 'syscall:::entry { @num[execname] = count(); }'
dtrace: description 'syscall:::entry ' matched 226 probes
^C
fmd 1
inetd 1
svc.configd 1
sshd 8
svc.startd 12
sendmail 20
dced 30
picld 34
xntpd 50
httpd 68
nscd 236
dtrace 454
init 2265
nagios_xng_1.2 5170
sh 9645
mysqld 21901
php 250039
Видно, что безусловным лидером здесь является php. Далее он попытался узнать, какие же системные вызовы использует php:
# dtrace -n 'syscall:::entry { @num[probefunc] = count(); }'
dtrace: description 'syscall:::entry ' matched 226 probes
^C
[...]
pollsys 951
llseek 1263
getcwd 1371
memcntl 1667
write 2679
lseek 3552
resolvepath 3745
munmap 3807
sigaction 3917
gtime 4228
fcntl 4758
close 5185
lwp_sigmask 5279
open 5311
mmap 7933
brk 34003
stat 43151
read 86493
Вызов
read лидирует. Теперь с помощью скриптов
readid.d и
readfile.d он решил узнать, участвуют ли здесь разные процессы php и получить имена файлов, к которым обращается php:
# ./readid.d php 5s
Sampling for 5s ... Please wait.
PROGRAM PID COUNT
[...]
php 26333 1351
php 26345 1353
php 26408 1353
php 26448 1353
php 26340 1353
php 26440 1353
php 26432 1353
php 26424 1353
php 26436 2376
php 26372 2376
php 26357 2376
php 26353 2376
php 26379 2376
php 26369 2378
php 26328 3136
#
# ./readfile.d php 5s
Sampling for 5s ... Please wait.
FILE NAME COUNT
[...]
/data/p2/sysdoc/soft/php_5.0.3_3/php.ini 231
/data/sybase_client/V12.5.1_32bits_SunOS/charsets/iso_1/charset.loc 330
/data/sybase_client/V12.5.1_32bits_SunOS/config/objectid.dat 374
/data/sybase_client/V12.5.1_32bits_SunOS/locales/message/us_english/cslib.loc
429
/data/sybase_client/V12.5.1_32bits_SunOS/charsets/utf8/iso_1.ctb 660
/data/sybase_client/V12.5.1_32bits_SunOS/locales/message/us_english/tcllib.loc
858
/data/sybase_client/V12.5.1_32bits_SunOS/locales/locales.dat 1056
/data/sybase_client/V12.5.1_32bits_SunOS/locales/message/us_english/ctlib.loc
2244
/data/sybase_client/V12.5.1_32bits_SunOS/charsets/utf8/charset.loc 5473
/tools/list/sybase/interfaces 33116
Итак, видно, что несколько процессов php используют вызов
read. Второй вывод более интересен, так как он показывает, что файл, к которому так часто обращается php - конфигурационный файл Sybase RDBMS для соединения с сервером.
Наконец, с помощью скрипта opensnoop.d француз увидел, что в конфигурации Nagios некоторые пути прописаны неправильно - в системе их нет:
# sh ./opensnoop.d -x -n php
UID PID COMM FD PATH
620 8483 php -1 /var/ld/ld.config
620 8483 php -1 /bin//php-cli.ini
620 8483 php -1 /soft/sun_free/php/php-cli.ini
620 8483 php -1 /bin//php.ini
620 8483 php -1 /usr/nagios/site/my_syb_client/OCS-12_5/config/ocs.cfg
620 8483 php -1 //getinfo.php
620 8483 php -1 /soft/sun_free/php/lib/php/getinfo.php
620 8483 php -1 /soft/sun_free/adodb/getinfo.php
620 8483 php -1 //recuperation_seuil.php
620 8483 php -1 /soft/sun_free/php/lib/php/recuperation_seuil.php
620 8483 php -1 /soft/sun_free/adodb/recuperation_seuil.php
620 8483 php -1 //mysql_connect.php
620 8483 php -1 /soft/sun_free/php/lib/php/mysql_connect.php
620 8483 php -1 /soft/sun_free/adodb/mysql_connect.php
620 8483 php -1 //sybase_check_appli.php
620 8483 php -1 /soft/sun_free/php/lib/php/sybase_check_appli.php
620 8483 php -1 /soft/sun_free/adodb/sybase_check_appli.php
620 8483 php -1 //sybase_check_system.php
620 8483 php -1 /soft/sun_free/php/lib/php/sybase_check_system.php
620 8483 php -1 /soft/sun_free/adodb/sybase_check_system.php
620 8483 php -1 //mysql_connect.php
620 8483 php -1 /soft/sun_free/php/lib/php/mysql_connect.php
620 8483 php -1 /soft/sun_free/adodb/mysql_connect.php
620 8487 php -1 /var/ld/ld.config
620 8487 php -1 /bin//php-cli.ini
620 8487 php -1 /soft/sun_free/php/php-cli.ini
620 8487 php -1 /bin//php.ini
[...]
DTrace помог в данном примере увидеть причины чрезмерного потребления CPU: соединение с Sybase RDBMS, и неправильные пути в конфигурации Nagios.
