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.

Sign up for GitHub

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

Jump to bottom

Ensure no redundant rcl_logging initialization and finalization. #560

Closed
wants to merge 5 commits into from
Closed

Ensure no redundant rcl_logging initialization and finalization. #560

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
2a141c2
Merge remote-tracking branch 'upstream/master'
fujitatomoya Jan 23, 2020
6602f6c
Avoid redundant rcl_logging initialization and finalization.
fujitatomoya Jan 23, 2020
1bf89b8
use atomic counter for rcl logging init/fini.
fujitatomoya Jan 24, 2020
894e883
reconsider atomic counter with expectation logging init/fini always s…
fujitatomoya Jan 28, 2020
3df75c1
get rid of unnecessary difference and change name for global variable.
fujitatomoya Feb 3, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion rcl/include/rcl/logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,7 @@ extern "C"
RCL_PUBLIC
RCL_WARN_UNUSED
rcl_ret_t
rcl_logging_configure(
rcl_logging_init(
const rcl_arguments_t * global_args,
const rcl_allocator_t * allocator);

Expand Down
2 changes: 1 addition & 1 deletion rcl/src/rcl/init.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -122,7 +122,7 @@ rcl_init(
goto fail;
}

ret = rcl_logging_configure(&context->global_arguments, &allocator);
ret = rcl_logging_init(&context->global_arguments, &allocator);
if (RCL_RET_OK != ret) {
fail_ret = ret;
RCUTILS_LOG_ERROR_NAMED(
Expand Down
19 changes: 17 additions & 2 deletions rcl/src/rcl/logging.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ extern "C"
#include "rcl/macros.h"
#include "rcutils/logging.h"
#include "rcutils/time.h"
#include "rcutils/stdatomic_helper.h"

#define RCL_LOGGING_MAX_OUTPUT_FUNCS (4)

Expand All @@ -43,6 +44,8 @@ static bool g_rcl_logging_stdout_enabled = false;
static bool g_rcl_logging_rosout_enabled = false;
static bool g_rcl_logging_ext_lib_enabled = false;

static atomic_uint_least64_t __rcl_logging_init_count = ATOMIC_VAR_INIT(0);
fujitatomoya marked this conversation as resolved.
Show resolved Hide resolved

/**
* An output function that sends to multiple output appenders.
*/
Expand All @@ -64,10 +67,13 @@ rcl_logging_ext_lib_output_handler(
const char * format, va_list * args);

rcl_ret_t
rcl_logging_configure(const rcl_arguments_t * global_args, const rcl_allocator_t * allocator)
rcl_logging_init(const rcl_arguments_t * global_args, const rcl_allocator_t * allocator)
{
RCL_CHECK_ARGUMENT_FOR_NULL(global_args, RCL_RET_INVALID_ARGUMENT);
RCL_CHECK_ARGUMENT_FOR_NULL(allocator, RCL_RET_INVALID_ARGUMENT);
if (rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, 1)) {
Copy link
Member

Choose a reason for hiding this comment

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

Why are we counting and not just using a flag? This function is marked as not thread-safe, and rcl_logging_fini as well. So we don't have to handle the case where this is called multiple times concurrently. It's up to the code above this to ensure it isn't called in a thread unsafe way.

Copy link
Member

Choose a reason for hiding this comment

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

Ok, I see why a counter, but why atomic?

return RCL_RET_OK;
Copy link
Member

Choose a reason for hiding this comment

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

I wonder if we should log something here, to not return silently.
Maybe, an user might expect to be able to configure a logging of two contexts differently.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

okay, that is one of the cases, let's add it to notify the user.

Copy link
Member

Choose a reason for hiding this comment

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

I agree, but instead I'd prefer for this to fail instead (return an error code). That way the caller can decide how to react to this. As-is the caller cannot tell if the function succeeded or "succeeded" but didn't use the given settings.

Copy link
Member

Choose a reason for hiding this comment

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

In fact, I think the better solution would look like this (from the caller side):

Context::Context(...)
{
  // ...
  std::lock_guard<std::mutex> lock(g_logging_mutex);  // ensures thread-safety
  if (rcl_logging_is_initialized()) {
    auto ret = rcl_logging_init(...);
    if (ret != RCL_RET_OK) {
      // error handling
    }
  } else {
    auto ret = rcl_logging_increase_ref_count();  // safe because of lock above
    if (ret != RCL_RET_OK) {
      // error handling
    }
  }
  // ...
}

Context::~Context()
{
  // ...
  std::lock_guard<std::mutex> lock(g_logging_mutex);  // ensures thread-safety
  auto ret = rcl_logging_decrease_ref_count();  // will implicitly fini() if ref_count is zero
  if (ret != RCL_RET_OK) {
    // error handling
  }
  // ...
}

So that it is more explicit what's happening.

Or in the case where something is using logging but doesn't have what is required to initialize it (requires something else initialized it first):

{
  // ...
  std::lock_guard<std::mutex> lock(g_logging_mutex);  // ensures thread-safety
  if (rcl_logging_increase_ref_count() == RCL_LOGGING_NOT_INITIALIZED) {
    // error handling because it was unexpectedly not initialized...
  }
  // ...
}

Not sure there's a use case for the second example, but either way I think having init return OK but not actually consider the input arguments is probably not good. But at the same time you need to see if it is initialized and increase the reference count some how.

Also, out of scope for this pr, but logging should probably not require the use of global... This is only a problem because we're mapping non-globals (multiple context) to the initialization of a global. If each context could create its own logging instance this would not be a problem.

}
RCUTILS_LOGGING_AUTOINIT
g_logging_allocator = *allocator;
int default_level = global_args->impl->log_level;
Expand Down Expand Up @@ -107,6 +113,16 @@ rcl_logging_configure(const rcl_arguments_t * global_args, const rcl_allocator_t
rcl_ret_t rcl_logging_fini()
{
rcl_ret_t status = RCL_RET_OK;

if (rcutils_atomic_load_uint64_t(&__rcl_logging_init_count) > 0) {
uint64_t current_count = rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, -1);
wjwwood marked this conversation as resolved.
Show resolved Hide resolved
if (current_count != 1) {
return RCL_RET_OK;
}
} else {
return RCL_RET_OK;
}

rcutils_logging_set_output_handler(rcutils_logging_console_output_handler);

if (g_rcl_logging_rosout_enabled) {
Expand All @@ -115,7 +131,6 @@ rcl_ret_t rcl_logging_fini()
if (RCL_RET_OK == status && g_rcl_logging_ext_lib_enabled) {
status = rcl_logging_external_shutdown();
}

fujitatomoya marked this conversation as resolved.
Show resolved Hide resolved
return status;
}

Expand Down