timer.hh File Reference
Timing nested tasks. More...
Go to the source code of this file.
Classes | |
| class | ScopedTimer |
| Allow the timing of a task within a scope. More... | |
Detailed Description
Timing nested tasks.The purpose of the class Timer provided here is to measure the time user-defined tasks use in the execution of a program.
Each task is identified by a unique name (std::string), or alternatively, once task has been declared, by an id number. Special characters in task names must be escaped for the XML export to work properly.
The program source code must be equipped with calls to methods of the Timer instance.
For the timing to be accurate, a task should take 1ms of execution time or more (preferably over 10ms).
Once all the relevant timing data are gathered, the Timer object builds a graph of the results (using the boost graph library), which can be printed to a stream or exported in DOT format. Alternatively, export of the complete results in XML format for further analysis will be made available.
How to use this timer in Vaucauson (taf-kit):
A global timer is declared in taf-kit/src/common.hh. See misc/global_timer.hh for a list of commands on the global timer (using macro definitions).
Refer to the description of the class's methods below.
The global timer is automatically started and stopped in taf-kit/tests/vcsn* programs. Only the source code of automata manipulation algorithm has to be equipped with declaration an execution of tasks (using TIMER_SCOPED(Task) alone or TIMER_PUSH(Task) and TIMER_POP() together).
To obtain a detailed report of the results on std::cerr, use the command-line option --report-time (results are not printed otherwise). This option takes an optional int argument as the verbose degree of the report (from 1 to 3, default 2)
To export the graph of the timing results in DOT format on std::cerr, use the command-line option --export-time-dot. This option takes an optional int argument as the verbose degree of the graph (from 0 to 3, default 2)
To dump the timer in XML format on std::cerr, use the command-line option --export-time-xml.
To benchmark several executions of the same set of tasks, use the command-line option --bench=X where X is the number of iterations. A summary of the results is printed on std::cerr.
How to use this timer outside Vaucanson:
- Create an instance of misc::Timer.
- Before the beginning of the sequence of tasks (which can be nested), insert a call to Timer.start (). This will initialize the timer, discarding any previous data. The special task _program_ will be initialized here. This task computes the total time of the program: Do not use it elsewhere.
- Declare and execute tasks. The data gathering process is based on a stack (comparable to a system call stack): use push () and pop () methods accordingly.
There are two ways to refer to a given task:
- Its unique name can be passed to every function requiring it (as in Timer.push ("MyTask")). This leads to a map lookup which can be costly with a large number of tasks.
- It can be declared using Timer.task ("MyTask"). This method returns the task's id (creating the task in the process if it doesn't exist). This id is an int and can be used in place of the task's full name. It removes the map lookup, thus decreasing the influence of the timer's data gathering on the program.
There are two ways to time a task:
- Calls can be explicitely made to Timer.push (Task) and Timer.pop (). Tasks may be nested, recursive, and may form cycles e.g. A -> B -> A. Only the task started last can be stopped. Timer.pop (Task) fails if the Task is not the task on top of the timer's internal stack.
- A class ScopedTimer (Timer, Task) is provided. It simply calls Timer.push (Task) upon creation and Timer.pop () upon destruction. Instanciate it in a scope, i.e. at the beginning of a function.
- After the part of the program to be timed, insert a call to Timer.stop (). This computes the data into a graph. The timer can't be resumed.
* Once stopped, standard arithmetic operators (+, +=, /, /=) can be used on timers, e.g. to calculate the mean of several iterations of the same program. The structure of timers added to each other must be strictly identical (same function calls). A Timer.join () method might appear in the future.
- Print the results using Timer.print (Stream, VerboseDegree). VerboseDegree represents the amount of information printed. Available VerboseDegree values are: misc::timer::VERBOSE_NONE misc::timer::VERBOSE_MINIMAL misc::timer::VERBOSE_NORMAL (Default) misc::timer::VERBOSE_MAXIMAL
* In this report, task names can be truncated to fit the layout. See the description of the report's fields below.
- Export the results in DOT format using Timer.export(Stream, VerboseDegree, ChargeColorRatio). VerboseDegree is the same as above. ChargeColorRatio controls the adjustement of the graph node colors to the task's self charge. The node color ranges from cyan to red. Increasing ChargeColorRatio makes nodes attain red for lower charges. This is for fine tuning, as the color is internally adjusted to the number of tasks. Default value for ChargeColorRatio is 1.0.
- Subsequent calls to Timer.start () would initialize the timer, thus allowing the same timer to time different sets of tasks in a row (results are discarded upon calling Timer.start ()).
Note on performance:
The data gathering process is generally non-obtrusive (timing one task by its id takes about 1 extra microsecond). However, for a large number of small tasks, using only full name lookup may impact the results.
Documentation for the standard report:
The report obtained using Timer.print () is 80 columns wide. Task names are truncated to fit. Times are reported in the most accurate unit (among hours, minutes, seconds, and milliseconds), except in the task list where the same unit is shared between all tasks' total and self times.
Task list:
- charge: Percentage of the total program time the task has taken by itself.
- total: Total time spent in the task and its children. If the task is part of a cycle (total time is irrelevant), the cycle id is printed there.
- self: Time spent in the task itself.
- calls: Total number of calls to the task, including recursive calls
- self avg.: Average time spent in the task itself per call.
- total avg.: Average time a call to the task takes to return. If the task is part of a cycle (total time is irrelevant), the cycle id is printed there.
Call graph (VERBOSE_NORMAL or higer):
Cycles:
- charge: percentage of the program time spent in the cycle/task.
- total: total time spent in the cycle and the external tasks it called.
- self: time spend in the cycle/task itself.
- calls:e/i: (e) Calls to the cycle/task from outside the cycle. (i) Calls to the cycle/task from inside the cycle.
- int avg.: (cycle) Average time spent in a member per internal call. (task) Average time spent in the task itself per call.
- self avg.: Average time spent in the cycle itself per call from outside.
- total avg.: (cycle) Average time a call to the cycle from outside takes to return. (task) Task name is printed here.
Tasks: This section lists each task, as well as its incoming and outgoing calls. Incoming calls are listed above the task (D: <-), while outgoing calls are listed below (D: ->).
- Incoming calls:
- name: Name of the caller.
- charge: Percentage of the called task's charge caused by the call.
- self: Part of the called task's self time caused by the call.
- calls: Number of calls from this caller.
- self avg.: Average time spend in the called task per call from this caller.
- Task: See Task list.
- Outgoing calls:
- name: Name of the called task.
- charge: Percentage of the called task's charge caused by the call.
- self: Part of the called task's self time caused by the call.
- calls: Number of calls to this task.
- self avg.: Average time spend in the called task per call.
Note: Recursive calls are listed both in incoming and outgoing calls.
Detailed tasks (VERBOSE_MAXIMAL):
Each task is listed here with its gathered data.
Self time refers to the time spent in the task itself. Total time refers to the time spent in the task and its children.
All times are in clock ticks.
User time is the time spent in user code. System time is the time spent in system calls. Cpu time is the total time the cpu spent in the program. It is the value used in the previous parts of the report. Wall time is the real time spent in the task, i.e. the time observed by the user on a wall clock.
Definition in file timer.hh.
