use parent logger

[iuhilnehc-ynos]

to fix ros2/rclcpp#1694

Signed-off-by: Chen Lihui Lihui.Chen@sony.com

[clalancette]

I've got a couple of changes suggested inline.

Separately, I'm slightly concerned about the run-time performance hit of this. That is, this function is called for every log message that goes out, and we are now making this function even more expensive for sub-loggers. I'm kind of wondering if we should instead add all sub-loggers to the __logger_map instead, which means we would use more memory, but keep this function faster. Thoughts?

[iuhilnehc-ynos]

I've got a couple of changes suggested inline.

Thanks for your review.

Separately, I'm slightly concerned about the run-time performance hit of this. That is, this function is called for every log message that goes out, and we are now making this function even more expensive for sub-loggers. I'm kind of wondering if we should instead add all sub-loggers to the __logger_map instead, which means we would use more memory, but keep this function faster. Thoughts?

You're right. It definitely costs more consumption each time while using the sub-loggers not existing. I think we could add all sub-loggers to the __logger_map. I'll reconsider it.

[iuhilnehc-ynos]

@clalancette

I think a node is unnecessary to have multiple publishers on a topic named '/rosout', so I will have the publisher shared by the sub-logger.

The following is my thought.

• update the rosout_map_entry_t structure

typedef struct rosout_map_entry_t
{
  rcl_node_t * node;
  rcl_publisher_t publisher;
  // identicate whether the publisher is shared from parent node
  bool share_from_parent;
  // store the child logger names to make sure clean them if current node is finalized
  rcutils_array_list_t child_logger_names;
} rosout_map_entry_t;

• rcl_logging_rosout_output_handler will create a new map item (with subloggername and its parent entry, the entry need to be updated) for a coming sublogger if necessary
• also update rcl_logging_rosout_init_publisher_for_node and rcl_logging_rosout_fini_publisher_for_node

Do you have any suggestions?

[clalancette]

I think I understand your proposal; basically, whenever we see a new sublogger in rcl_logging_rosout_output_handler, we'll create a new entry in the map for it, and then subsequent calls to rcl_logging_rosout_output_handler can reuse that map entry. The rest of the changes are bookkeeping for cleaning up subloggers later on. Is that correct?

That will work, though it makes rcl_logging_rosout_output_handler more complicated and more jittery; it will "sometimes" have to do memory allocations in the fast path.

Before we go that route, let me ask a question: is the rosout logging layer notified when a new sublogger is created from a parent logger? If it isn't, can we make it so? Being able to do all of this setup work at sublogger creation time would be better, in my opinion.

[iuhilnehc-ynos]

I think I understand your proposal; basically, whenever we see a new sublogger in rcl_logging_rosout_output_handler, we'll create a new entry in the map for it, and then subsequent calls to rcl_logging_rosout_output_handler can reuse that map entry. The rest of the changes are bookkeeping for cleaning up subloggers later on. Is that correct?

Yes.

That will work, though it makes rcl_logging_rosout_output_handler more complicated and more jittery; it will "sometimes" have to do memory allocations in the fast path.

