Как сделать профилирование настенных часов с помощью dtrace? Или, как подсчитать не запущенные процессы с помощью провайдера профилей?

Я разрабатываю плагин для стороннего хост-приложения на OSX, используя С++. Он скомпилирован как .dylib. Я хочу профилировать свой плагин, когда он работает в хост-приложении.

К сожалению, хост вызывает код плагина со скоростью, которая зависит от (последнего) времени выполнения плагина. Это означает, что общее время процесса может значительно отличаться от реального времени. Таким образом, с профилировщиком выборки «время, затраченное» на плагин, на самом деле не связано ни с чем полезным, поскольку оно сравнивается только с кадрами стека, которые попадают в процесс. Если я улучшу производительность плагина, то шаблон выполнения плагина хостом изменится соответственно, и будет очень сложно измерить улучшения в плагине.

Я могу использовать инструменты, но, насколько я могу судить, я могу получить только относительное время по отношению к процессорному времени процесса.

Я использовал dtrace для получения гистограммы пользовательского стека хост-процесса:

#!/usr/sbin/dtrace -s

#pragma ustackframes 100
#pragma D option quiet

/* $1 is pid  */
/* $2 is sample rate in Hz (e.g. 100)  */
/* $3 is duration (e.g. '20s')  */

profile-$2
/pid == $1 && arg1/
{
  @[ustack()] = count();
}

tick-$3
{
  exit(0);
}

Это работает, но по-прежнему предоставляет выборки только относительно времени процесса, поскольку предикат сопоставляется только тогда, когда процесс находится в пользовательском пространстве. Даже удаление условия && arg1 для его запуска во время вызовов ядра процесса на самом деле не помогает.

Что я действительно хочу знать, так это то, сколько profile-n образцов привело к тому, что процесс вообще не запустился. Затем я могу сравнить число в моем плагине с общим количеством образцов и получить абсолютные значения образцов для функций моего плагина. Это заставляет меня задаться вопросом: можно ли предположить, что запрошенная частота дискретизации profile-n соблюдается? Могу ли я просто взять время * частоту дискретизации и использовать ее для расчета времени «вне процесса»? Я предположил, что, скажем, на частоте 1500 Гц он отбрасывал сэмплы и работал с какой-то другой, неизвестной частотой, но если я могу быть уверен, что это сэмплирование на частоте 1500 Гц, то я могу определить время «вне процесса».

В качестве альтернативы, существует ли известный способ профилирования настенных часов с помощью dtrace?


person davidA    schedule 01.02.2014    source источник


Ответы (1)


Это заставляет меня задаться вопросом: можно ли предположить, что запрошенная частота дискретизации profile-n соблюдается?

В Solaris это не гарантируется: в некоторых старых аппаратных средствах отсутствует необходимая поддержка прерываний произвольного разрешения на основе таймера. Я бы предположил, что такое же теоретическое ограничение применимо и к DTrace OS X.

В любом случае вы можете проверить разрешение таймера на себе. документация для поставщика профиля включает соответствующий сценарий и есть немного больше по теме. Вот еще один скрипт для решения вашего конкретного вопроса:

bash-3.2# cat test.d
uint64_t last;

profile-1500
/cpu == 0/
{
    now = timestamp;
    @ = lquantize(now - last, 500000, 800000, 30000);
    last = now;
}   

tick-1
/i++ == 10/
{
    exit(0);
}
bash-3.2# dtrace -qs test.d


           value  ------------- Distribution ------------- count    
          560000 |                                         0        
          590000 |@@@                                      1041     
          620000 |@@@@@@@@@@                               4288     
          650000 |@@@@@@@@@@@@@@                           5680     
          680000 |@@@@@@@@@@                               3999     
          710000 |@@@@                                     1451     
          740000 |                                         0        
          770000 |                                         0        
       >= 800000 |                                         1        

bash-3.2# 

Обратите внимание, что на практике вы должны производить выборку с частотой, равной простому числу: это предотвращает синхронизацию с другими регулярно запланированными системными действиями.

Следуя обсуждению в комментариях, вот как вы можете измерить прошедшее время внутри данной функции:

pid$target:mylib:myfunc:entry
/!self->depth/
{
    self->depth = ustackdepth;      /* beware recursion */
    self->start_time = timestamp;   /* for relative wall time calculations */
    self->start_vtime = vtimestamp; /* CPU time */      
}

pid$target:mylib:myfunc:return
/ustackdepth == self->depth/
{
    printf("%d ms (real) %d ms (CPU)\n",
        (timestamp - self->start_time) / 1000000,
        (vtimestamp - self->start_vtime) / 1000000);
    self->depth = 0;
}   

