flush stdout logs #2669
flush stdout logs #2669
Conversation
else pipes end up not getting log output until much later
|
Because we are printing to stdout in sync mode this will slowdown all the process if |
|
Aren't we already flushing stdout here? https://github.com/status-im/nim-chronicles/blob/8b1419b4a37a3a8995a9a0a992b4705427056d98/chronicles.nim#L317 Worth checking the C output. |
|
It's a noop for the dynamic output: https://github.com/status-im/nim-chronicles/blob/63ce43a86a40a4c73d1b3b8317278d47ec55a458/chronicles/log_output.nim#L384 Also, the effect is plainly visible before and after (ie pipe through grep and look at the timestamps of first logs from startup vs how they appear on screen) |
I agree, but debug mode implies perf implications anyway. |
beacon_chain/nimbus_beacon_node.nim
Outdated
| stdout.write msg | ||
| render statusBar | ||
| # p.showPrompt | ||
| else: |
There was a problem hiding this comment.
When is this false branch taken? Since a DynamicOutput implies a BufferedOutput in Chronicles, only complete log lines are supposed to reach here.
There was a problem hiding this comment.
someone mentioned it as a possibility so I added the extra protection..
There was a problem hiding this comment.
but looking at the data that comes here, it's indeed the case that only full log lines make it
There was a problem hiding this comment.
it would be more clean if chronicles had a flush call as well for the dynamic output
There was a problem hiding this comment.
You mean a flush callback? The dynamic output is entirely application-specific. Some applications may decide to use a custom logging UI, other will send the data over the network, etc.
There was a problem hiding this comment.
so you mean it's part of the API of the dynamic output that only fully preformatted lines are ever given? even if they're significantly long etc?
There was a problem hiding this comment.
ie your comment BufferedOutput sounds more like an implementation detail than a guarantee
There was a problem hiding this comment.
Yes, indeed, this assumption is part of the API. This simplifies the problem for the user in two ways:
- No need to buffer the partial messages on your own
- No need to implement a separate flush call. You can flush in your single-message callback if you wish.
I believe the usage here is a real-world example for this simplification actually. Due to some complications in the way erase statusBar works, I think the code wouldn't produce the desired effect if partial messages were being pushed.
Maybe it would make sense to use a timer to only flush when it hasn't been done in the last few hundred milliseconds or so? This is a real problem: When restarting, I don't see any log output in the systemd journal for a few minutes which initially made me suspect something was broken. |
| try: | ||
| stdout.write(msg) | ||
| if msg[^1] == '\n': | ||
| stdout.flushFile() |
There was a problem hiding this comment.
The PR can be reduced to include only this call to flushFile (it will be unconditional)
There was a problem hiding this comment.
incidentally, that's what the first commit does
arnetheduck
force-pushed
the
flush-stdout
branch
from
300bb1d
to
11066a3
Compare
|
reverted back to commit that just simply flushes since it's only called ones per log message anyway |
else pipes end up not getting log output until much later
else pipes end up not getting log output until much later