日志库EasyLogging++学习系列(9)—— 性能跟踪功能

101 篇文章 2 订阅

性能跟踪是 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) 这个宏定义,下面是其源码:
  1. #define TIMED_BLOCK(obj, blockName) for (struct { int i; el::base::PerformanceTracker timer; } obj = { 0, \  
  2.     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) ,需要对这段代码做一个小改动,就是把结构体的定义放在循环外面即可:
  1. typedef struct st_PerformanceTracker{  
  2.     int i;   
  3.     el::base::PerformanceTracker timer;  
  4. } TIME_BLOCK_PERFORMANCE_TRACKER;  
  5. #define TIMED_BLOCK(obj, blockName) for (TIME_BLOCK_PERFORMANCE_TRACKER obj = { 0, \  
  6.     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)
下面的代码演示了 上述三个实现性能跟踪的宏定义最简单的一个用法:
  1. #include "easylogging++.h"  
  2.   
  3. INITIALIZE_EASYLOGGINGPP  
  4.   
  5. void PerformanceTest()   
  6. {  
  7.     /// TIMED_FUNC会统计其后续所有代码的执行时间  
  8.     TIMED_FUNC(timerFunObj);  
  9.     Sleep(100);  
  10.   
  11.     /// TIMED_SCOPE会统计其后续所有代码的执行时间  
  12.     TIMED_SCOPE(timerScopeObj, "TIMED_SCOPE_Test");  
  13.     Sleep(100);  
  14.   
  15.     /// TIMED_BLOCK只会统计花括号{}里所有代码的执行时间  
  16.     TIMED_BLOCK(timerBlockObj, "TIMED_BLOCK_Test")  
  17.     {  
  18.         Sleep(100);  
  19.     }  
  20.   
  21.     Sleep(100);  
  22. }  
  23.   
  24. int main(int argc, char** argv)  
  25. {  
  26.     PerformanceTest();  
  27.   
  28.     system("pause");  
  29.     return 0;  
  30. }  
#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)
这两个宏定义的用法和功能是一样的,只是后者多了一个标识。下面的代码演示了这两个宏定义的用法:
  1. #include "easylogging++.h"  
  2.   
  3. INITIALIZE_EASYLOGGINGPP  
  4.   
  5. int main(int argc, char** argv)  
  6. {  
  7.     /// 用花括号是为了使宏TIMED_SCOPE能够输出日志,不然类el::base::PerformanceTracker无法进行析构  
  8.     {  
  9.         /// TIMED_SCOPE会统计其后续所有代码的执行时间  
  10.         TIMED_SCOPE(timerScopeObj, "TIMED_SCOPE_Test");  
  11.         Sleep(100);  
  12.   
  13.         /// PERFORMANCE_CHECKPOINT会统计和TIMED_SCOPE之间所有代码的执行时间  
  14.         PERFORMANCE_CHECKPOINT(timerScopeObj);  
  15.         Sleep(100);  
  16.   
  17.         /// PERFORMANCE_CHECKPOINT_WITH_ID会统计和TIMED_SCOPE之间所有代码的执行时间  
  18.         /// 参数"mychkpnt"可以标识该宏定义的输出  
  19.         /// 另外计算出和前面最近一次使用PERFORMANCE_CHECKPOINT之间所有代码的执行时间  
  20.         PERFORMANCE_CHECKPOINT_WITH_ID(timerScopeObj, "mychkpnt");  
  21.         Sleep(100);  
  22.     }  
  23.   
  24.     system("pause");  
  25.     return 0;  
  26. }  
#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;
}

最后,我们还可以利用回调函数对性能跟踪的数据进行更有效的处理,下面的例子将会演示如何注册和注销回调函数:
  1. #include "easylogging++.h"  
  2.   
  3. INITIALIZE_EASYLOGGINGPP  
  4.   
  5. class MyPerformanceTrackingOutput : public el::PerformanceTrackingCallback   
  6. {  
  7. public:  
  8.     MyPerformanceTrackingOutput()   
  9.     {  
  10.         /// 禁用默认的性能日志输出格式  
  11.         el::PerformanceTrackingCallback* defaultCallback =  
  12.             el::Helpers::performanceTrackingCallback<el::base::DefaultPerformanceTrackingCallback>("DefaultPerformanceTrackingCallback");  
  13.         defaultCallback->setEnabled(false);  
  14.     }  
  15.     virtual ~MyPerformanceTrackingOutput()   
  16.     {  
  17.         /// 恢复默认的性能日志输出格式  
  18.         el::PerformanceTrackingCallback* defaultCallback =  
  19.             el::Helpers::performanceTrackingCallback<el::base::DefaultPerformanceTrackingCallback>("DefaultPerformanceTrackingCallback");  
  20.         defaultCallback->setEnabled(true);  
  21.     }  
  22.   
  23. protected:  
  24.   
  25.     /// 自定义性能日志输出格式  
  26.     void handle(const el::PerformanceTrackingData* data)   
  27.     {  
  28.         if (data->firstCheckpoint())  
  29.         {   
  30.             return;     /// 跳过第一次PERFORMANCE_CHECKPOINT  
  31.         }   
  32.   
  33.         el::base::type::stringstream_t ss;  
  34.         ss << data->blockName()->c_str() << " took " << *data->formattedTimeTaken() << " to run";  
  35.   
  36.         if (data->dataType() == el::PerformanceTrackingData::DataType::Checkpoint)   
  37.         {  
  38.             ss << " [CHECKPOINT ONLY] ";  
  39.         }  
  40.         CLOG(INFO, data->loggerId().c_str()) << ss.str();  
  41.     }  
  42. };  
  43.   
  44. int main(int argc, char** argv)   
  45. {  
  46.     {  
  47.         TIMED_SCOPE(mainBlock, "main");     /// 使用默认的性能日志格式输出日志  
  48.         Sleep(100);  
  49.   
  50.         el::Helpers::installPerformanceTrackingCallback<MyPerformanceTrackingOutput>("MyPerformanceTrackingOutput");  
  51.   
  52.         TIMED_SCOPE(timer, "myblock");      /// 使用自定义的性能日志格式输出日志  
  53.         Sleep(100);  
  54.   
  55.         PERFORMANCE_CHECKPOINT(timer);      /// 第一次使用PERFORMANCE_CHECKPOINT,会被忽略  
  56.         Sleep(100);  
  57.   
  58.         PERFORMANCE_CHECKPOINT(timer);      /// 使用自定义的性能日志格式输出日志  
  59.         Sleep(100);  
  60.       
  61.         el::Helpers::uninstallPerformanceTrackingCallback<MyPerformanceTrackingOutput>("MyPerformanceTrackingOutput");  
  62.     }  
  63.       
  64.     system("pause");  
  65.     return 0;  
  66. }  
#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;
}
在使用回调函数时,可以使用正常的日志记录,但是千万不要再使用性能跟踪功能,否则将会陷于无限循环之中!

  • 0
    点赞
  • 3
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值