-
Notifications
You must be signed in to change notification settings - Fork 163
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
Ensure no redundant rcl_logging initialization and finalization. #560
Ensure no redundant rcl_logging initialization and finalization. #560
Conversation
Signed-off-by: Tomoya.Fujita <Tomoya.Fujita@sony.com>
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I left some comments.
Besides that, rcl_logging_init
is actually called more than once when multiple context are created.
How this new return value will be handled there?
Actually, as I commented in the issue, we should ensure that the logger is not finished until the last context is finished. So we should probably do some kind of "reference" counting, instead of just a boolean indicating if it was already init or not.
Signed-off-by: Tomoya.Fujita <Tomoya.Fujita@sony.com>
rcl/src/rcl/logging.c
Outdated
@@ -77,6 +81,7 @@ rcl_logging_configure(const rcl_arguments_t * global_args, const rcl_allocator_t | |||
g_rcl_logging_ext_lib_enabled = !global_args->impl->log_ext_lib_disabled; | |||
rcl_ret_t status = RCL_RET_OK; | |||
g_rcl_logging_num_out_handlers = 0; | |||
(void) rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, 1); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
if multiple contexts exist, this will be called more than once. so that there should be no warning.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think that the return value should be used.
Like,
if(rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, 1)) {
return RMW_RET_OK; // already inited, just return.
}
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Also, I think this should be the first thing done in the function.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
we are not sure rcl_logging_init is actually done without any error, what if argument is missing?
counter == 1 does only mean rcl_logging_init is called, but rcl_logging_init is succeeded.
rcl/src/rcl/logging.c
Outdated
@@ -107,6 +112,12 @@ 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; | |||
uint64_t current_count = rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, -1); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
using atomic is not exactly thread safe, but expecting good enough for this case. besides we do not really want to introduce mutex in here.
thanks for enlighten me, could you check once again? |
I think that in this case (doing an atomic fetch add followed by a guard that ensures that the following code is executed only under an specific previous value of the atomic) should be thread safe, right? |
rcl/src/rcl/logging.c
Outdated
@@ -77,6 +81,7 @@ rcl_logging_configure(const rcl_arguments_t * global_args, const rcl_allocator_t | |||
g_rcl_logging_ext_lib_enabled = !global_args->impl->log_ext_lib_disabled; | |||
rcl_ret_t status = RCL_RET_OK; | |||
g_rcl_logging_num_out_handlers = 0; | |||
(void) rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, 1); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think that the return value should be used.
Like,
if(rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, 1)) {
return RMW_RET_OK; // already inited, just return.
}
rcl/src/rcl/logging.c
Outdated
@@ -77,6 +81,7 @@ rcl_logging_configure(const rcl_arguments_t * global_args, const rcl_allocator_t | |||
g_rcl_logging_ext_lib_enabled = !global_args->impl->log_ext_lib_disabled; | |||
rcl_ret_t status = RCL_RET_OK; | |||
g_rcl_logging_num_out_handlers = 0; | |||
(void) rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, 1); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Also, I think this should be the first thing done in the function.
rcl/src/rcl/logging.c
Outdated
@@ -107,6 +112,12 @@ 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; | |||
uint64_t current_count = rcutils_atomic_fetch_add_uint64_t(&__rcl_logging_init_count, -1); | |||
|
|||
if (current_count != 1) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Shouldn't be != 0
? The returned value by fetch add is the previous value of the atomic.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
No, current_count is fetched before addition(subtraction), confirmed this with simple test program.
current_count == 1 means that initialized once, so that needs to be finalized.
current_count != 1 means that initialized multiple times.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, sorry you're right. But current_count
sounds confusing, maybe previous_count
?
…ucceed. Signed-off-by: Tomoya.Fujita <Tomoya.Fujita@sony.com>
i did reconsider the code with expectation with rcl logging init/fini always succeed. could you share your thoughts? |
@@ -71,7 +71,9 @@ rcl_logging_init(const rcl_arguments_t * global_args, const rcl_allocator_t * al | |||
{ | |||
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)) { | |||
return RCL_RET_OK; |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
I think that's fine, I'm not sure if we should log something or in some cases indicate an error.
I think there is no need of an extra rwlock/mutex, but a second reviewer may think different. |
rcl/src/rcl/logging.c
Outdated
{ | ||
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)) { |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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?
@wjwwood I suggested doing reference counting, because the creation/destruction of each context calls Line 125 in 7537f83
Line 188 in 7537f83
If in rclcpp::init(argc, argv);
...
{
auto context1 = std::make_shared<rclcpp::Context >();
context1->init(0, nullptr);
}
RCLCPP_INFO(...); // Logging was finished when the above context shutdown.
... I think that's a problem. |
rcl/src/rcl/logging.c
Outdated
{ | ||
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)) { |
There was a problem hiding this comment.
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?
@@ -71,7 +71,9 @@ rcl_logging_init(const rcl_arguments_t * global_args, const rcl_allocator_t * al | |||
{ | |||
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)) { | |||
return RCL_RET_OK; |
There was a problem hiding this comment.
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.
@@ -71,7 +71,9 @@ rcl_logging_init(const rcl_arguments_t * global_args, const rcl_allocator_t * al | |||
{ | |||
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)) { | |||
return RCL_RET_OK; |
There was a problem hiding this comment.
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.
I agree, but that would modify completly the logging API. e.g: RCLCPP_INFO(context.get_logger(), ...); And we wouldn't necessary want a logger per The question is: who is responsible of configuring the logger? About the above solution proposed, I think that solving the problem in an upper layer is fine, though we will have to solve the problem independently in each client.
I think that the second option is probable more reasonable, as the caller should be responsible of not initing the logger more than once. So, my idea is something like this: atomic_uint_least64_t g_logging_ref_count = ATOMIC_VAR_INIT(0);
rcl_init(...)
{
...
if (0u == rcutils_atomic_fetch_add_uint64_t(&g_logging_ref_count, 1)) {
rcl_logging_configure(...);
} else {
// log a warn if logging arguments were passed again.
}
...
}
rcl_shutdown(...)
{
...
if (1u == rcutils_atomic_fetch_add_uint64_t(&g_logging_ref_count, -1)) {
rcl_logging_fini(...);
}
...
} @wjwwood Is that a reasonable solution? |
That's fine, but...
I don't think that can be done safely without a mutex, and Using just atomics will not be sufficient in my opinion, or at least I haven't seen a patch that achieves that. If you think it can be done, then that's fine I'll review a patch for that, but then the documentation needs to be updated to indicate that it is thread-safe.
My opinion is that this will be required, regardless of whether or not it is confusing, though I don't see why it is confusing to be honest. |
I don't see why an atomic counter would not ensure thread-safety in this case, though it's arguable whether we should be using them at all, along with other global state, instead of pushing loggers inside contexts. But then the question becomes, does it make sense to have a logger per context? If not, why are contexts initializing logging in the first place? Should logging initialization be done once per process, like signal handlers? |
Well, if you're mutating global state then fini and init cannot be called concurrently. I don't see how the atomic counter can protect you. We can review and discuss a concrete pull request more easily. Do you guys think the current patch is thread-safe? If so I'll re-review it with that in mind, though the doc strings still claim that they are not thread-safe.
The implications are annoying, but I think it makes sense. Alternatively, perhaps the context should not initialize the logging, as you suggest.
As to "why", init (
Maybe. The signal handlers are initialized only if the global If having library globals is an issue for the user (e.g. due to destruction order issues) then they would just have to forego using our signal handlers and make their own and avoid using the global versions of our functions. For logging this isn't as easy for the user to do since logging calls are made through out the code, so they cannot easily avoid them all. Also, in my opinion, comparing logging to signal handling is kind of flawed, because the logger could technically be used without globals (think about our deliberations over log4cxx vs spdlog) and ideally our logging API would allow for non-global usage. Conversely, I do not believe the signal handling is technically feasible without using globals. While important, I think this is well out of scope for this pull request. For this pull request we just need to decide how to make it thread-safe, either in rcl or rclcpp depending on how the atomic issue is resolved. |
For sure. I meant "...to be initialized on a per process basis". But that doesn't have to be the case really. Logging could be initialized separately, against either global or non-global storage, and made available globally or associated explicitly with contexts or nodes, or simply passed around. Not all of those combinations are sane though.
Fully agreed. |
No, atomic counter is atomic access, it cannot take care of the failure cases. for supporting failure cases, we surely will need mutex or rwlock to keep the everyone else exclusive in specific time window. |
How you guys really want to proceed? Taking care of thread-safe via rclcpp? IMO, i believe that current implementation is reasonable at certain level but expecting logging init and fini never fails. |
Signed-off-by: Tomoya.Fujita <Tomoya.Fujita@sony.com>
I proposed an altarnative in #573, just to clarify my idea with code. |
I've merged the alternative PRs, sorry for the delay. |
this is fix for #551.
the following, i would like to hear from others.