This class can be used to generate formatted output from time measurements of different subsections in a program. It is possible to create several sections that perform certain aspects of the program. A section can be entered several times. By changing the options in OutputFrequency and OutputType, the user can choose whether output should be generated every time a section is joined or just at the end of the program. Moreover, it is possible to show CPU times, wall times, or both.
To ensure output from this class is properly synchronized in parallel programs and to simplify internal data handling, output from this class can only be generated, if no subsection is currently being timed. I.e. all subsections have to be closed before producing output or accessing data.
The class is used in a substantial number of tutorial programs that collect timing data. step-77 is an example of a relatively simple sequential program that uses it. step-40 and several others mentioned below use it for parallel computations.
Usage
Use of this class could be as follows:
timer.enter_subsection ("Setup dof system");
setup_dofs();
timer.leave_subsection();
timer.enter_subsection ("Assemble");
assemble_system_1();
timer.leave_subsection();
timer.enter_subsection ("Solve");
solve_system_1();
timer.leave_subsection();
timer.enter_subsection ("Assemble");
assemble_system_2();
timer.leave_subsection();
timer.enter_subsection ("Solve");
solve_system_2();
timer.leave_subsection();
When run, this program will return an output like this:
+---------------------------------------------+------------+------------+
| Total wallclock time elapsed since start | 88.8s | |
| | | |
| Section | no. calls | wall time | % of total |
+---------------------------------+-----------+------------+------------+
| Assemble | 2 | 19.7s | 22% |
| Solve | 2 | 3.03s | 3.4% |
| Setup dof system | 1 | 3.97s | 4.5% |
+---------------------------------+-----------+------------+------------+
The output shows that we entered the assembly and solve section twice, and reports how much time we spent there. Moreover, the class measures the total time spent from start to termination of the TimerOutput object. In this case, we did a lot of other stuff, so that the time proportions of the functions we measured are far away from 100 percent.
Using scoped timers
The scheme above where you have to have calls to TimerOutput::enter_subsection() and TimerOutput::leave_subsection() is awkward if the sections in between these calls contain return statements or may throw exceptions. In that case, it is easy to forget that one nevertheless needs to leave the section somehow, somewhere. An easier approach is to use "scoped" sections. This is a variable that when you create it enters a section, and leaves the section when you destroy it. If this is a variable local to a particular scope (a code block between curly braces) and you leave this scope due to a return statements or an exception, then the variable is destroyed and the timed section is left automatically. Consequently, we could have written the code piece above as follows, with exactly the same result but now exception-safe:
{
setup_dofs();
}
{
assemble_system_1();
}
{
solve_system_1();
}
{
assemble_system_2();
}
{
solve_system_2();
}
Usage in parallel programs using MPI
In a parallel program built on MPI, using the class in a way such as the one shown above would result in a situation where each process times the corresponding sections and then outputs the resulting timing information at the end. This is annoying since you'd get a lot of output – one set of timing information from each processor.
This can be avoided by only letting one processor generate screen output, typically by using an object of type ConditionalOStream instead of std::cout to write to screen (see, for example, step-17, step-18, step-32 and step-40, all of which use this method).
This way, only a single processor outputs timing information, typically the first process in the MPI universe. However, if you take the above code snippet as an example, imagine what would happen if setup_dofs() is fast on processor zero and slow on at least one of the other processors; and if the first thing assemble_system_1() does is something that requires all processors to communicate. In this case, on processor zero, the timing section with name "Setup dof system" will yield a short run time on processor zero, whereas the section "Assemble" will take a long time: not because assemble_system_1() takes a particularly long time, but because on the processor on which we time (or, rather, the one on which we generate output) happens to have to wait for a long time till the other processor is finally done with setup_dofs() and starts to participate in assemble_system_1(). In other words, the timing that is reported is unreliable because it reflects run times from other processors. Furthermore, the run time of this section on processor zero has nothing to do with the run time of the section on other processors but instead with the run time of the previous section on another processor.
The first way to avoid this is to introduce a barrier into the parallel code just before we start and stop timing sections. This ensures that all processes are at the same place and the timing information then reflects the maximal run time across all processors. To achieve this, you need to initialize the TimerOutput object with an MPI communicator object, for example as in the following code:
Here, pcout is an object of type ConditionalOStream that makes sure that we only generate output on a single processor. See the step-32, step-40, and step-42 tutorial programs for this kind of usage of this class.
The second variant to cope with this issue is print more information about the recorded times to be able to understand this kind of imbalances without actually adding the barriers. While this approach is still affected by imbalances between different MPI processes, its output is not the arbitrary time of rank 0, but the minimum, average and maximum of the MPI results, using information from Utilities::MPI::MinMaxAvg. As the data is also equipped with the rank id where the minimum and maximum are attained, this approach allows to identify on which ranks certain slowdowns occur. In case some imbalance between the MPI ranks from one section to the next can be tolerated, this strategy can hence be advantageous over the barrier variant as it does not synchronize the program in places where it is not necessary, and rather tries to display the imbalance observed in various phases. In order to use this variant initialize the output object without any native print settings and without communicator,
and then call
timer.print_wall_time_statistics(MPI_COMM_WORLD);
where appropriate. Here, the output is written to the pcout object of type ConditionalOStream passed to the constructor, making sure the information is only printed once. See step-67 for an example usage of this variant. Besides the basic minimum, average, and maximum of times over all MPI ranks, the TimerOutput::print_wall_time_statistics() function also takes a second argument to specify output of quantiles, e.g., the time taken by the 10% of the slowest and fastest ranks, respectively, to get additional insight into the statistical distribution.
Definition at line 649 of file timer.h.
1.9.8