使用 gprof 进行分析时的神秘函数 _L_lock_154

Question

在分析我的代码时，gprof 输出以下内容：

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 30.69     10.55    10.55                             _L_lock_154
 16.58     16.25     5.70 1126059616     0.00     0.00  double_cmp
 14.25     21.15     4.90    13737     0.36     0.36  bsdi
 10.01     24.59     3.44                             memcpy

（只取第一行）

占据榜首是一个我不认识的功能，不幸的是，谷歌也没有。

可能是什么 - 有人知道吗？因为它占用了我大部分时间，我很想知道。

使用麦克风建议进行 DIY 分析，我经常看到这个堆栈回溯：

Program received signal SIGINT, Interrupt.
0xb7fff424 in __kernel_vsyscall ()
(gdb) bt
#0  0xb7fff424 in __kernel_vsyscall ()
#1  0x080ada62 in __write_nocancel ()
#2  0x080859c1 in _IO_new_file_write ()
#3  0x08084b64 in new_do_write ()
#4  0x080861ed in _IO_new_do_write ()
#5  0x080869c5 in _IO_new_file_overflow ()
#6  0x08085f3e in _IO_new_file_xsputn ()
#7  0x080c4d54 in vfprintf ()
#8  0x080b071c in __fprintf_chk ()
#9  0x0805ec36 in fprint_track_hum ()
#10 0x0805efe1 in fprint_hash_tracks ()
#11 0x08049c33 in main (argc=22, argv=0xbfffeac4) at harness.c:537

虽然我没有看到对 _L_lock_154 的调用，但我开始认为它可能与打印到 file/stdio.h 相关 - 锁定写入文件指针或类似的东西。所以我会尝试禁用所有打印和重新配置，看看神秘功能是否消失..

更新 #1

不 - 它仍然有点神秘，禁用所有输出到文件/标准输出，但险恶的 _L_lock_154 仍然占用了我 10% 的时间。可能与从文件中读取有关，但如果没有一些输入，我就无法运行我的线束..

我真的很惊讶谷歌在这方面空白 - 非常罕见..

更新 #2

只是在调用图中而不是平面模式下运行 gprof - 它为 _L_lock_154 吐出这个：

granularity: each sample hit covers 4 byte(s) for 0.03% of 36.86 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]     49.6   11.82    6.45                 _L_lock_154 [1]
                5.84    0.00 1198163721/1198163721     double_cmp [8]
                0.52    0.00 125628587/125628587     fptype_cmp [24]
                0.04    0.00 13096233/13096233     grp_cmp_by_density_descending [52]
                0.04    0.00 3464916/3464916     pdw_ptr_cmp_by_amp [53]
                0.01    0.00   73812/73812       pdw_ptr_cmp_by_idx [89]
                0.00    0.00   71682/9288620     int_cmp [44]
                0.00    0.00  636314/842100      pri_ptr_cmp_by_second_pdw_idx [123]
                0.00    0.00  277089/407783      pri_ptr_cmp_by_first_pdw_idx [124]
                0.00    0.00   76178/76178       window_cmp_by_emitter_id [128]
                0.00    0.00   10147/10147       pri_ptr_cmp_by_first_pdw_toa [137]
-----------------------------------------------

我确定这是想告诉我一些事情，但我不确定如何解释它？我所有的 cmp 类型函数都用于 stdlib 中的 qsort - 如果 _L_lock_154 是所有这些调用的父级，是否意味着它是 qsort 的别名？

Answer 1

好的，gprof 在 CPU 时间采样，而在挂钟时间随机暂停采样。因此，当gprof 说例程需要 30% 的时间时，这意味着 CPU 时间，很可能不到挂钟时间的 1%。换句话说，你是 I/O-bound。因此，即使您可以使其花费 0 时间，您也永远不会看到差异。 （这就是我贬低“CPU 分析”的原因——它导致经验不足的程序员将注意力集中在无关紧要的事情上。）

如果不清楚，您的程序可能会进行 1 微秒的实际计算，其中很大一部分包括进入和退出例程的 I/O 堆栈。一旦它到达 I/O 堆栈的底部，它可能会等待 99 微秒，然后再出来并使用 CPU 1 微秒。 gprof 只是告诉你这 1% 的时间是如何使用的，就好像那是最重要的一样。

要在随机暂停中获得与gprof 相当的结果，您必须丢弃任何包含__kernel_vsyscall 的样本。因此，您可能必须先采集 100 个样本，然后才能找到一个实际使用 CPU 时间的样本。 工作量很大，但如果你这样做了，我希望你会在大约 30% 的非 I/O 样本上看到 Lock 例程。

请记住，gprof 是由在加州大学伯克利分校工作的人编写的，这是一个正在开发 unix 版本的学术环境。 它有一个内置假设——所有 I/O 都是必要的 I/O。 在真正的用户级软件中，通常情况并非如此。 此外，I/O 不是非 CPU 时间，它只是一个 不同 CPU。 有一个 I/O 控制器芯片运行该磁盘、端口或你有什么。