brk(0) 是否花费了太多时间？

Question

这是strace -T -ttt -ff -x -y -o pid.trace -p 2145 的输出。跟踪如下。

1503431273.934716 semop(1204093022, {{0, 1, SEM_UNDO}}, 1) = 0 
1503431273.934737 clock_gettime(CLOCK_REALTIME, {1503431273, 934741536}) = 0 
1503431273.934763 写入（6/red/samples/debug/hexa.debug>，“17.08.23 01:17:53 [ hexa:2145”...，79）= 79 
1503431273.934960 brk(0) = 0x1adc000 
1503431273.934974 brk(0x1afd000) = 0x1afd000 
1503431273.934994 brk(0) = 0x1afd000 
1503431273.935006 brk(0) = 0x1afd000 
1503431273.935017 brk(0x1afc000) = 0x1afc000 
1503431273.935033 brk(0) = 0x1afc000 
1503431273.935045 brk(0) = 0x1afc000 
1503431273.935057 brk(0) = 0x1afc000 
1503431273.935068 brk(0x1afb000) = 0x1afb000 
1503431273.935080 brk(0) = 0x1afb000 
1503431291.010338 brk(0) = 0x1afb000 
1503431291.010366 brk(0x1b1c000) = 0x1b1c000 
1503431291.010391 brk(0) = 0x1b1c000 
1503431291.010403 brk(0) = 0x1b1c000 
1503431291.010414 brk(0x1b12000) = 0x1b12000 
1503431291.010430 brk(0) = 0x1b12000 
1503431291.010443 brk(0) = 0x1b12000 
1503431291.010455 brk(0) = 0x1b12000 
1503431291.010466 brk(0x1b11000) = 0x1b11000 
1503431291.010478 brk(0) = 0x1b11000 
1503431301.277050 clock_gettime(CLOCK_REALTIME, {1503431301, 277067441}) = 0 
1503431301.277094 写（6/red/samples/debug/hexa.debug>，“17.08.23 01:18:21 [ hexa:2145”...，91）= 91 
1503431301.277201 clock_gettime(CLOCK_REALTIME, {1503431301, 277216542}) = 0 
1503431301.277234 写入（6/red/samples/debug/hexa.debug>，“17.08.23 01:18:21 [ hexa:2145”...，126）= 126 
1503431301.277296 clock_gettime(CLOCK_REALTIME, {1503431301, 277301142}) = 0 
1503431301.277317 write(6/red/samples/debug/hexa.debug>, "17.08.23 01:18:21 [ hexa:2145"..., 126) = 126 
1503431301.288030 clock_gettime(CLOCK_REALTIME, {1503431301, 288037704}) = 0 

如果您在两个 brk(0)（请参阅 1503431273.935080 和 1503431291.010478）上查看上述跟踪，分别花费了太多时间，分别约为 17 秒和 10 秒 （比较左侧时间）。但是右侧的执行时间很短。我在同一个 Redhat Linux box (7.2) 中多次运行了这个程序，所有运行都在系统调用的同一位置 (brk(0)) 给出了相同的时间（微秒差异）。

可能是什么问题？它是在编程级别还是操作系统级别？我没有这方面的源代码，但我知道它是一个 c/c++ 程序。

Answer 1

回答标题中的问题：不，brk(0) 不会花太多时间。

您可以通过查看系统调用本身报告的时间来查看这一点（<0.000003>，由-T 选项添加）。这只有 3 微秒。

左边的值是（绝对）时间戳。但这只是意味着该进程在 1503431273.935080 处执行了 brk 系统调用，在 1503431291.010338 处执行了另一个系统调用。这并不意味着任何一个系统调用都需要 17 秒。这只是意味着该进程需要 17 秒才能到达下一个系统调用。

该进程可能一直在做许多其他事情，例如进行原始计算（消耗 CPU），或者没有被调度（因为系统正忙于其他程序）。后一种选择当然不太可能，因为您说这发生在程序的多次运行中。因此，我认为最可能的解释是代码只是花费大量时间计算事物而无需调用内核（例如，循环中的紧密数字代码，没有内存分配）。