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 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)

Re: Avoiding performance overhead for disabled logging levels Göran Weinholt 27 Dec 2020 22:24 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