Add callback that estimates walltime

[charleskawczynski]

This PR adds a callback that logs some helpful runtime information:

┌ Info: Progress
│   simulation_time = "21 hours, 30 minutes"
│   n_steps_completed = 129
│   wall_time_per_step = "101 milliseconds, 824 microseconds"
│   wall_time_total = "2 minutes, 26 seconds"
│   wall_time_remaining = 133.4913111176602
│   wall_time_spent = "13 seconds, 135 milliseconds"
│   percent_complete = "9.0%"
│   sypd = 16.144
│   date_now = 2023-12-14T10:42:19.127
└   estimated_finish_date = 2023-12-14T10:44:32.618

The callback uses a doubling backoff (we log on step 2, 4, 8, 16, 32, ...) to provide frequent estimates near the beginning of simulations, but increasingly infrequent as time goes on to avoid bloating the log (I don't want people to have to scroll through a zillion info statements in the longruns to get to the end of the log).

[Sbozzolo]

Thanks, this is very useful! I will review it tomorrow morning.

A very quick comment is that I find total a little misleading: at the beginning, I thought I meant "total elapsed time since the beginning"

[charleskawczynski]

Ah, time_and_units looks wrong.. It'd be nice if we can do this more elegantly. Looking at DateTIme now..

[Sbozzolo]

Ah, time_and_units looks wrong.. It'd be nice if we can do this more elegantly. Looking at DateTIme now..

Let me know when you want me to review the PR :)

[charleskawczynski]

Let me know when you want me to review the PR :)

I think I have a nice solution, but maybe you can review the rest of the PR in the mean time (just ignore time_and_units for now). @Sbozzolo

[simonbyrne]

I find the output kind of hard to parse: could you put the values next to the name? Or even on multiple lines (the macros do this automatically if you provide extra arguments

julia> @info "Wall time" var"per step"=100 total=200 remaining=300
┌ Info: Wall time
│   per step = 100
│   total = 200
└   remaining = 300

[simonbyrne]

Ah, time_and_units looks wrong.. It'd be nice if we can do this more elegantly. Looking at DateTIme now..

canonicalize is helpful here:

julia> using Dates

julia> canonicalize(Second(10_000))
2 hours, 46 minutes, 40 seconds

[charleskawczynski]

canonicalize is helpful here:

julia> using Dates

julia> canonicalize(Second(10_000))
2 hours, 46 minutes, 40 seconds

Yeah but, for now (JuliaLang/julia#52519 😄), there's no way to convert from Real.

[Sbozzolo]

Let me know when you want me to review the PR :)

I think I have a nice solution, but maybe you can review the rest of the PR in the mean time (just ignore time_and_units for now). @Sbozzolo

One general design comment before I look at the details is that maybe we can be a little bit more ambitious that just tracking the walltime. You added a TWE object to the cache, maybe we can turn this into a more general instrumentation object for ClimaAtmos runs. For example, the object might also track memory usage, and maybe optionally print more detailed/frequent stats to file. At this stage, it would just track walltime, but this would provide a natural place where to put extra instrumentation.

What do you think?

(For this PR, this would probably just amounts to renaming the struct)

(And I also agree with Simon that the output is hard to read.)

[charleskawczynski]

Let's also add time spent

[simonbyrne]

I think it would be good to have:

• time elapsed (how long so far)
• sypd estimate (can compute from wall time / time step)

[simonbyrne]

ideally we would also want to exclude the first time step.

[charleskawczynski]

Alright, I've

• added time elapsed / spent
• Added simulation time
• Renamed n_steps to n_calls, which is a more accurate name
• Added n_steps_completed
• Avoided n_steps = 1 (since the cb is called during init, which messed up the timings)
• Added a sypd estimate
• Updated names a bit so that some things are a bit more clear, but there's probably still room for improvement.
• Added Dates.now()
• Added an estimated finish date - this should be useful because then we now won't need to know when the last progress log was printed!

it now looks like:

┌ Info: Progress
│   simulation_time = "21 hours, 30 minutes"
│   n_steps_completed = 129
│   wall_time_per_step = "101 milliseconds, 824 microseconds"
│   wall_time_total = "2 minutes, 26 seconds"
│   wall_time_remaining = 133.4913111176602
│   wall_time_spent = "13 seconds, 135 milliseconds"
│   percent_complete = "9.0%"
│   sypd = 16.144
│   date_now = 2023-12-14T10:42:19.127
└   estimated_finish_date = 2023-12-14T10:44:32.618

I think this is ready for review + bike shedding cc @simonbyrne, @Sbozzolo . I'll update the original post to include this snapshot.

[Sbozzolo]

Thank you! I have only minor cosmetic comments.

[Sbozzolo]

Looks good to me! :)