Commit d336cb45 authored by Lorenz Huedepohl's avatar Lorenz Huedepohl

A couple of new routines to query usage of children

The type timer_t got two new kind of methods to query information about
the resource usage if its children. The method

  %get_in_children

queries the seconds spent in all children of the queried node, and

  %get_without_children

conversely returns the number of seconds spent excluding all children.

Additionally, there also version where the node in question is passed
directly instead of by a string path (*_node) and versions where the
result is a type(value_t) with all measurements (get_value_*).
parent 72202d7e
...@@ -67,7 +67,7 @@ ftimings_@FCNAME@_example_LDFLAGS = -static ...@@ -67,7 +67,7 @@ ftimings_@FCNAME@_example_LDFLAGS = -static
ftimings_c_example_SOURCES = \ ftimings_c_example_SOURCES = \
examples/c_example.c examples/c_example.c
ftimings_c_example_LDADD = libftimings-@API_VERSION@-@FCNAME@.la ftimings_c_example_LDADD = libftimings-@API_VERSION@-@FCNAME@.la
ftimings_c_example_LDFLAGS = $(FCLIBS) ftimings_c_example_LDFLAGS = -static $(FCLIBS)
# Small test programs: # Small test programs:
......
...@@ -35,6 +35,10 @@ int main(int argc, char **argv) { ...@@ -35,6 +35,10 @@ int main(int argc, char **argv) {
ftimings_print(timer, 0.0, "foobar", "blafasel"); ftimings_print(timer, 0.0, "foobar", "blafasel");
printf("\n"); printf("\n");
printf("Time spent in \"foobar\": %.6f\n", ftimings_get(timer, "foobar"));
printf(" in \"foobar\"'s children: %.6f\n", ftimings_get_in_children(timer, "foobar"));
printf(" in \"foobar\" without its children: %.6f\n", ftimings_get_without_children(timer, "foobar"));
/* Loop with just _start and _stop calls to measure overhead */ /* Loop with just _start and _stop calls to measure overhead */
ftimings_start(timer, "overhead"); ftimings_start(timer, "overhead");
...@@ -78,19 +82,19 @@ int main(int argc, char **argv) { ...@@ -78,19 +82,19 @@ int main(int argc, char **argv) {
ftimings_print(timer, 0.0); ftimings_print(timer, 0.0);
printf("\n"); printf("\n");
printf("Time spent in \"blafasel\" entries: %g\n", printf("Time spent in \"blafasel\" entries: %.6f\n",
ftimings_in_entries(timer, "blafasel")); ftimings_in_entries(timer, "blafasel"));
printf("Time spent in \"blafasel\" entries below \"foobar\": %g\n", printf("Time spent in \"blafasel\" entries below \"foobar\": %.6f\n",
ftimings_in_entries(timer, "foobar", "blafasel")); ftimings_in_entries(timer, "foobar", "blafasel"));
printf("\nOverhead of ftimings_start() + ftimings_stop() calls:\n %.2g microseconds\n", printf("\nOverhead of ftimings_start() + ftimings_stop() calls:\n %.2f microseconds\n",
ftimings_get(timer, "overhead")); ftimings_get(timer, "overhead"));
printf("\nIncluding PAPI (if usable):\n %.2g microseconds\n", printf("\nIncluding PAPI (if usable):\n %.2f microseconds\n",
ftimings_get(timer, "overhead_papi")); ftimings_get(timer, "overhead_papi"));
printf("\nIncluding PERF (if usable):\n %.2g microseconds\n", printf("\nIncluding PERF (if usable):\n %.2f microseconds\n",
10 * ftimings_get(timer, "overhead_perf")); 10 * ftimings_get(timer, "overhead_perf"));
printf("\nTime since program start: %.2g seconds\n", ftimings_since(timer)); printf("\nTime since program start: %.2f seconds\n", ftimings_since(timer));
ftimings_destroy(timer); ftimings_destroy(timer);
......
...@@ -74,10 +74,12 @@ program test_timings ...@@ -74,10 +74,12 @@ program test_timings
endif endif
write(*,*) write(*,*)
write(*,'(a,f12.6)') " cycle total : ", timer%get("main-loop", "cycle") write(*,'(a,f12.6)') " cycle total : ", timer%get("main-loop", "cycle")
write(*,'(a,f12.6)') " cycle '(own)': ", timer%get_without_children("main-loop", "cycle")
write(*,'(a,f12.6)') "cycle children: ", timer%get_in_children("main-loop", "cycle")
write(*,'(a,f12.6)') " in c entries: ", timer%in_entries("c") write(*,'(a,f12.6)') " in c entries: ", timer%in_entries("c")
write(*,'(a,f8.2,a)') " c part: ", timer%in_entries("c") / timer%get("main-loop", "cycle") * 100, "%" write(*,'(a,f8.2,a)') " c part: ", timer%in_entries("c") / timer%get("main-loop", "cycle") * 100, "%"
write(*,'(a,f12.6)') " in b entries: ", timer%in_entries("b") write(*,'(a,f12.6)') " in b entries: ", timer%in_entries("b")
write(*,'(a,f8.2,a)') " b part: ", timer%in_entries("b") / timer%get("main-loop", "cycle") * 100, "%" write(*,'(a,f8.2,a)') " b part: ", timer%in_entries("b") / timer%get("main-loop", "cycle") * 100, "%"
#ifndef _OPENMP #ifndef _OPENMP
write(*,'(a,f12.6)') " cycle -> a -> b -> c : ", timer%get("main-loop", "cycle", "a", "b", "c") write(*,'(a,f12.6)') " cycle -> a -> b -> c : ", timer%get("main-loop", "cycle", "a", "b", "c")
#else #else
......
...@@ -163,6 +163,14 @@ module ftimings ...@@ -163,6 +163,14 @@ module ftimings
procedure, pass :: get_node => timer_get_node procedure, pass :: get_node => timer_get_node
procedure, pass :: get_value => timer_get_value procedure, pass :: get_value => timer_get_value
procedure, pass :: get_value_node => timer_get_value_node procedure, pass :: get_value_node => timer_get_value_node
procedure, pass :: get_in_children => timer_get_in_children
procedure, pass :: get_in_children_node => timer_get_in_children_node
procedure, pass :: get_value_in_children => timer_get_value_in_children
procedure, pass :: get_value_in_children_node => timer_get_value_in_children_node
procedure, pass :: get_without_children => timer_get_without_children
procedure, pass :: get_without_children_node => timer_get_without_children_node
procedure, pass :: get_value_without_children => timer_get_value_without_children
procedure, pass :: get_value_without_children_node => timer_get_value_without_children_node
procedure, pass :: since => timer_since procedure, pass :: since => timer_since
procedure, pass :: since_node => timer_since_node procedure, pass :: since_node => timer_since_node
procedure, pass :: sort => timer_sort procedure, pass :: sort => timer_sort
...@@ -1068,6 +1076,15 @@ module ftimings ...@@ -1068,6 +1076,15 @@ module ftimings
!> The result is only meaningfull if the entry was never appended by !> The result is only meaningfull if the entry was never appended by
!> additional %start() calls. !> additional %start() calls.
!> !>
!> \param name1 If given, first descend one level to the node with name name1
!> \param name2 If given, also descend another level to the node with name2 there
!> \param name3 etc.
!> \param name4 etc.
!> \param name5 etc.
!> \param name6 etc.
!>
!> \returns The seconds spent in that node
!>
function timer_get(self, name1, name2, name3, name4, name5, name6) result(s) function timer_get(self, name1, name2, name3, name4, name5, name6) result(s)
class(timer_t), intent(inout), target :: self class(timer_t), intent(inout), target :: self
character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6 character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6
...@@ -1107,7 +1124,21 @@ module ftimings ...@@ -1107,7 +1124,21 @@ module ftimings
s = real(node%value%micros, kind=rk) * 1e-6_rk s = real(node%value%micros, kind=rk) * 1e-6_rk
end function end function
!> Access a specific, already stopped entry of the graph by specifying the
!> names of the nodes along the graph from the root node
!>
!> The result is only meaningfull if the entry was never appended by
!> additional %start() calls.
!>
!> \param name1 If given, first descend one level to the node with name name1
!> \param name2 If given, also descend another level to the node with name2 there
!> \param name3 etc.
!> \param name4 etc.
!> \param name5 etc.
!> \param name6 etc.
!>
!> \returns An object of type(value_t) with the resources spent in that node
!>
function timer_get_value(self, name1, name2, name3, name4, name5, name6) result(v) function timer_get_value(self, name1, name2, name3, name4, name5, name6) result(v)
class(timer_t), intent(inout) :: self class(timer_t), intent(inout) :: self
character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6 character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6
...@@ -1132,6 +1163,95 @@ module ftimings ...@@ -1132,6 +1163,95 @@ module ftimings
v = node%value v = node%value
end function end function
!> Analog to timer_get but returns only the seconds spent in all children of the
!> specified node
function timer_get_in_children(self, name1, name2, name3, name4, name5, name6) result(s)
class(timer_t), intent(inout) :: self
character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6
type(node_t), pointer :: node
real(kind=rk) :: s
node => self%resolve_node(name1, name2, name3, name4, name5, name6)
s = self%get_in_children_node(node)
end function
!> _node version of timer_get_in_children
function timer_get_in_children_node(self, node) result(s)
class(timer_t), intent(inout) :: self
type(node_t), pointer, intent(in) :: node
real(kind=rk) :: s
type(value_t) :: v
v = node%sum_of_children()
s = real(v%micros, kind=rk) * 1e-6_rk
end function
!> Analog to timer_get_value, but returns only the resources spent in all children of the
!> specified node
function timer_get_value_in_children(self, name1, name2, name3, name4, name5, name6) result(v)
class(timer_t), intent(inout) :: self
character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6
type(node_t), pointer :: node
type(value_t) :: v
node => self%resolve_node(name1, name2, name3, name4, name5, name6)
v = self%get_value_in_children_node(node)
end function
!> _node version of timer_get_value_in_children
function timer_get_value_in_children_node(self, node) result(v)
class(timer_t), intent(inout) :: self
type(node_t), pointer, intent(in) :: node
type(value_t) :: v
v = node%sum_of_children()
end function
!> Analog to timer_get, but returns only the seconds spent in this node
!> that are not spent in any children of the specified node
function timer_get_without_children(self, name1, name2, name3, name4, name5, name6) result(s)
class(timer_t), intent(inout) :: self
character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6
type(node_t), pointer :: node
real(kind=rk) :: s
type(value_t) :: v
node => self%resolve_node(name1, name2, name3, name4, name5, name6)
s = self%get_without_children_node(node)
end function
!> _node version of timer_get_without_children
function timer_get_without_children_node(self, node) result(s)
class(timer_t), intent(inout) :: self
type(node_t), pointer, intent(in) :: node
real(kind=rk) :: s
type(value_t) :: v
v = node%value - node%sum_of_children()
s = real(v%micros, kind=rk) * 1e-6_rk
end function
!> Analog to timer_get_value, but returns only the resource spent in this node
!> that are not spent in any children of the specified node
function timer_get_value_without_children(self, name1, name2, name3, name4, name5, name6) result(v)
class(timer_t), intent(inout) :: self
character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6
type(node_t), pointer :: node
type(value_t) :: v
node => self%resolve_node(name1, name2, name3, name4, name5, name6)
v = self%get_value_without_children_node(node)
end function
!> _node version of timer_get_value_without_children
function timer_get_value_without_children_node(self, node) result(v)
class(timer_t), intent(inout) :: self
type(node_t), pointer, intent(in) :: node
type(value_t) :: v
v = node%value - node%sum_of_children()
end function
!> Access a specific, not yet stopped entry of the graph by specifying the !> Access a specific, not yet stopped entry of the graph by specifying the
!> names of the nodes along the graph from the root node and return the !> names of the nodes along the graph from the root node and return the
!> seconds that have passed since the entry was created. !> seconds that have passed since the entry was created.
...@@ -2215,6 +2335,44 @@ module ftimings ...@@ -2215,6 +2335,44 @@ module ftimings
s = real(node%value%micros, kind=rk) * 1e-6_rk s = real(node%value%micros, kind=rk) * 1e-6_rk
end function end function
!c> double ftimings_get_in_children_node(ftimer_t *timer, ftimer_node_t *node);
function ftimings_get_in_children_node(timer_ptr, node_ptr) result(s) bind(c, name="ftimings_get_in_children_node")
type(c_ptr), value, intent(in) :: timer_ptr, node_ptr
real(kind=c_double) :: s
type(timer_t), pointer :: timer
type(node_t), pointer :: node
call c_f_pointer(timer_ptr, timer)
call c_f_pointer(node_ptr, node)
s = 0._rk
if (.not. timer%active) then
return
endif
s = timer%get_in_children_node(node)
end function
!c> double ftimings_get_without_children_node(ftimer_t *timer, ftimer_node_t *node);
function ftimings_get_without_children_node(timer_ptr, node_ptr) result(s) bind(c, name="ftimings_get_without_children_node")
type(c_ptr), value, intent(in) :: timer_ptr, node_ptr
real(kind=c_double) :: s
type(timer_t), pointer :: timer
type(node_t), pointer :: node
call c_f_pointer(timer_ptr, timer)
call c_f_pointer(node_ptr, node)
s = 0._rk
if (.not. timer%active) then
return
endif
s = timer%get_without_children_node(node)
end function
!c> double ftimings_since_node(ftimer_t *timer, ftimer_node_t *node); !c> double ftimings_since_node(ftimer_t *timer, ftimer_node_t *node);
function ftimings_since_node(timer_ptr, node_ptr) result(s) bind(c, name="ftimings_since_node") function ftimings_since_node(timer_ptr, node_ptr) result(s) bind(c, name="ftimings_since_node")
type(c_ptr), value, intent(in) :: timer_ptr, node_ptr type(c_ptr), value, intent(in) :: timer_ptr, node_ptr
......
...@@ -22,20 +22,6 @@ ...@@ -22,20 +22,6 @@
#include <ftimings/ftimings_generated.h> #include <ftimings/ftimings_generated.h>
#define __ftimings_node_from_args(node, last_arg, error_return) \
do { \
va_list args; \
va_start(args, last_arg); \
node = ftimings_node(timer, args); \
va_end(args); \
\
if (!node) { \
debug("ftimings_get_node() returned NULL"); \
error_return; \
} \
} while(0)
#define ftimings_in_entries(timer, ...) ftimings_in_entries_impl(timer, ##__VA_ARGS__, NULL) #define ftimings_in_entries(timer, ...) ftimings_in_entries_impl(timer, ##__VA_ARGS__, NULL)
double ftimings_in_entries_impl(ftimer_t *timer, ...); double ftimings_in_entries_impl(ftimer_t *timer, ...);
...@@ -48,4 +34,10 @@ double ftimings_get_impl(ftimer_t *timer, ...); ...@@ -48,4 +34,10 @@ double ftimings_get_impl(ftimer_t *timer, ...);
#define ftimings_since(timer, ...) ftimings_since_impl(timer, ##__VA_ARGS__, NULL) #define ftimings_since(timer, ...) ftimings_since_impl(timer, ##__VA_ARGS__, NULL)
double ftimings_since_impl(ftimer_t *timer, ...); double ftimings_since_impl(ftimer_t *timer, ...);
#define ftimings_get_in_children(timer, ...) ftimings_get_in_children_impl(timer, ##__VA_ARGS__, NULL)
double ftimings_get_in_children_impl(ftimer_t *timer, ...);
#define ftimings_get_without_children(timer, ...) ftimings_get_without_children_impl(timer, ##__VA_ARGS__, NULL)
double ftimings_get_without_children_impl(ftimer_t *timer, ...);
#endif #endif
...@@ -7,6 +7,19 @@ ...@@ -7,6 +7,19 @@
#include <stdio.h> #include <stdio.h>
#include <math.h> #include <math.h>
#define __ftimings_node_from_args(node, last_arg, error_return) \
do { \
va_list args; \
va_start(args, last_arg); \
node = ftimings_node(timer, args); \
va_end(args); \
\
if (!node) { \
debug("ftimings_get_node() returned NULL"); \
error_return; \
} \
} while(0)
static int looked_for_verbose_debug = 0; static int looked_for_verbose_debug = 0;
static int verbose_debug = 0; static int verbose_debug = 0;
...@@ -83,6 +96,20 @@ double ftimings_get_impl(ftimer_t *timer, ...) { ...@@ -83,6 +96,20 @@ double ftimings_get_impl(ftimer_t *timer, ...) {
return ftimings_get_node(timer, node); return ftimings_get_node(timer, node);
} }
double ftimings_get_in_children_impl(ftimer_t *timer, ...) {
ftimer_node_t *node;
__ftimings_node_from_args(node, timer, return NAN);
return ftimings_get_in_children_node(timer, node);
}
double ftimings_get_without_children_impl(ftimer_t *timer, ...) {
ftimer_node_t *node;
__ftimings_node_from_args(node, timer, return NAN);
return ftimings_get_without_children_node(timer, node);
}
double ftimings_since_impl(ftimer_t *timer, ...) { double ftimings_since_impl(ftimer_t *timer, ...) {
ftimer_node_t *node; ftimer_node_t *node;
__ftimings_node_from_args(node, timer, return NAN); __ftimings_node_from_args(node, timer, return NAN);
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment