Builtin timer blocks

[christophernhill]

Adding this before I forget.

It could be useful to have builtin support for getting wall clock time spent in key "blocks" of code during any
simulation.

For example knowing how long is spent in iterative solver, how long in I/O, how long in time stepping, how long in initialization, how long in dynamics computations, how long in tracer computations, how long in communication etc.. can be a useful check and help see what is requiring resources in different configurations.

[glwagner]

Perhaps we could put log this info at the @debug level?

We've also discussed logging initialization at @info (so that everyone sees it).

I think logging individual tendency kernel timings might be hard because they are completed asychronously, but we can log how long it takes to compute all the tendencies.

[glwagner]

We could also introduce a new log level, eg TIMINGS or something.

Might not be good to hijack @debug --- it's used for other stuff, so the timing logs might get buried. Like this 100-iteration simulation:

 Debug: PreconditionedConjugateGradientSolver 9, |r|: 2.0861651135626188e-13
└ @ Oceananigans.Solvers ~/Projects/Oceananigans.jl/src/Solvers/preconditioned_conjugate_gradient_solver.jl:185
┌ Debug: PreconditionedConjugateGradientSolver 9, ρ: 4.352084881045736e-26
└ @ Oceananigans.Solvers ~/Projects/Oceananigans.jl/src/Solvers/preconditioned_conjugate_gradient_solver.jl:192
┌ Debug: PreconditionedConjugateGradientSolver 9, |z|: 2.0861651135626188e-13
└ @ Oceananigans.Solvers ~/Projects/Oceananigans.jl/src/Solvers/preconditioned_conjugate_gradient_solver.jl:193
┌ Debug: Launching kernel broadcast_xy! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: PreconditionedConjugateGradientSolver 9, β: 0.1312038209706307
└ @ Oceananigans.Solvers ~/Projects/Oceananigans.jl/src/Solvers/preconditioned_conjugate_gradient_solver.jl:201
┌ Debug: Launching kernel _fill_west_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_east_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _implicit_free_surface_linear_operation! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_west_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_east_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: PreconditionedConjugateGradientSolver 9, |q|: 3.772383893402093e-14
└ @ Oceananigans.Solvers ~/Projects/Oceananigans.jl/src/Solvers/preconditioned_conjugate_gradient_solver.jl:208
┌ Debug: PreconditionedConjugateGradientSolver 9, α: -6.011747836845152
└ @ Oceananigans.Solvers ~/Projects/Oceananigans.jl/src/Solvers/preconditioned_conjugate_gradient_solver.jl:209
┌ Debug: Launching kernel broadcast_xy! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel broadcast_xy! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_west_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_east_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Implict step solve took 37.994 ms.
└ @ Oceananigans.Models.HydrostaticFreeSurfaceModels ~/Projects/Oceananigans.jl/src/Models/HydrostaticFreeSurfaceModels/implicit_free_surface.jl:94
┌ Debug: Launching kernel _barotropic_pressure_correction with worksize (128, 1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel set_east_west_u_velocity! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel set_east_west_u_velocity! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_bottom_halo! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_top_halo! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_west_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_east_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_bottom_halo! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_top_halo! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_west_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_east_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_west_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_east_halo! with worksize (1, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85
┌ Debug: Launching kernel _fill_bottom_halo! with worksize (128, 1)
└ @ Oceananigans.Utils ~/Projects/Oceananigans.jl/src/Utils/kernel_launching.jl:85

I think I'll try to pepper a few @info here and there when resolving this issue.

Ultimately it'd be slick to have some cool wigits, spinners, and progress bars like what happens when julia precompiles packages...

[ali-ramadhan]

Timing blocks would be great. I believe with https://github.com/KristofferC/TimerOutputs.jl timing blocks is a zero-cost operation with the @timeit_debug macro (see https://github.com/KristofferC/TimerOutputs.jl#overhead).

[glwagner]

@ali-ramadhan what do you think about a new log level for timing that doesn't spit debug?

[ali-ramadhan]

New log level should be enough if we just need flat per-iteration timings to time a few blocks for a few iterations. Are you thinking of just logging raw @time data?

I'm not sure if we need anything more than a new log level, but I imagine some of the benefits of using a package like TimerOutputs.jl would make the timer blocks much more useful for debugging and for users. It allows for nested timers and produces a very nice table summary at the end which includes number of calls and average time/memory allocations.

This could also be useful for users wishing to time their simulations to figure out how much time is being spent on I/O vs. in kernels vs. solvers vs. callbacks, etc. I guess I also see timers as a debugging tool for users. Could help be figure out cluster filesystem issues or figure out whether Oceananigans or my coupled model (via callback) is the bottleneck.

Otherwise if the timers are just a developer debugging tool that dumps timing information, that's useful but it might not be useful for timing real-world scripts/simulations since the log would fill up with a huge number of lines that can't be interpreted without further processing.

Here's an example of it in use: JuliaGPU/CUDA.jl#149 (comment) (CUDA.jl has been using TimerOutputs.jl for a long time I think)

TimerOutputs.jl is easy to use since you just add @timeit blocks but that does add some noise to the code (not sure if more or less than using a timing log level).

[christophernhill]

New log level should be enough if we just need flat per-iteration timings to time a few blocks for a few iterations. Are you thinking of just logging raw @time data?

I'm not sure if we need anything more than a new log level, but I imagine some of the benefits of using a package like TimerOutputs.jl would make the timer blocks much more useful for debugging and for users. It allows for nested timers and produces a very nice table summary at the end which includes number of calls and average time/memory allocations.

This could also be useful for users wishing to time their simulations to figure out how much time is being spent on I/O vs. in kernels vs. solvers vs. callbacks, etc. I guess I also see timers as a debugging tool for users. Could help be figure out cluster filesystem issues or figure out whether Oceananigans or my coupled model (via callback) is the bottleneck.

Otherwise if the timers are just a developer debugging tool that dumps timing information, that's useful but it might not be useful for timing real-world scripts/simulations since the log would fill up with a huge number of lines that can't be interpreted without further processing.

Here's an example of it in use: JuliaGPU/CUDA.jl#149 (comment) (CUDA.jl has been using TimerOutputs.jl for a long time I think)

TimerOutputs.jl is easy to use since you just add @timeit blocks but that does add some noise to the code (not sure if more or less than using a timing log level).

@ali-ramadhan I was thinking timing would be useful for general use around figuring out where time is going in day-to-day modeling - so some summary table as in TimerOutputs.jl would be a great thing to aim for - I think?

[glwagner]

TimerOutputs sounds awesome! Was just thinking about a new log level since debug spits a lot of information, which might make the output hard to interpret if you're only interested in looking at timings. So maybe a TIMINGS log level between INFO and DEBUG would be useful.

[glwagner]

Are you thinking of just logging raw @time data?

Agnostic about the logging format and TimerOutputs sounds awesome.

[glwagner]

I guess I also see timers as a debugging tool for users.

Totally agree since simulation performance can depend entirely on performance of forcing functions, boundary conditions, and diagnostics; not just code that ships in src.