add run-time and history-write logging for ufs

cicecore/drivers/nuopc/cmeps/CICE_RunMod.F90

@@ -16,6 +16,7 @@ module CICE_RunMod
 
       use ice_kinds_mod
       use cice_wrapper_mod, only : t_startf, t_stopf, t_barrierf
+      use cice_wrapper_mod, only : ufs_logfhour
       use ice_fileunits, only: nu_diag
       use ice_arrays_column, only: oceanmixed_ice
       use ice_constants, only: c0, c1
@@ -107,9 +108,11 @@ end subroutine CICE_Run
 
       subroutine ice_step
 
+      use ice_constants, only: c3600
       use ice_boundary, only: ice_HaloUpdate
       use ice_calendar, only: dt, dt_dyn, ndtd, diagfreq, write_restart, istep
-      use ice_calendar, only: idate, msec
+      use ice_calendar, only: idate, myear, mmonth, mday, msec, timesecs
+      use ice_calendar, only: calendar_sec2hms, write_history, nstreams, histfreq
       use ice_diagnostics, only: init_mass_diags, runtime_diags, debug_model, debug_ice
       use ice_diagnostics_bgc, only: hbrine_diags, zsal_diags, bgc_diags
       use ice_domain, only: halo_info, nblocks
@@ -133,7 +136,7 @@ subroutine ice_step
       use ice_timers, only: ice_timer_start, ice_timer_stop, &
           timer_diags, timer_column, timer_thermo, timer_bound, &
           timer_hist, timer_readwrite
-      use ice_communicate, only: MPI_COMM_ICE
+      use ice_communicate, only: MPI_COMM_ICE, my_task, master_task
       use ice_prescribed_mod
 
       integer (kind=int_kind) :: &
@@ -152,6 +155,8 @@ subroutine ice_step
       character(len=*), parameter :: subname = '(ice_step)'
 
       character (len=char_len) :: plabeld
+      integer (kind=int_kind)  :: hh,mm,ss,ns
+      character (len=char_len) :: logmsg
 
       if (debug_model) then
          plabeld = 'beginning time step'
@@ -384,7 +389,15 @@ subroutine ice_step
          endif
 
          call ice_timer_stop(timer_readwrite)  ! reading/writing
-
+         if (my_task == master_task) then
+            do ns = 1,nstreams
+               if (write_history(ns) .and. histfreq(ns) .eq. 'h') then
+                  call calendar_sec2hms(msec,hh,mm,ss)
+                  write(logmsg,'(6(i4,2x))')myear,mmonth,mday,hh,mm,ss
+                  call ufs_logfhour(trim(logmsg),timesecs/c3600)
+               end if
+            end do
+         end if
       end subroutine ice_step
 
 !=======================================================================

cicecore/drivers/nuopc/cmeps/cice_wrapper_mod.F90

@@ -1,25 +1,93 @@
 module cice_wrapper_mod
 
 #ifdef CESMCOUPLED
-  use perf_mod     , only : t_startf, t_stopf, t_barrierf
-  use shr_file_mod , only : shr_file_getlogunit, shr_file_setlogunit
+  use perf_mod      , only : t_startf, t_stopf, t_barrierf
+  use shr_file_mod  , only : shr_file_getlogunit, shr_file_setlogunit
 
+  use ice_kinds_mod , only : dbl_kind, int_kind, char_len, char_len_long
+
+  implicit none
+
+  real(dbl_kind) :: wtime = 0.0
+contains
+  ! Define stub routines that do nothing - they are just here to avoid
+  ! having cppdefs in the main program
+  subroutine ufs_settimer(timevalue)
+    real(dbl_kind),    intent(inout) :: timevalue
+  end subroutine ufs_settimer
+  subroutine ufs_logtimer(nunit,elapsedsecs,string,runtimelog,time0)
+    integer,           intent(in)  :: nunit
+    integer(int_kind), intent(in)  :: elapsedsecs
+    character(len=*),  intent(in)  :: string
+    logical,           intent(in)  :: runtimelog
+    real(dbl_kind),    intent(in)  :: time0
+  end subroutine ufs_logtimer
+  subroutine ufs_file_setLogUnit(filename,nunit,runtimelog)
+    character(len=*),  intent(in)  :: filename
+    logical,           intent(in)  :: runtimelog
+    integer,           intent(out) :: nunit
+  end subroutine ufs_file_setLogUnit
+  subroutine ufs_logfhour(msg,hour)
+    character(len=*),  intent(in)  :: msg
+    real(dbl_kind),    intent(in)  :: hour
+  end subroutine ufs_logfhour
 #else
