对于使用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会耗时这么长时间,可能涉及到系统的硬件资源调度方面,在本篇中不再深入探讨。