Logs are not line buffered

[quozl]

Sugar on Python 2 log files are line-buffered, such that tail and cat can see output in logs as it happens.

Sugar on Python 3 has lost this feature.

[quozl]

Calling _logging.getlogger() and then changing logging.* invocations to logger.* fixes the problem in datastore. Sugar has used logging.* too.

[quozl]

https://github.com/sugarlabs/sugar/pull/880 is a very large change, so I'm considering if it is the best solution to the problem.

Cause of this issue was upstream change in Python 3. For interactive programs where sys.stderr is a terminal, sys.stderr is an instance of file, and _sys.stderr.linebuffering is True. For non-interactive programs where sys.stderr is directed to a file, sys.stderr is an instance of TextIOWrapper, and _sys.stderr.linebuffering is False. Sugar, Datastore, and activities fall into the non-interactive mode.

For the Datastore, which is almost never debugged, and emits very little in the way of log lines, yet is critical to interactive performance, I did the change from logging to logger without understanding why it worked. I still don't understand why, and it might change.

Then there's the issue of why we originally chose line-buffered logs, and the performance impacts.

Thinking back into history of the project, flushed logs were helpful given the computer could be shut down at any time by the child. Newer systems don't have user removable batteries, and the power button causes an organised shutdown to begin. It is unlikely we'll ever see Python 3 port of Sugar on the OLPC XO. So we don't need line-buffered logs for the same reasons we once did.

The performance impacts are real, and are why we search out and remove excessive logging, to this day. What happens is that every line logged causes a write(2) syscall at the Linux kernel API, which updates the block and filesystem cache, and may block execution while the cache is written to storage device. On the XO-1 with 256 MB of RAM this was a probable write to the jffs2 filesystem and eventually the mtd driver and the NAND Flash. On the XO-1.5, XO-1.75, and XO-4 this was a write to the ext3 filesystem and eventually the driver for the SD host controller interface. Newer systems are similar, but very unlikely to need to write in order to free dirty memory.

Perhaps what we should be doing now is to configure Sugar and activities for fully buffered logs, and configure line-buffering only when Sugar is being used by a developer. i.e. set sys.stderr.line_buffering = True based on an environment variable. Comments?

[chimosky]

880 is a very large change, so I'm considering if it is the best solution to the problem.

Agreed.

Cause of this issue was upstream change in Python 3. For interactive programs where sys.stderr is a terminal, sys.stderr is an instance of file, and _sys.stderr.linebuffering is True. For non-interactive programs where sys.stderr is directed to a file, sys.stderr is an instance of TextIOWrapper, and _sys.stderr.linebuffering is False. Sugar, Datastore, and activities fall into the non-interactive mode.

For the Datastore, which is almost never debugged, and emits very little in the way of log lines, yet is critical to interactive performance, I did the change from logging to logger without understanding why it worked. I still don't understand why, and it might change.

I haven't understood why too.

Then there's the issue of why we originally chose line-buffered logs, and the performance impacts.

Thinking back into history of the project, flushed logs were helpful given the computer could be shut down at any time by the child. Newer systems don't have user removable batteries, and the power button causes an organised shutdown to begin. It is unlikely we'll ever see Python 3 port of Sugar on the OLPC XO. So we don't need line-buffered logs for the same reasons we once did.

The performance impacts are real, and are why we search out and remove excessive logging, to this day. What happens is that every line logged causes a write(2) syscall at the Linux kernel API, which updates the block and filesystem cache, and may block execution while the cache is written to storage device. On the XO-1 with 256 MB of RAM this was a probable write to the jffs2 filesystem and eventually the mtd driver and the NAND Flash. On the XO-1.5, XO-1.75, and XO-4 this was a write to the ext3 filesystem and eventually the driver for the SD host controller interface. Newer systems are similar, but very unlikely to need to write in order to free dirty memory.

Perhaps what we should be doing now is to configure Sugar and activities for fully buffered logs, and configure line-buffering only when Sugar is being used by a developer. i.e. set sys.stderr.line_buffering = True based on an environment variable. Comments?

Configuring sugar is a good idea but activities doesn't seem feasible as they're few activities that are interactive except we want to look at their interaction with the datastore.

[quozl]

Configuring sugar is a good idea but activities doesn't seem feasible as they're few activities that are interactive except we want to look at their interaction with the datastore.

Could you explain this again please? I don't think I understand what you mean.

I think we will need to find out why using an instance of logger has restored line buffering, if only so we can stop it happening.

[chimosky]

Perhaps what we should be doing now is to configure Sugar and activities for fully buffered logs, and configure line-buffering only when Sugar is being used by a developer.

You said this and I was saying it's a good idea to configure line-buffering for sugar when it's been used by a developer but I don't think doing the same with activities is feasible.

[quozl]

How is it not feasible with activities? All activities execute sugar3.logger called by sugar3.activity.activityinstance which is called by sugar-activity3, so that should be apt for enabling line buffering.

In particular I don't understand;

doesn't seem feasible as they're few activities that are interactive except we want to look at their interaction with the datastore.

Because;

• "interactive" in this issue means started from a Terminal, not Sugar, and;
• the change already made to Datastore can be reverted once we find out "why using an instance of logger has restored line buffering."

[chimosky]

How is it not feasible with activities? All activities execute sugar3.logger called by sugar3.activity.activityinstance which is called by sugar-activity3, so that should be apt for enabling line buffering.

I didn't know this before, I do now thanks. I hadn't seen an explicit use of sugar3.logger that's why I was a bit confused.

In particular I don't understand;

doesn't seem feasible as they're few activities that are interactive except we want to look at their interaction with the datastore.

Because;

* "interactive" in this issue means started from a Terminal, not Sugar, and;

Yes it does, I'd thought of something else.

* the change already made to Datastore can be reverted once we find out "why using an instance of _logger_ has restored line buffering."

Agreed.

[quozl]

Thanks!

[quozl]

Closing as Not Sugar.

Problem is solved by upgrading to Python 3.8.2, though there may be an earlier version that had the fix.