Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Only evaluate logging 'function'/'expression' if severity is enabled #75

Merged
merged 7 commits into from
Nov 28, 2017

Conversation

dhood
Copy link
Member

@dhood dhood commented Nov 25, 2017

While working on ros2/demos#194 I noticed that RCUTILS_LOG_DEBUG_FUNCTION evaluates the function even when the debug severity is not enabled, which is inefficient. I looked for a specific reason it might have been done this way but couldn't find one (it's been like this since it was added). This behaviour is not the case in ROS 1: the conditions are only evaluated if the severity is enabled.

An example of a side effect of this change is that the "hit" flag for the 'once' filter will only get evaluated after the severity is enabled now. I see this as an improvement because otherwise, without this PR, RCUTILS_LOG_DEBUG_ONCE would never be printed if the first time it gets hit is when the severity threshold is INFO instead of DEBUG. Similar side effects apply for SKIPFIRST, THROTTLE but I don't consider any of them points for concern. The behaviour after this PR matches what I expect if/when we add a "notify logger levels changed" concept for resetting filter states whenever severity thresholds are changed.

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

@dhood dhood added the in review Waiting for review (Kanban column) label Nov 25, 2017
@dhood dhood self-assigned this Nov 25, 2017
return (g_counter % 3) != 0;
}

TEST_F(TestLoggingMacros, test_logging_function) {
// check that evaluation of a specified function does not occur if the severity is not enabled
g_rcutils_logging_default_severity_threshold = RCUTILS_LOG_SEVERITY_INFO;
for (int i : {1, 2, 3, 4, 5, 6}) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do we need to make 6 calls here to confirm the function is not called a single time ? We could just do:

g_counter = 1;
RCUTILS_LOG_DEBUG_FUNCTION(&not_divisible_by_three, "should not be logged");
EXPECT_EQ(0u, g_log_calls);
EXPECT_FALSE(g_function_called);

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yep you're right: 3dcd3c2

@dhood
Copy link
Member Author

dhood commented Nov 25, 2017

This is what the doxygen looks like for a macro with a condition after ad46cef:

screen shot 2017-11-24 at 1 47 45 pm

Without a condition it just says e.g.: Log a message with severity INFO.

return (g_counter % 3) != 0;
}

TEST_F(TestLoggingMacros, test_logging_function) {
// check that evaluation of a specified function does not occur if the severity is not enabled
g_rcutils_logging_default_severity_threshold = RCUTILS_LOG_SEVERITY_INFO;
RCUTILS_LOG_DEBUG_FUNCTION(&not_divisible_by_three, "should not be logged");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We still need to set g_counter to 1 otherwise not_divisible_by_three returns false. The check of g_function_called is still valid but it makes the check for g_log_calls not relevant

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Really just checking g_function_called is false should be sufficient here, but more coverage can't hurt: 8c369f9

Copy link
Member

@mikaelarguedas mikaelarguedas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks for iterating,

Regarding the doc, a potential improvement would be to highlight parameters when we refer to them in function/macro description (here the "function" parameter). But that's outside of the scope of this PR

@dhood dhood merged commit 1398a2e into master Nov 28, 2017
@dhood dhood deleted the lazy_expression_eval branch November 28, 2017 16:57
@dhood dhood removed the in review Waiting for review (Kanban column) label Nov 28, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants