Последние статьи
DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD
Сертификация по Solaris
The beep
Oracle Solaris 11 Express
Sunday, April 10 2011
Сертификация по Solaris
Sunday, January 16 2011
The beep
Sunday, January 16 2011
Oracle Solaris 11 Express
Tuesday, November 16 2010
Monday, 21 May. 2007
DTrace в решении повседневных задач
Профилирование - процесс анализа характеристик приложения, обычно ради улучшения его работы. Однако прежде, чем вы cможете профилировать программу, необходимо дать D программе возможность ограничить зарегистрированные события, связанные только с одним приложением. Есть несколько способов для достижения данной задачи. Во-первых, вы можете связать вашу D программу с одним или более процессами с помощью использования опции -c, чтобы определить выполняющуюся команду, или опции -p для определения PID'а уже выполняющегося процесса. Можно указывать множество процессов или команд для обеих опций, но первый всегда хранит свой PID в специальной макро-переменной $target. (Макро-переменные заменяются связанными с ними значениями фактически до запуска D программы, таким образом любое место в вашей D программе, где вы используете $target, будет заменено номером PID первого указанного с помощью опций -c или -p процесса). Например, можно использовать $target в предикате, чтобы ограничить выполнение пробы только для одного процесса. После того, как все ассоциированные процессы умирают, D программа также заканчивает свою работу, отобразив любой конечный вывод или выполнив пробу END.
Во вторых, можно просто передать PID процесса как параметр D программе. Любые параметры после любых опций передаются переменным 1 $, 2 $, 3 $ и т.д. (макропеременная $0 - название вашей D программы). Так как DTrace не знает о том, что ваши параметры являются процессами, при использовании этого метода D-скрипт не заканчивает свою работу при завершении процессов.
Во вторых, можно просто передать PID процесса как параметр D программе. Любые параметры после любых опций передаются переменным 1 $, 2 $, 3 $ и т.д. (макропеременная $0 - название вашей D программы). Так как DTrace не знает о том, что ваши параметры являются процессами, при использовании этого метода D-скрипт не заканчивает свою работу при завершении процессов.
Хороший первый шаг в профилировании - сбор информации о том, где процесс расходует свое время. В моем эксперименте я собираюсь сравнить команды cp и dd для копирования файла. Создав 50-мегабайтный файл с названием file1 и запустив time cp file1 file2, получаю:
Однако если вместо этого копировать файл, используя time dd if=file1 of=file2, результат отличен от предыдущего:
Команде dd потребовалось почти вдвое больше времени, чтобы скопировать файл, кроме того она использовала в четыре раза больше системного времени (См. прим.1). Поскольку различие в системном времени очень высокое, давайте сделаем сравнение системных вызовов для каждой из выполняемых команд. Чтобы сосчитать системные вызовы, я буду использовать следующую D программу (scount.d):
syscall:::entry
/ $target == pid /
{
@[probefunc] = count()
}
Здесь используется функция агрегирования для подсчета всех системных вызовов. Для syscall провайдера, probefunc - название системного вызова, таким образом подсчет агрегирования будет ключевым на системных вызовах. Предикат ограничивает наш сбор данных системными вызовами для указанного процесса. Теперь я запущу каждую из команд копирования против D программы:
Выделяются два различия между cp и dd: cp использует вызов write только семь раз, тогда как dd, чтобы сделать ту же самую копию - 102 406. Кроме того, cp подозрительно пропускает любые чтения вообще. Тогда какже читается file1 для копирования?
Даже этот высокий уровень анализа дает нам некоторое представление о происходящем. Так как dd производит гораздо больше записей чем cp, я готов поверить, что она вероятно записывает меньшие блоки чем cp. Кроме того, отсутствие любых вызовов на чтение в cp заставляет меня задаться вопросом, имеет ли cp отличный, возможно лучший путь для чтения файлов.
Здесь мы ощущаем власть DTrace. Язык программирования D дает вам инструменты для наблюдения и за лесом и за деревьями, и позволяет как угодно менять масштаб между ними. Чтобы доказать или опровергнуть нашу теорию, мы должны будем пронаблюдать системные вызовы более близко. Давайте рассмотрим системные вызовы write. Системный вызов write имеет три параметра (см. man -s 2 write). Первый параметр - описание файла, второй - указатель на буфер, который будет записан, и третий - число байт, которые будут записаны. Чтобы сосредоточиться только на системных вызовах write, мы создадим новую D программу (wcount.d):
syscall::write:entry
/ $target == pid /
{
@[arg0] = quantize(arg2);
}
Для этого примера я ввел новую агрегирующую функцию - quantize. Применение quantize позволяет отобразить гистограмму вызовов write. Отдельный распределенный график отображается для каждого ключа агрегации, который в данном случае является файловым дескриптором write:
Каждая строка в выводе представлена в виде "ведра" (См. прим.2). Каждое ведро содержит значения, которые являются столь же большими или меньшими чем значения, перечисленные слева от строки, но больше чем значения на предыдущей строке (rn < x <= rn+1). Значение r для каждой строки увеличивается в степени два. Например, вторая строка третьего распределения говорит, что было сделано 102 400 записей, которые больше чем 256 байт, но меньше или равны 512. В этом случае я подозреваю что большинство записей имеют одинаковую длину. Мы должны точно знать, сколько записей сделано для каждого буферного размера и для достижения этой цели я возвращаюсь к использованию count (wcount2.d), даже учитывая что с помощью quantize вывод выглядит более привлекательно:
syscall::write:entry
/ $target == pid /
{
@[arg0, arg2] = count();
}
Запуск этого скрипта против каждой из команд копирования выдает следующие результаты:
Команда cp произвела лишь семь записей: шесть 8Mб-записей, и одну в 2Mб, в общей сложности 50Mб. Команда dd обращалась к двум файловым дескрипторам. Файловый дескриптор 2 - стандартная ошибка, таким образом мы можем заключить, что эти вызовы write использовались для отображения количества записей. Это оставляет файловуму дескриптору 4 102 400 512 побайтовых записей. Эти записи также составляют в целом 50Mб данных. Наше заключение правильно: dd производит намного больше маленьких записей. Оказывается, что команда dd имеет параметр blocksize, который позволяет нам заставить dd использовать 8Mб буфер для копирования. Если я запущу time dd if=file1 of=file2 bs=8192k, я получу следующие результаты:
Этот вывод dd ясно показывают что программа теперь пишет шесть 8Mб блоков и один 2Mб блок. Мы могли бы доказать это с помощью нашей D программы, но я оставлю это для вас, чтобы вы смогли попробовать самостоятельно. Смотрим далее - время системного вызова все еще почти на 50 % выше для dd, чем для cp. Возможно к этому имеет некоторое отношение то, что cp не использует системный вызов read. Если это так, то как же cp читает файл?
Другой единственный системный вызов в описании system calls, который имеет отношение к операциям IO файла, является mmap. Этот системный вызов отражает область памяти по сегменту файла, так, чтобы файл стал частью виртуальной памяти. Поскольку программа обращается к памяти - страницам Solaris в разделах файла, нет никаких системных вызовов чтения. Конечно же, есть все еще операции с IO, но это все управляется алгоритмами пэйджинга системы, которые являются очень эффективными. Похоже на хорошую теорию. Как нам доказать это? Также как мы сделали с writes, мы можем ограничить D программу, чтобы наблюдать только системные вызовы mmap (mcount.d):
syscall::mmap*:entry
/ $target == pid /
{
@[(int)arg4, arg1] = count();
}
Системный вызов mmap имеет шесть параметров (см. man -s 2 mmap), но прямо сейчас нас интересуют только размеры распределенной области памяти arg1 и файлового дескриптора arg4. Я использовал * в названии probefunc, потому что есть два системных вызова: mmap и mmap64. Кроме того, заметьте, что я перевел агрегационный ключ, arg4, в int. Вот вывод от команды dtrace -s mcount.d -c "cp file1 file2":
Есть распределение вокруг некоторых анонимных вызовов mmap (файловый дескриптор -1), и распределение вокруг файлового дескриптора 3. (Заметьте, что счетчики для файлового дескриптора 3 разбиты на две группы. Это потому что счетчик сортирует вывод по значению). Этот файловый дескриптор 3 представляет большой интерес. Однако, есть несколько различных распределений по размеру памяти. Как нам узнать, какие имеют отношение к читению file1? Я подозреваю, что вызовы mmap для размера 8Mб и 2Mб являются теми самыми, котрые мы ищем.
Чтобы доказать это, мы должны ограничить наш вывод вызовами mmap, которые только связаны с чтением "file1". В нашей программе D мы можем установить контрольную переменную, которая получит значение, как только file1 будет открыт (mcount2.d):
BEGIN
{
fd = -1; /* -1 means file1 not open */
}
/* If file1 not open, save the file name pointer */
syscall::open*:entry
/ $target == pid && fd == -1 /
{
fnp = arg0;
}
/* If file1 not open, open succeeded,
and filename is file1, save fd */
syscall::open*:return
/ $target == pid && fd == -1 && arg0 != -1 /
{
fd = basename(copyinstr(fnp)) == "file1" ? arg0 : -1;
}
/* If file1 is open and the mmap fildes is file1's,
collect size data */
syscall::mmap*:entry
/ $target == pid && fd != -1 && fd == arg4 /
{
@[arg4, arg1] = count();
}
/* If close is for file1, show that file1
no longer open */
syscall::close*:entry
/ $target == pid && arg0 == fd /
{
fd = -1;
}
(Заметьте, что я использовал глобальные переменные, так как команды cp и dd однопоточные.), Как только программа D видит открытый системный вызов для file1, это устанавливает fd в файловый дескриптор при открытии. Проба для mmap срабатывает только если файл открыт, таким образом мы только собираем данные для вызовов mmap, связанных с file1. (Для информации, почему мы должны обработать указатель имени файла при открытии:entry в open:return.) Вот вывод, получаемый при выполнении команды dtrace -s mcount2.d -c "cp file1 file2":
Это ясно показывает нам что cp отображает 8Mб из памяти file1 шесть раз и 2Mб из памяти file1 один раз. Но доказывает ли то, как file1 был отображен то, как file1 читается? Поскольку нет в наличии никаких других системных вызовов IO, вероятно; но есть еще один шаг, который мы могли бы сделать, чтобы доказать это. Было бы трудно проследить фактические обращения cp к отображенным участкам памяти, но нам действительно это не нужно. Все, что мы должны увидеть - пэйджинг ядра из памяти в данные файла. Вносим изменения в mcount2.d (mcount3.d):
#pragma D option quiet
BEGIN
{
fd = -1; /* -1 means file1 not open */
pc = 0; /* Page-in count per mmap */
}
syscall::open*:entry
/ $target == pid && fd == -1 /
{
fnp = arg0;
}
syscall::open*:return
/ $target == pid && fd == -1 && arg0 != -1 /
{
fd = basename(copyinstr(fnp)) == "file1" ? arg0 : -1;
}
syscall::mmap*:entry
/ $target == pid && fd != -1 && fd == arg4 /
{
printf ("Last mmap page-in count %d\n", pc);
pc = 0;
}
vminfo:::fspgin
/ $target == pid && fd != -1 /
{
pc++;
}
syscall::close*:entry
/ $target == pid && arg0 == fd /
{
fd = -1;
}
END
{
printf ("Last mmap page-in count %d\n", pc);
}
Я добавил новую пробу, vminfo:::fspgin. Проба vminfo включается при изменениях виртуальной памяти (пэйджинг и своппинг). Случай, которым мы интересуемся - страница в данных файловой системы между вызовами mmap. В конце программа D имеет счетчик страницы (pc), который увеличивается каждый раз когда включается проба fspgin. Когда проба mmap выполняется, сигнализируя, что новый сегмент памяти был отображен на file1, pc выводится, и затем обнуляется. Для первого раза мы выполняем dtrace -s mcount3.d -c "cp file1 file2" и видим следующее:
Первый счетчик имеет значение нуль, потому что это - первый вызов mmap, и никто к отображаемой памяти еще не обращался. После этого видны от 60 до 70 page-ins после каждого вызова mmap. Активность пэйджинга похоже, является результатом обращения cp к памяти, которая была только что отображена. Последний счетчик является намного меньшим, потому что последняя отображенная область файла имела размер только 2Mб. Если мы выполним команду снова, то с кэшем, который теперь загружен вместе с содержимым file1, мы получаем:
Так как содержимое file1 все еще в кэше, не потребовалось никаких page-ins, чтобы сделать копию во второй раз (См. прим.3).
Другое общее использование DTrace - обнаружение системных проблем, с которыми обычные инструментальные средства не могут справиться. В этом примере я наблюдаю приличное использование процессорного времени, но кажется, нет никаких процессов, виновных в этом. Запуск vmstat 5 дает мне следующий вывод:
Система не простаивает и тратит приблизительно половину времени на системные вызовы и приблизительно половину на пользовательский код. Давайте обратимся к prstat, чтобы определить процессы, расходующие это время:
Не видно процессов, которые бы использовали этот вид процессорного времени, поэтому давайте более пристально посмотрим на то, какие системные вызовы извлекаются. Мы будем должны изменить наш оригинальный сценарий scount.d, нам уже не нужен орпеделенный адресат. Кроме того, даже при том, что я мог только собрать данные за некоторое время и затем прервать мою D программу, на сей раз я хотел бы чтобы она выполнялась точно 5 секунд и заканчивала работу самостоятельно. Чтобы добиться этого, я буду использовать провайдер profile. Я назову новый сценарий sc.d:
#pragma D option quiet
BEGIN
{
tick2 = 0;
}
tick-5s
/ tick2 /
{
exit (0);
}
tick-5s
/ !tick2 /
{
trace ("Collecting data\n");
tick2 = 1;
}
syscall:::entry
/ tick2 /
{
@[probefunc] = count();
}
Контрольная переменная tick2 позволяет нам собирать данные на втором включении пробы tick-5s. Поскольку вы можете повторить вызов, мы не можем пологаться на пробы profile, ждущие указанное время в первый раз, когда они включаются, таким образом мы хотим собрать данные за 5 секунд на первом включении tick-5s. При первом включении tick-5s, проба устанавливает переменную tick2 = 1, которая делает истиннным предикат sycall:::entry. Программа D собирает данные в течение 5 секунд и затем выходит на следующем включении tick-5s. Когда я запустил эту D программу против моей занятой системы, я получил следующий вывод:
Здесь большое количество системных вызовов, таким образом мы должны выбрать один из запросов системы для больших подробностей. Было 1793 запросов open за 5-секундный период. Давайте узнаем, какие файлы при открытии так заняли систему (oc.d):
syscall::open:entry
{
self->fnp = arg0;
}
syscall::open:return
/ self->fnp /
{
@[copyinstr(self->fnp)] = count();
self->fnp = 0;
}
Полученный вывод очень длинный, поэтому привожу лишь наиболее важные 10 последних строк:
Эти имена файлов, кажется, связаны с GNU C компилятором. Мы видим много вызовов open только для одной инстанции компилятора C. Интересно, сколько раз вызывается компилятор. Давайте проверим это (exc.d):
syscall::exec*:return
{
@[execname] = count();
}
Этот сценарий, запущенный в течение пяти секунд на моей занятой системе вывел следующее (удостоверьтесь, что вы ждете, пока DTrace не скажет вам, сколько проб было обнаружено прежде чем вы запустите 5-секундный счетчик):
Здесь множество вызовов компилятора C в течение 5-секундного периода. Мы должны узнать, кто инициализирует всю эту деятельность. Самый легкий способ сделать это - перечислить вызовы exec и их родителей (exlist.d):
#pragma D option quiet
syscall::exec*:entry
{
self->exn = execname;
}
syscall::exec*:return
/ self->exn != "" /
{
printf ("%s -> %s\n", self->exn, execname);
self->exn = 0;
}
Запуск этой D программы все разъясняет:
Процесс с именем callfast вызывает компилятор C неоднократно. Короткие процессы, сгенерированные компилятором C настолько кратковременны, что не оказывают существенное влияние на prstat. Однако DTrace легко нашел проблему.
Существуют разнообразные проблемы, которые подчас трудно решить, используя традиционные инструментальные средства и методы. DTrace позволяет добраться до сути этих проблем намного проще.
Примечание 1.
Вы должны знать, что я немного схитрил здесь, чтобы получить соответствующие результаты. В первый раз, когда вы выполняете команду, которая читает файл, файл читается в кэш. Каждый раз после этого, когда вы читаете файл, данные исходят уже из кэша, а не из диска. Очевидно, это испортило бы результаты. Чтобы компенсировать эту проблему, я написал программу на C, чтобы распределить достаточное пространство "кучи", чтобы использовать всю доступную реальную память. (Я не советую использовать эту методику на промышленной системе - это может повлиять на другие приложения.) Перед каждым запуском, я выполнял эту программу, чтобы сбросить на диск кэш файла:
main()
{
int i = 0;
while ((char *)malloc(1024*1024) != 0)
{
printf ("%d ", ++i);
}
exit(0);
}
Вам на самом деле не надо запускать программу, пока она не заканчивает свою работу (не исчерпывает виртуальную память). Если распределение замедляется, это значит что вы аннулировали все страницы памяти, которые использовались для кэша файла.
Примечание 2.
http://docs.sun.com/app/docs/doc/817-6223
Примечание 3.
Прежде, чем вы удивитесь тому что memory mapping намного лучше чем регулярные чтения файла, вы должны знать, что проектировщики Solaris знают об этом. Именно поэтому Solaris осуществляет регулярное чтение файла, используя алгоритмы пэйджинга. При данном методе используется немного меньше системного времени, но операции IO в обоих случаях столь же эффективны.
real 4.1
user 0.0
sys 0.9
Однако если вместо этого копировать файл, используя time dd if=file1 of=file2, результат отличен от предыдущего:
real 7.5
user 1.0
sys 4.6
Команде dd потребовалось почти вдвое больше времени, чтобы скопировать файл, кроме того она использовала в четыре раза больше системного времени (См. прим.1). Поскольку различие в системном времени очень высокое, давайте сделаем сравнение системных вызовов для каждой из выполняемых команд. Чтобы сосчитать системные вызовы, я буду использовать следующую D программу (scount.d):
syscall:::entry
/ $target == pid /
{
@[probefunc] = count()
}
Здесь используется функция агрегирования для подсчета всех системных вызовов. Для syscall провайдера, probefunc - название системного вызова, таким образом подсчет агрегирования будет ключевым на системных вызовах. Предикат ограничивает наш сбор данных системными вызовами для указанного процесса. Теперь я запущу каждую из команд копирования против D программы:
# dtrace -s scount.d -c "cp file1 file2"
dtrace: script 'scount.d' matched 226 probes
dtrace: pid 2194 has exited
creat64 1
fstat64 1
getpid 1
getrlimit 1
open64 1
pathconf 1
rexit 1
acl 2
brk 2
memcntl 2
setcontext 2
open 3
resolvepath 3
stat 3
close 5
stat64 5
mmap64 7
munmap 7
write 7
mmap 15
# dtrace -s scount.d -c "dd if=file1 of=file2"
dtrace: script 'scount.d' matched 226 probes
102400+0 records in
102400+0 records out
dtrace: pid 2200 has exited
creat64 1
fstat64 1
getpid 1
getrlimit 1
open 1
open64 1
resolvepath 1
rexit 1
stat 1
sysconfig 1
munmap 2
setcontext 2
sigaction 2
close 3
brk 4
mmap 4
read 102401
write 102406
Выделяются два различия между cp и dd: cp использует вызов write только семь раз, тогда как dd, чтобы сделать ту же самую копию - 102 406. Кроме того, cp подозрительно пропускает любые чтения вообще. Тогда какже читается file1 для копирования?
Даже этот высокий уровень анализа дает нам некоторое представление о происходящем. Так как dd производит гораздо больше записей чем cp, я готов поверить, что она вероятно записывает меньшие блоки чем cp. Кроме того, отсутствие любых вызовов на чтение в cp заставляет меня задаться вопросом, имеет ли cp отличный, возможно лучший путь для чтения файлов.
Здесь мы ощущаем власть DTrace. Язык программирования D дает вам инструменты для наблюдения и за лесом и за деревьями, и позволяет как угодно менять масштаб между ними. Чтобы доказать или опровергнуть нашу теорию, мы должны будем пронаблюдать системные вызовы более близко. Давайте рассмотрим системные вызовы write. Системный вызов write имеет три параметра (см. man -s 2 write). Первый параметр - описание файла, второй - указатель на буфер, который будет записан, и третий - число байт, которые будут записаны. Чтобы сосредоточиться только на системных вызовах write, мы создадим новую D программу (wcount.d):
syscall::write:entry
/ $target == pid /
{
@[arg0] = quantize(arg2);
}
Для этого примера я ввел новую агрегирующую функцию - quantize. Применение quantize позволяет отобразить гистограмму вызовов write. Отдельный распределенный график отображается для каждого ключа агрегации, который в данном случае является файловым дескриптором write:
# dtrace -s wcount.d -c "cp file1 file2"
dtrace: script 'wcount.d' matched 1 probe
dtrace: pid 2264 has exited
4
value ------------- Distribution ------------- count
1048576 | 0
2097152 |@@@@@@ 1
4194304 | 0
8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6
16777216 | 0
# dtrace -s wcount.d -c "dd if=file1 of=file2"
dtrace: script 'wcount.d' matched 1 probe
102400+0 records in
102400+0 records out
dtrace: pid 2266 has exited
2
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@ 2
4 |@@@@@@@@@@@@@ 2
8 |@@@@@@@@@@@@@ 2
16 | 0
4
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 102400
1024 | 0
Каждая строка в выводе представлена в виде "ведра" (См. прим.2). Каждое ведро содержит значения, которые являются столь же большими или меньшими чем значения, перечисленные слева от строки, но больше чем значения на предыдущей строке (rn < x <= rn+1). Значение r для каждой строки увеличивается в степени два. Например, вторая строка третьего распределения говорит, что было сделано 102 400 записей, которые больше чем 256 байт, но меньше или равны 512. В этом случае я подозреваю что большинство записей имеют одинаковую длину. Мы должны точно знать, сколько записей сделано для каждого буферного размера и для достижения этой цели я возвращаюсь к использованию count (wcount2.d), даже учитывая что с помощью quantize вывод выглядит более привлекательно:
syscall::write:entry
/ $target == pid /
{
@[arg0, arg2] = count();
}
Запуск этого скрипта против каждой из команд копирования выдает следующие результаты:
# dtrace -s wcount2.d -c "cp file1 file2"
dtrace: script 'wcount2.d' matched 1 probe
dtrace: pid 13164 has exited
4 2097152 1
4 8388608 6
# dtrace -s wcount2.d -c "dd if=file1 of=file2"
dtrace: script 'wcount2.d' matched 1 probe
102400+0 records in
102400+0 records out
dtrace: pid 13166 has exited
2 12 1
2 13 1
2 2 2
2 6 2
4 512 102400
Команда cp произвела лишь семь записей: шесть 8Mб-записей, и одну в 2Mб, в общей сложности 50Mб. Команда dd обращалась к двум файловым дескрипторам. Файловый дескриптор 2 - стандартная ошибка, таким образом мы можем заключить, что эти вызовы write использовались для отображения количества записей. Это оставляет файловуму дескриптору 4 102 400 512 побайтовых записей. Эти записи также составляют в целом 50Mб данных. Наше заключение правильно: dd производит намного больше маленьких записей. Оказывается, что команда dd имеет параметр blocksize, который позволяет нам заставить dd использовать 8Mб буфер для копирования. Если я запущу time dd if=file1 of=file2 bs=8192k, я получу следующие результаты:
6+1 records in
6+1 records out
real 3.3
user 0.0
sys 1.3
Этот вывод dd ясно показывают что программа теперь пишет шесть 8Mб блоков и один 2Mб блок. Мы могли бы доказать это с помощью нашей D программы, но я оставлю это для вас, чтобы вы смогли попробовать самостоятельно. Смотрим далее - время системного вызова все еще почти на 50 % выше для dd, чем для cp. Возможно к этому имеет некоторое отношение то, что cp не использует системный вызов read. Если это так, то как же cp читает файл?
Другой единственный системный вызов в описании system calls, который имеет отношение к операциям IO файла, является mmap. Этот системный вызов отражает область памяти по сегменту файла, так, чтобы файл стал частью виртуальной памяти. Поскольку программа обращается к памяти - страницам Solaris в разделах файла, нет никаких системных вызовов чтения. Конечно же, есть все еще операции с IO, но это все управляется алгоритмами пэйджинга системы, которые являются очень эффективными. Похоже на хорошую теорию. Как нам доказать это? Также как мы сделали с writes, мы можем ограничить D программу, чтобы наблюдать только системные вызовы mmap (mcount.d):
syscall::mmap*:entry
/ $target == pid /
{
@[(int)arg4, arg1] = count();
}
Системный вызов mmap имеет шесть параметров (см. man -s 2 mmap), но прямо сейчас нас интересуют только размеры распределенной области памяти arg1 и файлового дескриптора arg4. Я использовал * в названии probefunc, потому что есть два системных вызова: mmap и mmap64. Кроме того, заметьте, что я перевел агрегационный ключ, arg4, в int. Вот вывод от команды dtrace -s mcount.d -c "cp file1 file2":
dtrace: script 'mcount.d' matched 2 probes
dtrace: pid 14500 has exited
3 296 1
3 3260 1
3 13512 1
3 13613 1
3 55381 1
3 2097152 1
-1 5880 1
-1 16384 1
-1 24576 1
-1 81920 1
-1 147456 1
-1 8192 2
3 8192 3
3 8388608 6
Есть распределение вокруг некоторых анонимных вызовов mmap (файловый дескриптор -1), и распределение вокруг файлового дескриптора 3. (Заметьте, что счетчики для файлового дескриптора 3 разбиты на две группы. Это потому что счетчик сортирует вывод по значению). Этот файловый дескриптор 3 представляет большой интерес. Однако, есть несколько различных распределений по размеру памяти. Как нам узнать, какие имеют отношение к читению file1? Я подозреваю, что вызовы mmap для размера 8Mб и 2Mб являются теми самыми, котрые мы ищем.
Чтобы доказать это, мы должны ограничить наш вывод вызовами mmap, которые только связаны с чтением "file1". В нашей программе D мы можем установить контрольную переменную, которая получит значение, как только file1 будет открыт (mcount2.d):
BEGIN
{
fd = -1; /* -1 means file1 not open */
}
/* If file1 not open, save the file name pointer */
syscall::open*:entry
/ $target == pid && fd == -1 /
{
fnp = arg0;
}
/* If file1 not open, open succeeded,
and filename is file1, save fd */
syscall::open*:return
/ $target == pid && fd == -1 && arg0 != -1 /
{
fd = basename(copyinstr(fnp)) == "file1" ? arg0 : -1;
}
/* If file1 is open and the mmap fildes is file1's,
collect size data */
syscall::mmap*:entry
/ $target == pid && fd != -1 && fd == arg4 /
{
@[arg4, arg1] = count();
}
/* If close is for file1, show that file1
no longer open */
syscall::close*:entry
/ $target == pid && arg0 == fd /
{
fd = -1;
}
(Заметьте, что я использовал глобальные переменные, так как команды cp и dd однопоточные.), Как только программа D видит открытый системный вызов для file1, это устанавливает fd в файловый дескриптор при открытии. Проба для mmap срабатывает только если файл открыт, таким образом мы только собираем данные для вызовов mmap, связанных с file1. (Для информации, почему мы должны обработать указатель имени файла при открытии:entry в open:return.) Вот вывод, получаемый при выполнении команды dtrace -s mcount2.d -c "cp file1 file2":
dtrace: script 'mcount2.d' matched 8 probes
dtrace: pid 14530 has exited
3 2097152 1
3 8388608 6
Это ясно показывает нам что cp отображает 8Mб из памяти file1 шесть раз и 2Mб из памяти file1 один раз. Но доказывает ли то, как file1 был отображен то, как file1 читается? Поскольку нет в наличии никаких других системных вызовов IO, вероятно; но есть еще один шаг, который мы могли бы сделать, чтобы доказать это. Было бы трудно проследить фактические обращения cp к отображенным участкам памяти, но нам действительно это не нужно. Все, что мы должны увидеть - пэйджинг ядра из памяти в данные файла. Вносим изменения в mcount2.d (mcount3.d):
#pragma D option quiet
BEGIN
{
fd = -1; /* -1 means file1 not open */
pc = 0; /* Page-in count per mmap */
}
syscall::open*:entry
/ $target == pid && fd == -1 /
{
fnp = arg0;
}
syscall::open*:return
/ $target == pid && fd == -1 && arg0 != -1 /
{
fd = basename(copyinstr(fnp)) == "file1" ? arg0 : -1;
}
syscall::mmap*:entry
/ $target == pid && fd != -1 && fd == arg4 /
{
printf ("Last mmap page-in count %d\n", pc);
pc = 0;
}
vminfo:::fspgin
/ $target == pid && fd != -1 /
{
pc++;
}
syscall::close*:entry
/ $target == pid && arg0 == fd /
{
fd = -1;
}
END
{
printf ("Last mmap page-in count %d\n", pc);
}
Я добавил новую пробу, vminfo:::fspgin. Проба vminfo включается при изменениях виртуальной памяти (пэйджинг и своппинг). Случай, которым мы интересуемся - страница в данных файловой системы между вызовами mmap. В конце программа D имеет счетчик страницы (pc), который увеличивается каждый раз когда включается проба fspgin. Когда проба mmap выполняется, сигнализируя, что новый сегмент памяти был отображен на file1, pc выводится, и затем обнуляется. Для первого раза мы выполняем dtrace -s mcount3.d -c "cp file1 file2" и видим следующее:
Last mmap page-in count 0
Last mmap page-in count 67
Last mmap page-in count 64
Last mmap page-in count 69
Last mmap page-in count 64
Last mmap page-in count 65
Last mmap page-in count 64
Last mmap page-in count 18
Первый счетчик имеет значение нуль, потому что это - первый вызов mmap, и никто к отображаемой памяти еще не обращался. После этого видны от 60 до 70 page-ins после каждого вызова mmap. Активность пэйджинга похоже, является результатом обращения cp к памяти, которая была только что отображена. Последний счетчик является намного меньшим, потому что последняя отображенная область файла имела размер только 2Mб. Если мы выполним команду снова, то с кэшем, который теперь загружен вместе с содержимым file1, мы получаем:
Last mmap page-in count 0
Last mmap page-in count 0
Last mmap page-in count 0
Last mmap page-in count 0
Last mmap page-in count 0
Last mmap page-in count 0
Last mmap page-in count 0
Last mmap page-in count 0
Так как содержимое file1 все еще в кэше, не потребовалось никаких page-ins, чтобы сделать копию во второй раз (См. прим.3).
Решение проблемы производительности системы - анонимное процессорное время.
Другое общее использование DTrace - обнаружение системных проблем, с которыми обычные инструментальные средства не могут справиться. В этом примере я наблюдаю приличное использование процессорного времени, но кажется, нет никаких процессов, виновных в этом. Запуск vmstat 5 дает мне следующий вывод:
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr dd dd s1 -- in sy cs us sy id
0 0 21 2773568 815736 2 8 3 3 4 0 29 0 0 0 0 463 26 100 0 1 99
0 0 37 2641992 768704 2474 5583 0 0 0 0 0 0 19 0 0 499 4493 268 55 45 0
0 0 37 2641968 768928 2493 5616 0 0 0 0 0 0 19 0 0 499 4494 259 55 45 0
Система не простаивает и тратит приблизительно половину времени на системные вызовы и приблизительно половину на пользовательский код. Давайте обратимся к prstat, чтобы определить процессы, расходующие это время:
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
27494 root 1576K 1120K sleep 49 0 0:00:00 0.7% callfast/1
28891 root 4048K 2072K run 29 0 0:00:00 0.2% ld/1
28041 root 4792K 4424K cpu0 59 0 0:00:00 0.2% prstat/1
28887 root 1352K 960K sleep 19 0 0:00:00 0.1% gcc/1
28890 root 1320K 928K run 19 0 0:00:00 0.0% collect2/1
Не видно процессов, которые бы использовали этот вид процессорного времени, поэтому давайте более пристально посмотрим на то, какие системные вызовы извлекаются. Мы будем должны изменить наш оригинальный сценарий scount.d, нам уже не нужен орпеделенный адресат. Кроме того, даже при том, что я мог только собрать данные за некоторое время и затем прервать мою D программу, на сей раз я хотел бы чтобы она выполнялась точно 5 секунд и заканчивала работу самостоятельно. Чтобы добиться этого, я буду использовать провайдер profile. Я назову новый сценарий sc.d:
#pragma D option quiet
BEGIN
{
tick2 = 0;
}
tick-5s
/ tick2 /
{
exit (0);
}
tick-5s
/ !tick2 /
{
trace ("Collecting data\n");
tick2 = 1;
}
syscall:::entry
/ tick2 /
{
@[probefunc] = count();
}
Контрольная переменная tick2 позволяет нам собирать данные на втором включении пробы tick-5s. Поскольку вы можете повторить вызов, мы не можем пологаться на пробы profile, ждущие указанное время в первый раз, когда они включаются, таким образом мы хотим собрать данные за 5 секунд на первом включении tick-5s. При первом включении tick-5s, проба устанавливает переменную tick2 = 1, которая делает истиннным предикат sycall:::entry. Программа D собирает данные в течение 5 секунд и затем выходит на следующем включении tick-5s. Когда я запустил эту D программу против моей занятой системы, я получил следующий вывод:
Collecting data
lwp_continue 1
lwp_create 1
lwp_exit 1
lwp_kill 1
nanosleep 1
stat64 1
pset 3
pollsys 4
gtime 7
lwp_park 10
vfork 25
chmod 26
rusagesys 26
open64 50
getgid 52
getuid 52
umask 52
sysconfig 75
times 75
schedctl 77
fork1 103
lwp_self 103
unlink 125
rexit 127
exece 128
fcntl 129
read 155
waitsys 178
fstat64 206
write 210
getrlimit 228
memcntl 231
setcontext 257
llseek 259
ioctl 281
lseek 333
dup 377
fstat 384
resolvepath 640
munmap 665
getpid 860
lwp_sigmask 865
access 869
sigaction 1173
close 1375
open 1793
mmap 2441
stat 2479
brk 2950
Здесь большое количество системных вызовов, таким образом мы должны выбрать один из запросов системы для больших подробностей. Было 1793 запросов open за 5-секундный период. Давайте узнаем, какие файлы при открытии так заняли систему (oc.d):
syscall::open:entry
{
self->fnp = arg0;
}
syscall::open:return
/ self->fnp /
{
@[copyinstr(self->fnp)] = count();
self->fnp = 0;
}
Полученный вывод очень длинный, поэтому привожу лишь наиболее важные 10 последних строк:
...
/usr/sfw/lib/gcc/sparc-sun-solaris2.10/3.4.3/libgcc.a 54
/usr/sfw/lib/gcc/sparc-sun-solaris2.10/3.4.3/libgcc.so 54
/usr/sfw/lib/gcc/sparc-sun-solaris2.10/3.4.3/libgcc_eh.a 54
/usr/sfw/lib/gcc/sparc-sun-solaris2.10/3.4.3/libgcc_eh.so 54
/usr/sfw/lib/gcc/sparc-sun-solaris2.10/3.4.3/crt1.o 55
/usr/ccs/lib/libc.a 108
/usr/ccs/lib/libc.so 108
/lib/libc.so.1 110
/platform/SUNW,UltraAX-i2/lib/libc_psr.so.1 138
/var/ld/ld.config 138
Эти имена файлов, кажется, связаны с GNU C компилятором. Мы видим много вызовов open только для одной инстанции компилятора C. Интересно, сколько раз вызывается компилятор. Давайте проверим это (exc.d):
syscall::exec*:return
{
@[execname] = count();
}
Этот сценарий, запущенный в течение пяти секунд на моей занятой системе вывел следующее (удостоверьтесь, что вы ждете, пока DTrace не скажет вам, сколько проб было обнаружено прежде чем вы запустите 5-секундный счетчик):
cc1 30
collect2 30
gas 30
gcc 30
ld 30
Здесь множество вызовов компилятора C в течение 5-секундного периода. Мы должны узнать, кто инициализирует всю эту деятельность. Самый легкий способ сделать это - перечислить вызовы exec и их родителей (exlist.d):
#pragma D option quiet
syscall::exec*:entry
{
self->exn = execname;
}
syscall::exec*:return
/ self->exn != "" /
{
printf ("%s -> %s\n", self->exn, execname);
self->exn = 0;
}
Запуск этой D программы все разъясняет:
callfast -> gcc
gcc -> cc1
gcc -> gas
gcc -> collect2
collect2 -> ld
callfast -> gcc
gcc -> cc1
gcc -> gas
gcc -> collect2
collect2 -> ld
...
Процесс с именем callfast вызывает компилятор C неоднократно. Короткие процессы, сгенерированные компилятором C настолько кратковременны, что не оказывают существенное влияние на prstat. Однако DTrace легко нашел проблему.
Существуют разнообразные проблемы, которые подчас трудно решить, используя традиционные инструментальные средства и методы. DTrace позволяет добраться до сути этих проблем намного проще.
Примечание 1.
Вы должны знать, что я немного схитрил здесь, чтобы получить соответствующие результаты. В первый раз, когда вы выполняете команду, которая читает файл, файл читается в кэш. Каждый раз после этого, когда вы читаете файл, данные исходят уже из кэша, а не из диска. Очевидно, это испортило бы результаты. Чтобы компенсировать эту проблему, я написал программу на C, чтобы распределить достаточное пространство "кучи", чтобы использовать всю доступную реальную память. (Я не советую использовать эту методику на промышленной системе - это может повлиять на другие приложения.) Перед каждым запуском, я выполнял эту программу, чтобы сбросить на диск кэш файла:
main()
{
int i = 0;
while ((char *)malloc(1024*1024) != 0)
{
printf ("%d ", ++i);
}
exit(0);
}
Вам на самом деле не надо запускать программу, пока она не заканчивает свою работу (не исчерпывает виртуальную память). Если распределение замедляется, это значит что вы аннулировали все страницы памяти, которые использовались для кэша файла.
Примечание 2.
http://docs.sun.com/app/docs/doc/817-6223
Примечание 3.
Прежде, чем вы удивитесь тому что memory mapping намного лучше чем регулярные чтения файла, вы должны знать, что проектировщики Solaris знают об этом. Именно поэтому Solaris осуществляет регулярное чтение файла, используя алгоритмы пэйджинга. При данном методе используется немного меньше системного времени, но операции IO в обоих случаях столь же эффективны.
(вольный перевод статьи Чипа Беннета)
Обратные ссылки
URI этой записи для создания обратных ссылок (trackback)
Нет обратных ссылок
Комментарии
Показывать комментарии
(Как список | Древовидной структурой)
Очень интересно было прочесть данный материал!
Никак не могу серьезно заняться Solaris, но прочитав статью, любопытство берет вверх и в очередной раз хочу "сесть и уже не слазить с" Solaris.
Правда моего уровня пока не хватает для того, чтобы разобраться с системой на уровне системных вызовов. Я сам не программист (простой админ), поэтому с системными вызовами мне совсем не приходилось сталкиваться вплотную. Буду признателен, если посоветуете что-нибудь почитать, чтобы пришло понимание как всё работает "из глубины": системные вызовы (какие бывают, что делают) , линкование библиотек, взаимодействие с ядром и т.п....
Никак не могу серьезно заняться Solaris, но прочитав статью, любопытство берет вверх и в очередной раз хочу "сесть и уже не слазить с" Solaris.
Правда моего уровня пока не хватает для того, чтобы разобраться с системой на уровне системных вызовов. Я сам не программист (простой админ), поэтому с системными вызовами мне совсем не приходилось сталкиваться вплотную. Буду признателен, если посоветуете что-нибудь почитать, чтобы пришло понимание как всё работает "из глубины": системные вызовы (какие бывают, что делают) , линкование библиотек, взаимодействие с ядром и т.п....
что касается Solaris, то лучшие книги - Solaris Internals и
Solaris Performance and Tools.
Solaris Performance and Tools.
Категории
Быстрый поиск
Календарь
|
February '12 | |||||
| Mon | Tue | Wed | Thu | Fri | Sat | Sun |
| 1 | 2 | 3 | 4 | 5 | ||
| 6 | 7 | 8 | 9 | 10 | 11 | 12 |
| 13 | 14 | 15 | 16 | 17 | 18 | 19 |
| 20 | 21 | 22 | 23 | 24 | 25 | 26 |
| 27 | 28 | 29 | ||||
