From 77d00724dde5a564e7b218a5191bf3c6568df233 Mon Sep 17 00:00:00 2001 From: Brian Ezequiel Marchi Date: Tue, 1 Oct 2019 13:55:12 -0300 Subject: [PATCH 1/6] Make use of time source type for throttling logs Signed-off-by: Brian Ezequiel Marchi --- rcutils/logging.py | 3 ++- resource/logging_macros.h.em | 2 +- test/test_logging_macros.cpp | 4 ++-- 3 files changed, 5 insertions(+), 4 deletions(-) diff --git a/rcutils/logging.py b/rcutils/logging.py index 2d7fcf28..603708d8 100644 --- a/rcutils/logging.py +++ b/rcutils/logging.py @@ -54,7 +54,8 @@ skipfirst_doc_lines = [ 'The first log call is being ignored but all subsequent calls are being processed.'] throttle_params = OrderedDict(( - ('time_source_type', 'The time source type of the time to be used'), + ('time_source_type', 'Function that returns rcutils_ret_t and expects a ' + 'rcutils_time_point_value_t pointer.'), ('duration', 'The duration of the throttle interval'), )) throttle_args = { diff --git a/resource/logging_macros.h.em b/resource/logging_macros.h.em index 71d56ec4..4976920e 100644 --- a/resource/logging_macros.h.em +++ b/resource/logging_macros.h.em @@ -178,7 +178,7 @@ typedef bool (* RclLogFilter)(); static rcutils_time_point_value_t __rcutils_logging_last_logged = 0; \ rcutils_time_point_value_t __rcutils_logging_now = 0; \ bool __rcutils_logging_condition = true; \ - if (rcutils_steady_time_now(&__rcutils_logging_now) != RCUTILS_RET_OK) { \ + if (time_source_type(&__rcutils_logging_now) != RCUTILS_RET_OK) { \ rcutils_log( \ &__rcutils_logging_location, RCUTILS_LOG_SEVERITY_ERROR, "", \ "%s() at %s:%d getting current steady time failed\n", \ diff --git a/test/test_logging_macros.cpp b/test/test_logging_macros.cpp index 825fc851..440ecf26 100644 --- a/test/test_logging_macros.cpp +++ b/test/test_logging_macros.cpp @@ -154,7 +154,7 @@ TEST_F(TestLoggingMacros, test_logging_throttle) { auto is_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); RCUTILS_LOG_ERROR_THROTTLE( - RCUTILS_STEADY_TIME, throttle_time.count(), first ? "first" : "other"); + rcutils_steady_time_now, throttle_time.count(), first ? "first" : "other"); first = false; auto is_still_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); @@ -185,7 +185,7 @@ TEST_F(TestLoggingMacros, test_logging_skipfirst_throttle) { auto is_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); RCUTILS_LOG_FATAL_SKIPFIRST_THROTTLE( - RCUTILS_STEADY_TIME, throttle_time.count(), first ? "first" : "other"); + rcutils_steady_time_now, throttle_time.count(), first ? "first" : "other"); first = false; auto is_still_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); From e1b4344f90c79523908ece4454399e5743585eea Mon Sep 17 00:00:00 2001 From: Brian Ezequiel Marchi Date: Wed, 2 Oct 2019 12:24:35 -0300 Subject: [PATCH 2/6] Change macro parameter name Signed-off-by: Brian Ezequiel Marchi --- include/rcutils/time.h | 2 ++ rcutils/logging.py | 4 ++-- resource/logging_macros.h.em | 4 ++-- test/test_logging_macros.cpp | 4 ++-- 4 files changed, 8 insertions(+), 6 deletions(-) diff --git a/include/rcutils/time.h b/include/rcutils/time.h index e08692fa..d29ca609 100644 --- a/include/rcutils/time.h +++ b/include/rcutils/time.h @@ -39,6 +39,8 @@ extern "C" #define RCUTILS_NS_TO_MS(nanoseconds) (nanoseconds / (1000LL * 1000LL)) /// Convenience macro to convert nanoseconds to microseconds. #define RCUTILS_NS_TO_US(nanoseconds) (nanoseconds / 1000LL) +/// Convenience macro to reference the function for system time. +#define RCUTILS_STEADY_TIME rcutils_steady_time_now /// A single point in time, measured in nanoseconds since the Unix epoch. typedef int64_t rcutils_time_point_value_t; diff --git a/rcutils/logging.py b/rcutils/logging.py index 603708d8..c41b1102 100644 --- a/rcutils/logging.py +++ b/rcutils/logging.py @@ -54,12 +54,12 @@ skipfirst_doc_lines = [ 'The first log call is being ignored but all subsequent calls are being processed.'] throttle_params = OrderedDict(( - ('time_source_type', 'Function that returns rcutils_ret_t and expects a ' + ('time_source', 'Function that returns rcutils_ret_t and expects a ' 'rcutils_time_point_value_t pointer.'), ('duration', 'The duration of the throttle interval'), )) throttle_args = { - 'condition_before': 'RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(time_source_type, duration)', + 'condition_before': 'RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(time_source, duration)', 'condition_after': 'RCUTILS_LOG_CONDITION_THROTTLE_AFTER'} throttle_doc_lines = [ 'Log calls are being ignored if the last logged message is not longer ago than the specified ' diff --git a/resource/logging_macros.h.em b/resource/logging_macros.h.em index 4976920e..0a9f1152 100644 --- a/resource/logging_macros.h.em +++ b/resource/logging_macros.h.em @@ -173,12 +173,12 @@ typedef bool (* RclLogFilter)(); * \def RCUTILS_LOG_CONDITION_THROTTLE_BEFORE * A macro initializing and checking the `throttle` condition. */ -#define RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(time_source_type, duration) { \ +#define RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(time_source, duration) { \ static rcutils_duration_value_t __rcutils_logging_duration = RCUTILS_MS_TO_NS((rcutils_duration_value_t)duration); \ static rcutils_time_point_value_t __rcutils_logging_last_logged = 0; \ rcutils_time_point_value_t __rcutils_logging_now = 0; \ bool __rcutils_logging_condition = true; \ - if (time_source_type(&__rcutils_logging_now) != RCUTILS_RET_OK) { \ + if (time_source(&__rcutils_logging_now) != RCUTILS_RET_OK) { \ rcutils_log( \ &__rcutils_logging_location, RCUTILS_LOG_SEVERITY_ERROR, "", \ "%s() at %s:%d getting current steady time failed\n", \ diff --git a/test/test_logging_macros.cpp b/test/test_logging_macros.cpp index 440ecf26..825fc851 100644 --- a/test/test_logging_macros.cpp +++ b/test/test_logging_macros.cpp @@ -154,7 +154,7 @@ TEST_F(TestLoggingMacros, test_logging_throttle) { auto is_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); RCUTILS_LOG_ERROR_THROTTLE( - rcutils_steady_time_now, throttle_time.count(), first ? "first" : "other"); + RCUTILS_STEADY_TIME, throttle_time.count(), first ? "first" : "other"); first = false; auto is_still_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); @@ -185,7 +185,7 @@ TEST_F(TestLoggingMacros, test_logging_skipfirst_throttle) { auto is_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); RCUTILS_LOG_FATAL_SKIPFIRST_THROTTLE( - rcutils_steady_time_now, throttle_time.count(), first ? "first" : "other"); + RCUTILS_STEADY_TIME, throttle_time.count(), first ? "first" : "other"); first = false; auto is_still_before_throttle_end = ((std::chrono::system_clock::now() - start) < throttle_time); From 82f76c10d5ff85a7ff5b2b3672cd7e3096555ffb Mon Sep 17 00:00:00 2001 From: Brian Ezequiel Marchi Date: Fri, 4 Oct 2019 11:04:37 -0300 Subject: [PATCH 3/6] Change time_source signature and add method to reconstruct feature combinations Signed-off-by: Brian Ezequiel Marchi --- rcutils/logging.py | 81 ++++++++++++++++++++++++++++++++++-- resource/logging_macros.h.em | 4 +- 2 files changed, 80 insertions(+), 5 deletions(-) diff --git a/rcutils/logging.py b/rcutils/logging.py index c41b1102..7de22b2e 100644 --- a/rcutils/logging.py +++ b/rcutils/logging.py @@ -54,12 +54,12 @@ skipfirst_doc_lines = [ 'The first log call is being ignored but all subsequent calls are being processed.'] throttle_params = OrderedDict(( - ('time_source', 'Function that returns rcutils_ret_t and expects a ' + ('get_time_point_value', 'Function that returns rcutils_ret_t and expects a ' 'rcutils_time_point_value_t pointer.'), ('duration', 'The duration of the throttle interval'), )) throttle_args = { - 'condition_before': 'RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(time_source, duration)', + 'condition_before': 'RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(get_time_point_value, duration)', 'condition_after': 'RCUTILS_LOG_CONDITION_THROTTLE_AFTER'} throttle_doc_lines = [ 'Log calls are being ignored if the last logged message is not longer ago than the specified ' @@ -169,7 +169,82 @@ def __init__(self, *, params=None, args=None, doc_lines=None): }, **name_args }, doc_lines=skipfirst_doc_lines + throttle_doc_lines + name_doc_lines)), -)) + )) + + +def reconstruct_feature_combinations(): + """Reload the feature combination dict in case variables where modified.""" + feature_combinations = OrderedDict(( + ((), Feature()), + (('named'), Feature( + params=name_params, + args=name_args, + doc_lines=name_doc_lines)), + (('once'), Feature( + params=None, + args=once_args, + doc_lines=once_doc_lines)), + (('once', 'named'), Feature( + params=name_params, + args={**once_args, **name_args}, + doc_lines=once_doc_lines + name_doc_lines)), + (('expression'), Feature( + params=expression_params, + args=expression_args, + doc_lines=expression_doc_lines)), + (('expression', 'named'), Feature( + params=OrderedDict((*expression_params.items(), *name_params.items())), + args={**expression_args, **name_args}, + doc_lines=expression_doc_lines + name_doc_lines)), + (('function'), Feature( + params=function_params, + args=function_args, + doc_lines=function_doc_lines)), + (('function', 'named'), Feature( + params=OrderedDict((*function_params.items(), *name_params.items())), + args={**function_args, **name_args}, + doc_lines=function_doc_lines + name_doc_lines)), + (('skip_first'), Feature( + params=None, + args=skipfirst_args, + doc_lines=skipfirst_doc_lines)), + (('skip_first', 'named'), Feature( + params=name_params, + args={**skipfirst_args, **name_args}, + doc_lines=skipfirst_doc_lines + name_doc_lines)), + (('throttle'), Feature( + params=throttle_params, + args=throttle_args, + doc_lines=throttle_doc_lines)), + (('skip_first', 'throttle'), Feature( + params=throttle_params, + args={ + 'condition_before': ' '.join([ + throttle_args['condition_before'], + skipfirst_args['condition_before']]), + 'condition_after': ' '.join([ + throttle_args['condition_after'], skipfirst_args['condition_after']]), + }, + doc_lines=skipfirst_doc_lines + throttle_doc_lines)), + (('throttle', 'named'), Feature( + params=OrderedDict((*throttle_params.items(), *name_params.items())), + args={**throttle_args, **name_args}, + doc_lines=throttle_doc_lines + name_doc_lines)), + (('skip_first', 'throttle', 'named'), Feature( + params=OrderedDict((*throttle_params.items(), *name_params.items())), + args={ + **{ + 'condition_before': ' '.join([ + throttle_args['condition_before'], + skipfirst_args['condition_before']]), + 'condition_after': ' '.join([ + throttle_args['condition_after'], + skipfirst_args['condition_after']]), + }, **name_args + }, + doc_lines=skipfirst_doc_lines + throttle_doc_lines + name_doc_lines)), + )) + return feature_combinations def get_macro_parameters(feature_combination): diff --git a/resource/logging_macros.h.em b/resource/logging_macros.h.em index 0a9f1152..f1c79a36 100644 --- a/resource/logging_macros.h.em +++ b/resource/logging_macros.h.em @@ -173,12 +173,12 @@ typedef bool (* RclLogFilter)(); * \def RCUTILS_LOG_CONDITION_THROTTLE_BEFORE * A macro initializing and checking the `throttle` condition. */ -#define RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(time_source, duration) { \ +#define RCUTILS_LOG_CONDITION_THROTTLE_BEFORE(get_time_point_value, duration) { \ static rcutils_duration_value_t __rcutils_logging_duration = RCUTILS_MS_TO_NS((rcutils_duration_value_t)duration); \ static rcutils_time_point_value_t __rcutils_logging_last_logged = 0; \ rcutils_time_point_value_t __rcutils_logging_now = 0; \ bool __rcutils_logging_condition = true; \ - if (time_source(&__rcutils_logging_now) != RCUTILS_RET_OK) { \ + if (get_time_point_value(&__rcutils_logging_now) != RCUTILS_RET_OK) { \ rcutils_log( \ &__rcutils_logging_location, RCUTILS_LOG_SEVERITY_ERROR, "", \ "%s() at %s:%d getting current steady time failed\n", \ From 62ab5e27166330c523e2168d2a5c050396bdd2ae Mon Sep 17 00:00:00 2001 From: Brian Ezequiel Marchi Date: Fri, 4 Oct 2019 12:35:09 -0300 Subject: [PATCH 4/6] Revert changes Signed-off-by: Brian Ezequiel Marchi --- rcutils/logging.py | 75 ---------------------------------------------- 1 file changed, 75 deletions(-) diff --git a/rcutils/logging.py b/rcutils/logging.py index 7de22b2e..e643feb6 100644 --- a/rcutils/logging.py +++ b/rcutils/logging.py @@ -172,81 +172,6 @@ def __init__(self, *, params=None, args=None, doc_lines=None): )) -def reconstruct_feature_combinations(): - """Reload the feature combination dict in case variables where modified.""" - feature_combinations = OrderedDict(( - ((), Feature()), - (('named'), Feature( - params=name_params, - args=name_args, - doc_lines=name_doc_lines)), - (('once'), Feature( - params=None, - args=once_args, - doc_lines=once_doc_lines)), - (('once', 'named'), Feature( - params=name_params, - args={**once_args, **name_args}, - doc_lines=once_doc_lines + name_doc_lines)), - (('expression'), Feature( - params=expression_params, - args=expression_args, - doc_lines=expression_doc_lines)), - (('expression', 'named'), Feature( - params=OrderedDict((*expression_params.items(), *name_params.items())), - args={**expression_args, **name_args}, - doc_lines=expression_doc_lines + name_doc_lines)), - (('function'), Feature( - params=function_params, - args=function_args, - doc_lines=function_doc_lines)), - (('function', 'named'), Feature( - params=OrderedDict((*function_params.items(), *name_params.items())), - args={**function_args, **name_args}, - doc_lines=function_doc_lines + name_doc_lines)), - (('skip_first'), Feature( - params=None, - args=skipfirst_args, - doc_lines=skipfirst_doc_lines)), - (('skip_first', 'named'), Feature( - params=name_params, - args={**skipfirst_args, **name_args}, - doc_lines=skipfirst_doc_lines + name_doc_lines)), - (('throttle'), Feature( - params=throttle_params, - args=throttle_args, - doc_lines=throttle_doc_lines)), - (('skip_first', 'throttle'), Feature( - params=throttle_params, - args={ - 'condition_before': ' '.join([ - throttle_args['condition_before'], - skipfirst_args['condition_before']]), - 'condition_after': ' '.join([ - throttle_args['condition_after'], skipfirst_args['condition_after']]), - }, - doc_lines=skipfirst_doc_lines + throttle_doc_lines)), - (('throttle', 'named'), Feature( - params=OrderedDict((*throttle_params.items(), *name_params.items())), - args={**throttle_args, **name_args}, - doc_lines=throttle_doc_lines + name_doc_lines)), - (('skip_first', 'throttle', 'named'), Feature( - params=OrderedDict((*throttle_params.items(), *name_params.items())), - args={ - **{ - 'condition_before': ' '.join([ - throttle_args['condition_before'], - skipfirst_args['condition_before']]), - 'condition_after': ' '.join([ - throttle_args['condition_after'], - skipfirst_args['condition_after']]), - }, **name_args - }, - doc_lines=skipfirst_doc_lines + throttle_doc_lines + name_doc_lines)), - )) - return feature_combinations - - def get_macro_parameters(feature_combination): return feature_combinations[feature_combination].params From bbe16af770d5e0e3718adafd47294c23486a5eca Mon Sep 17 00:00:00 2001 From: Brian Ezequiel Marchi Date: Mon, 7 Oct 2019 08:33:52 -0300 Subject: [PATCH 5/6] Remove extra tab Signed-off-by: Brian Ezequiel Marchi --- rcutils/logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rcutils/logging.py b/rcutils/logging.py index e643feb6..8bd0273a 100644 --- a/rcutils/logging.py +++ b/rcutils/logging.py @@ -169,7 +169,7 @@ def __init__(self, *, params=None, args=None, doc_lines=None): }, **name_args }, doc_lines=skipfirst_doc_lines + throttle_doc_lines + name_doc_lines)), - )) +)) def get_macro_parameters(feature_combination): From 0815d74809bae0158b8e92ca502017eec5779fa4 Mon Sep 17 00:00:00 2001 From: Brian Ezequiel Marchi Date: Mon, 7 Oct 2019 12:20:12 -0300 Subject: [PATCH 6/6] Add link to function in macro Signed-off-by: Brian Ezequiel Marchi --- include/rcutils/time.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/rcutils/time.h b/include/rcutils/time.h index d29ca609..46f682ef 100644 --- a/include/rcutils/time.h +++ b/include/rcutils/time.h @@ -39,7 +39,7 @@ extern "C" #define RCUTILS_NS_TO_MS(nanoseconds) (nanoseconds / (1000LL * 1000LL)) /// Convenience macro to convert nanoseconds to microseconds. #define RCUTILS_NS_TO_US(nanoseconds) (nanoseconds / 1000LL) -/// Convenience macro to reference the function for system time. +/// Convenience macro for rcutils_steady_time_now(rcutils_time_point_value_t *). #define RCUTILS_STEADY_TIME rcutils_steady_time_now /// A single point in time, measured in nanoseconds since the Unix epoch.