Add logging features to nuopc/cmeps cap; deprecates zsalinity in cap

cicecore/drivers/nuopc/cmeps/CICE_InitMod.F90

@@ -232,7 +232,7 @@ subroutine init_restart()
          restart_iso, read_restart_iso, &
          restart_aero, read_restart_aero, &
          restart_hbrine, read_restart_hbrine, &
-         restart_zsal, restart_bgc
+         restart_bgc
     use ice_restart_driver, only: restartfile
     use ice_restart_shared, only: runtype, restart
     use ice_state ! almost everything
@@ -243,7 +243,7 @@ subroutine init_restart()
     logical(kind=log_kind) :: &
          tr_iage, tr_FY, tr_lvl, tr_pond_lvl, &
          tr_pond_topo, tr_fsd, tr_iso, tr_aero, tr_brine, tr_snow, &
-         skl_bgc, z_tracers, solve_zsal
+         skl_bgc, z_tracers
     integer(kind=int_kind) :: &
          ntrcr
     integer(kind=int_kind) :: &
@@ -259,8 +259,7 @@ subroutine init_restart()
     if (icepack_warnings_aborted()) call abort_ice(error_message=subname, &
          file=__FILE__, line=__LINE__)
 
-    call icepack_query_parameters(skl_bgc_out=skl_bgc, &
-         z_tracers_out=z_tracers, solve_zsal_out=solve_zsal)
+    call icepack_query_parameters(skl_bgc_out=skl_bgc, z_tracers_out=z_tracers)
     call icepack_query_tracer_flags(tr_iage_out=tr_iage, tr_FY_out=tr_FY, &
          tr_lvl_out=tr_lvl, tr_pond_lvl_out=tr_pond_lvl, &
          tr_pond_topo_out=tr_pond_topo, tr_aero_out=tr_aero, tr_brine_out=tr_brine, &
@@ -404,8 +403,6 @@ subroutine init_restart()
     if (trim(runtype) == 'continue') then
        if (tr_brine) &
             restart_hbrine = .true.
-       if (solve_zsal) &
-            restart_zsal = .true.
        if (skl_bgc .or. z_tracers) &
             restart_bgc = .true.
     endif
@@ -415,7 +412,7 @@ subroutine init_restart()
        if (tr_brine .and. restart_hbrine) call read_restart_hbrine
     endif
 
-    if (solve_zsal .or. skl_bgc .or. z_tracers) then ! biogeochemistry
+    if (skl_bgc .or. z_tracers) then ! biogeochemistry
        if (tr_fsd) then
           write (nu_diag,*) 'FSD implementation incomplete for use with BGC'
           call icepack_warnings_flush(nu_diag)

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,11 +108,13 @@ 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_diagnostics_bgc, only: hbrine_diags, bgc_diags
       use ice_domain, only: halo_info, nblocks
       use ice_dyn_eap, only: write_restart_eap
       use ice_dyn_shared, only: kdyn, kridge
@@ -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) :: &
@@ -147,11 +150,13 @@ subroutine ice_step
       logical (kind=log_kind) :: &
           tr_iage, tr_FY, tr_lvl, tr_fsd, tr_snow, &
           tr_pond_lvl, tr_pond_topo, tr_brine, tr_iso, tr_aero, &
-          calc_Tsfc, skl_bgc, solve_zsal, z_tracers, wave_spec
+          calc_Tsfc, skl_bgc, z_tracers, wave_spec
 
       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'
