8. Where the time goes

fobis profile CASE builds a case with a profiler's flags, in its own directory, runs it, and maps the profiler's report to the project: procedures by their module, source lines with their text, the time spent outside the sources and who calls it.

The default tool is gprof, a sampling profiler:

$ fobis profile fine 2>/dev/null
profile fine (gprof): 0 s
  routines (self):
      0.0%  0 s  __integrands_MOD_sine = integrands::sine (src/integrands.F90:10), 8000002 calls
      0.0%  0 s  MAIN__ = area (src/area.F90:2), 1 calls
      0.0%  0 s  __quad_rules_MOD_simpson = quad_rules::simpson (src/quad_rules.F90:61), 1 calls
      0.0%  0 s  __quad_rules_MOD_trapezoid = quad_rules::trapezoid (src/quad_rules.F90:38), 1 calls
  note: no time measured: the run is shorter than one 0.01 s sample; only the call counts are facts (profile a longer case, or use --tool callgrind, which counts instructions)
  note: procedures inlined by the compiler count in their caller (callgrind's per-line view attributes them to their own lines)

The case runs in a few hundredths of a second, so gprof took no sample: only its call counts are facts, as the note says. callgrind counts the instructions every line executes instead, however short the run (and runs the program some tens of times slower):

$ fobis profile fine --tool callgrind --top 6 2>/dev/null
profile fine (callgrind): 756,982,530 instructions, 14.8% in the mode's sources
  routines (self):
     85.2%  644,679,162 Ir  __sin_fma (outside the sources: runtime, libraries)
             called by integrands::sine (src/integrands.F90:10): 8,000,002 calls, 85.16%
      5.8%  44,000,060 Ir  __quad_rules_MOD_simpson = quad_rules::simpson (src/quad_rules.F90:61)
      5.8%  44,000,033 Ir  __quad_rules_MOD_trapezoid = quad_rules::trapezoid (src/quad_rules.F90:38)
      3.2%  24,000,006 Ir  __integrands_MOD_sine = integrands::sine (src/integrands.F90:10)
      0.0%  60,940 Ir  do_lookup_x (outside the sources: runtime, libraries)
      0.0%  45,058 Ir  _dl_relocate_object (outside the sources: runtime, libraries)
  project procedures (by their source lines, inlined code included):
      5.8%  quad_rules::simpson
      5.8%  quad_rules::trapezoid
      3.2%  integrands::sine
      0.0%  area
  hottest lines:
      5.0%  src/quad_rules.F90:56  s = s + f(a + i * h)
      3.2%  src/integrands.F90:15  y = sin(x)
      2.5%  src/quad_rules.F90:84  odd = odd + f(a + i * h)
      2.5%  src/quad_rules.F90:88  even = even + f(a + i * h)
      0.8%  src/quad_rules.F90:55  do i = 1, n - 1
      0.4%  src/quad_rules.F90:83  do i = 1, n - 1, 2
  note: instructions executed (Ir), not time: memory stalls, cache misses and vector width are not weighed

85% of the instructions are in sin, a library routine, called 8 million times from integrands::sine. The quadrature loops are the rest: making them faster could not gain more than 15%. The new Simpson loops (lines 84 and 88) execute half the instructions of the trapezoid loop each, as they visit half the nodes.

Measured, not generated

Profiles depend on the machine and on its libraries (here glibc's __sin_fma): these outputs were recorded once.

On a GPU, --tool nsys maps the kernel time to the OpenACC or OpenMP directive lines and reports the host-device transfers per direction and per source line: chapter 9 uses it on a cluster.

What you learned

fobis profile, --tool gprof|callgrind|nsys, reading the share outside the sources. Reference: profiling.

Next: 9. On a cluster.