Project

General

Profile

Task #1505

improve handling of logging

Added by Mark Abraham over 5 years ago. Updated 8 months ago.

Status:
New
Priority:
Normal
Assignee:
Category:
core library
Target version:
-
Difficulty:
uncategorized
Close

Description

In https://gerrit.gromacs.org/#/c/3453/, Szilárd Páll said

How about printing [list of compatible GPUs] only in verbose mode? My thinking is that we should try to move toward a better use of verbosity levels, especially in filtering messages to the stout which will allow us to omit more useful messages, but many of them only with verbose output on.

Mark Abraham said

Some more sanity would be nice. Configuring (say) md_print_extra_info to write only to the log with -v set makes sense. md_print_info should probably not hit the console at all. Also, passing around only a logger object and not both fplog and cr would be good. Perhaps tie in the -debug output also. But we need about half a dozen key files converted to C++ first. So I think some time soon for this.

Teemu Murtola said

If/when we want to go that way, I'd prefer that the implementation is not specific to mdrun, but applicable to all code, so that there are no direct writes to stderr/stdout. This makes automated testing a lot more sane. It may also make sense to make this a global property instead of passing one or more data structures for this purpose to ~every function in the codebase. Threading handling (in particular in the context of tMPI+OpenMP) may need extra thought, but even with this approach, it would still be possible to pass those objects around as parameters in places where it simplifies things.


Related issues

Related to GROMACS - Task #2084: MPI and stderr/log outputNew
Related to GROMACS - Bug #2211: gmx writes normal output to stderr New
Related to GROMACS - Task #2344: Agree on standards for different types of output and log filesClosed
Related to GROMACS - Task #2999: Move all logging in core library and tools to use MDLoggerNew

Associated revisions

Revision 20bbcb75 (diff)
Added by Teemu Murtola about 3 years ago

Use C++ replacement for md_logging.*

Replace md_logging.h with the new C++ implementation. This removes the
need to pass around a (FILE *, t_commrec *) tuple for just calling
md_logging.h routines. Initialize the logger in runner.cpp to get the
same output as earlier. For now, output is the same as earlier, but the
new interface could also relatively easily support, e.g., automatic line
wrapping.

Further changes should see all of fplog access go through the same
object (possibly after finetuning the interface), but that would be too
large of a change to do in one go.

Thread affinity tests for now just discard the log output, making them
more silent. Future changes should see the log output verified, to
check that the correct messages are produced.

Related to #1505, closes #1644.

Change-Id: I0895b752b040d231cacb49a3a7a48d26c6096944

History

#1 Updated by Mark Abraham over 5 years ago

Line wrapping would also be a nice feature here - md_print_* currently leaves that to the caller, whereas grompp-style warnings do wrapping.

#2 Updated by Teemu Murtola over 5 years ago

Line wrapping should be easy: the C++ side has a quite flexible line wrapper that can be used even without memory allocation, so even performance should not be an issue. utility/errorformat.cpp shows an example of using this mode (there, the motivation is exception-free operation).

#3 Updated by Gerrit Code Review Bot about 3 years ago

Gerrit received a related patchset '5' for Issue #1505.
Uploader: Teemu Murtola ()
Change-Id: I0895b752b040d231cacb49a3a7a48d26c6096944
Gerrit URL: https://gerrit.gromacs.org/5449

#4 Updated by Mark Abraham over 2 years ago

  • Related to Task #2084: MPI and stderr/log output added

#5 Updated by Mark Abraham about 2 years ago

  • Related to Bug #2211: gmx writes normal output to stderr added

#6 Updated by Mark Abraham over 1 year ago

  • Related to Task #2344: Agree on standards for different types of output and log files added

#7 Updated by Mark Abraham over 1 year ago

