實測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之間的時間差。