gettimeofday函数_内核态调测工具：ftrace(六)-ftrace应用：跟踪&统计函数耗时

最新推荐文章于 2023-05-10 14:34:17 发布
最新推荐文章于 2023-05-10 14:34:17 发布
阅读量307 收藏
点赞数
CC 4.0 BY-SA版权
文章标签： gettimeofday函数
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/weixin_28692867/article/details/113073665
本文通过一个实例分析了在CPU压力大时，使用ftrace工具跟踪并统计gettimeofday函数执行耗时的问题。通过ftrace在test.c中添加跟踪代码，发现CPU1长时间运行其他任务导致test_trace执行延迟，揭示了CFS调度策略在高负载下的现象，并建议尝试将任务设置为SCHED_RR以改善执行及时性。

摘要生成于 C知道 ，由 DeepSeek-R1 满血版支持， 前往体验 >

问题

实际应用中，当系统CPU压力较大，某些固定频率触发的任务突然不稳定起来，或者出现（比较关注性能的）某函数的执行耗时出现波动，这种情况是为什么呢？是函数本身不稳定，还是系统导致？

举例test.c：

#include <stdio.h>
#include <sys/time.h>

int delaytime(int t) {
        int i, j;
        for (i = 0; i < t; i++)
                for (j = 0; j < 5000; j++);
}

void main() {
        struct timeval tv1, tv2;

        gettimeofday(&tv1, NULL);
        delaytime(100);
        gettimeofday(&tv2, NULL);

        printf("diff: %ldusn", 1000000 * (tv2.tv_sec - tv1.tv_sec) + (tv2.tv_usec - tv1.tv_usec));
}

如下执行：

$ stress -c 8 &
$ taskset -c 6 ./test
diff: 1045us
$ taskset -c 6 ./test
diff: 1124us
$ taskset -c 6 ./test
diff: 1444us
$ taskset -c 6 ./test
diff: 2162us
$ taskset -c 6 ./test
diff: 11995us
$ taskset -c 6 ./test
diff: 1067us

如上，一个固定的for循环在CPU加压的情况下，执行耗时不再稳定。

Ftrace跟踪

利用之前讲到的知识

Hello小崔：内核态调测工具：ftrace(三)-ftrace在C程序中应用​zhuanlan.zhihu.com
zhihu-card-default.svg

在test.c中添加跟踪代码：

$ cat test_trace.c
#include <stdio.h>
#include <sys/time.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>

int delaytime(int t) {
        int i, j;
        for (i = 0; i < t; i++)
                for (j = 0; j < 5000; j++);
}

void main() {
        struct timeval tv1, tv2;
        int fd_sched = open("/sys/kernel/debug/tracing/events/sched/enable", O_CREAT | O_RDWR, 0666);
        int fd_irq = open("/sys/kernel/debug/tracing/events/irq/enable", O_CREAT | O_RDWR, 0666);
        int fd_mark = open("/sys/kernel/debug/tracing/trace_marker", O_CREAT | O_RDWR, 0666);
        int fd_trace = open("/sys/kernel/debug/tracing/tracing_on", O_CREAT | O_RDWR, 0666);

        write(fd_trace, "1", 2); // enable ftrace
        write(fd_sched, "1", 2); // enable sched event
        write(fd_irq, "1", 2); // enable irq event

        while (1) {
                gettimeofday(&tv1, NULL);
                write(fd_mark, "start delay", 12); // add mark
                delaytime(100);
                write(fd_mark, "end delay", 12); // end mark
                gettimeofday(&tv2, NULL);

                if ((1000000 * (tv2.tv_sec - tv1.tv_sec) + (tv2.tv_usec - tv1.tv_usec)) > 10000) {
                        printf("break!n");
                        write(fd_trace, "1", 2); // find something wrong， stop ftrace
                        write(fd_sched, "0", 2);
                        write(fd_irq, "0", 2);
                        break;
                }
        }
        close(fd_mark);
        close(fd_trace);
        close(fd_sched);
        close(fd_irq);
}

重新执行：

$ stress -c 8 &
$ taskset -c 6 ./test_trace
break!
$ killall stress
$ sudo cat /sys/kernel/debug/tracing/trace > trace.log
$ vim trace.log

找到最终出现时间过长是在CPU1：

