add run time info

[junwang-noaa]

For detailed information about submitting Pull Requests (PRs) to the CICE-Consortium,
please refer to: https://github.com/CICE-Consortium/About-Us/wiki/Resource-Index#information-for-developers

PR checklist

• Short (1 sentence) summary of your PR:
  Add run time information for the NUOPC phases at each time step
• Developer(s):
  Jun.Wang@noaa.gov
• Suggest PR reviewers from list in the column to the right.
• Please copy the PR test results link or provide a summary of testing completed below.
  ENTER INFORMATION HERE
• How much do the PR code changes differ from the unmodified code?
  • bit for bit
  • different at roundoff level
  • more substantial
• Does this PR create or have dependencies on Icepack or any other models?
  • Yes
  • No
• Does this PR update the Icepack submodule? If so, the Icepack submodule must point to a hash on Icepack's main branch.
  • Yes
  • No
• Does this PR add any new test cases?
  • Yes
  • No
• Is the documentation being updated? ("Documentation" includes information on the wiki or in the .rst files from doc/source/, which are used to create the online technical docs at https://readthedocs.org/projects/cice-consortium-cice/. A test build of the technical docs will be performed as part of the PR testing.)
  • Yes
  • No, does the documentation need to be updated at a later time?
    • Yes
    • No
• Please provide any additional information or relevant details below:

[junwang-noaa]

@DeniseWorthen Please review the code changes and let me know if you have any suggestions/concerns

[DeniseWorthen]

The r*8 variables should be defined as dbl_kind.

Also, there is an existing perf_mod within the cice_wrapper.F90. For CESM, it uses GPTL but the calls are just stubs for non-CESM. I think it would better if we could implement something like that for this functionality.

[junwang-noaa]

@DeniseWorthen I could not find the cice_wrapper.F90 in the cice code so I can't see the perf_mod. From the stub call interface, I am curious if the per_mod uses hash to get the actual running time for the subroutine surrounded by the "t_startf" and t_stopf at every time step or it just prints out starting time and stop time or total calling time. It would be good to understand more on how CESM is using it.
I changed r*8 to real(dbl_kind) at this time.

[DeniseWorthen]

cice_wrapper_mod.F90 is in the cap directory (cicecore/drivers/nuopc/cmeps). From what I understand, CESM uses GPTL across all components and each component can access this same perf_mod so timing calls are consistent across all components. They do something similar w/ component logging, all components call into a logging routine so logging (filename, format) is consistent across components.

While this kind of across-component functionality would be really nice to have, at this point what I was suggesting is that in the cice_wrapper, the non-CESM timing calls could be defined--these calls would be stubs for CESM. That way either can compile the code but there will be no impact outside of UFS. This is also how I was planning to implement the logging function to write a small log file when the history write returns.

I've attached a copy of the perf_mod.F90 so you can see how they define the t_startf calls etc.
perf_mod.F90.txt

[junwang-noaa]

Thanks for the information. Do you have some CESM perf_mod output? I am not sure if this is the temporal timing we are looking for. ESMF does provide time stamp information for ESMF phases, but we have to compute the time interval from that to get the temporal timing information. From the code itself, I seem not seeing such temporal timing info, maybe I missed something.
I will update the code to work for non-CESM timing only.

[DeniseWorthen]

I don't have any perf_mod output. I have looked at the information for GPTL (https://jmrosinski.github.io/GPTL/) but I'm not an expert in this area by any means.

In any case, at this point, I think if we can put the timing functionality into a cice_wrapper routine, that would be a workable solution. I actually think a wrapper is probably what we should do for MOM6 and WW3 also. I can try to see if I can get something to work for CICE.

[DeniseWorthen]

using nu_diag will write this information to the file ice_diag.d. It will also write it there for all other users, which is probably not going to be acceptable.

[junwang-noaa]

I see. Can I use a MACRO (e.g. UFS) around this sentence?

[DeniseWorthen]

Do you mean "ifdef UFS"?

In any case, do you want this time information written to the same file as all the other diagnostics (ice_diag.d) or in it's own timer file?

[junwang-noaa]

I am thinking of the ice_diag_d if possible, and it can be turned on or off.

[DeniseWorthen]

@junwang-noaa I have an alternate implementation here. It uses the cice_wrapper_mod, and for CESM it should be a no op. I have runs on orion comparing our two methods:

/work/noaa/stmp/dworthen/stmp/dworthen/cicelog/cpld.jun
/work/noaa/stmp/dworthen/stmp/dworthen/cicelog/cpld.log

I haven't actually verified yet the numbers are identical but I can do that also. I'm not sure they should be identical though.

[junwang-noaa]

Great! Your code looks good. There is no need for the two results to be identical.

[DeniseWorthen]

@junwang-noaa One issue is that both your original code and my version show this

       21600  CICE ModelAdvance time since last step:   3725125.59289522

This is at the first time it enters model advance (model clock = 21600 secs, which is the secs-of-day for the first timestep). Is this worth fixing or can we live with it?

@jiandewang Currently MOM does not have a "wrapper" module, but the equivalent thing is done inside mom_cap

#ifndef CESMCOUPLED
subroutine shr_log_setLogUnit(nunit)
  integer, intent(in) :: nunit
  ! do nothing for this stub - its just here to replace
  ! having cppdefs in the main program
end subroutine shr_log_setLogUnit
#endif

I think the best solution would be to add a mom_wrapper_mod in the same way we have for CICE.

[junwang-noaa]

Yes. Can you add the following if statement in ufs_logtimer?

if (time0 >0.) then
timevalue = MPI_Wtime()-time0
write(nunit,*)etime,' CICE '//trim(string),timevalue
endif

[DeniseWorthen]

Thanks, that works. Now there is no 'time since' report for the first time.

It would be easy to also add a filename to write this information to instead of ice_diag.d. We could use a similar name for MOM and even WW3---something like component.time.log. I need to add this functionality anyway in order to create the log.component.fhour that the G-W wanted.

[DeniseWorthen]

@junwang-noaa I've written the ice timer values to log.ice.timer and written the log.ice.fXXX (Issue #57) using the wrapper. Can you and @aerorahul check that the formats and info look OK? I have a run directory on orion:

/work/noaa/stmp/dworthen/stmp/dworthen/cicelog/cpld.log

[junwang-noaa]

@DeniseWorthen I want to follow up with this PR, do you have your branch ready to make a PR (the one with with timing functionality into a cice_wrapper routine)? I can point to your branch in my ufs-weather-model branch.