DSP

关于调试中的printf的坑

2019-07-13 19:59发布

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