+
+  use ice_kinds_mod , only : dbl_kind, int_kind, char_len, char_len_long
+
+  implicit none
+
+  real(dbl_kind) :: wtime = 0.0
 contains
+  subroutine ufs_settimer(timevalue)
+    real(dbl_kind),    intent(inout) :: timevalue
+    real(dbl_kind)                   :: MPI_Wtime
+    timevalue = MPI_Wtime()
+  end subroutine ufs_settimer
+
+  subroutine ufs_logtimer(nunit,elapsedsecs,string,runtimelog,time0)
+    integer,           intent(in)    :: nunit
+    integer(int_kind), intent(in)    :: elapsedsecs
+    character(len=*),  intent(in)    :: string
+    logical,           intent(in)    :: runtimelog
+    real(dbl_kind),    intent(in)    :: time0
+    real(dbl_kind)                   :: MPI_Wtime, timevalue
+    if (.not. runtimelog) return
+    if (time0 > 0.) then
+       timevalue = MPI_Wtime()-time0
+       write(nunit,*)elapsedsecs,' CICE '//trim(string),timevalue
+    end if
+  end subroutine ufs_logtimer
 
-  ! These are just stub routines put in place to remove
+  subroutine ufs_file_setLogUnit(filename,nunit,runtimelog)
+    character(len=*),  intent(in)    :: filename
+    logical,           intent(in)    :: runtimelog
+    integer,           intent(out)   :: nunit
+    if (.not. runtimelog) return
+    open (newunit=nunit, file=trim(filename))
+  end subroutine ufs_file_setLogUnit
 
+  subroutine ufs_logfhour(msg,hour)
+    character(len=*),  intent(in)    :: msg
+    real(dbl_kind),    intent(in)    :: hour
+    character(len=char_len)          :: filename
+    integer(int_kind)                :: nunit
+    write(filename,'(a,i3.3)')'log.ice.f',int(hour)
+    open(newunit=nunit,file=trim(filename))
+    write(nunit,'(a)')'completed: cice'
+    write(nunit,'(a,f10.3)')'forecast hour:',hour
+    write(nunit,'(a)')'valid time: '//trim(msg)
+    close(nunit)
+  end subroutine ufs_logfhour
+
+  ! Define stub routines that do nothing - they are just here to avoid
+  ! having cppdefs in the main program
   subroutine shr_file_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_file_setLogUnit
   subroutine shr_file_getLogUnit(nunit)
     integer, intent(in) :: nunit
-    ! do nothing for this stub - its just here to replace
-    ! having cppdefs in the main program
   end subroutine shr_file_getLogUnit
-
   subroutine t_startf(string)
     character(len=*) :: string
   end subroutine t_startf

cicecore/drivers/nuopc/cmeps/ice_comp_nuopc.F90

@@ -38,6 +38,7 @@ module ice_comp_nuopc
   use icepack_intfc      , only : icepack_query_tracer_flags, icepack_query_parameters
   use cice_wrapper_mod   , only : t_startf, t_stopf, t_barrierf
   use cice_wrapper_mod   , only : shr_file_getlogunit, shr_file_setlogunit
+  use cice_wrapper_mod   , only : ufs_settimer, ufs_logtimer, ufs_file_setlogunit, wtime
 #ifdef CESMCOUPLED
   use shr_const_mod
   use shr_orb_mod        , only : shr_orb_decl, shr_orb_params, SHR_ORB_UNDEF_REAL, SHR_ORB_UNDEF_INT
@@ -87,11 +88,12 @@ module ice_comp_nuopc
 
   type(ESMF_Mesh)              :: ice_mesh
 
-  integer                      :: nthrds   ! Number of threads to use in this component
-
+  integer                      :: nthrds       ! Number of threads to use in this component
+  integer                      :: nu_timer = 6 ! Simple timer log, unused except by UFS
   integer                      :: dbug = 0
   logical                      :: profile_memory = .false.
   logical                      :: mastertask
+  logical                      :: runtimelog = .false.
   integer                      :: start_ymd          ! Start date (YYYYMMDD)
   integer                      :: start_tod          ! start time of day (s)
   integer                      :: curr_ymd           ! Current date (YYYYMMDD)
@@ -245,6 +247,8 @@ subroutine InitializeAdvertise(gcomp, importState, exportState, clock, rc)
     character(len=*), parameter :: subname=trim(modName)//':(InitializeAdvertise) '
     !--------------------------------
 
