Implement new utility code and coding standards for timing.

[quantheory]

I have proposed the changes explained here for CESM. While the driver code largely follows these standards already, some changes are needed in perf_mod to make this approach more convenient.

[rljacob]

Is this proposal still pending?

[worleyph]

Note that some movement in this direction already appears in ACME, including a redefintion of default detail. I do not see any other perf_mod specific changes*, though I did not read the todo list very carefully. I did redo the logic (in ACME) so that detail == 0 only outputs enough detail for the timing summary scripts to work. (Great minds think alike :-) .)

Beyond that, much of this resides in the component models themselves. For example, in ACME full detail below bc_physics is output by default. ACME has the problem that there are too many timers on by default, but this is deliberate in that the model is still very new, and I would not propose cutting back on these until performance is better understood (especially in production scenarios).

---

*Sorry - I did notice page 3. Note that the t_adj_detailf logic does not work in threaded region (if called from within a threaded region, t_adj_detailf does nothing). Even an explicit argument to set detail would need a thread-aware mechanism to restore the prior detail.

[worleyph]

Also

There is too much output by default. E.g. a typical CAM5-FV 2 degree run tells you that “d2a3dikj_reprosum” takes a very small amount of time.

"d2a3dikj_reprosum" is a collective communcation operator. At scale, it can be expensive (or when something "bad" happens in the interconnect), which is why it is useful to measure this. FYI.

[worleyph]

JPE: I would like a way to instrument key subsets of code with PAPI hardware counters, gptl has this capability - how can we exploit it in CESM?

perf_mod already supports PAPI, in an all or nothing mode. You then get PAPI counters for each timing event. Is this sufficient or do you want something else?

[worleyph]

Another comment, hopefully the last for the moment. I use detail to implement (at least) 3 modes:

0: minimum 1: everything in the run loop, a little in initialization 2: everything, including initialization

I may currently have "2" really "3" - ran out of time to try to completely rationalize this, since I couldn't make up my mind. Need to check. What needn't be measured all of the time is a matter of taste. How many people need the detailed timing data? If they do, they probably do not know what they want until they see everything. Initialization is a pain because the lack of attribution between initialization and run loop calls makes it difficult to understand what is going on (for events that occur in both locations, in the component models).

[worleyph]

Due to significant reuse of software/timer names in the MPAS components in ACME, I'm forced to address some of these issue within ACME now. I'll have a pull request into ACME in the next day or so

a) adding two new perf_mod routines:

 t_set_prefixf(prefix_string)
 t_unset_prefixf

b) adding calls to these routines in component_mod.F90, in component_run

         call t_set_prefixf(comp(1)%oneletterid//":")
         call comp_run(EClock, comp(eci)%cdata_cc, comp(eci)%x2c_cc, comp(eci)%c2x_cc)
         call t_unset_prefixf()

and similarly in component_final. I'll drop similar calls into the ESMF-versions, but I never run with these, so can not test.

This appears to work well. Might be useful in CESM as well, as it disambiguates the PIO calls from the different components. The CPL-level calls are currently instrumented explicitly, and this seems to be working well. I do not think that using this automatic prefix setting capability would be as useful there. Calls to component routines during the initialization will not have the appended prefix, which means that they will appear separately from calls within component_run, which is nice. Common component timer names will still be lumped together in the initialization however. I have not looked at this closely yet, since this level of instrumentation in the initialization is currently not enabled by default.

[jedwards4b]

Pat - I have been working toward all components using a three letter prefix for timers, they are ATM, CPL, OCN, WAV, GLC, ICE, ROF, LND It would be nice if you considered doing the same.

[jedwards4b]

And PIO2 already uses PIO: prefix

[worleyph]

I can only work with the ACME code base. If you don't need this, then it needn't be adopted. I was just hijacking the existing (to me) comp(1)%oneletterid. However, I can't see imposing this naming convention within the components, and I also like the ability to differentiate PIO calls by component.

[rljacob]

There's no reason we can't impose a convention on the ACME code base. Thats actually easier in ACME.

[worleyph]

I thought that CIME was supposed to be model agnostic? I am not sure how Jim wanted to implement his design, but modifying every timer in every component seems like a large task. The MPAS crowd will have difficulties with this since they duplicate code for use in ocean, sea ice and land ice. Having the driver "impose" a prefix when a component is called seems to be a simpler solution (similar to DRV_THREADING logic). I have no problem adopting the suggested 3 letter prefixes (though timer names are already pretty long :-) ).

[rljacob]

For this thread, we only need to worry about if the timer library or driver needs to be modified to fit one or both group's timer needs.

[worleyph]

