update desi_proc timing logging

[sbailey]

This PR uses the new desiutil.timer.Timer class to standardize timing in bin/desi_proc. It uses some features in desihub/desiutil#152, so don't merge this until that PR is finalized.

New options to desi_proc:

• --starttime $(date +%s): log the time between this starttime and the beginning of the python script (srun & python interpreter launch overhead).
• --timingfile TIMINGFILE: save timing information to a json file for later analysis. When running in batch, this file is saved for each exposure.

New script bin/plot_timing uses the timing information saved with --timingfile to make plots like this:

@akremin please take a look to see if (or how badly) this will conflict with your changes in the desi_proc_mod branch.

[sbailey]

desihub/desiutil#152 has been merged, so this PR is now ready for full review and can be merged when ready

[akremin]

Two small comments. Both are considerations to take, but neither is required for merge. I will wait for comment before clicking approve, but these changes look good.

[akremin]

Should this be using the arg.timingfile from the parser or at least checking for its existence before defining to default?

[sbailey]

Good point; I added a check to use args.timingfile here.

Default usage with --batch is to not specify --timingfile, and then let desi_proc pick a timing file name based upon the job name and slurm jobid; but if the user specifies --batch and a specific --timingfile, that will be used instead.

[akremin]

Great. I think this is the best approach even if its not meant to be used by end users. It's either this or documenting the use cases, and this is simpler and more flexible.

[akremin]

Some of these moved imports aren't picked up as the same. Is there a motivation behind the moves or was this a result of adding and removing code during development?

It isn't a blocking factor but it does increase the differences with master that will impact the upcoming rebase of the desi_proc_mod branch.

[sbailey]

It was mostly a side effect of rearranging imports to be able to time them properly (import time and grab time.time() ASAP; wait on MPI until after argparsing; wait on freeze_iers until we've got the timers going...) For now I reverted the order to close to the original with only the minimally necessary rearrangement.

At the same time, our import order has gotten a bit messy compared to our (perhaps undocumented?) typical order:

• python standard libraries (os, sys, glob, ...)
• 3rd party libraries (numpy, scipy, astropy, ...)
• other desi packages (desiutil, desitarget, ...)
• other modules from within this package (desispec.io, desispec.sky, ...)

We can standardize that in a later update.

[akremin]

Thank you for reverting. We can refactor right after rebase so you can capture the timing appropriately.

[sbailey]

Thanks for review @akremin; I made updates in response to your comments. Just in case I introduced a typo, I'd like to double check this at NERSC when Cori is back before merging.

[akremin]

Feel free to merge after testing when Cori comes back online