d6c106908cb69dd3e440801fb119b625.png
cat trace.log |grep 001
test_trace-6345  [001] .... 8271351.623351: tracing_mark_write: start delay             vim-27246 [000] d.h. 8271351.623846: sched_waking: comm=containerd pid=3658 prio=120 target_cpu=000
          stress-6314  [002] d.h. 8271351.624001: softirq_raise: vec=1 [action=TIMER]
          stress-6317  [004] d.h. 8271351.624001: softirq_raise: vec=1 [action=TIMER]
      test_trace-6345  [001] d.h. 8271351.624002: softirq_raise: vec=1 [action=TIMER]
      test_trace-6345  [001] d.h. 8271351.624003: softirq_raise: vec=9 [action=RCU]
      test_trace-6345  [001] d.h. 8271351.624003: sched_stat_runtime: comm=test_trace pid=6345 runtime=3999453 [ns] vruntime=3795265129978053 [ns]
      test_trace-6345  [001] .Ns. 8271351.624006: softirq_entry: vec=1 [action=TIMER]
      test_trace-6345  [001] .Ns. 8271351.624007: softirq_exit: vec=1 [action=TIMER]
      test_trace-6345  [001] .Ns. 8271351.624007: softirq_entry: vec=9 [action=RCU]
      test_trace-6345  [001] .Ns. 8271351.624008: softirq_exit: vec=9 [action=RCU]
      test_trace-6345  [001] dN.. 8271351.624009: sched_stat_runtime: comm=test_trace pid=6345 runtime=5493 [ns] vruntime=3795265129983546 [ns]
      test_trace-6345  [001] d... 8271351.624010: sched_switch: prev_comm=test_trace prev_pid=6345 prev_prio=120 prev_state=R ==> next_comm=stress next_pid=6312 next_prio=120
          stress-6317  [004] d.h. 8271351.628001: softirq_raise: vec=9 [action=RCU]
          stress-6317  [004] d.h. 8271351.628001: sched_stat_runtime: comm=stress pid=6317 runtime=3999078 [ns] vruntime=2602931922779310 [ns]
          stress-6316  [003] d.h. 8271351.628001: softirq_raise: vec=1 [action=TIMER]
          stress-6314  [002] d.h. 8271351.628001: sched_stat_runtime: comm=stress pid=6314 runtime=3999141 [ns] vruntime=2856602266991255 [ns]
          stress-6316  [003] d.h. 8271351.628001: softirq_raise: vec=9 [action=RCU]
          stress-6312  [001] d.h. 8271351.628002: softirq_raise: vec=1 [action=TIMER]
          stress-6312  [001] d.h. 8271351.628002: sched_stat_runtime: comm=stress pid=6312 runtime=3993578 [ns] vruntime=3795265118124082 [ns]
          stress-6312  [001] ..s. 8271351.628005: softirq_entry: vec=1 [action=TIMER]
          stress-6312  [001] ..s. 8271351.628005: softirq_exit: vec=1 [action=TIMER]
          stress-6317  [004] d.h. 8271351.632001: softirq_raise: vec=9 [action=RCU]
          stress-6314  [002] d.h. 8271351.632001: softirq_raise: vec=1 [action=TIMER]
          stress-6315  [005] d.h. 8271351.632001: softirq_raise: vec=9 [action=RCU]
          stress-6317  [004] d.h. 8271351.632001: sched_stat_runtime: comm=stress pid=6317 runtime=3999776 [ns] vruntime=2602931926779086 [ns]
          stress-6314  [002] d.h. 8271351.632001: softirq_raise: vec=9 [action=RCU]
          stress-6315  [005] d.h. 8271351.632001: sched_stat_runtime: comm=stress pid=6315 runtime=3997437 [ns] vruntime=773930908522608 [ns]
          stress-6314  [002] d.h. 8271351.632001: sched_stat_runtime: comm=stress pid=6314 runtime=3999959 [ns] vruntime=2856602270991214 [ns]
          stress-6312  [001] d.h. 8271351.632001: softirq_raise: vec=1 [action=TIMER]
          stress-6316  [003] d.h. 8271351.632001: softirq_raise: vec=1 [action=TIMER]
          stress-6312  [001] d.h. 8271351.632002: softirq_raise: vec=9 [action=RCU]
          stress-6312  [001] d.h. 8271351.632002: sched_stat_runtime: comm=stress pid=6312 runtime=3999764 [ns] vruntime=3795265122123846 [ns]
          stress-6312  [001] ..s. 8271351.632004: softirq_entry: vec=1 [action=TIMER]
          stress-6312  [001] ..s. 8271351.632004: softirq_exit: vec=1 [action=TIMER]
          stress-6312  [001] ..s. 8271351.632005: softirq_entry: vec=9 [action=RCU]
          stress-6312  [001] ..s. 8271351.632022: softirq_exit: vec=9 [action=RCU]
          stress-6316  [003] dN.. 8271351.632896: sched_stat_runtime: comm=stress pid=6316 runtime=882192 [ns] vruntime=1181827362000120 [ns]
          stress-6317  [004] d.h. 8271351.636001: softirq_raise: vec=9 [action=RCU]
          stress-6317  [004] d.h. 8271351.636001: sched_stat_runtime: comm=stress pid=6317 runtime=4000319 [ns] vruntime=2602931930779405 [ns]
          stress-6315  [005] d.h. 8271351.636002: sched_stat_runtime: comm=stress pid=6315 runtime=4001146 [ns] vruntime=773930912523754 [ns]
          stress-6312  [001] d.h. 8271351.636003: softirq_raise: vec=1 [action=TIMER]
          stress-6312  [001] d.h. 8271351.636003: softirq_raise: vec=9 [action=RCU]
          stress-6312  [001] d.h. 8271351.636004: sched_stat_runtime: comm=stress pid=6312 runtime=4001619 [ns] vruntime=3795265126125465 [ns]
          stress-6318  [007] d.h. 8271351.636004: sched_stat_runtime: comm=stress pid=6318 runtime=4001016 [ns] vruntime=1587598060233969 [ns]
             vim-27246 [000] d.h. 8271351.636005: sched_stat_runtime: comm=vim pid=27246 runtime=4000114 [ns] vruntime=365313085464828 [ns]
          stress-6312  [001] ..s. 8271351.636007: softirq_entry: vec=1 [action=TIMER]
          stress-6312  [001] ..s. 8271351.636008: softirq_exit: vec=1 [action=TIMER]
          stress-6312  [001] ..s. 8271351.636008: softirq_entry: vec=9 [action=RCU]
          stress-6312  [001] ..s. 8271351.636008: softirq_exit: vec=9 [action=RCU]
          stress-6312  [001] d.h. 8271351.640003: softirq_raise: vec=1 [action=TIMER]
          stress-6312  [001] d.h. 8271351.640004: softirq_raise: vec=9 [action=RCU]
          stress-6312  [001] d.h. 8271351.640004: sched_stat_runtime: comm=stress pid=6312 runtime=4000085 [ns] vruntime=3795265130125550 [ns]
          stress-6312  [001] .Ns. 8271351.640007: softirq_entry: vec=1 [action=TIMER]
          stress-6312  [001] .Ns. 8271351.640008: softirq_exit: vec=1 [action=TIMER]
          stress-6312  [001] .Ns. 8271351.640008: softirq_entry: vec=9 [action=RCU]
          stress-6312  [001] .Ns. 8271351.640008: softirq_exit: vec=9 [action=RCU]
          stress-6312  [001] dN.. 8271351.640009: sched_stat_runtime: comm=stress pid=6312 runtime=5234 [ns] vruntime=3795265130130784 [ns]
          stress-6313  [006] ..s. 8271351.640010: softirq_exit: vec=1 [action=TIMER]
          stress-6313  [006] ..s. 8271351.640010: softirq_entry: vec=9 [action=RCU]
             vim-27246 [000] ..s. 8271351.640010: softirq_entry: vec=1 [action=TIMER]
             vim-19564 [002] ..s. 8271351.640010: softirq_entry: vec=1 [action=TIMER]
          stress-6313  [006] ..s. 8271351.640010: softirq_exit: vec=9 [action=RCU]
             vim-27246 [000] ..s. 8271351.640010: softirq_exit: vec=1 [action=TIMER]
             vim-27246 [000] ..s. 8271351.640011: softirq_entry: vec=7 [action=SCHED]
             vim-19564 [002] ..s. 8271351.640011: softirq_exit: vec=1 [action=TIMER]
          stress-6312  [001] d... 8271351.640011: sched_switch: prev_comm=stress prev_pid=6312 prev_prio=120 prev_state=R ==> next_comm=test_trace next_pid=6345 next_prio=120
             vim-19564 [002] ..s. 8271351.640011: softirq_entry: vec=9 [action=RCU]
             vim-19564 [002] ..s. 8271351.640011: softirq_exit: vec=9 [action=RCU]
      test_trace-6345  [001] .... 8271351.640410: tracing_mark_write: end delay      test_trace-6345  [001] d... 8271351.640489: sched_waking: comm=kworker/u16:0 pid=20387 prio=120 target_cpu=000

