Быстрый и грязный способ профилирования вашего кода
https://stackoverflow.com/questions/61278
-
09-06-2019 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianВопрос
Какой метод вы используете, когда хотите получить данные о производительности для конкретных путей кода?
Решение
Этот метод имеет несколько ограничений, но я все равно нахожу его очень полезным.Я заранее перечислю ограничения (о которых я знаю) и позволю любому, кто захочет его использовать, делать это на свой страх и риск.
- В первоначальной версии, которую я опубликовал, было завышено время, затраченное на рекурсивные вызовы (как указано в комментариях к ответу).
- Это не потокобезопасно, оно не было потокобезопасным до того, как я добавил код для игнорирования рекурсии, и теперь оно еще менее потокобезопасно.
- Хотя это очень эффективно, если вызывать его много раз (миллионы), это окажет ощутимое влияние на результат, так что области, которые вы измеряете, займут больше времени, чем те, которые вы не измеряете.
Я использую этот класс, когда текущая проблема не оправдывает профилирование всего моего кода или я получаю некоторые данные из профилировщика, которые хочу проверить.По сути, он суммирует время, которое вы потратили на определенный блок, и в конце программы выводит его в поток отладки (доступен для просмотра с помощью DbgView), включая количество раз, когда код был выполнен (и, конечно, среднее затраченное время)).
#pragma once
#include <tchar.h>
#include <windows.h>
#include <sstream>
#include <boost/noncopyable.hpp>
namespace scope_timer {
class time_collector : boost::noncopyable {
__int64 total;
LARGE_INTEGER start;
size_t times;
const TCHAR* name;
double cpu_frequency()
{ // cache the CPU frequency, which doesn't change.
static double ret = 0; // store as double so devision later on is floating point and not truncating
if (ret == 0) {
LARGE_INTEGER freq;
QueryPerformanceFrequency(&freq);
ret = static_cast<double>(freq.QuadPart);
}
return ret;
}
bool in_use;
public:
time_collector(const TCHAR* n)
: times(0)
, name(n)
, total(0)
, start(LARGE_INTEGER())
, in_use(false)
{
}
~time_collector()
{
std::basic_ostringstream<TCHAR> msg;
msg << _T("scope_timer> ") << name << _T(" called: ");
double seconds = total / cpu_frequency();
double average = seconds / times;
msg << times << _T(" times total time: ") << seconds << _T(" seconds ")
<< _T(" (avg ") << average <<_T(")\n");
OutputDebugString(msg.str().c_str());
}
void add_time(__int64 ticks)
{
total += ticks;
++times;
in_use = false;
}
bool aquire()
{
if (in_use)
return false;
in_use = true;
return true;
}
};
class one_time : boost::noncopyable {
LARGE_INTEGER start;
time_collector* collector;
public:
one_time(time_collector& tc)
{
if (tc.aquire()) {
collector = &tc;
QueryPerformanceCounter(&start);
}
else
collector = 0;
}
~one_time()
{
if (collector) {
LARGE_INTEGER end;
QueryPerformanceCounter(&end);
collector->add_time(end.QuadPart - start.QuadPart);
}
}
};
}
// Usage TIME_THIS_SCOPE(XX); where XX is a C variable name (can begin with a number)
#define TIME_THIS_SCOPE(name) \
static scope_timer::time_collector st_time_collector_##name(_T(#name)); \
scope_timer::one_time st_one_time_##name(st_time_collector_##name)
Другие советы
Я создаю свои профили, создавая два класса: cProfile и cProfileManager.
cProfileManager будет содержать все данные, полученные в результате cProfile.
cProfile к которым предъявляются следующие требования:
cProfileимеет конструктор, который инициализирует текущее время.cProfileимеет деконструктор, который отправляет общее время, в течение которого класс был живcProfileManager
Чтобы использовать эти классы профилей, я сначала создаю экземпляр cProfileManager.Затем я помещаю блок кода, который я хочу профилировать, в фигурные скобки.Внутри фигурных скобок я создаю cProfile пример.Когда блок кода заканчивается, cProfile отправит время, затраченное на завершение работы блока кода, в cProfileManager.
Пример кода Вот пример кода (упрощенный):
class cProfile
{
cProfile()
{
TimeStart = GetTime();
};
~cProfile()
{
ProfileManager->AddProfile (GetTime() - TimeStart);
}
float TimeStart;
}
Для использования cProfile, Я бы сделал что -то вроде этого:
int main()
{
printf("Start test");
{
cProfile Profile;
Calculate();
}
ProfileManager->OutputData();
}
или это:
void foobar()
{
cProfile ProfileFoobar;
foo();
{
cProfile ProfileBarCheck;
while (bar())
{
cProfile ProfileSpam;
spam();
}
}
}
Техническое примечание
Этот код на самом деле является злоупотреблением тем, как работают scoping, конструкторы и деконструкторы C++. cProfile существует только внутри области действия блока (блока кода, который мы хотим протестировать).Как только программа покинет область действия блока, cProfile записывает результат.
Дополнительные усовершенствования
Вы можете добавить строковый параметр в конструктор, чтобы сделать что-то вроде этого:cProfile Profile ("Профиль для сложных вычислений");
Вы можете использовать макрос, чтобы сделать код более чистым (будьте осторожны и не злоупотребляйте этим.В отличие от других наших злоупотреблений языком, макросы могут быть опасны при использовании).
Пример:
#определить START_PROFILE Профиль cProfile();{ #определить КОНЕЧНЫЙ ФАЙЛ_ПРОФИЛЯ }
cProfileManagerможет проверить, сколько раз вызывается блок кода.Но вам понадобится идентификатор для блока кода.Первое усовершенствование может помочь идентифицировать блок.Это может быть полезно в случаях, когда код, который вы хотите профилировать, находится внутри цикла (как во втором примере выше).Вы также можете добавить среднее, самое быстрое и продолжительное время выполнения блока кода.Не забудьте добавить флажок пропускать профилирование, если вы находитесь в режиме отладки.
Обратите внимание, что все нижеследующее написано специально для Windows.
У меня также есть класс timer, который я написал для быстрого профилирования, который использует QueryPerformanceCounter() для получения высокоточных таймингов, но с небольшой разницей.Мой класс timer не выводит значение прошедшего времени, когда объект Timer выходит за пределы области видимости.Вместо этого он накапливает затраченное время в коллекции.Я добавил статическую функцию-член, Dump(), которая создает таблицу прошедшего времени, отсортированную по категории времени (указанной в конструкторе Timer в виде строки) вместе с некоторым статистическим анализом, таким как среднее затраченное время, стандартное отклонение, max и min.Я также добавил статическую функцию-член Clear(), которая очищает коллекцию и позволяет вам начать все сначала.
Как использовать класс Timer (псевдокод):
int CInsertBuffer::Read(char* pBuf)
{
// TIMER NOTES: Avg Execution Time = ~1 ms
Timer timer("BufferRead");
: :
return -1;
}
Выборочный вывод :
Timer Precision = 418.0095 ps
=== Item Trials Ttl Time Avg Time Mean Time StdDev ===
AddTrade 500 7 ms 14 us 12 us 24 us
BufferRead 511 1:19.25 0.16 s 621 ns 2.48 s
BufferWrite 516 511 us 991 ns 482 ns 11 us
ImportPos Loop 1002 18.62 s 19 ms 77 us 0.51 s
ImportPosition 2 18.75 s 9.38 s 16.17 s 13.59 s
Insert 515 4.26 s 8 ms 5 ms 27 ms
recv 101 18.54 s 0.18 s 2603 ns 1.63 s
файл Timer.inl :
#include <map>
#include "x:\utils\stlext\stringext.h"
#include <iterator>
#include <set>
#include <vector>
#include <numeric>
#include "x:\utils\stlext\algorithmext.h"
#include <math.h>
class Timer
{
public:
Timer(const char* name)
{
label = std::safe_string(name);
QueryPerformanceCounter(&startTime);
}
virtual ~Timer()
{
QueryPerformanceCounter(&stopTime);
__int64 clocks = stopTime.QuadPart-startTime.QuadPart;
double elapsed = (double)clocks/(double)TimerFreq();
TimeMap().insert(std::make_pair(label,elapsed));
};
static std::string Dump(bool ClipboardAlso=true)
{
static const std::string loc = "Timer::Dump";
if( TimeMap().empty() )
{
return "No trials\r\n";
}
std::string ret = std::formatstr("\r\n\r\nTimer Precision = %s\r\n\r\n", format_elapsed(1.0/(double)TimerFreq()).c_str());
// get a list of keys
typedef std::set<std::string> keyset;
keyset keys;
std::transform(TimeMap().begin(), TimeMap().end(), std::inserter(keys, keys.begin()), extract_key());
size_t maxrows = 0;
typedef std::vector<std::string> strings;
strings lines;
static const size_t tabWidth = 9;
std::string head = std::formatstr("=== %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s ===", tabWidth*2, tabWidth*2, "Item", tabWidth, tabWidth, "Trials", tabWidth, tabWidth, "Ttl Time", tabWidth, tabWidth, "Avg Time", tabWidth, tabWidth, "Mean Time", tabWidth, tabWidth, "StdDev");
ret += std::formatstr("\r\n%s\r\n", head.c_str());
if( ClipboardAlso )
lines.push_back("Item\tTrials\tTtl Time\tAvg Time\tMean Time\tStdDev\r\n");
// dump the values for each key
{for( keyset::iterator key = keys.begin(); keys.end() != key; ++key )
{
time_type ttl = 0;
ttl = std::accumulate(TimeMap().begin(), TimeMap().end(), ttl, accum_key(*key));
size_t num = std::count_if( TimeMap().begin(), TimeMap().end(), match_key(*key));
if( num > maxrows )
maxrows = num;
time_type avg = ttl / num;
// compute mean
std::vector<time_type> sortedTimes;
std::transform_if(TimeMap().begin(), TimeMap().end(), std::inserter(sortedTimes, sortedTimes.begin()), extract_val(), match_key(*key));
std::sort(sortedTimes.begin(), sortedTimes.end());
size_t mid = (size_t)floor((double)num/2.0);
double mean = ( num > 1 && (num % 2) != 0 ) ? (sortedTimes[mid]+sortedTimes[mid+1])/2.0 : sortedTimes[mid];
// compute variance
double sum = 0.0;
if( num > 1 )
{
for( std::vector<time_type>::iterator timeIt = sortedTimes.begin(); sortedTimes.end() != timeIt; ++timeIt )
sum += pow(*timeIt-mean,2.0);
}
// compute std dev
double stddev = num > 1 ? sqrt(sum/((double)num-1.0)) : 0.0;
ret += std::formatstr(" %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s\r\n", tabWidth*2, tabWidth*2, key->c_str(), tabWidth, tabWidth, std::formatstr("%d",num).c_str(), tabWidth, tabWidth, format_elapsed(ttl).c_str(), tabWidth, tabWidth, format_elapsed(avg).c_str(), tabWidth, tabWidth, format_elapsed(mean).c_str(), tabWidth, tabWidth, format_elapsed(stddev).c_str());
if( ClipboardAlso )
lines.push_back(std::formatstr("%s\t%s\t%s\t%s\t%s\t%s\r\n", key->c_str(), std::formatstr("%d",num).c_str(), format_elapsed(ttl).c_str(), format_elapsed(avg).c_str(), format_elapsed(mean).c_str(), format_elapsed(stddev).c_str()));
}
}
ret += std::formatstr("%s\r\n", std::string(head.length(),'=').c_str());
if( ClipboardAlso )
{
// dump header row of data block
lines.push_back("");
{
std::string s;
for( keyset::iterator key = keys.begin(); key != keys.end(); ++key )
{
if( key != keys.begin() )
s.append("\t");
s.append(*key);
}
s.append("\r\n");
lines.push_back(s);
}
// blow out the flat map of time values to a seperate vector of times for each key
typedef std::map<std::string, std::vector<time_type> > nodematrix;
nodematrix nodes;
for( Times::iterator time = TimeMap().begin(); time != TimeMap().end(); ++time )
nodes[time->first].push_back(time->second);
// dump each data point
for( size_t row = 0; row < maxrows; ++row )
{
std::string rowDump;
for( keyset::iterator key = keys.begin(); key != keys.end(); ++key )
{
if( key != keys.begin() )
rowDump.append("\t");
if( nodes[*key].size() > row )
rowDump.append(std::formatstr("%f", nodes[*key][row]));
}
rowDump.append("\r\n");
lines.push_back(rowDump);
}
// dump to the clipboard
std::string dump;
for( strings::iterator s = lines.begin(); s != lines.end(); ++s )
{
dump.append(*s);
}
OpenClipboard(0);
EmptyClipboard();
HGLOBAL hg = GlobalAlloc(GMEM_MOVEABLE, dump.length()+1);
if( hg != 0 )
{
char* buf = (char*)GlobalLock(hg);
if( buf != 0 )
{
std::copy(dump.begin(), dump.end(), buf);
buf[dump.length()] = 0;
GlobalUnlock(hg);
SetClipboardData(CF_TEXT, hg);
}
}
CloseClipboard();
}
return ret;
}
static void Reset()
{
TimeMap().clear();
}
static std::string format_elapsed(double d)
{
if( d < 0.00000001 )
{
// show in ps with 4 digits
return std::formatstr("%0.4f ps", d * 1000000000000.0);
}
if( d < 0.00001 )
{
// show in ns
return std::formatstr("%0.0f ns", d * 1000000000.0);
}
if( d < 0.001 )
{
// show in us
return std::formatstr("%0.0f us", d * 1000000.0);
}
if( d < 0.1 )
{
// show in ms
return std::formatstr("%0.0f ms", d * 1000.0);
}
if( d <= 60.0 )
{
// show in seconds
return std::formatstr("%0.2f s", d);
}
if( d < 3600.0 )
{
// show in min:sec
return std::formatstr("%01.0f:%02.2f", floor(d/60.0), fmod(d,60.0));
}
// show in h:min:sec
return std::formatstr("%01.0f:%02.0f:%02.2f", floor(d/3600.0), floor(fmod(d,3600.0)/60.0), fmod(d,60.0));
}
private:
static __int64 TimerFreq()
{
static __int64 freq = 0;
static bool init = false;
if( !init )
{
LARGE_INTEGER li;
QueryPerformanceFrequency(&li);
freq = li.QuadPart;
init = true;
}
return freq;
}
LARGE_INTEGER startTime, stopTime;
std::string label;
typedef std::string key_type;
typedef double time_type;
typedef std::multimap<key_type, time_type> Times;
// static Times times;
static Times& TimeMap()
{
static Times times_;
return times_;
}
struct extract_key : public std::unary_function<Times::value_type, key_type>
{
std::string operator()(Times::value_type const & r) const
{
return r.first;
}
};
struct extract_val : public std::unary_function<Times::value_type, time_type>
{
time_type operator()(Times::value_type const & r) const
{
return r.second;
}
};
struct match_key : public std::unary_function<Times::value_type, bool>
{
match_key(key_type const & key_) : key(key_) {};
bool operator()(Times::value_type const & rhs) const
{
return key == rhs.first;
}
private:
match_key& operator=(match_key&) { return * this; }
const key_type key;
};
struct accum_key : public std::binary_function<time_type, Times::value_type, time_type>
{
accum_key(key_type const & key_) : key(key_), n(0) {};
time_type operator()(time_type const & v, Times::value_type const & rhs) const
{
if( key == rhs.first )
{
++n;
return rhs.second + v;
}
return v;
}
private:
accum_key& operator=(accum_key&) { return * this; }
const Times::key_type key;
mutable size_t n;
};
};
файл stringext.h (предоставляет функцию formatstr()):
namespace std
{
/* ---
Formatted Print
template<class C>
int strprintf(basic_string<C>* pString, const C* pFmt, ...);
template<class C>
int vstrprintf(basic_string<C>* pString, const C* pFmt, va_list args);
Returns :
# characters printed to output
Effects :
Writes formatted data to a string. strprintf() works exactly the same as sprintf(); see your
documentation for sprintf() for details of peration. vstrprintf() also works the same as sprintf(),
but instead of accepting a variable paramater list it accepts a va_list argument.
Requires :
pString is a pointer to a basic_string<>
--- */
template<class char_type> int vprintf_generic(char_type* buffer, size_t bufferSize, const char_type* format, va_list argptr);
template<> inline int vprintf_generic<char>(char* buffer, size_t bufferSize, const char* format, va_list argptr)
{
# ifdef SECURE_VSPRINTF
return _vsnprintf_s(buffer, bufferSize-1, _TRUNCATE, format, argptr);
# else
return _vsnprintf(buffer, bufferSize-1, format, argptr);
# endif
}
template<> inline int vprintf_generic<wchar_t>(wchar_t* buffer, size_t bufferSize, const wchar_t* format, va_list argptr)
{
# ifdef SECURE_VSPRINTF
return _vsnwprintf_s(buffer, bufferSize-1, _TRUNCATE, format, argptr);
# else
return _vsnwprintf(buffer, bufferSize-1, format, argptr);
# endif
}
template<class Type, class Traits>
inline int vstringprintf(basic_string<Type,Traits> & outStr, const Type* format, va_list args)
{
// prologue
static const size_t ChunkSize = 1024;
size_t curBufSize = 0;
outStr.erase();
if( !format )
{
return 0;
}
// keep trying to write the string to an ever-increasing buffer until
// either we get the string written or we run out of memory
while( bool cont = true )
{
// allocate a local buffer
curBufSize += ChunkSize;
std::ref_ptr<Type> localBuffer = new Type[curBufSize];
if( localBuffer.get() == 0 )
{
// we ran out of memory -- nice goin'!
return -1;
}
// format output to local buffer
int i = vprintf_generic(localBuffer.get(), curBufSize * sizeof(Type), format, args);
if( -1 == i )
{
// the buffer wasn't big enough -- try again
continue;
}
else if( i < 0 )
{
// something wierd happened -- bail
return i;
}
// if we get to this point the string was written completely -- stop looping
outStr.assign(localBuffer.get(),i);
return i;
}
// unreachable code
return -1;
};
// provided for backward-compatibility
template<class Type, class Traits>
inline int vstrprintf(basic_string<Type,Traits> * outStr, const Type* format, va_list args)
{
return vstringprintf(*outStr, format, args);
}
template<class Char, class Traits>
inline int stringprintf(std::basic_string<Char, Traits> & outString, const Char* format, ...)
{
va_list args;
va_start(args, format);
int retval = vstringprintf(outString, format, args);
va_end(args);
return retval;
}
// old function provided for backward-compatibility
template<class Char, class Traits>
inline int strprintf(std::basic_string<Char, Traits> * outString, const Char* format, ...)
{
va_list args;
va_start(args, format);
int retval = vstringprintf(*outString, format, args);
va_end(args);
return retval;
}
/* ---
Inline Formatted Print
string strprintf(const char* Format, ...);
Returns :
Formatted string
Effects :
Writes formatted data to a string. formatstr() works the same as sprintf(); see your
documentation for sprintf() for details of operation.
--- */
template<class Char>
inline std::basic_string<Char> formatstr(const Char * format, ...)
{
std::string outString;
va_list args;
va_start(args, format);
vstringprintf(outString, format, args);
va_end(args);
return outString;
}
};
Файл algorithmext.h (предоставляет функцию transform_if()) :
/* ---
Transform
25.2.3
template<class InputIterator, class OutputIterator, class UnaryOperation, class Predicate>
OutputIterator transform_if(InputIterator first, InputIterator last, OutputIterator result, UnaryOperation op, Predicate pred)
template<class InputIterator1, class InputIterator2, class OutputIterator, class BinaryOperation, class Predicate>
OutputIterator transform_if(InputIterator first, InputIterator last, OutputIterator result, BinaryOperation binary_op, Predicate pred)
Requires:
T is of type EqualityComparable (20.1.1)
op and binary_op have no side effects
Effects :
Assigns through every iterator i in the range [result, result + (last1-first1)) a new corresponding value equal to one of:
1: op( *(first1 + (i - result))
2: binary_op( *(first1 + (i - result), *(first2 + (i - result))
Returns :
result + (last1 - first1)
Complexity :
At most last1 - first1 applications of op or binary_op
--- */
template<class InputIterator, class OutputIterator, class UnaryFunction, class Predicate>
OutputIterator transform_if(InputIterator first,
InputIterator last,
OutputIterator result,
UnaryFunction f,
Predicate pred)
{
for (; first != last; ++first)
{
if( pred(*first) )
*result++ = f(*first);
}
return result;
}
template<class InputIterator1, class InputIterator2, class OutputIterator, class BinaryOperation, class Predicate>
OutputIterator transform_if(InputIterator1 first1,
InputIterator1 last1,
InputIterator2 first2,
OutputIterator result,
BinaryOperation binary_op,
Predicate pred)
{
for (; first1 != last1 ; ++first1, ++first2)
{
if( pred(*first1) )
*result++ = binary_op(*first1,*first2);
}
return result;
}
Ну, у меня есть два фрагмента кода.В псевдокод они выглядят так (это упрощенная версия, я использую Частота выполнения запросов на самом деле):
Первый фрагмент:
Timer timer = new Timer
timer.Start
Второй фрагмент:
timer.Stop
show elapsed time
Немного горячих клавиш кунг-фу, и я могу сказать, сколько времени этот фрагмент кода отнял у моего процессора.
Статья Профилировщик кода и его оптимизация содержит много информации о профилировании кода на C ++, а также бесплатную ссылку для скачивания программы / класса, которая покажет вам графическое представление различных путей / методов кода.
У меня есть класс быстрого профилирования, который можно использовать при профилировании даже в самых узких внутренних циклах.Акцент делается на предельно малом весе и простом коде.Класс выделяет двумерный массив фиксированного размера.Затем я добавляю вызовы "контрольной точки" повсюду.Когда контрольная точка N достигается сразу после контрольной точки M, я добавляю прошедшее время (в микросекундах) к элементу массива [M, N].Поскольку это предназначено для профилирования узких циклов, у меня также есть вызов "начало итерации", который сбрасывает переменную "последняя контрольная точка".В конце теста dumpResults() call выдает список всех пар контрольных точек, которые следовали друг за другом, вместе с общим учтенным и неучтенным временем.
Я написал простой кроссплатформенный класс под названием нанотаймер по этой причине.Цель состояла в том, чтобы быть как можно более легким, чтобы не влиять на фактическую производительность кода, добавляя слишком много инструкций и тем самым влияя на кэш команд.Он способен достигать микросекундной точности в Windows, Mac и linux (и, возможно, в некоторых вариантах unix).
Основное использование:
plf::timer t;
timer.start();
// stuff
double elapsed = t.get_elapsed_ns(); // Get nanoseconds
функция start() также перезапускает таймер при необходимости."Приостановка" таймера может быть достигнута путем сохранения прошедшего времени, затем перезапуска таймера при "снятии с паузы" и добавления к сохраненному результату при следующей проверке прошедшего времени.
