对于使用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
",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
",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
",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug test acegettime and print 20 times end at %02d:%02d:%02d-%02d
",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
", 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
",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug print 20 times end at %02d:%02d:%02d-%02d
",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
",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug acegettime 20 times end at %02d:%02d:%02d-%02d
",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
",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
",at1.hour(),at1.minute(),at1.second(),at1.microsec());
printf("debug acegettime and sprint 20 times end at %02d:%02d:%02d-%02d
",at2.hour(),at2.minute(),at2.second(),at2.microsec());
运行了四次,时间均为0,可忽略。
至于为什么printf会耗时这么长时间,可能涉及到系统的硬件资源调度方面,在本篇中不再深入探讨。