0

This is an output of strace -T -ttt -ff -x -y -o pid.trace -p 2145 . Trace given below.

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

if you look at the above trace at two brk(0)s (please see 1503431273.935080 and 1503431291.010478) taking too much time, around 17 seconds and 10 seconds respectively (comparing left side time). But execution time in the right side is just minimal. I have done multiple runs of this program, in the same Redhat Linux box (7.2), all runs were giving same timings (with microseconds difference) at same place of system call (brk(0)).

What could be the issue? is it at Programming Level or OS level? I am not having source code for this, but I know it is a c/c++ program.

melpomene
  • 84,125
  • 8
  • 85
  • 148
Umesh C G
  • 45
  • 5
  • why html tag is not coming? – Umesh C G Aug 23 '17 at 18:32
  • Last time I checked, [`strace`](https://linux.die.net/man/1/strace) still reported in μs, not seconds, so that's more like 17.8 μs. – dhke Aug 23 '17 at 18:32
  • 1
    Because it was part of an (indented) code block. Those get rendered verbatim. – melpomene Aug 23 '17 at 18:33
  • Nice fix to the markup, @melpomene. I trust you had a program do the grunt work for you. – Jonathan Leffler Aug 23 '17 at 18:34
  • @JonathanLeffler vim and a few regex substitutions. :-) – melpomene Aug 23 '17 at 18:35
  • 2
    @dhke `man strace`: "*`-ttt` ... the time printed will include the microseconds and the leading portion will be printed as the number of seconds since the epoch.*" So the number before the `.` is still in seconds. – melpomene Aug 23 '17 at 18:36
  • @melpomene ah, thanks. I stand corrected. – dhke Aug 23 '17 at 18:36
  • One possibility is that the system was rather busy with other processes while your program was hung up in the `brk()` system call. The problem may be nothing to do with `brk()` except that it happened to be the system call that allowed the O/S to take control again and run other processes instead of yours. – Jonathan Leffler Aug 23 '17 at 18:38

1 Answers1

3

To answer the question in the title: No, brk(0) is not taking too much time.

You can see this by looking at the time reported for the syscall itself (<0.000003>, added by the -T option). That's only 3 microseconds.

The values on the left are (absolute) timestamps. But that just means the process performed a brk syscall at 1503431273.935080 and another syscall at 1503431291.010338. That doesn't mean any single syscall took 17 seconds; it just means it took 17 seconds for the process to reach the next syscall.

The process could have been doing many other things, such as doing raw computation (burning CPU), or not being scheduled (because the system was busy with other programs). The latter option is admittedly unlikely because you said this happened in multiple runs of the program. Therefore I think the most likely explanation is that the code just spends a lot of time computing things without needing to call the kernel (e.g. tight numeric code in a loop, with no memory allocation).

melpomene
  • 84,125
  • 8
  • 85
  • 148
  • Thanks for reply. I too think about this, but got confused when saw this question and answer. https://stackoverflow.com/q/42535397/3027028 – Umesh C G Aug 23 '17 at 20:06