At a recent meeting in Stockholm, we decided on the following policy (assuming people agree with my memory, plus a few details I've added since):

For mdrun:
  • modules will write to three output streams (warning, info, debug)
  • the output destination of those streams is determined by the runner (e.g. by default, warning stream goes to stderr and log, info goes to log, debug is discarded)
  • stream output should have the first e.g. 4 columns contain a descriptor (to separate physics status info from performance/parallelism status info, and maybe also initial reporting)
  • spacing and line wrapping should be handled by the logger, not the coder
  • mdrun -v is an integer (default 0) that writes streams also to different output destinations, and/or adds more context to messages
  • stdout will be quiet by default (e.g. a line or two as the simulation starts, then a confirmation that it finished normally)
  • stderr may only report critical information (e.g. anything from the warning stream)
  • a "fatal error" should write to warning stream before passing control back to the runner (seems best to implement with exceptions)
For command-line tools (in which we include mdrun energy minimzation):
  • stdout may report status
  • stderr should be quiet unless failing

We still have the unresolved question of how to coordinate error handling between and within simulations over MPI.

#8 Updated by Szilárd Páll over 1 year ago

Mark Abraham wrote:

  • stdout will be quiet by default (e.g. a line or two as the simulation starts, then a confirmation that it finished normally)
  • stderr may only report critical information (e.g. anything from the warning stream)

I want add something that AFAIK we did discuss and agree on, but it has been and keeps being a point of disagreement: before yanking all console output claiming that "this is not an important message" or that "nothing should be written to stderr", we should first have the infrastructure to handle verbosity levels and instead take a more nuanced (and less opinionated / aggressive) approach to what "belongs" where. Just because something doesn't belong to stderr, it does not mean that in verbose mode it should not be reported; related is #2472 (and https://gerrit.gromacs.org/#/c/7741/) as well as hardware detection reports.

#9 Updated by Mark Abraham over 1 year ago

I'm happy for e.g. release-branch changes to note that some log file output might/would make sense to write to a terminal if the user chose a verbose mode, but that is not itself an argument for always writing it to the terminal (thereby adding to the perceived problem).

If the desire to be helpful to users who run with mdrun -v motivates people to help with changes to make more widespread use the logger functionality (and add such support for verbosity levels and stream redirection to it) then that sounds like an excellent compromise. We have bad habits of adopting technical debt during release phases, not touching it for a year, and then protesting that it shouldn't be changed during the subsequent release phase either.

#10 Updated by Mark Abraham 12 months ago

Szilárd Páll wrote:

I want add something that AFAIK we did discuss and agree on, but it has been and keeps being a point of disagreement: before yanking all console output claiming that "this is not an important message" or that "nothing should be written to stderr", we should first have the infrastructure to handle verbosity levels and instead take a more nuanced (and less opinionated / aggressive) approach to what "belongs" where. Just because something doesn't belong to stderr, it does not mean that in verbose mode it should not be reported.

There's some merit in that approach, however it seems excessive to require that we do not change any message before we build some infrastructure. (One could make a similar argument for any part of mdrun, e.g. we should do no new GPU work until the duplication in the CUDA and OpenCL modules is substantially improved, and I assume we don't want to live in that world.)

For messages currently sent to stdout/stderr that duplicate info-level content that is also found in the log file, the above policy is already sufficient. Stderr may only write critical content, so that can go now and simplify the job later. When we have new verbosity handling functionality, the info-level content currently sent to the log file will be considered for writing to stdout at a given verbosity level.

#11 Updated by Erik Lindahl 8 months ago

I just stumbled upon another reason we should be careful about issuing general performance warnings to stdout/stderr.

When running our usual unit tests on a machine with many cores, a bunch of them seem to fail because of various warnings related to thread pinning or numbers of cores being suboptimal. While this could be useful as a note for a normal user, it also creates more work - most of the mdrun/mdrun-mpi unit tests already contain a number of warnings that have had to be added as exceptions, and we don't want to create a situation where every such test now also requires separate exceptions depending on the hardware on which the test is run (e.g. lots of cores, multiple non-matching GPUs available, just having a subset of cores assigned from a batch system).

#12 Updated by Paul Bauer about 2 months ago

  • Related to Task #2999: Move all logging in core library and tools to use MDLogger added

Also available in: Atom PDF