Re: [racket-dev] (reposted from users) Noisy compiler at PLTSTDERR=info

2015-01-22 Thread Matthew Flatt
At Wed, 21 Jan 2015 11:22:38 -0500, Tony Garnock-Jones wrote:
 Over the past few months, more and more subsystems have started logging
 at info level as part of regular compilation.
 
 I prefer having PLTSTDERR=info in order to catch log-info that happens
 at runtime, and find the compile-time log output quite distracting.
 
 My current workaround is to set
 
 PLTSTDERR=info warning@cm warning@compiler/cm warning@module-prefetch
 warning@setup/parallel-build warning@cm-accomplice
 warning@online-check-syntax
 
 but this is quite verbose, and as subsystem log messages come and go
 I'll need to keep updating it.
 
 Could one of the following ideas be worth exploring?
 
  1. Have a superlogger for these (and other?) compile-time-ish loggers,
 so that I could write info warning@compilation, excluding the
 noise in one fell swoop
 
  2. Have a phase number associated with logging, so I could say
 info@0 warning@1, or similar

I have a suggestion below, but it's based on a guess of what you really
want, and it might be a bad guess.


Here's my train of thought:

On 1 above: I've been uncertain of the best way to organize logging
from the start, but the idea of grouping topics hierarchically (such as
a compilation topic group) doesn't sound promising. The original
implementation had a notion of hierarchy that I thought might play out
this way, but it didn't. Overall, it seems to be difficult to fit
topics into a hierarchy a priori, in much the same way that it has been
difficult or awkward to group exceptions hierarchically (and few Racket
libraries attempt to extend the exception hierarchy). I guess there's
often a mismatch between the producer's original idea of organization
the and consumer's eventual idea.

On 2 above: I'm not sure why compilation or phase 1 is special. As more
and more libraries use logging, it seems like they will generate noise
(from your perspective) at run time, too.


More generally:

The most successful step in the logging system's evolution was the move
toward level@topic specifications that include specific topics
of interest. In a growing sea of information, knowing which pieces you
want and specifying those pieces makes sense. Trying to exclude a
category of information is much harder, because it's hard to know all
the information that will be available to exclude.

At the same time, it makes sense to have error messages visible all
the time for all topics, because users should see errors that they
didn't anticipate. Similarly, it makes sense for a user to request
extra unanticipated information at the warning level.

In this sense, the info label is ambiguous. The info level could be
like warning: information that a human consumer might be interested
in without anticipating it, but (unlike warning) not a suggestion of
a problem. Or info could be more like debug: details that are only
useful when you're looking closely at a specific subsystem. A potential
distinction between info and debug is that the former makes sense
to the consumer of the subsystem as opposed to the producer.

My only idea, then, is that we're missing a level somewhere between
debug and warning. My guess is that you're getting too much
information from info, because you wanted a human-volume level of
status information; sometimes info is used for that. Other uses of
info are more like debug --- not really human-volume --- and that's
the part you don't want to see. It happens that many of the current
debug-like uses of info are in compilation subsystems.

If I'm guessing right, then we could introduce a new level and sort out
existing uses:

 * fatal - last-ditch communication channel before termination
 * error - errors
 * warning - info for humans that alerts a potential mistake
 * info - info for humans on status and progress
 * detail - info for subsystem consumers, not necessarily human-volume
 * debug - info for subsystem implementers, not necessarily human-volume

The idea is that most of the compilation messages could move to
detail. (Or maybe it makes sense to add the level between info and
warning; it becomes a transition and compatibility question as much
as anything.)

In retrospect, I realize that I've often struggled with choosing info
vs. debug levels precisely because I haven't been clear on which is
meant as human-volume --- or even that it makes sense to consider a
human-volume vs. machine-volume distinction. Other times, I've
struggled with info vs. debug because of a internal vs. external
distinction.


Does any of that connect to your actual situation and goals?

_
  Racket Developers list:
  http://lists.racket-lang.org/dev


Re: [racket-dev] (reposted from users) Noisy compiler at PLTSTDERR=info

2015-01-22 Thread Tony Garnock-Jones
Hi Matthew,

Thanks for those thoughts.

On 01/22/2015 09:11 AM, Matthew Flatt wrote:
 On 1 above: I've been uncertain of the best way to organize logging
 from the start, but the idea of grouping topics hierarchically (such as
 a compilation topic group) doesn't sound promising.

I agree. Better perhaps would be a more relational approach. There are
all sorts of cross-cutting ways one might like to filter log messages:

 - by package author (all the messages in code I wrote)
 - by package
 - by collection
 - by module
 - by specific subroutine?
 - by level (debug, info, warning etc)
 - by phase
 - by place
 - by predicate (e.g. regexp) on log message or log datum

I don't know how to do this yet. Certainly not with the efficiency of
the current logging system!

 I guess there's
 often a mismatch between the producer's original idea of organization
 the and consumer's eventual idea.

Yes, that's a very good point.

 On 2 above: I'm not sure why compilation or phase 1 is special. As more
 and more libraries use logging, it seems like they will generate noise
 (from your perspective) at run time, too.

On reflection, I agree with you. Phase is just one of the many axes
listed above.

 In this sense, the info label is ambiguous. [...]
 My only idea, then, is that we're missing a level somewhere between
 debug and warning.

To me it feels like there is one major divison when it comes to levels:
that between errors/warnings and informational messages. Within each
grouping, less important subdivisions exist.

If I can turn on and off the informational messages as a group, for
individual *subsystems*, I think I'm happy.

So my current workaround works OK for me. Adding an extra gradation
between info and debug wouldn't add much in this example.

I think I'm after finer control of selecting messages on axes *other*
than level/severity.

-- Tony

_
  Racket Developers list:
  http://lists.racket-lang.org/dev


[racket-dev] (reposted from users) Noisy compiler at PLTSTDERR=info

2015-01-21 Thread Tony Garnock-Jones
[Reposted from -users, since it seems likely I erred in my initial
selection of that list]

Hi all,

Over the past few months, more and more subsystems have started logging
at info level as part of regular compilation.

I prefer having PLTSTDERR=info in order to catch log-info that happens
at runtime, and find the compile-time log output quite distracting.

My current workaround is to set

PLTSTDERR=info warning@cm warning@compiler/cm warning@module-prefetch
warning@setup/parallel-build warning@cm-accomplice
warning@online-check-syntax

but this is quite verbose, and as subsystem log messages come and go
I'll need to keep updating it.

Could one of the following ideas be worth exploring?

 1. Have a superlogger for these (and other?) compile-time-ish loggers,
so that I could write info warning@compilation, excluding the
noise in one fell swoop

 2. Have a phase number associated with logging, so I could say
info@0 warning@1, or similar

-- Tony
_
  Racket Developers list:
  http://lists.racket-lang.org/dev