Sorry for not finding out a better idea based on the current design. Maybe in the future, we could make an implicit node to create a publisher on the topic '/rosout'. (I don't know why ros2 needs to create multiple publishers on topic '/rosout' if there are multiple nodes.)

Before we go that route, let me ask a question: is the rosout logging layer notified when a new sublogger is created from a parent logger? If it isn't, can we make it so? Being able to do all of this setup work at sublogger creation time would be better, in my opinion.

Could you give me more explanations about is the rosout logging layer notified when a new sublogger is created from a parent logger? I don't know the purpose of this notification.

[clalancette]

Could you give me more explanations about is the rosout logging layer notified when a new sublogger is created from a parent logger? I don't know the purpose of this notification.

Going back to the original problem, it seems like the problem comes about in a line like this:

    RCLCPP_INFO(get_logger().get_child("child"), "Child logger");

Reading the rclcpp code a bit, it looks like get_logger() returns a Logger instance. And get_child() is a method on the Logger instance.

My suggestion is that we add a new function to https://github.com/ros2/rcl/blob/master/rcl/include/rcl/logging_rosout.h called something like rcl_add_sublogger(), which would allocate and add a sublogger to the __logger_map if it doesn't already exist. And then we would call that anytime we construct a new child logger (maybe just anytime we construct a Logger at all, I'm not sure). That way, we do the initialization at child logger construction time, and keep rcl_logging_rosout_output_handler simpler.

[iuhilnehc-ynos]

Going back to the original problem, it seems like the problem comes about in a line like this:

    RCLCPP_INFO(get_logger().get_child("child"), "Child logger");

Reading the rclcpp code a bit, it looks like get_logger() returns a Logger instance. And get_child() is a method on the Logger instance.

My suggestion is that we add a new function to https://github.com/ros2/rcl/blob/master/rcl/include/rcl/logging_rosout.h called something like rcl_add_sublogger(), which would allocate and add a sublogger to the __logger_map if it doesn't already exist. And then we would call that anytime we construct a new child logger (maybe just anytime we construct a Logger at all, I'm not sure). That way, we do the initialization at child logger construction time, and keep rcl_logging_rosout_output_handler simpler.

Thank you for your suggestion. I'd really appreciate that.
Do you mean to use the sublogger must through get_child()? If so, I think I thought of that implementation before, but it seems there is unexpected behaviour, if we can accept that, I'll continue to implement it.

there is a node named 'node',

1. normal case

RCLCPP_INFO(get_logger().get_child("child"), "Child logger");

get_child() call rcl_add_sublogger to add a sublogger, so it will use the real sublogger to log message.

2. expected case

RCLCPP_INFO(rclcpp::get_logger("node.child"), "not to publish message on rosout");

Because rcl_add_sublogger was not called before and there is no node named /node/child, it can't publish the message on rosout

3. unexpected case

if get_child() was called before, such as

RCLCPP_INFO(get_logger().get_child("child"), "Child logger");

and then,

RCLCPP_INFO(rclcpp::get_logger("node.child"), "it will use the child logger");

Do you think the cases(2, 3) will make users confused?

[fujitatomoya]

adding dynamic memory allocation and hashmap operation would be issue for logging as mentioned before. in production, logging is really important to make sure that we can have sufficient information w/o overhead.

Because rcl_add_sublogger was not called before

i think we can call internally based on "node.child"? if i am not mistaken.

[iuhilnehc-ynos]

adding dynamic memory allocation and hashmap operation would be issue for logging as mentioned before. in production, logging is really important to make sure that we can have sufficient information w/o overhead.

Because rcl_add_sublogger was not called before

i think we can call internally based on "node.child"? if i am not mistaken.

Thank @fujitatomoya, if so, I think the added function rcl_add_sublogger only needs to be called in rcl instead of rclcpp. (In other words, rcl_add_sublogger can be a static function inside rcl, which will be called at rcl_logging_rosout_output_handler)

[clalancette]

@iuhilnehc-ynos Hm, good point about the "node.child" issue; I hadn't thought about that one.

In that case, I think I would propose:

1. Create a function in rcl which is rcl_add_sublogger. You'll probably also want an rcl_remove_sublogger for destruction time.
2. Call rcl_add_sublogger when a Logger instance is constructed (and rcl_remove_sublogger when it is destroyed).
3. Also call rcl_add_sublogger from rcl_logger_rosout_output_handler if the logger isn't in the __logger_map.

That way, you can avoid allocations at runtime by doing:

auto sublogger = get_logger().get_child("child");
RCLCPP_INFO(sublogger, "foo");

But if you forget to do that and just do:

RCLCPP_INFO(get_logger("node.child"), "foo");

things will still work. What do you think about that?

[iuhilnehc-ynos]

@clalancette

Thanks for your proposal. There is something that needs to be confirmed.

1. Currently, the Logger of rcpcpp does not use rcl_node_t inside, which means we can't use the following interface in Logger,

rcl_ret_t
rcl_logging_rosout_add_sublogger(
  rcl_node_t * node, const char * sublogger_name)
{
  rcl_ret_t status = RCL_RET_OK;
  char * logger_name = NULL;

  RCL_LOGGING_ROSOUT_VERIFY_INITIALIZED
  RCL_CHECK_ARGUMENT_FOR_NULL(node, RCL_RET_NODE_INVALID);
  if (NULL == sublogger_name) {
    RCL_SET_ERROR_MSG("Sub-logger name was null.");
    return RCL_RET_ERROR;
  }

  logger_name = _rcl_logging_rosout_get_sublogger_name(node, sublogger_name);
  if (NULL == logger_name) {
    // Error already set
    return RCL_RET_ERROR;
  }

  status = _rcl_logging_rosout_add_logger(node, logger_name);
  // TODO: save logger_name into a list,
  // it can't be freed immediately because the hashmap need it

  return status;
}

so the rcl_logging_rosout_add_sublogger seems to be implemented as,

rcl_ret_t
rcl_logging_rosout_add_sublogger(
  const char * sublogger_name)
{
  1. to search from `__logger_map` by substring the `sublogger_name` to locate an existing rcl_node_t
  2. create a new string `sublogger_name_dup` from sublogger_name
  3. use the rcl_node_t to create a new publisher, and then add the item(sublogger_name_dup, new_entry) into `__logger_map`
  4. put the new `sublogger_name_dup` into a list
}

I don't think it's what we want because this kind of API (without rcl_node_t * argument) can't be the same group inside logging_rosout.c, I need to wait for your confirmation.

[clalancette]

1. Currently, the `Logger` of `rcpcpp` does not use `rcl_node_t` inside, which means we can't use the following interface in `Logger`,

Good point.

rcl_ret_t
rcl_logging_rosout_add_sublogger(
  const char * sublogger_name)
{
  1. to search from `__logger_map` by substring the `sublogger_name` to locate an existing rcl_node_t
  2. create a new string `sublogger_name_dup` from sublogger_name
  3. use the rcl_node_t to create a new publisher, and then add the item(sublogger_name_dup, new_entry) into `__logger_map`
  4. put the new `sublogger_name_dup` into a list
}

OK, I understand this pseudo code.

I don't think it's what we want because this kind of API (without rcl_node_t * argument) can't be the same group inside logging_rosout.c, I need to wait for your confirmation.

I don't quite understand this part. Can you rephrase?

[iuhilnehc-ynos]

I don't think it's what we want because this kind of API (without rcl_node_t * argument) can't be the same group inside logging_rosout.c, I need to wait for your confirmation.

I don't quite understand this part. Can you rephrase?

Sorry to make you confused. I thought it seems like an indirect API in RCL because this API need to search a rcl_node_t inside. If only considering the implementation level of RCL, I'd prefer to encapsulate an API like the first one(rcl_logging_rosout_add_sublogger(rcl_node_t *, const char *)).

Anyway, I'll implement this API as

rcl_ret_t
rcl_logging_rosout_add_sublogger(
  const char * logger_name, const char * sublogger_name)

[iuhilnehc-ynos]

Use rcutils_hash_map_set(&__logger_map, &full_sublogger_name, &entry) instead of _rcl_logging_rosout_add_logger that adding a new publisher.

[iuhilnehc-ynos]

@clalancette

Could you help review it in your spare time? Thanks in advance.

[fujitatomoya]

@clalancette friendly ping.

[fujitatomoya]

lgtm

[fujitatomoya]

@clalancette friendly ping.

[clalancette]

Mostly small comments, though there is one question about the underlying data structure.

[clalancette]

This shouldn't be in here; it is only necessary in header files.

[clalancette]

I don't think we want to return the status from rcutils_hash_map_fini here. Instead, we should return the status from above.

[clalancette]

If we fail here, we actually should go back and remove the sublogger from the __logger_map.

[clalancette]

Like rcl_logging_rosout_add_sublogger, we should have a cleanup label and go there when we fail.

This will also allow us to unravel the cleanup below, so we can goto cleanup during failures.

[clalancette]

I'm wondering whether this should be a hash_map, rather than a list. That way when removing them, we don't have to look through all subloggers to find it, which should improve performance. Thoughts?

[clalancette]

I'll suggest to remove the trailing _, just to be consistent with the rest. We aren't totally consistent in tests, but we may as well be consistent within the same class.

[iuhilnehc-ynos]

@clalancette
Thanks for your reviews. Updated in 9f4005f.

[iuhilnehc-ynos]

try CI:

• Linux
• Linux-aarch64
• Windows

[iuhilnehc-ynos]

CI:

• Linux
• Linux-aarch64
• Windows

[clalancette]

I left two thoughts inline. Other than those, this is looking pretty good to me.

[clalancette]

This is purely stylistic, but I think that we can just return status here. That is, the extra goto here doesn't really buy us much. Same goes a few other times below.

[iuhilnehc-ynos]

CI:

• Linux
• Linux-aarch64
• Windows

[clalancette]

Thanks for the patience and all of the iterations here.