@@ -161,8 +166,7 @@ subroutine ice_step
       endif
 
       call icepack_query_parameters(calc_Tsfc_out=calc_Tsfc, skl_bgc_out=skl_bgc, &
-           solve_zsal_out=solve_zsal, z_tracers_out=z_tracers, ktherm_out=ktherm, &
-           wave_spec_out=wave_spec)
+           z_tracers_out=z_tracers, ktherm_out=ktherm, wave_spec_out=wave_spec)
       call icepack_query_tracer_flags(tr_iage_out=tr_iage, tr_FY_out=tr_FY, &
            tr_lvl_out=tr_lvl, tr_pond_lvl_out=tr_pond_lvl, &
            tr_pond_topo_out=tr_pond_topo, tr_brine_out=tr_brine, tr_aero_out=tr_aero, &
@@ -354,7 +358,6 @@ subroutine ice_step
          call ice_timer_start(timer_diags)  ! diagnostics
          if (mod(istep,diagfreq) == 0) then
             call runtime_diags(dt)          ! log file
-            if (solve_zsal) call zsal_diags
             if (skl_bgc .or. z_tracers)  call bgc_diags
             if (tr_brine) call hbrine_diags
          endif
@@ -376,15 +379,23 @@ subroutine ice_step
             if (tr_fsd)       call write_restart_fsd
             if (tr_iso)       call write_restart_iso
             if (tr_aero)      call write_restart_aero
-            if (solve_zsal .or. skl_bgc .or. z_tracers) &
+            if (skl_bgc .or. z_tracers) &
                               call write_restart_bgc
             if (tr_brine)     call write_restart_hbrine
             if (kdyn == 2)    call write_restart_eap
             call final_restart
          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
 
 !=======================================================================
@@ -396,7 +407,7 @@ end subroutine ice_step
       subroutine coupling_prep (iblk)
 
       use ice_arrays_column, only: alvdfn, alidfn, alvdrn, alidrn, &
-          albicen, albsnon, albpndn, apeffn, fzsal_g, fzsal, snowfracn
+          albicen, albsnon, albpndn, apeffn, snowfracn
       use ice_blocks, only: nx_block, ny_block, get_block, block
       use ice_domain, only: blocks_ice
       use ice_calendar, only: dt, nstreams
@@ -411,9 +422,8 @@ subroutine coupling_prep (iblk)
           fsens, flat, fswabs, flwout, evap, Tref, Qref, &
           scale_fluxes, frzmlt_init, frzmlt, Uref, wind
       use ice_flux_bgc, only: faero_ocn, fiso_ocn, Qref_iso, fiso_evap, &
-          fzsal_ai, fzsal_g_ai, flux_bio, flux_bio_ai, &
-          fnit, fsil, famm, fdmsp, fdms, fhum, fdust, falgalN, &
-          fdoc, fdic, fdon, ffep, ffed, bgcflux_ice_to_ocn
+          flux_bio, flux_bio_ai, fnit, fsil, famm, fdmsp, fdms, fhum, &
+          fdust, falgalN, fdoc, fdic, fdon, ffep, ffed, bgcflux_ice_to_ocn
       use ice_grid, only: tmask
       use ice_state, only: aicen, aice
       use ice_state, only: aice_init
@@ -566,8 +576,6 @@ subroutine coupling_prep (iblk)
             fsalt_ai  (i,j,iblk) = fsalt  (i,j,iblk)
             fhocn_ai  (i,j,iblk) = fhocn  (i,j,iblk)
             fswthru_ai(i,j,iblk) = fswthru(i,j,iblk)
-            fzsal_ai  (i,j,iblk) = fzsal  (i,j,iblk)
-            fzsal_g_ai(i,j,iblk) = fzsal_g(i,j,iblk)
 
             if (nbtrcr > 0) then
             do k = 1, nbtrcr
@@ -613,7 +621,6 @@ subroutine coupling_prep (iblk)
                             faero_ocn(:,:,:,iblk),                   &
                             alvdr    (:,:,iblk), alidr   (:,:,iblk), &
                             alvdf    (:,:,iblk), alidf   (:,:,iblk), &
-                            fzsal    (:,:,iblk), fzsal_g (:,:,iblk), &
                             flux_bio (:,:,1:nbtrcr,iblk),            &
                             Qref_iso =Qref_iso (:,:,:,iblk),         &
                             fiso_evap=fiso_evap(:,:,:,iblk),         &

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
 
   !===============================================================================