+    call ufs_settimer(wtime)
+
     call NUOPC_CompAttributeGet(gcomp, name="ScalarFieldName", value=cvalue, isPresent=isPresent, isSet=isSet, rc=rc)
     if (ChkErr(rc,__LINE__,u_FILE_u)) return
     if (isPresent .and. isSet) then
@@ -305,6 +309,12 @@ subroutine InitializeAdvertise(gcomp, importState, exportState, clock, rc)
     write(logmsg,'(i6)') dbug
     call ESMF_LogWrite('CICE_cap: dbug = '//trim(logmsg), ESMF_LOGMSG_INFO)
 
+    call NUOPC_CompAttributeGet(gcomp, name="RunTimeLog", value=cvalue, isPresent=isPresent, isSet=isSet, rc=rc)
+    if (ChkErr(rc,__LINE__,u_FILE_u)) return
+    if (isPresent .and. isSet) runtimelog=(trim(cvalue)=="true")
+    write(logmsg,*) runtimelog
+    call ESMF_LogWrite('CICE_cap:RunTimeLog = '//trim(logmsg), ESMF_LOGMSG_INFO)
+
     !----------------------------------------------------------------------------
     ! generate local mpi comm
     !----------------------------------------------------------------------------
@@ -487,6 +497,7 @@ subroutine InitializeAdvertise(gcomp, importState, exportState, clock, rc)
     ! Set the nu_diag_set flag so it's not reset later
 
     call shr_file_setLogUnit (shrlogunit)
+    call ufs_file_setLogUnit('./log.ice.timer',nu_timer,runtimelog)
 
     call NUOPC_CompAttributeGet(gcomp, name="diro", value=cvalue, &
          isPresent=isPresent, isSet=isSet, rc=rc)
@@ -699,7 +710,7 @@ subroutine InitializeAdvertise(gcomp, importState, exportState, clock, rc)
     end if
 
     call t_stopf ('cice_init_total')
-
+    if (mastertask) call ufs_logtimer(nu_timer,msec,'InitializeAdvertise time: ',runtimelog,wtime)
   end subroutine InitializeAdvertise
 
   !===============================================================================
@@ -735,6 +746,7 @@ subroutine InitializeRealize(gcomp, importState, exportState, clock, rc)
     rc = ESMF_SUCCESS
     if (dbug > 5) call ESMF_LogWrite(subname//' called', ESMF_LOGMSG_INFO)
 
+    call ufs_settimer(wtime)
     !----------------------------------------------------------------------------
     ! Second cice initialization phase -after initializing grid info
     !----------------------------------------------------------------------------
@@ -912,6 +924,7 @@ subroutine InitializeRealize(gcomp, importState, exportState, clock, rc)
 
     call flush_fileunit(nu_diag)
 
+    if (mastertask) call ufs_logtimer(nu_timer,msec,'InitializeRealize time: ',runtimelog,wtime)
   end subroutine InitializeRealize
 
   !===============================================================================
@@ -957,6 +970,8 @@ subroutine ModelAdvance(gcomp, rc)
     !--------------------------------
 
     rc = ESMF_SUCCESS
+    if (mastertask) call ufs_logtimer(nu_timer,msec,'ModelAdvance time since last step: ',runtimelog,wtime)
+    call ufs_settimer(wtime)
 
     call ESMF_LogWrite(subname//' called', ESMF_LOGMSG_INFO)
 
@@ -1177,6 +1192,9 @@ subroutine ModelAdvance(gcomp, rc)
 
     if (dbug > 5) call ESMF_LogWrite(subname//' done', ESMF_LOGMSG_INFO)
 
+    if (mastertask) call ufs_logtimer(nu_timer,msec,'ModelAdvance time: ',runtimelog,wtime)
+    call ufs_settimer(wtime)
+
   end subroutine ModelAdvance
 
   !===============================================================================
@@ -1321,6 +1339,7 @@ subroutine ModelFinalize(gcomp, rc)
     !--------------------------------
 
     rc = ESMF_SUCCESS
+    call ufs_settimer(wtime)
     if (dbug > 5) call ESMF_LogWrite(subname//' called', ESMF_LOGMSG_INFO)
     if (my_task == master_task) then
        write(nu_diag,F91)
@@ -1329,6 +1348,8 @@ subroutine ModelFinalize(gcomp, rc)
     end if
     if (dbug > 5) call ESMF_LogWrite(subname//' done', ESMF_LOGMSG_INFO)
 
+    if(mastertask) call ufs_logtimer(nu_timer,msec,'ModelFinalize time: ',runtimelog,wtime)
+
   end subroutine ModelFinalize
 
   !===============================================================================