实测STM32F4中printf的效率问题

一直认为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之间的时间差。