Avoiding performance overhead for disabled logging levels
Arvydas Silanskas
(03 Nov 2020 20:05 UTC)
|
Re: Avoiding performance overhead for disabled logging levels
Marc Nieper-Wißkirchen
(03 Nov 2020 21:56 UTC)
|
Re: Avoiding performance overhead for disabled logging levels
Alex Shinn
(04 Nov 2020 04:18 UTC)
|
Re: Avoiding performance overhead for disabled logging levels
Göran Weinholt
(07 Nov 2020 15:04 UTC)
|
Re: Avoiding performance overhead for disabled logging levels
Arvydas Silanskas
(25 Dec 2020 18:29 UTC)
|
Re: Avoiding performance overhead for disabled logging levels Göran Weinholt (27 Dec 2020 22:25 UTC)
|
Arvydas Silanskas <xxxxxx@gmail.com> writes: >> I think the feature you suggest is a good one to have in a logging >> system, but more suitable for a high-level system > > Fair enough, but that raises (to me at least) a question, how should > the high-level logger know about configuration of which severity > messages should be visible / calculated, and which should not? This would be configurable in the high-level logging system. There are several ways to go about it; command line flags, environment variables, configuration files, register keys, etc. > Should `lowest-visible-severity` state be part of a high-level logger? Yes, if it implements such a feature (which it very likely would). > If so, wouldn't it be a problem for the user, when configuration on > the high-level logger doesn't match the configuration on the real > logging backend attached through `current-log-callback`? If said state > shouldn't be part of the high-level logger, then I think this srfi > should have a procedure for fetching that info from the underlying > low-level logger. It is the application's responsibility set up the high-level logger's lowest visible log level. The application is also responsible for setting up current-log-callback, so it is fully capable of making them consistent. If they are inconsistent then it might be a bug, or it might be a feature. Let me explain how it might be a feature. One RTOS that I'm very familiar with has two log levels per log source ("logger"): a compile time setting and a run-time setting. The application's configuration can say that debug-level logging should be omitted for certain loggers, which improves performance and reduces the size of the program. It can also say that a certain logger should still emit debug-level logs, and in that case that level can be enabled or disabled at runtime. (When debugging a system it's sometimes useful to increase the log level of certain loggers which you suspect have useful information, but you don't want the full flood of messages from all loggers). In these festive times I felt like writing a story. Here's a contrived bit of DevOps sci-fi to dramatize how I see this srfi being used in the large. I hope it will help put some things into perspective, or at least provide some light entertainment. It is the future. People have stopped counting the years and it's always year 2020+x. Guy Q. Schemer has written an MQTT client library. One feature of his library is that it automatically reconnects if it loses the connection. He wishes to log a warning that this has happened, but he doesn't want to pull in any large dependency just for this one message. In the past he would probably just print something to standard error. (Run almost any graphical Linux program today and watch standard error fill up with unactionable messages from random sources). But it is the future and SRFI-215 has gained wide acceptance. So he just calls send-log and considers it done. He can trust that the application makes the logs go somewhere reasonable. Since he now uses SRFI-215 anyway, he also adds debug-level logging for all MQTT messages. Concurrent with these events, M.C. Eschemer made a concurrent DNS resolver library. There was enough weird stuff happening while he wrote his library that he decided to log queries and any weird data that comes back from the Internet. He asks his users to paste log data into bug reports so he can debug problems. He was already familiar with the logging system in Rotty's spells library, so he used that. We now join the ambitious J. Random Hacker, who has been writing an application in several months: a high performance web server. She needs logging, but her needs are a bit more serious than a one-off log message, so she goes to find a high-level logging system. She finds one that promises to be highly performant, Hyper Fast Logs 4 U (HyFL4U), and modifies her web server to use it. Now it so happens that J. Random Hacker has a paying client, and they ask her to add MQTT support. (For reasons that can only be understood by clients that would pay for MQTT support in a web server). She grabs the MQTT library that Guy Q. Schemer wrote and is delighted to find that it uses SRFI-215. She hooks up current-log-callback to send log messages to HyFL4U. It turns out that some other libraries she was already using were already sending logs with SRFI-215 and now that she can see those logs she finds and fixes a latent bug. Life is good. On the very day before New Year's Eve, the client reports that sometimes the web server stops responding for several seconds. They think it's because of the MQTT feature that she added, but logs show that it's not the source of the problem. She worries that maybe she'll have to work through the holidays and can't spend time with her family. After some debugging she finds that there are two reasons for the web server being slow: it has to do DNS lookups to implement reverse proxying, and sometimes the DNS is slow, causing lockups. The other reason is that HyFL4U itself is pretty performant, but the client's log server is too slow to receive all logs during bursts of high activity. Turning off logging is not an option, according to the client. After some quick research she finds M.C. Eschemer's concurrent DNS resolver, which she uses to fix the slow DNS problem. She sees that it uses the spells library, so she configures spells' log formatter to use SRFI-215's send-log. She tells her client that the web server will not lock up anymore from a slow DNS response, but that certain requests can still be slow, and to check the logs to see if this is happening. Finally she needs to do something about the client's overloaded log server. She finds no way to fix the performance issues in HyFL4U's log writer, so instead she configures HyFL4U to send its logs to SRFI-215. All logs in her application now go to current-log-callback. She next writes a concurrent log callback that buffers log entries in memory and writes them to the server at the rate it accepts them, without blocking the web server itself. Short bursts of high activity are now handled by the in-memory buffer and no logs are lost (assuming that the load goes back to normal levels reasonably soon). Having used SRFI-215 to save the day, she goes to spend New Year's Eve with her family. Happy 2020+x! With that little story out of the way, I really need to go over some aspects of the srfi document and submit a new draft. Someone asked about which type of parameters should be used and I want to not specify any exact type, meaning SRFI-39/R7RS parameters are just as fine as e.g. Chez Scheme's parameters. I've also noted something while I've been using this logging API internally in Loko Scheme. The part about how to handle condition types in message values needs some more thought. I think it's actually more convenient to allow raw condition objects to be logged, instead of converting them as the current text suggests: they are easily added to messages in exception handlers, they are easily passed through as-is to the log handler, and (at least on R6RS systems) they are easily destructured and printed. But my concern is about what to then do with condition types on R7RS systems: an R7RS program that encounters logged condition objects would not be able to do anything useful with them, just by using the tools in R7RS and other SRFIs (at least AFAIK). At best they can be converted to strings. Any opinions? Best Regards, -- Göran Weinholt | https://weinholt.se/ Debian Developer | 73 de SA6CJK