default RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED to 1

[rotu]

Saner default logging behavior.
fixes #168

[ivanpauno]

Though I thing the changes are fine, IMO this is only a workaround to a bug in launch.
If you're launching multiple process with launch that don't use our logging macros, messages should be still in the correct order. We should maybe explore using PYTHONUNBUFFERED enviroment variable when running subprocesses ...

[ivanpauno]

this line should be:

} else if (strcmp(line_buffered, "1") != 0 && strcmp(line_buffered, "") != 0) {

[rotu]

Oops. Thank you!

[rotu]

Though I thing the changes are fine, IMO this is only a workaround to a bug in launch.

Fair. I think it's both. I wouldn't mind this PR being rejected so long as it was fixed in a different way.

If you're launching multiple process with launch that don't use our logging macros, messages should be still in the correct order. We should maybe explore using PYTHONUNBUFFERED enviroment variable when running subprocesses ...

A big part of the situation is splitting diagnostics over different streams. If I were writing my own logging, I would just log everything (even low-priority messages) over stderr, though I figure I would break something if I changed it here.

[ivanpauno]

I will detail a little bit what the problem is: in linux (and probably mac), stdout is line buffered when associated with a terminal, if not it's fully buffered.
When launching sub-processes using launch, their stdout end up being fully buffered. So, the output isn't showed in the correct order. I haven't found a way of forcing the stdout of the subprocess to be line buffered with the python api (without using shell=True).

Other possible workarounds:

• Doing this in every program: https://github.com/ros2/demos/blob/f78dcc981cc783aad162e2a8530a7aa23c4fda21/logging_demo/src/logging_demo_main.cpp#L24, or change RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED default to 1 (as proposed in this PR). This won't work for python programs, PYTHONUNBUFFERED=1 would be needed for that.
• Use something like unbuffer behind the scenes in launch.
• Find a proper solution when creating a sub-process in python (IDK if it's possible).

[ivanpauno]

This is related to ros2/launch#188.

[dirk-thomas]

I don't agree with the statement made in the original ticket:

The consequences of having RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED=1 when it should be 0 is a tiny (if noticeable) performance hit.

I doubt that the performance hit is actually tiny. When a program outputs frequent messages I would rather expect the performance hit to be fairly significant.

I understand that line buffering results in more convenient to read output but I expect this change to impact performance in an undesired way and therefore am hesitant to change it as is (especially without any further investigation into how it actually effects the performance).

---

Just one external article writing about the performance implications: https://eklitzke.org/stdout-buffering

[jacobperron]

@dirk-thomas beat me to it.

This was the same reason for defaulting to 0 in rosconsole (where this logic was copied from).

[rotu]

I doubt that the performance hit is actually tiny. When a program outputs frequent messages I would rather expect the performance hit to be fairly significant.

@dirk-thomas, I tested it. It's not a significant performance hit, and to notice it, you'd have to be doing a truly massive amount of logging (the 10k messages in the below examples amount to 2.3 MB of log output). For reference, 100k calls to rclcpp::spin have an overhead of 3.668 seconds.

Line buffering off:

RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED=0
ros2 run logperf main > /dev/null
Did 100000 messages in 0.250194 seconds
ros2 run logperf main
# ...
Did 100000 messages in 0.615212 seconds
ros2 run logperf main > outfile.txt  
Did 100000 messages in 0.290205 seconds

Line buffering on:

RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED=1
ros2 run logperf main > /dev/null
Did 100000 messages in 0.290174 seconds
ros2 run logperf main
# ...
Did 100000 messages in 0.613463 seconds
ros2 run logperf main > outfile.txt   
Did 100000 messages in 0.489006 seconds

Code:

#include <chrono>
#include "rclcpp/rclcpp.hpp"
int main(int argc, char * argv[])
{
  size_t count = 100000;
  rclcpp::init(argc, argv);
  rclcpp::Node n("main");
  auto t0 = n.now();
  for (int i = 0; i < count; i++) RCLCPP_INFO(n.get_logger(), "logging");
  auto t1 = n.now();

  std::cerr << "Did " << count << " messages in " << (t1 - t0).seconds() << " seconds";
}

[dirk-thomas]

The default for buffering of non-interactive terminals is fully buffered. We won't be changing that default since the reason for that default in C as well as Python is performance. While some slowdown might be acceptable in many cases we don't think it should be the default.

That being said we happy to make changing the default - either for a specific program or from a launch file - as easy and convenient as possible. Demos / tutorials should explicitly use these options if immediate flushing is desired.

Since the current state of the PR changes the default I will go ahead and close it.

[rotu]

Makes sense. I don’t think this is quite the right fix anymore anyway ;-)