Okay, but I am proposing to modify the driver (very slightly) to add component-specific prefixes. If Jim/others want to add prefixes directly in the components, then these approaches will be in conflict. In any case, I'll be pushing the above change to ACME soon. The timing mods are innocuous - new capability does not have to be used, so the only changes that may cause conflicts are the few calls added to component_mod.F90, which will be simple to remove/alter/ifdef as appropriate, when we next do a merge.

[quantheory]

This is probably orthogonal to most of what has been discussed here, but it's really annoying that some timers have whitespace in them, and the timings end up in a whitespace-separated table. It makes it harder to write a script that can actually parse timing files and compute additional statistics. It would be better if we banned spaces from appearing in timers (or output timings in a CSV table and banned commas).

[worleyph]

but it's really annoying that some timers have whitespace in them,

Yep. The primary offenders are the MPAS codes (sorry @douglasjacobsen , but it's true). I've been sloppy recently as I was trying to match the MPAS "style", and also because I thought that I had already lost the battle. HOWEVER, if the ACME and CESM software engineering leads jointly decide that timer names should not have white spaces in them, I will be happy to back them on this. Would need to convince the model development teams of this, and then watch for this as new code is checked in.

[douglasjacobsen]

I have scripts that can parse the timers even with white space in them. It mostly just depends on the standards for the columns, but here is an example: https://gist.github.com/douglasjacobsen/02d7bbcfb4f769f71108a9f1b50a0042

This specific file parses MPAS stand alone timers, not timers from perf mod, but this should be easily modifiable to work with perf mod timers, when the timers may or may not have whitespace in them.

[worleyph]

@douglasjacobsen , guess that I'll have to learn python some day ... looks like (a) you are assuming that two white spaces are a delimiter, and one is not? (b) Then internally you replace white spaces in names with ''? I didn't spend much time looking at this - probably not interpreting it correctly. However, if (b) is correct, you could have two timer names confused if one in fact uses '' and one uses ' ' and are otherwise identical? (Probably would never happen.)

[quantheory]

I just sat down with Bill Sacks and talked about this; it doesn't seem to hard to fix this for CESM. The issue is not that having spaces in the names makes them impossible to read, just that it gets a lot simpler and more robust without the spaces. In the past (versions of CESM where there were no spaces in any timers), I used a regex that basically looked like '(\S+)\s+(\S+)\s+(\S+)' (and so on) to grab the name, number of entries, number of MPI tasks (and so on) for each line.

This might not be something that everyone agrees on, but I don't actually care about the timing file output format in any way except that it should be trivially machine-readable. I virtually always want to compare two or more runs (possibly of unequal length), to figure out where one run is slower than another, and that means doing some postprocessing of the files and scripting a search for longer times. So from my perspective, it doesn't even really matter whether the files are human-readable at all; I just treat them as little case-specific databases to query.

[billsacks]

HOWEVER, if the ACME and CESM software engineering leads jointly decide that timer names should not have white spaces in them, I will be happy to back them on this. Would need to convince the model development teams of this, and then watch for this as new code is checked in.

It seems like, if this is decided as a requirement, then it could be checked in the timing library: If you try to call t_startf with a timer name that has spaces, it could abort with an error saying, "Sorry, invalid timer name: timer names can't have spaces".

[worleyph]

it doesn't even really matter whether the files are human-readable at all

For what it's worth, I strongly prefer that it be human-readable.

[douglasjacobsen]

I think there are plenty of ways to make the timing output trivially machine readable without requiring that timer names not have spaces.

Additionally, I think a timer library should only error if there is an actual error, and not die because we don't like the format of the timer names.

I mean, something silly the timer library could do, is add quotes before and after the timer name.

Personally, I would find it annoying if the timer library died due to something that wasn't a fatal timing error or something wrong with MPI.

[quantheory]

I mean, something silly the timer library could do, is add quotes before and after the timer name.

I suppose that would work, as long as there are no quotation marks in any field in the table other than the name. Which should be OK given that the rest of the table is just numbers.

[douglasjacobsen]

You could even use back-ticks

`

if you wanted to further reduce the likelihood that someone would use them within the timer name.

[quantheory]

I don't think that's necessary, really. A greedy regex like this will pick up everything from the first quotation mark to the last one, regardless of whether there are internal quotation marks as well: ^"(.*)"\s+

The important thing is just that there not be any quotation marks in the rest of the line, outside of the name.

[douglasjacobsen]

Agreed, but rules like that should be easy to enforce, since we're all in control of what is on the line.

Anyway, I'd prefer something like this, rather than restricting what a user could put in as a timer name and forcing an error in the event that we don't like it.

[worleyph]

Unless a timer name began with white spaces, would only need one "special" character, appended to the timer name, correct? Quotes at both the beginning and the end would allow white space at the beginning, I suppose.

[worleyph]

If this is a real proposal, I'll go ahead and implement it. I'm already adding prefixes when certain options are enabled, so pre- and appending quotes will be simple. This would be in the ACME version of perf_mod, but it is probably currently sync'ed with CIME? (Quotes could be added only to the output as well, but that requires modifying GPTL. Adding it to the timer names in t_startf and t_stopf calls affects only perf_mod.)

[quantheory]

As I mentioned way up above, we could also just make the output a CSV or otherwise non-space-separated table, e.g.

name       , processes, threads, ...
some name  ,        64,      64, ...
other name ,        64,      64, ...

or:

name       | processes| threads| ...
some name  |        64|      64| ...
other name |        64|      64| ...

I don't think that we have any | characters being used in names in practice, and they are not especially out-of-place in the table. One benefit there is that parsing in Python becomes trivial:

import csv
with open('timing_file_name') as csvfile:
    reader = csv.DictReader(csvfile, delimiter='|')
    for row in reader:
        print "%s ran on %s threads" % (row['name'], row['threads'])

[douglasjacobsen]

I think that sounds like a good idea. The pipe characters make the format more human readable too.

[worleyph]

Okay - again, this requires a change to GPTL. Should be simple enough to do. I'll see if I can generate a prototype tonight, and will post an update tomorrow (I hope).

[quantheory]

@worleyph Thanks!

[worleyph]

Looking at the existing timing output, adding quotes might be more readable, and would defintely require much fewer code mods. The issue is with the other output, e.g.

 thread 0 had some hash collisions:
 ...
 hashtable[0][1865] had 2 entries: a_i:CC pio_swapm B bar i_i:ice_HaloUpdate2DR8

Note that one of these events has white space: "a_i:CC pio_swapm B bar". There are multiple types of output, for some of which '|' is not as visually appealing.

I'd prefer to look at quotes first, and can do this very quickly. If '|' is the preferred approach, I'm going to have to add this incrementally, and "optimize" for each instance.

[worleyph]

Pretty simple, but my modifications did work (adding double quotes to the beginning and end of timer names, in t_startf and t_stopf in perf_mod.F90). Modified getTiming scripts accordingly, and the postprocessing was also successful. Don't know what the next step is. I can provide the example output and the code modifications, in case anyone wants to look at it. Based on the complexity, and even further divergence from original GPTL code, I prefer quoting the timer name over adding '|' as a column delimeter.

[quantheory]

OK. I'm not sure what the workflow on the ACME side is for getting changes into this repo, but from my perspective, we just need a pull request opened with the changes here, so that the CIME developers can see/review them as a group.

[rljacob]

Pat, its the same process as for ACME. Clone this repo, make a branch, make a PR with your changes. They will then come in to ACME when we finish the upgrade to this version of CIME.

[worleyph]

@rljacob , Will do. Guess that I wanted to make sure is that this is what people wanted (or close enough), and how much they wanted it, before starting the process. A PR will allow people to play with it, and see if it is satisfactory. Note that this change to the timing library also requires a change to getTiming, which may have been rewritten in CIME5? I don't have time to test this in CIME right now - someone else will need to take over as soon as I create the PR.

[jedwards4b]

I'd prefer that you just start a branch to pass on to someone and not open a PR if you cannot commit to following it through.

[rljacob]

We sometimes use PRs as a "Request for Comment" since it allows us to use the github code commenting features. Can't do that if its just on a branch. Pat, just make it clear that it needs more testing.

[jedwards4b]

Fair enough. I withdraw my objection.

[worleyph]

@jedwards4b , @rljacob , I don't care. This is at the request of @quantheory . I don't need it.

[worleyph]

FYI, my attempt to update getTiming was not sufficient. It gets the basic summary information right, but not the "More info on coupler timing:" section at the bottom.

[bertinia]

I just tried to run getTiming in a caseroot generated by cesm2_0_alpha06n and cime master and it failed with an I/O error:

`IOError: [Errno 2] No such file or directory: '/scratch/cluster/aliceb/b.e20.B1850.f09_g17.01/run/timing/model_timing_stats'

Since this tool is tagged as an enhancement and currently doesn't work, do we want to continue to include it in $CASE/Tools?

[bertinia]

@jedwards4b claims this tool is working correctly when the run is complete and correct. For a failed run, the error message should be more user friendly indicating that the run did not complete and the dir model_timing_stats does not exist.

[jgfouca]

This is issue is very old. Is anyone expecting work to be done on this ticket?

[jgfouca]

@worleyph @rljacob ?

[billsacks]

I skimmed through this, and nothing seems critical from my perspective, so I'm okay with it being closed. It was a bit hard to understand the context, since the google doc referenced initially seems to have disappeared (maybe it was in @quantheory 's NCAR google drive space which is no longer active?).