GEOS-DEV
[Feature] Ideas for better logging
This is a proposal to improve the clarity of logging and overall user experience in GEOSX. I will describe several ideas that can be discussed/accepted/rejected separately.
-
Component log levels. Declare a fixed set of logging levels with well-defined usage guidelines across different components of the code. It remains up to each individual component to define specifically what to output at each level, in accordance with these guidelines. In addition to that, we should introduce a separate flag into physics solvers and/or linear solvers for dumping large-volume debugging information (primarily linear systems) to screen/file, and separate this setting from
logLevel. Off the top of my head, I would define at least these 4 log levels:-
silent: maximum possible silent execution, not even time stepping; not sure if this is useful to anyone in practice, but I like it when command-line programs have a silent mode, it's good for scripting -
progress(ornormal, ordefault): forward progress information only, such as time steps forEventManager, time step attempts and Newton loop progress for physics solvers -
detailed: in addition to progress, print more detailed info and stats that affect progress, e.g. residual norms. -
trace: in addition to all of the above, log a detailed trace of what each component is doing, this would include for example a line for every part of the assembly process, every boundary condition that's being applied by a physics solver, etc. This is intended as a user-level debugging tool.
-
-
Application-wide log levels. These can be the same or different from the above, but controlled globally via a command-line flag (e.g.
--verbosity=trace). This can have two functions:- Override component-level log levels, i.e. if the application-wide log level is
silent, even components with more verbose log levels shouldn't print anything. This way we could enable high verbosity by default in all of our tests, but a developer running a specific test case where they aren't interested in that level of detail can bring it down a notch without changing the input file. - Control logging level for things that are either not attached to a specific component (e.g. printing overall time statistics at the end, version/threads at the beginning, etc.), or where component log level cannot yet apply (e.g. trace of the XML being read - we haven't parsed the
logLevelattribute at that point yet).
- Override component-level log levels, i.e. if the application-wide log level is
-
Structured logging. Currently we are rather random in how the logging is structured, e.g. what amount of whitespace is prepended to each line, and logs aren't very grep-friendly because important context (such as current time) is missing from each specific line. The idea is to introduce call-stack-based logging contexts and have them automatically prepended to each log line, to have it looking along the lines of:
[t=1e+6][dt=1e+4][compflow][attempt=1][newton=8] Convergence not reached, going to cut the time step
This would likely take a form similar to annotating scopes with Caliper macros:
for( integer newtonIter = 0; newtonIter < maxNewtonIter; ++newtonIter )
{
GEOSX_LOG_SCOPE( "newton=" << newtonIter );
...
}
I haven't fully developed this idea in my head yet, feel free to disagree (or even immediately hate it) :)
- Memory transfer logging. This is a very minor point, but I think that logging all host-device memory transfers in CUDA runs should be an option, not the default. It aids the developer, but not very useful for a normal user. We have the command-line flag that disables it, but it should be exactly the other way around.
Override component-level log levels, i.e. if the application-wide log level is silent, even components with more verbose log levels shouldn't print anything.
As first thought, I would say that the specific should prevail over the general.
Structured logging
That could be a nice feature, specially if we manage to "intercept" our TPLs outputs (which may not be so simple!). Which benefit do you exactly hope from this? Easier parsing? Will this practically be the case?
Memory transfer logging
Quite true imho.
Override component-level log levels, i.e. if the application-wide log level is silent, even components with more verbose log levels shouldn't print anything.
As first thought, I would say that the specific should prevail over the general.
There are certainly different ways of looking at it, we can decide based on specific use cases we'd like to support. Maybe you're right, and my "silencing the test" example is not very convincing.
Structured logging
That could be a nice feature, specially if we manage to "intercept" our TPLs outputs (which may not be so simple!). Which benefit do you exactly hope from this? Easier parsing? Will this practically be the case?
Yes, I was thinking about the ease of analyzing logs semi-automatically, like finding all instances of a non-converged time step, or wells switching control type. But also just the overall aesthetics of log output, like consistent indentation at different levels of detail (which can be achieved in different ways).
TPL output intercept is probably not going to work indeed, luckily the only TPLs that do direct output are linear algebra packages - with higher verbosity enabled. If somebody wants that level of detail, it's probably fine to just let them "break" the log structure.