Если функция вызывается с высокой частотой, то, очевидно, вы можете поддерживать агрегацию прошедшего времени, например. для расчета средних затрат функции.

Вполне возможно выполнить подобное упражнение для всех функций в вашей библиотеке, хотя устранение ложных результатов от рекурсии и оптимизации хвостовых вызовов может оказаться весьма обременительной задачей. Чтобы быть более полезным, вы, вероятно, также захотите исключить из стоимости функции время, затрачиваемое на вызов стека; это делает работу еще более сложной (но не невозможной). Таким образом, вооружившись указанными выше средствами для создания объективного эталона, я был бы более склонен придерживаться подхода профилирования, возможно, что-то вроде

# cat sample.d 
profile-997
/pid == $target && arg1 >= $1 && arg1 < $2/
{
    @[ufunc(arg1)] = count();
}

END
{
    trunc(@,5);
    exit(0);
}
#

Это фиксирует пять наиболее часто встречающихся функций в данной области памяти. Например (и используя pmap в Solaris для поиска libc),

# dtrace -qs sample.d -p `pgrep -n firefox` 0xfc090000 0xfc200000
^C

  libc.so.1`mutex_lock_impl                                        35
  libc.so.1`clear_lockbyte                                         46
  libc.so.1`gettimeofday                                           71
  libc.so.1`memset                                                 73
  libc.so.1`memcpy                                                170
# 

Это оказывается довольно хорошей иллюстрацией преимущества выборки: memcpy() и memset() кодируются вручную на ассемблере --- т. е. мы обнаруживаем, что самые трудоемкие функции уже оптимизированы.

person Robert Harris    schedule 02.02.2014
comment
Спасибо, на OSX Mavericks это дает мне 13950/16451, что составляет 650000. Другой запуск дает 16114/16451 - очень узкий разброс. Общее количество всегда кажется около 16000, обычно 16451, кстати. Спасибо за подсказку о частоте простых чисел. - person davidA; 03.02.2014
comment
Это должно дать вам некоторую уверенность в вашей выборке: вы профилируете с частотой около 1496 Гц вместо 1500 Гц с узким распределением интервалов. Я не совсем понял, что вы имели в виду под остальной частью вашего вопроса. Что именно вы подразумеваете под профилированием настенных часов? Вы хотите измерить долю времени настенных часов (в отличие от времени процессора), которое конкретный процесс тратит в данной библиотеке? Если да, вас интересует, когда функции из этой библиотеки появляются в стеке вызовов процесса или когда счетчик программы процесса находится в текстовом разделе библиотеки? - person Robert Harris; 03.02.2014
comment
Я полагаю, что ищу измерение производительности библиотеки в реальном времени. Код (моей) библиотеки будет вызываться с фиксированной частотой, но вызывающая среда хоста может иметь переменное время ЦП до и после каждого вызова, поэтому сравнение числа выборок библиотеки и хоста не очень полезно. Я также строю график с помощью FlameGraph, который (в настоящее время) является относительным. Моя цель на самом деле состоит в том, чтобы выяснить, действительно ли улучшения в моей библиотеке являются реальными улучшениями. Я считаю, что относительные измерения инструментов (и dtrace, который я сейчас использую) сложно использовать в данном конкретном случае. - person davidA; 04.02.2014
comment
Однако, как вы сказали, теперь у меня есть некоторая уверенность в моей выборке, поэтому я могу использовать ее для определения абсолютного времени (насколько этот метод выборки позволяет такое вычисление), затраченного на каждую библиотечную функцию. - person davidA; 04.02.2014
comment
Итак, каково ваше определение измерения производительности библиотеки в реальном времени? Прошедшее время (на стене или ЦП) для каждого вызова библиотеки? Время для каждой функции? Что-то другое? - person Robert Harris; 04.02.2014
comment
Справедливый вопрос - плагин (то есть библиотека) имеет единственную точку входа, которая вызывается периодически, поэтому меня интересуют два набора вещей: 1. сколько времени ЦП тратит в плагине - это дает мне некоторое представление стоимости плагина относительно других плагинов; 2. внутри плагина какие функции самые затратные по времени. Я пытаюсь определить, какие функции плагина могут получить наибольшую пользу от оптимизации, чтобы сократить общее время, которое ЦП тратит на плагин. - person davidA; 04.02.2014
comment
Относительные измерения действительно помогают, но они измеряются относительно того, что я не могу контролировать, — поведения хозяина. Так как это изменилось, у меня нет возможности сравнивать испытания, если у меня нет фиксированного эталона для сравнения (например, время стены или известное общее количество образцов). - person davidA; 04.02.2014