性能跟踪是 Easylogging++ 其中一个非常显著的功能,而且使用起来也十分简单。如果在Windows平台下使用性能跟踪的话,其原理是基于 Windows API函数 GetSystemTimeAsFileTime 实现的。关于API函数 GetSystemTimeAsFileTime 的精度讨论,网上众说纷纭,根据我自己的经验,个人认为在毫秒级的话,这个函数还是可以用的,其精准度和 Sleep 函数差不多。虽然在 Easylogging++ 的介绍中,该功能可以跟踪到微妙级别,不过我在实际使用中发现,微妙级别基本都不正确。所以,在Windows平台下使用性能跟踪的话,建议只在精度为毫秒级(请根据实际情况选择精度)的情况下使用。
如果你想在你的程序中使用性能跟踪功能,只需要在你想要开始跟踪的地方加上下面其中一个宏定义即可:
TIMED_FUNC(obj-name),主要用来检测整个函数的性能,一般放在函数首行。
TIMED_SCOPE(obj-name, block-name),主要用来检测一定范围内的代码性能。
TIMED_BLOCK(obj-name, block-name),主要用来检测某一段代码块的性能。
其实上面三个宏定义是差不多的,都是使用了 el::base::PerformanceTracker 这个类,而日志的输出也都是在这个类的析构函数中控制的,使用时灵活运用就可以了。另外,如果把宏 TIMED_SCOPE(obj-name, block-name) 中的参数 block-name 用函数名称来赋值之后就变成了宏 TIMED_FUNC(obj-name) ,而宏 TIMED_BLOCK(obj-name, block-name) 的定义实际上就是在一个只有一次循环的 For 循环中使用了宏 TIMED_SCOPE(obj-name, block-name) 的定义。这里特别说一下 TIMED_BLOCK(obj-name, block-name) 这个宏定义,下面是其源码:
- #define TIMED_BLOCK(obj, blockName) for (struct { int i; el::base::PerformanceTracker timer; } obj = { 0, \
- el::base::PerformanceTracker(blockName, ELPP_MIN_UNIT) }; obj.i < 1; ++obj.i)
#define TIMED_BLOCK(obj, blockName) for (struct { int i; el::base::PerformanceTracker timer; } obj = { 0, \
el::base::PerformanceTracker(blockName, ELPP_MIN_UNIT) }; obj.i < 1; ++obj.i)
这段代码中在 Visual Studio 的C++编译器里是编译不过的,如果直接就调用宏
TIMED_BLOCK(obj-name, block-name) ,编译器会提示“error C2332: “struct”: 缺少标记名”之类的错误,这种在循环里定义一个结构体变量的用法在 Visual Studio 里需要用C语言编译器才能编译通过。所以,为了能在C++代码里面能够直接就调用宏 TIMED_BLOCK(obj-name, block-name) ,需要对这段代码做一个小改动,就是把结构体的定义放在循环外面即可:
- typedef struct st_PerformanceTracker{
- int i;
- el::base::PerformanceTracker timer;
- } TIME_BLOCK_PERFORMANCE_TRACKER;
- #define TIMED_BLOCK(obj, blockName) for (TIME_BLOCK_PERFORMANCE_TRACKER obj = { 0, \
- el::base::PerformanceTracker(blockName, ELPP_MIN_UNIT) }; obj.i < 1; ++obj.i)
typedef struct st_PerformanceTracker{
int i;
el::base::PerformanceTracker timer;
} TIME_BLOCK_PERFORMANCE_TRACKER;
#define TIMED_BLOCK(obj, blockName) for (TIME_BLOCK_PERFORMANCE_TRACKER obj = { 0, \
el::base::PerformanceTracker(blockName, ELPP_MIN_UNIT) }; obj.i < 1; ++obj.i)
下面的代码演示了
上述三个实现性能跟踪的宏定义最简单的一个用法:
- #include "easylogging++.h"
- INITIALIZE_EASYLOGGINGPP
- void PerformanceTest()
- {
- /// TIMED_FUNC会统计其后续所有代码的执行时间
- TIMED_FUNC(timerFunObj);
- Sleep(100);
- /// TIMED_SCOPE会统计其后续所有代码的执行时间
- TIMED_SCOPE(timerScopeObj, "TIMED_SCOPE_Test");
- Sleep(100);
- /// TIMED_BLOCK只会统计花括号{}里所有代码的执行时间
- TIMED_BLOCK(timerBlockObj, "TIMED_BLOCK_Test")
- {
- Sleep(100);
- }
- Sleep(100);
- }
- int main(int argc, char** argv)
- {
- PerformanceTest();
- system("pause");
- return 0;
- }
#include "easylogging++.h"
INITIALIZE_EASYLOGGINGPP
void PerformanceTest()
{
/// TIMED_FUNC会统计其后续所有代码的执行时间
TIMED_FUNC(timerFunObj);
Sleep(100);
/// TIMED_SCOPE会统计其后续所有代码的执行时间
TIMED_SCOPE(timerScopeObj, "TIMED_SCOPE_Test");
Sleep(100);
/// TIMED_BLOCK只会统计花括号{}里所有代码的执行时间
TIMED_BLOCK(timerBlockObj, "TIMED_BLOCK_Test")
{
Sleep(100);
}
Sleep(100);
}
int main(int argc, char** argv)
{
PerformanceTest();
system("pause");
return 0;
}
从演示代码中可以看到,三个宏定义中的参数是可以随便命名的,其中的参数
block-name 会在日志中输出,可以标识某个宏定义的输出;而参数 obj-name 并不会在日志中输出,它主要是用在下面两个宏定义中:
PERFORMANCE_CHECKPOINT(timed-block-obj-name)
PERFORMANCE_CHECKPOINT_WITH_ID(timed-block-obj-name, id)
- #include "easylogging++.h"
- INITIALIZE_EASYLOGGINGPP
- int main(int argc, char** argv)
- {
- /// 用花括号是为了使宏TIMED_SCOPE能够输出日志,不然类el::base::PerformanceTracker无法进行析构
- {
- /// TIMED_SCOPE会统计其后续所有代码的执行时间
- TIMED_SCOPE(timerScopeObj, "TIMED_SCOPE_Test");
- Sleep(100);
- /// PERFORMANCE_CHECKPOINT会统计和TIMED_SCOPE之间所有代码的执行时间
- PERFORMANCE_CHECKPOINT(timerScopeObj);
- Sleep(100);
- /// PERFORMANCE_CHECKPOINT_WITH_ID会统计和TIMED_SCOPE之间所有代码的执行时间
- /// 参数"mychkpnt"可以标识该宏定义的输出
- /// 另外计算出和前面最近一次使用PERFORMANCE_CHECKPOINT之间所有代码的执行时间
- PERFORMANCE_CHECKPOINT_WITH_ID(timerScopeObj, "mychkpnt");
- Sleep(100);
- }
- system("pause");
- return 0;
- }
#include "easylogging++.h"
INITIALIZE_EASYLOGGINGPP
int main(int argc, char** argv)
{
/// 用花括号是为了使宏TIMED_SCOPE能够输出日志,不然类el::base::PerformanceTracker无法进行析构
{
/// TIMED_SCOPE会统计其后续所有代码的执行时间
TIMED_SCOPE(timerScopeObj, "TIMED_SCOPE_Test");
Sleep(100);
/// PERFORMANCE_CHECKPOINT会统计和TIMED_SCOPE之间所有代码的执行时间
PERFORMANCE_CHECKPOINT(timerScopeObj);
Sleep(100);
/// PERFORMANCE_CHECKPOINT_WITH_ID会统计和TIMED_SCOPE之间所有代码的执行时间
/// 参数"mychkpnt"可以标识该宏定义的输出
/// 另外计算出和前面最近一次使用PERFORMANCE_CHECKPOINT之间所有代码的执行时间
PERFORMANCE_CHECKPOINT_WITH_ID(timerScopeObj, "mychkpnt");
Sleep(100);
}
system("pause");
return 0;
}
- #include "easylogging++.h"
- INITIALIZE_EASYLOGGINGPP
- class MyPerformanceTrackingOutput : public el::PerformanceTrackingCallback
- {
- public:
- MyPerformanceTrackingOutput()
- {
- /// 禁用默认的性能日志输出格式
- el::PerformanceTrackingCallback* defaultCallback =
- el::Helpers::performanceTrackingCallback<el::base::DefaultPerformanceTrackingCallback>("DefaultPerformanceTrackingCallback");
- defaultCallback->setEnabled(false);
- }
- virtual ~MyPerformanceTrackingOutput()
- {
- /// 恢复默认的性能日志输出格式
- el::PerformanceTrackingCallback* defaultCallback =
- el::Helpers::performanceTrackingCallback<el::base::DefaultPerformanceTrackingCallback>("DefaultPerformanceTrackingCallback");
- defaultCallback->setEnabled(true);
- }
- protected:
- /// 自定义性能日志输出格式
- void handle(const el::PerformanceTrackingData* data)
- {
- if (data->firstCheckpoint())
- {
- return; /// 跳过第一次PERFORMANCE_CHECKPOINT
- }
- el::base::type::stringstream_t ss;
- ss << data->blockName()->c_str() << " took " << *data->formattedTimeTaken() << " to run";
- if (data->dataType() == el::PerformanceTrackingData::DataType::Checkpoint)
- {
- ss << " [CHECKPOINT ONLY] ";
- }
- CLOG(INFO, data->loggerId().c_str()) << ss.str();
- }
- };
- int main(int argc, char** argv)
- {
- {
- TIMED_SCOPE(mainBlock, "main"); /// 使用默认的性能日志格式输出日志
- Sleep(100);
- el::Helpers::installPerformanceTrackingCallback<MyPerformanceTrackingOutput>("MyPerformanceTrackingOutput");
- TIMED_SCOPE(timer, "myblock"); /// 使用自定义的性能日志格式输出日志
- Sleep(100);
- PERFORMANCE_CHECKPOINT(timer); /// 第一次使用PERFORMANCE_CHECKPOINT,会被忽略
- Sleep(100);
- PERFORMANCE_CHECKPOINT(timer); /// 使用自定义的性能日志格式输出日志
- Sleep(100);
- el::Helpers::uninstallPerformanceTrackingCallback<MyPerformanceTrackingOutput>("MyPerformanceTrackingOutput");
- }
- system("pause");
- return 0;
- }
#include "easylogging++.h"
INITIALIZE_EASYLOGGINGPP
class MyPerformanceTrackingOutput : public el::PerformanceTrackingCallback
{
public:
MyPerformanceTrackingOutput()
{
/// 禁用默认的性能日志输出格式
el::PerformanceTrackingCallback* defaultCallback =
el::Helpers::performanceTrackingCallback<el::base::DefaultPerformanceTrackingCallback>("DefaultPerformanceTrackingCallback");
defaultCallback->setEnabled(false);
}
virtual ~MyPerformanceTrackingOutput()
{
/// 恢复默认的性能日志输出格式
el::PerformanceTrackingCallback* defaultCallback =
el::Helpers::performanceTrackingCallback<el::base::DefaultPerformanceTrackingCallback>("DefaultPerformanceTrackingCallback");
defaultCallback->setEnabled(true);
}
protected:
/// 自定义性能日志输出格式
void handle(const el::PerformanceTrackingData* data)
{
if (data->firstCheckpoint())
{
return; /// 跳过第一次PERFORMANCE_CHECKPOINT
}
el::base::type::stringstream_t ss;
ss << data->blockName()->c_str() << " took " << *data->formattedTimeTaken() << " to run";
if (data->dataType() == el::PerformanceTrackingData::DataType::Checkpoint)
{
ss << " [CHECKPOINT ONLY] ";
}
CLOG(INFO, data->loggerId().c_str()) << ss.str();
}
};
int main(int argc, char** argv)
{
{
TIMED_SCOPE(mainBlock, "main"); /// 使用默认的性能日志格式输出日志
Sleep(100);
el::Helpers::installPerformanceTrackingCallback<MyPerformanceTrackingOutput>("MyPerformanceTrackingOutput");
TIMED_SCOPE(timer, "myblock"); /// 使用自定义的性能日志格式输出日志
Sleep(100);
PERFORMANCE_CHECKPOINT(timer); /// 第一次使用PERFORMANCE_CHECKPOINT,会被忽略
Sleep(100);
PERFORMANCE_CHECKPOINT(timer); /// 使用自定义的性能日志格式输出日志
Sleep(100);
el::Helpers::uninstallPerformanceTrackingCallback<MyPerformanceTrackingOutput>("MyPerformanceTrackingOutput");
}
system("pause");
return 0;
}
在使用回调函数时,可以使用正常的日志记录,但是千万不要再使用性能跟踪功能,否则将会陷于无限循环之中!