关于调试中的printf的坑

对于使用c/c++进行跨平台开发的项目，由于调试手段有限，利用printf打印中间信息就成为了调试中非常重要的手段。但是这种调试手段却让本人掉到了坑里。分享一下。

简介一下背景，做的项目为跨平台的项目，我们通常的方法是首先使用vs在windows下开发和调试，再使用gcc在linux下编译linux版本。程序对于时间比较敏感。

在调试过程中，为了跟踪程序运行，增加了许多的以下语句：

ACE_Date_Time at;
 at=ACE_Date_Time(ACE_OS::gettimeofday());
 printf("sudebug, at=%02d:%02d:%02d-%02d \n",at.hour(),at.minute(),at.second(),at.microsec());    

这样就可以在希望跟踪的地方打印出时间和信息。由于希望得到微秒时间，所以使用了ace来获取时间。

但是在调试过程中，发现了问题，执行时间无法满足要求。正常来说，执行一个循环需要大概5~6ms，但是现在飙升到了100ms。让我一度怀疑是我修改的代码导致的这个问题。

在通过与同事讨论之后，同事提到printf是需要耗时的，用ace获取时间之前也没怎么用过。

于是写了测试代码来测试这两个函数的耗时。

分别测试循环20次ACE_OS::gettimeofday()加printf，只printf，只ACE_OS::gettimeofday()的时间。

示例代码如下：

ACE_Date_Time at,at1, at2;
at1=ACE_Date_Time(ACE_OS::gettimeofday());
for(int i=0;i<20;i++)
{
	at=ACE_Date_Time(ACE_OS::gettimeofday());
	printf("debug print at %02d:%02d:%02d-%02d\n",at.hour(),at.minute(),at.second(),at.microsec());
}
at2=ACE_Date_Time(ACE_OS::gettimeofday());
printf("debug test acegettime and print 20 times start at %02d:%02d:%02d-%02d\n",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug test acegettime and print 20 times end at %02d:%02d:%02d-%02d\n",at2.hour(),at2.minute(),at2.second(),at2.microsec());

at1=ACE_Date_Time(ACE_OS::gettimeofday());
for(int i=0;i<20;i++)
{
	printf("debug print at %02d:%02d:%02d-%02d-- time not right\n", at.hour(),at.minute(),at.second(),at.microsec());
}
at2=ACE_Date_Time(ACE_OS::gettimeofday());
printf("debug print 20 times start at %02d:%02d:%02d-%02d\n",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug print 20 times end at %02d:%02d:%02d-%02d\n",at2.hour(),at2.minute(),at2.second(),at2.microsec());

			
at1=ACE_Date_Time(ACE_OS::gettimeofday());
for(int i=0;i<20;i++)
{
	at=ACE_Date_Time(ACE_OS::gettimeofday());
}
at2=ACE_Date_Time(ACE_OS::gettimeofday());
printf("debug acegettime 20 times start at %02d:%02d:%02d-%02d\n",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug acegettime 20 times end at %02d:%02d:%02d-%02d\n",at2.hour(),at2.minute(),at2.second(),at2.microsec());

运行了四次，得到的运行时间如下：（单位微秒）

次数	CE_OS::gettimeofday()加printf	只printf	只ACE_OS::gettimeofday()
1	50750	25376	0
2	28303	20496	0
3	39035	18587	0
4	38063	11713	0

可以看出，只运行获取时间的函数基本不耗时，而如果运行print，耗时增加，如果同时运行获取时间和打印，耗时会增加更多。

那么为了测试这个程序而对程序产生较大的影响是不可接受的。那么，如果又希望获得调试信息，又不想对运行时间产生影响怎么处理呢？于是想到了sprintf，把需要打印的信息先暂存下来，然后在时间不敏感的时间再一块打印。

为了测试这种方案的用时，写了如下测试代码

char log[1024];
sprintf(log,"");
at1=ACE_Date_Time(ACE_OS::gettimeofday());
for(int i=0;i<20;i++)
{
	at=ACE_Date_Time(ACE_OS::gettimeofday());
	sprintf(log,"%s debug print at %02d:%02d:%02d-%02d\n",log,at.hour(),at.minute(),at.second(),at.microsec());
}
at2=ACE_Date_Time(ACE_OS::gettimeofday());
printf("debug acegettime and sprint 20 times start at %02d:%02d:%02d-%02d\n",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug acegettime and sprint 20 times end at %02d:%02d:%02d-%02d\n",at2.hour(),at2.minute(),at2.second(),at2.microsec());

       运行了四次，时间均为0，可忽略。

至于为什么printf会耗时这么长时间，可能涉及到系统的硬件资源调度方面，在本篇中不再深入探讨。