diff --git a/Makefile.am b/Makefile.am index 3c9849ba6ff747d479abef2f1b5902cc7305d394..e410ff1a2148349e8917f90df3be55287e9f1682 100644 --- a/Makefile.am +++ b/Makefile.am @@ -67,7 +67,7 @@ ftimings_@FCNAME@_example_LDFLAGS = -static ftimings_c_example_SOURCES = \ examples/c_example.c ftimings_c_example_LDADD = libftimings-@API_VERSION@-@FCNAME@.la -ftimings_c_example_LDFLAGS = $(FCLIBS) +ftimings_c_example_LDFLAGS = -static $(FCLIBS) # Small test programs: diff --git a/examples/c_example.c b/examples/c_example.c index 15b8909b19a3f14a8ec971e6aa50c9988ff092de..cdeb2084c6886c6edbb083ecd41c42ae4a21a169 100644 --- a/examples/c_example.c +++ b/examples/c_example.c @@ -35,6 +35,10 @@ int main(int argc, char **argv) { ftimings_print(timer, 0.0, "foobar", "blafasel"); 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 */ ftimings_start(timer, "overhead"); @@ -78,19 +82,19 @@ int main(int argc, char **argv) { ftimings_print(timer, 0.0); printf("\n"); - printf("Time spent in \"blafasel\" entries: %g\n", + printf("Time spent in \"blafasel\" entries: %.6f\n", 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")); - 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")); - printf("\nIncluding PAPI (if usable):\n %.2g microseconds\n", + printf("\nIncluding PAPI (if usable):\n %.2f microseconds\n", 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")); - 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); diff --git a/examples/example.F90 b/examples/example.F90 index aa0fac7c5f96d8f6204ea398b0eb6fb3f2511876..7940489928066a9f6b834f86ca95512b206d8baa 100644 --- a/examples/example.F90 +++ b/examples/example.F90 @@ -74,10 +74,12 @@ program test_timings endif write(*,*) 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,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,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 write(*,'(a,f12.6)') " cycle -> a -> b -> c : ", timer%get("main-loop", "cycle", "a", "b", "c") #else diff --git a/ftimings/ftimings.F90 b/ftimings/ftimings.F90 index 1a67f40cb0b34166235836b8e2306b9e5e84daaa..e6c139abbd6cf8fcea5ee186498460a8e89794fd 100644 --- a/ftimings/ftimings.F90 +++ b/ftimings/ftimings.F90 @@ -163,6 +163,14 @@ module ftimings procedure, pass :: get_node => timer_get_node procedure, pass :: get_value => timer_get_value 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_node => timer_since_node procedure, pass :: sort => timer_sort @@ -1068,6 +1076,15 @@ module ftimings !> 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 The seconds spent in that node + !> function timer_get(self, name1, name2, name3, name4, name5, name6) result(s) class(timer_t), intent(inout), target :: self character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6 @@ -1107,7 +1124,21 @@ module ftimings s = real(node%value%micros, kind=rk) * 1e-6_rk 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) class(timer_t), intent(inout) :: self character(len=*), intent(in), optional :: name1, name2, name3, name4, name5, name6 @@ -1132,6 +1163,95 @@ module ftimings v = node%value 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 !> names of the nodes along the graph from the root node and return the !> seconds that have passed since the entry was created. @@ -2215,6 +2335,44 @@ module ftimings s = real(node%value%micros, kind=rk) * 1e-6_rk 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); 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 diff --git a/ftimings/ftimings.h b/ftimings/ftimings.h index 92078598471fdf10897ac136b02b49bfc765f0d7..05eb2a5788187329171a9c7a9743e5e1e461d475 100644 --- a/ftimings/ftimings.h +++ b/ftimings/ftimings.h @@ -22,20 +22,6 @@ #include -#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) double ftimings_in_entries_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) 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 diff --git a/ftimings/ftimings_c_support.c b/ftimings/ftimings_c_support.c index 29cf707dbd74919d0c21879afab7a84bcb9c586c..85a4a280a33fcf8d18b59977b96a03a7efc74cc9 100644 --- a/ftimings/ftimings_c_support.c +++ b/ftimings/ftimings_c_support.c @@ -7,6 +7,19 @@ #include #include +#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 verbose_debug = 0; @@ -83,6 +96,20 @@ double ftimings_get_impl(ftimer_t *timer, ...) { 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, ...) { ftimer_node_t *node; __ftimings_node_from_args(node, timer, return NAN);