c - 使用 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

(仅取第一几行)

占据首位是我不认识的功能，不幸的是谷歌也不认识。

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

使用 Mikes 建议进行 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 限制。因此，即使您可以使其花费 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 Controller 芯片运行该磁盘、端口或您拥有的东西。