Oceananigans.jl: Logging.

[ali-ramadhan]

Good logging should be a high priority item. Python's logging is great...

Some options:

• Base logging
• Memento.jl
• MicroLogging.jl

[arcavaliere]

Hi, I'd like to help out with this! What would you like logged?

[ali-ramadhan]

Hey @arcavaliere that would be awesome if you have the time! It's not a glamorous issue but super important for developing good software.

How familiar are you with Julia?

I think the first step is to figure out how to use the logging macros, e.g. @info and @debug, to print the current time (and possibly even filename and line number) to provide more useful logging messages.

So instead of

julia> @info "Test line"
[ Info: Test line

which isn't super useful hopefully we can have logging messages like

[09/10/2019 16:12:33] some_file.jl:55: Test line

which would be more useful.

If that's possible, I think we can start logging a lot more stuff knowing that the messages will have useful timestamps and line numbers.

[arcavaliere]

@ali-ramadhan I'm just getting started with Julia (coming from a Python background). I'll start looking into those macros!

[ali-ramadhan]

Awesome, let us know if you have any questions about anything!

Julia Slack is a pretty nice community and are pretty fast at answering general questions too, if you're interested. You just have to request an invite but everyone gets one: https://slackinvite.julialang.org/

[glwagner]

@arcavaliere just to clarify what I think this issue is all about: during a simulation we often would like to print messages that inform us of the simulation's progress. One example of this comes from a @printf statement inside a time-stepping loop in our wind mixing and convection example:

https://github.com/climate-machine/Oceananigans.jl/blob/ca814dbe608487857c06a51a7383350dcf1e46f4/examples/ocean_wind_mixing_and_convection.jl#L199

This printing produces a stream of messages during the simulation:

julia> include("ocean_wind_mixing_and_convection.jl")
i: 0010, t: 11.000 s, Δt: 1.100 s, wmax = 7.8e-04 ms⁻¹, wall time: 594.383 ms
i: 0020, t: 23.100 s, Δt: 1.210 s, wmax = 1.5e-03 ms⁻¹, wall time: 581.628 ms
i: 0030, t: 36.410 s, Δt: 1.331 s, wmax = 2.3e-03 ms⁻¹, wall time: 567.346 ms
i: 0040, t: 51.051 s, Δt: 1.464 s, wmax = 3.2e-03 ms⁻¹, wall time: 562.455 ms
i: 0050, t: 1.119 min, Δt: 1.611 s, wmax = 4.2e-03 ms⁻¹, wall time: 576.511 ms
i: 0060, t: 1.415 min, Δt: 1.772 s, wmax = 5.2e-03 ms⁻¹, wall time: 571.096 ms

In this case, the information we decide to print is:

• iteration number i
• the simulation time t
• the time-step (because we are using adaptive time-stepping)
• the maximum vertical velocity
• the elapsed wall time for time stepping only (not including plotting) between print messages

I think this issue is about a better way to achieve the printing of simulation progress. Two ideas are:

1. Somehow use a logging package (though I'm not 100% what this would look like --- perhaps this means adding lines to our time-stepping loop?
2. Create some types that allow the user to more easily manage the printing of progress messages, expanding on the pattern used in our example.

I've thought a bit about 2: I think a generic progress messenger would be both configurable but also include some comforting defaults. A simple way to start could be something like

struct ProgressPrinter{DT, M, D}
    Δt :: DT
    model :: M
    diagnostics :: D
end

with some kind of print function, something like

pretty_Δt(Δt::Number) = prettytime(Δt)
pretty_Δt(Δt::TimeStepWizard) = prettytime(wizard.Δt)

function Base.print(progress::ProgressMessenger)
    @printf("i: %04d, t: %s, Δt: %s, 
            progress.model.clock.iteration, prettytime(progress.model.clock.time), pretty_Δt(progress.Δt)) 
    return nothing
end

One could then expand on this design by setting up the diagnostics field to accept a list of callable objects or functions. Or even better, a list of objects that look something like

struct PrintableDiagnostic{D}
    diagnostic :: D
    format :: String
    name :: String
    units :: String
end

function pretty_diagnostic(pd::PrintableDiagnostic, model)
    return @sprintf("%s: $(pd.format) %s", pd.name, pd.diagnostic(model), pd.units)
end

with this design, the user can pass a list of PrintableDiagnostics to ProgressPrinter, which are then evaluated and the results turned into a string via the function pretty_diagnostic.

As for option 1 of using a logging package, perhaps it could be nice to use some logging functionality that's configurable with global variables (?) rather than manually creating a ProgressPrinter that does "brute force" printing as I have described above. However I think that it would require some customization of existing logging packages, since the typical info or debug settings are not sufficient for the purposes of logging simulation output (right?) Instead, we would need more options, and it'd be nice to obtain the ability to also print the output of diagnostics / monitoring functions, as we do in the example script. And I think doing it this way might involve adding some lines to our time stepping loop.

Perhaps @ali-ramadhan has more to say.

Another thing we have talked about is somehow having the ability to live-update messages in the terminal (rather than printing a stream of message). This would be nice because it could dramatically reduce the text-noise that a stream of messages invokes, allowing the user to much more easily read and interpret the output of a simulation progress (in addition to creating the possibility for nice pseudo-animations via UnicodePlots.jl). I'm not 100% sure how to do this; one places to start could be https://github.com/ronisbr/TextUserInterfaces.jl.

Any work on any of these ideas could be useful! I'd be happy to Skype to talk more and clarify any questions.

[ali-ramadhan]

These are definitely cool ideas for progress statements!

I see logging as being much more general though. It should also be used when printing progress statements, but I think it's especially useful to have @debug messages in certain places to help with debugging.

And maybe @info messages so the user knows what the model is doing. It could get noisy if we get carried away with them but a user staring at a blank screen for 3 minutes might not know that the GPU stuff is just compiling in the background. More responsive software feels more user-friendly.

[glwagner]

That sounds like it could be nice; can you maybe give some examples? These messages used in constructors perhaps?

So there are two issues: simulation progress statements, and logging for model construction / instantiation?

[arcavaliere]

I started working on a ModelLogger that will handle printing @info calls in the style @ali-ramadhan proposed. It's based on Logging.SimpleLogger. I am running into some trouble with Julia not finding my definitions of the functions associated with AbstractLogger though.

Additional log levels can be defined if there would be interest in something like @diagnostic or @setup.

For ProgressPrinter I think it would be straight forward enough to use either @info or a custom macro to handle progress logging.

[ali-ramadhan]

Didn't know you could define custom macros like @diagnostic, that would be pretty cool!

What's the error you're getting? Can you post your code in this issue (or open a pull request)? We can help out with debugging!

[ali-ramadhan]

@arcavaliere There's some discussion about logging at https://github.com/climate-machine/CLIMA/issues/134

[arcavaliere]

Here's the PR.

I'm running into a LoadError: MethodError for min_enabled_level(::ModelLogger). I'm not sure how to rectify that issue. Any help will be appreciated!

[c42f]

Hi guys, please feel free to ping me on all logging-related stuff for CLiMA. I pushed through the logging frontend API which exists in 1.0 and I think it can help you understand your simulations. I'm particularly keen to hear use cases related to CLIMA because it's a large scale code with several modules running in a distributed execution environment. Some new logging backend components will need to be invented to make this work well but I think the existing logging frontend is a solid foundation to build on.

Regarding live tracking of simulation progress, a couple of points:

• The logging system is designed for exactly this kind of thing - it should slot in nicely
• For graphs you could check out TensorBoardLogger. It's designed for ML applications, but the core need seems similar: TensorBoard is a log aggregator which provides rich graphical display for certain data types and can run on the cluster where the compute is happening.
• MicroLogging master contains some utilities to make progress reporting nicer so you could check those out. There's also ProgressLogging.jl which does something similar. (Eventually we should to consolidate some of these tools.)

[ali-ramadhan]

Hi @c42f thank you for chiming in! Will definitely ping you as we work on logging.

I think we probably should have tackled logging much earlier. We still use @printf and vanilla @info for logging, which has been quite counter-productive haha.

Definitely hoping we can reach a useful logger that can

• help developers by providing info and debug messages. Also nice in test logs.
• help users understand what the model is doing and provide a better and more responsive user experience by logging what the model is doing. This is where @setup and @diagnostic logging messages might be really nice.

Although @setup and @diagnostic might be bad names as they don't imply logging? Not sure of the best solution but maybe your kwarg suggestion would help here, e.g. @info source="diagnostic" msg?

@arcavaliere seems to be developing a pretty general-purpose ModelLogger which hopefully we can adapt for all these uses! @arcavaliere I'm more than happy to help if you need anything.

MicroLogging.jl looks pretty neat! I like that it puts the log level, file name, and line number on the right as putting them on the left causes messages not to align and makes logs harder to read.

TensorBoardLogger looks pretty cool! Would be awesome to have something like that one day, but I guess you'd have to use something like ncusrses...

[arcavaliere]

I updated the PR with @diagnostic and @setup as suggested here. Would you like me to work on porting the formatting from MicroLogging & Logging.ConsoleLogger over the ModelLogger next? Or is the getting the PrintableDiagnostic struct created and usable the next priority?

[ali-ramadhan]

That's awesome, thanks @arcavaliere!

I think if we can get a printing format similar to MicroLogging.jl with a timestamp on the left and log level + line location then we'll have a great logger we can merge into the code and start using!

And once we start using it we can tweak and improve it as we learn more.

But let me know if you had other features in mind!

[c42f]

I do think @diagnostic and @setup are just @info level logging because they describe normal state changes in your application.

As you can see over on the Base repo, there's ongoing debate about exactly what the _group keyword is for, but you could experiment with keywords _group=:diagnostic or _group=:setup and see how that feels.

[c42f]

I like that it puts the log level, file name, and line number on the right as putting them on the left causes messages not to align and makes logs harder to read.

By the way, this is available in stdlib Logging.ConsoleLogger, but it's hidden behind the right_justify keyword and I'm not sure anyone uses it! I had a long debate about this when putting this code into Base, which I lost ;-) (TBH I'm happy with the outcome because having people copy and paste log messages which are right-justified to a particular terminal width would have led to rather a mess.)

[c42f]

I do think @diagnostic and @setup are just @info level logging because they describe normal state changes in your application.

Just reading the code, I see you've assigned them different importance levels. So perhaps I'm wrong!

[ali-ramadhan]

Resolved by @arcavaliere in PR #478 :tada: