linux - gprof 显示一个简单的信号处理程序占用大量 CPU

Question

我使用 gprof 来分析在 linux 上运行的程序，该程序使用 25 毫秒间隔计时器(由 timer_create() 创建)来更新全局变量。信号处理程序类似于 update_every_25ms()，它调用 profile_dummy() 来增加一个全局变量:

static void update_every_25ms(int sig_nr) { profile_dummy(); }
void profile_dummy(void) { global_var++; }

计时器是通过以下方式创建的:

timer_t timer;
struct itimerspec itimer;
timer_create(CLOCK_MONOTONIC, NULL, &timer)
itimer.it_interval.tv_sec = 0;
itimer.it_interval.tv_nsec = 25 * 1000 * 1000;
timer_settime(timer, 0, &itimer, NULL);

我的程序做了很多繁重的工作，但 gprof 显示 update_every_25ms() 函数在 CPU 使用率为 100% 时占用了大部分时间，而这个函数本身每次调用大约需要 1.53 毫秒!

以下是间隔25ms时的几组gprof输出:

%time  cumulative  self     calls  self    total    name
       seconds     seconds         ms/call ms/call
3.72   116.26      7.76     22963  0.34    0.34     profile_dummy

此处 CPU 使用率为 60%。为什么 profile_dummy() 每次调用需要 0.34 毫秒？

%time  cumulative  self     calls  self    total    name
       seconds     seconds         ms/call ms/call
9.38   38.87       38.87    25349  0.00    0.00     profile_dummy

此处 CPU 使用率为 100%。38.87s/25349 = 1.53ms 但 gprof 输出 0.00，发生了什么？

%time  cumulative  self     calls  self    total    name
       seconds     seconds         ms/call ms/call
6.21   270.58      57.72 59105     0.00    0.00     profile_dummy

此处 CPU 使用率为 90%。57.72s/59105 = 0.98ms 但 gprof 也输出 0.00。

这是我将计时器间隔更改为 25 秒时的 gprof 输出:

%time  cumulative  self     calls  self    total    name
       seconds     seconds         ms/call ms/call
0.01   287.52      0.03  23        1.30    1.30     profile_dummy

函数只是增加一个全局变量，为什么需要1.30ms？

感谢任何回复。

Answer 1

我只是在冒险猜测。

gprof 每 10ms 有一个信号中断，此时它对程序计数器 (PC) 进行采样。例程的总自身时间是在该例程中着陆的样本数。由于它还计算例程的调用次数，因此它可以获得每次调用的平均自用时间。

通常，当您的程序被阻塞时，例如 I/O、 sleep 或多任务挂起，PC 是没有意义的，因此中断被挂起。这就是 gprof 根本看不到 I/O 的原因。

但是，如果您有自己的定时器中断，这可能只会屏蔽探查器中断，而不是暂停它，导致它在您的定时器中断被解除后得到响应，这可能会将 PC 优先放在您的中断处理程序中。

但这只是一个猜测。

除非这纯粹是一个学术问题，否则有比 gprof 更好的分析器。