5 h743的奇怪问题，rt_kprintf不同的写法会影响其它代码执行速度

发布于 2021-12-10 21:25:34 浏览：1172 订阅该版

程序是rt studio的stm32h743工程，测试一段代码的执行速度（时长），通过rt_kprintf打印执行测试函数前后tick之差来查看，然后发现在相同的测试执行后rt_kprintf打印语句的写法使用：

正常写法
```c
test_fun(x);
t = rt_tick_get()-t;
rt_kprintf("...%d...", t );    //正常写法
```

缩减写法：
```
test_fun(x);
rt_kprintf("...%d...", rt_tick_get()-t );    //缩减写法
```

结果有明显差异！test_fun(x)的一次执行时间是千ms以上，按理说不同写法生成的机器指令可能有差异，但在这里的影响每次就是几条指令ns级别的差异，而实际相差能达到几十tick（ms）以上，并且随着测试函数执行时间增加这个差异也随着增大。

测试函数`test_fun(x)`内部是重复执行另一段代码x次，实际上通过对比反编译的内容能确定在两种rt_kprintf语句的情形中  
test_fun()及其子函数的汇编代码内容完全一致，那么怎么会导致这样明显的差异呢？
实际代码如下
```c
extern void test_loop_fun_do_none_c(int loops);
int main(void)
{
    int count = 1;
    rt_thread_delay(3000);
    rt_kprintf("C_vs_Cpp speed test...\n");

rt_tick_t t;
    while (count++){
        uint32_t variable = count*10000;
        t = rt_tick_get();
        test_loop_fun_do_none_c( variable );
        t = rt_tick_get()-t;
        rt_kprintf("main.c run test_loop_fun_do_none_c(%d) use %d ticks\n", variable, t );    //正常写法
        //rt_kprintf("main.c run test_loop_fun_do_none_c(%d) use %d ticks\n", variable, rt_tick_get()-t );    //缩减写法
        rt_thread_mdelay(1000);
    }
    return RT_EOK;
}
```
```c
//一个占一定时间的函数
float fun_do_none_c(float in){
    float a[200];
    float b[200];

for(int i=0; i<(sizeof(b)/sizeof(b[0])); i++){
        a[i] = in+i;
        b[i] = in-i;
    }

float tmp=0;
    for(int i=0; i<(sizeof(b)/sizeof(b[0])); i++){
        tmp += a[i]*b[i];

if(tmp==0) tmp =1; //模拟一个异常
    }
    return tmp;
}

void test_loop_fun_do_none_c(int loops){
    float in=loops;
    for (int i=0; i<loops; i++){
        in = fun_do_none_c(in);
    }
}
```
正常写法的结果如下：
```
C_vs_Cpp speed test...
main.c run test_loop_fun_do_none_c(20000) use 1294 ticks
main.c run test_loop_fun_do_none_c(30000) use 1941 ticks
main.c run test_loop_fun_do_none_c(40000) use 2588 ticks
main.c run test_loop_fun_do_none_c(50000) use 3235 ticks
main.c run test_loop_fun_do_none_c(60000) use 3882 ticks
main.c run test_loop_fun_do_none_c(70000) use 4529 ticks
main.c run test_loop_fun_do_none_c(80000) use 5176 ticks
main.c run test_loop_fun_do_none_c(90000) use 5824 ticks
main.c run test_loop_fun_do_none_c(100000) use 6471 ticks
```
缩减写法的结果如下：
```
C_vs_Cpp speed test...
main.c run test_loop_fun_do_none_c(20000) use 1275 ticks
main.c run test_loop_fun_do_none_c(30000) use 1913 ticks
main.c run test_loop_fun_do_none_c(40000) use 2551 ticks
main.c run test_loop_fun_do_none_c(50000) use 3188 ticks
main.c run test_loop_fun_do_none_c(60000) use 3826 ticks
main.c run test_loop_fun_do_none_c(70000) use 4464 ticks
main.c run test_loop_fun_do_none_c(80000) use 5102 ticks
main.c run test_loop_fun_do_none_c(90000) use 5740 ticks
main.c run test_loop_fun_do_none_c(100000) use 6377 ticks
```
，后者与前者的tick数分别多19,28,37,47,56,65,74,84,94。从这个结果来看，每一次循环只执行一次的rt_kprintf()或者rt_tick_get()影响到了test_loop_fun_do_none_c()的执行，否则不会有递增的差异，但是输入参数variable的值没有差别，test_loop_fun_do_none_c()内部代码没有差别，感觉就挺匪夷所思了。

rt studio建的stm32h743工程，使用默认设置没有做任何更改。
后面测试了F407没有这个问题。因为我的mdk没有支持H743所以没有测试mdk下的情况，有兴趣的同学试一下看看。

这个问题是在想确认C++调用c的运行速度与c调用c的差异测试时发现，想使用C++做上层应用调用c写的算法。在C++的测试中差异更大并且更不解，test_loop_fun_do_none_c(20000)的差异能达到1145与1445，而代码上的差别只是在while(){}循环之前是否有执行过一次test_loop_fun_do_none_c()以及执行的代码位置。

也没研究过编译原理这会没法理解了，请大家来看看，这里把工程上传了，

[C-nano.rar](https://oss-club.rt-thread.org/uploads/20211210/72e509d63d30341f0ef3cdbac656aa2a.rar)，<--这是上面所贴代码的工程，

[C_vs_Cpp.rar](https://oss-club.rt-thread.org/uploads/20211210/8de02b2555abdbe2fe420b2fb44f08d4.rar) <--这是cpp测试工程，

[rtt函数执行时间测试.rar](https://oss-club.rt-thread.org/uploads/20211210/627864ec76715f229e55fb98061b2b1d.rar) <--这里是一些测试记录