diff --git a/cicecore/drivers/nuopc/cmeps/CICE_RunMod.F90 b/cicecore/drivers/nuopc/cmeps/CICE_RunMod.F90 index e908f509f..301ada1ea 100644 --- a/cicecore/drivers/nuopc/cmeps/CICE_RunMod.F90 +++ b/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 !======================================================================= diff --git a/cicecore/drivers/nuopc/cmeps/cice_wrapper_mod.F90 b/cicecore/drivers/nuopc/cmeps/cice_wrapper_mod.F90 index 0da2ed491..d0aafbb43 100644 --- a/cicecore/drivers/nuopc/cmeps/cice_wrapper_mod.F90 +++ b/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 diff --git a/cicecore/drivers/nuopc/cmeps/ice_comp_nuopc.F90 b/cicecore/drivers/nuopc/cmeps/ice_comp_nuopc.F90 index b94fcff05..4bdb7deb2 100644 --- a/cicecore/drivers/nuopc/cmeps/ice_comp_nuopc.F90 +++ b/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 !===============================================================================