Basilisk source code (http://basilisk.fr/src/)

root / src / README.trace.page

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
# Built-in profiling

Functions marked with the [trace](/Basilisk C#tracing-and-profiling)
keyword can be automatically instrumented to keep a record of how much
time is spent within each of these functions. In addition the time
spent in [events](/Basilisk C#events) can also be automatically
tracked.

To activate built-in profiling the *TRACE* macro needs to be set with
a value larger than 1 for example using

~~~bash
CFLAGS=-DTRACE=2 make test.tst
~~~

or

~~~bash
qcc -DTRACE=2 test.c -o test -lm
~~~

After execution, the program will then produce a report on standard
output looking like

~~~bash
cat test/out
...
   calls    total     self   % total   function
    2193     1.09     1.09     43.2%   boundary():/home/popinet/basilisk-octree/src/grid/cartesian-common.h:268
     874     1.28     0.96     38.0%   update_saint_venant():/home/popinet/basilisk-octree/src/saint-venant.h:272
     438     0.60     0.19      7.5%   adapt():bump2D.c:65
      18     0.19     0.18      7.2%   output_field():/home/popinet/basilisk-octree/src/output.h:100
     874     0.41     0.05      2.1%   advance_saint_venant():/home/popinet/basilisk-octree/src/saint-venant.h:100
     438     0.02     0.02      0.7%   logfile():bump2D.c:23
  147456     0.01     0.01      0.5%   interpolate():/home/popinet/basilisk-octree/src/grid/cartesian-common.h:581
       1     2.52     0.01      0.3%   run():/home/popinet/basilisk-octree/src/predictor-corrector.h:80
       9     0.20     0.00      0.2%   outputfile():bump2D.c:49
       3     0.00     0.00      0.1%   init_grid():/home/popinet/basilisk-octree/src/grid/tree.h:1527
       1     0.00     0.00      0.1%   defaults():/home/popinet/basilisk-octree/src/predictor-corrector.h:45
       1     0.00     0.00      0.0%   init_0():bump2D.c:18
       1     0.00     0.00      0.0%   init():/home/popinet/basilisk-octree/src/saint-venant.h:310
       1     0.00     0.00      0.0%   defaults_0():/home/popinet/basilisk-octree/src/saint-venant.h:299
~~~

The first column is the number of times the function was called. The
second column is the total time spent within the function (including
any calls to other functions). The third column is the time spent
within the function, excluding any time spent within called functions
which are traced, i.e. this is really the time spent executing
instructions belonging to the function. The "self" time is what is
used to rank the function and to report the percentage of the total
time indicated in the fourth column. The fifth column gives the name
of the traced function, the file it belongs to and the line number
corresponding to the point where the function returned (i.e. the end
of the function, not the start).

For this example (the [bump2D](test/bump2D.c) test case), we see that
we spent 1.09 seconds (43.2% of the total) applying boundary
conditions (this is mostly coarse/fine interpolations due to adaptive
refinement), 0.96 seconds (38%) doing actual work (in the
[Saint-Venant solver](saint-venant.h#computing-fluxes)), 0.19 seconds
(7.5%) doing mesh adaptation, and so on. We also see that
*output_field()* used a significant amount of the total (7.2%) i.e. we
could easily speed up the calculation (a bit) by outputting less often
(i.e. less than 18 times).

## Graphing tools

It is sometimes useful to monitor the evolution with time of how much
time is taken by each function. This can be done by adding something
like:

~~~literatec
#if TRACE > 1
event profiling (i += 20) {
  static FILE * fp = fopen ("profiling", "w");
  trace_print (fp, 1);
}
#endif
~~~

where argument `1` specifies that only functions taking more than one
percent of runtime should be displayed. The `profiling` file will
contain records looking like the above but measured between successive
calls to the `trace_print()` function (not over the entire program
runtime). These data can be conveniently displayed using

~~~bash
gnuplot> load ("< awk -f $BASILISK/trace.awk < profiling");
~~~

which will display a graph looking like:

![Output of the `trace.awk` profiling script](figures/trace.png)

The functions are arranged in decreasing order of runtime (for example
here the `project()` function takes the largest proportion of the
runtime, followed by `mpi_waitany()` etc.). The horizontal axis is the
time, where the units are the number of outputs of the `profiling()`
event above.

This can also be automated using [continuous monitoring](profiling.h).

# See also

* [Built-in memory profiling](README.mtrace)