一直认为printf所做的工作就是格式化字符串,然后依次调用fputc函数发送出去。于是以前都认为printf函数的瓶颈是在fputc这里,是因为发送一个字节所占的时间太长,才导致printf效率慢。也就是说,一直认为如果串口的波特率设置成115200的话,printf至少也是能达到115200的波特率的。
而这几天在学习ucOS,于是想到,如果printf的瓶颈是在等在串口发送完成的话,那么我在等待串口发送完成中断的时候是不是挂起一个信号量,然后就可以去做点别的事情了呢?这也正是RTOS的目的之一嘛————最大化利用CPU。
花了点时间时间试了下之后,发现完全没有改善!于是有了测试两次进入fputc间隔时间的想法。
测试环境:MDK5.12 + 自带STM32F4 HAL层 + UCOS3.04.04
硬件平台:安富莱V5板卡,主芯片STM32F407IG,USB转串口线CH430芯片,ThinkPad T420
代码如下:
int fputc(int ch, FILE *f)
{
OS_ERR err;
CPU_TS ts;
Dbg_printf_time[Dbg_printf_cnt++] = STK_VAL_REG; //进入函数前读取systick的寄存器值
Dbg_printf_inter[Dbg_printf_cnt] = Dbg_printf_time[Dbg_printf_cnt-2] - Dbg_printf_time[Dbg_printf_cnt-1];//用刚读取的寄存器值减去上一次退出该函数的寄存器值,从而得到两次进入该函数之间的时间
while (HAL_UART_Transmit_IT(&huart, (uint8_t *)&ch, 1) != HAL_OK)
{
OSTaskSemPend(10, OS_OPT_PEND_BLOCKING, &ts, &err);
//check “err”
}
Dbg_printf_time[Dbg_printf_cnt++] = STK_VAL_REG; //退出函数前读取systick的寄存器值
Dbg_printf_inter[Dbg_printf_cnt] = Dbg_printf_time[Dbg_printf_cnt-2] - Dbg_printf_time[Dbg_printf_cnt-1];//用刚读取的寄存器值减去进入该函数的寄存器值,从而得到两次进入该函数之间的时间
if (Dbg_printf_cnt > 90)
{
Dbg_printf_cnt = 1;
}
return ch;
}
重点关注Dbg_printf_inter的值,结果如下:
可以看到进入两次fputc之间的间隔达到了15937个tick,考虑到主频为168M
由
time=tick/sysfreq
可以计算得出time=94.86us。
而115200波特率的串口在发送两个Byte之间的时间是:86.5us
也就是说:用115200波特率的速度打印printf就已经把STM32的CPU都耗光了!
实在是好奇printf里面都做了什么??作为库函数,它不应该是精简,效率的典范吗?怎么会这么慢?
抛出这个问题,求高手解答,同时也欢迎像我这么无聊的同学在别的平台上验证两次fputc之间的时间差。