结论

最终跟踪到当时CPU1长时间在运行stress，在8271351.640011时间才切回test_trace运行。

现在知道为什么在CPU压力大的情况下，有时候任务不能及时执行的原因了吧，这是CFS调度策略的现象。

试着将任务设置成SCHED_RR看下是否可以保证运行。

$ sudo chrt -r 99 ./test
diff: 1051us
$ sudo chrt -r 99 ./test
diff: 1068us
$ sudo chrt -r 99 ./test
diff: 1024us
$ sudo chrt -r 99 ./test
diff: 1072us
$ sudo chrt -r 99 ./test
diff: 1039us
$ sudo chrt -r 99 ./test
diff: 1019us
$ sudo chrt -r 99 ./test
diff: 1041us
$ sudo chrt -r 99 ./test
diff: 1036us
$ sudo chrt -r 99 ./test
diff: 1047us
聂小影
关注
【C语言进阶】使用gettimeofday为你的程序运行时间做统计
一个专注于嵌入式IoT领域的架构师，深耕IoT领域多年，深度掌握IoT领域的相关技术栈，包括但不限于RTOS内核的实现及其移植、硬件驱动移植开发、网络通讯协议开发、编译构建原理及其实现、底层汇编及编译原理、编译优化及代码重构、嵌入式IoT系统的架构设计等。
12-14 1万+
有时候在编程调试的时候，会遇到个别性能问题需要调试，这时候我们需要比较精确地统计每段代码的耗时情况，这种情况下，你是怎么做的呢？本文介绍一种方法来实现此功能
gettimeofday 统计代码耗时
jielunqiu的博客
02-27 1226
#inlcude&amp;lt;sys/time.h&amp;gt;   struct timval tv_begin,tv_end; UINT32 ulTime1 = 0,ulTime2 =0; gettimeofday(&amp;amp;tv_begin,NULL);            code gettimeofday(&amp;amp;tv_end,NULL); ulTime1 = tv_end.tv_...
查看程序执行耗时gettimeofday
willis
08-02 653
查看程序执行耗时gettimeofday
ftrace-统计函数时间
weixin_43690845的博客
07-28 770
a)设置trace跟踪器 echo function_graph > /sys/kernel/debug/tracing/current_tracer 查看可用的跟踪器： cat /sys/kernel/debug/tracing/available_tracers hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop b)设置最大跟踪深度，可以避免内部函数嵌套太多，设置为１时只跟踪函数本身 echo 2
gettimeofday时间
linuxheik的专栏
12-24 5814
elpi   Preferences Help/Guide About Trac Wiki Timeline Roadmap Browse Source View Tickets Search Start Page Index History Last Change gettimeof
如何利用SystemTap统计函数执行耗时详解
09-15
SystemTap是一种强大的Linux工具，用于实时监控和分析运行中的内核和用户空间应用程序。它允许开发者无需修改源代码或重新编译系统即可收集系统级别的数据。在本文中，我们将深入探讨如何利用SystemTap来统计特定...
(.text._gettimeofday_r+0xe): warning: _gettimeofday is not implemented and will always fail
最新发布
07-19
这个警告通常发生在嵌入式系统或某些交叉编译环境中，因为目标平台可能没有实现标准的gettimeofday函数。 根据引用[1]和[2]，我们知道gettimeofday是一个系统调用，用于获取当前时间（精确到微秒）。在Linux系统中...
C语言中settimeofday函数和gettimeofday函数的使用
01-01
C语言settimeofday()函数：设置当前时间戳 头文件： #include <sys> #include 定义函数： int settimeofday(const struct timeval *tv, const struct timezone *tz); 函数说明：settimeofday()会把目前时间设成...
Linux下通过gettimeofday函数获取程序段执行时间【推荐】
09-15
总之，`gettimeofday`函数是Linux环境下测量程序执行时间的一个实用工具，结合`timeval`结构体，可以方便地进行性能调试和分析。通过了解和运用这些技术，开发者能够更好地理解和优化他们的代码，提高软件的性能。
Linux时间函数之gettimeofday()函数之使用方法
07-22
Linux中的gettimeofday()函数是一个用于获取当前时间的系统调用，该函数能够提供精确到微秒的时间值。在C语言的开发环境中，尤其是Linux系统编程中，gettimeofday()函数经常被使用以获取准确的时间信息。了解并掌握...
C语言：获取程序运行消耗的时间——gettimeofday
热门推荐
小二的茶馆
02-27 1万+
在测试程序时，往往需要了解程序执行所需的时间，在C语言中可以使用函数gettimeofday来得到时间。来不及解释了，直接上例子。对于普通的C程序：使用 gettimeofday() 函数#include<stdio.h> #include<sys/time.h> //注意引用这个头文件 #include<unistd.h>int delay(int time) { //这里用来表示你自己要运
linux下统计代码运行时间消耗-gettimeofday
奔狼
10-27 1827
最近在工控机的centos上做业务功能开发，有些业务流程对时间要求比较苛刻，但系统又不是实时系统，代码运行时间没法保证，所以每次添加代码和进程的时候都只能手工测试一下时间消耗，也是醉醉的。 linux上有获取当前系统时间的接口gettimeofday，获取回来的时间可以精确到微妙（实际精度到不了1微妙，测试大概也就是几十微妙）。简单测试例子如下，用usleep代表想测试的实际代码。 #include <stdio.h> #include <iostream> #include &lt
浅谈时间函数gettimeofday的成本（更正）
iteye_10227的博客
01-09 2140
我们在程序中会频繁地取当前时间，例如处理一个http请求时，两次调用gettimeofday取差值计算出处理该请求消耗了多少秒。这样的调用无处不在，所以我们有必要详细了解下，gettimeofday这个函数做了些什么？内核1ms一次的时钟中断处理真的可以支持tv_usec字段达到微秒精度吗？它的调用成本在i386/x86_64体系架构上代价一样吗？如果在系统繁忙时，频繁的调用它有问题吗？   ...
统计cuda函数耗时：win10 + vs2015 + 实现gettimeofday
zfjBIT的专栏
12-12 1291
统计cuda函数耗时： 在利用CPU计时函数对GPU部分进行计时时时，要考虑的一个问题是：核函数的执行是异步执行的，所以必须加上核函数同步函数，才能得到准确的时间。 计时方式，示例代码如下： double cpuSecond() {     struct timeval tp;     gettimeofday(&amp;amp;tp,NULL);     return ((double)t...
time(),gettimeofday()及GetTickCount()效率比较
C.J.
03-24 3269
转自：http://1.guotie.sinaapp.com/?p=157 time()和gettimeofday()是linux的系统调用，GetTickCount()是windows的函数。 time：返回至1970-1-1 00:00:00至今的秒数； gettimeofday：除了返回秒数外，还有纳秒数，用于更精确的计时； GetTickCoun
gettimeofday
joben的专栏
11-07 963
struct timeval nowTime; gettimeofday(&nowTime,NULL); unsigned long iTime = (nowTime.tv_sec*1000+nowTime.tv_usec/1000);
程序运行耗时计算
qq_17278169的博客
08-18 1339
程序运行耗时计算常用的程序运行耗时计算有四中方法：1，clock_t 头文件为time.hclock_t start = clock(); function(); clock_t end = clock(); std::cout<<"time is:"<<(double)(end -time)/CLOCKS_PER_SEC<<std::endl;2,利用gettimeofday()struct
测试ftrace的命令
finallyjustice的博客
04-20 585
测试ftrace的命令 echo 0 > /proc/sys/kernel/ftrace_enabled echo 0 > /sys/kernel/debug/tracing/tracing_on echo 1 > /proc/sys/kernel/ftrace_enabled echo function > /sys/kernel/debug/tracing/current_
C语言计算函数耗时方法
Haomione的博客
05-10 1743
C语言计算函数耗时方法
Linux耗时函数：测试与调试指南
"Linux 耗时函数是一个实用工具，用于测量程序运行时的执行时间，特别是在测试阶段对关键功能进行性能评估。它是在Red Hat Enterprise 5.5操作系统环境下编写的，并且已经过调试验证。该代码包括了几个头文件，如...
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值