Add tracing instrumentation to nuopc driver

mediator/CMakeLists.txt

@@ -16,7 +16,8 @@ set(SRCFILES esmFldsExchange_cesm_mod.F90 med_fraction_mod.F90
               med_phases_post_ocn_mod.F90  med_phases_ocnalb_mod.F90
               med_phases_post_atm_mod.F90 med_phases_post_ice_mod.F90
               med_phases_post_lnd_mod.F90 med_phases_post_glc_mod.F90
-              med_phases_post_rof_mod.F90 med_phases_post_wav_mod.F90)
+              med_phases_post_rof_mod.F90 med_phases_post_wav_mod.F90
+              med_ufs_trace_wrapper.F90)
 
 foreach(FILE ${SRCFILES})
   if(EXISTS "${CASEROOT}/SourceMods/src.cmeps/${FILE}")

mediator/med.F90

@@ -52,7 +52,7 @@ module MED
   use esmFldsExchange_hafs_mod , only : esmFldsExchange_hafs
   use med_phases_profile_mod   , only : med_phases_profile_finalize
   use shr_log_mod              , only : shr_log_error
-
+  use med_ufs_trace_wrapper_mod, only : ufs_trace_init_wrapper, ufs_trace_wrapper, ufs_trace_finalize_wrapper
 
   implicit none
   private
@@ -87,6 +87,7 @@ subroutine SetServices(gcomp, rc)
     use ESMF                    , only: ESMF_SUCCESS, ESMF_GridCompSetEntryPoint
     use ESMF                    , only: ESMF_METHOD_INITIALIZE, ESMF_METHOD_RUN
     use ESMF                    , only: ESMF_GridComp, ESMF_MethodRemove
+    use ESMF                    , only: ESMF_VM, ESMF_VMGet, ESMF_GridCompGet
     use NUOPC                   , only: NUOPC_CompDerive, NUOPC_CompSetEntryPoint, NUOPC_CompSpecialize, NUOPC_NoOP
     use NUOPC_Mediator          , only: mediator_routine_SS             => SetServices
     use NUOPC_Mediator          , only: mediator_routine_Run            => routine_Run
@@ -133,13 +134,24 @@ subroutine SetServices(gcomp, rc)
     type(ESMF_GridComp)  :: gcomp
     integer, intent(out) :: rc
 
+    type(ESMF_VM)        :: vm
+    integer              :: localPet
     ! local variables
     character(len=*), parameter :: subname = '('//__FILE__//':SetServices)'
     !-----------------------------------------------------------
 
     rc = ESMF_SUCCESS
     if (profile_memory) call ESMF_VMLogMemInfo("Entering "//trim(subname))
 
+    call ESMF_GridCompGet(gcomp, vm=vm, rc=rc)
+    if (ChkErr(rc,__LINE__,u_FILE_u)) return
+    call ESMF_VMGet(vm, localPet=localPet, rc=rc)
+    if (ChkErr(rc,__LINE__,u_FILE_u)) return
+    maintask = .false.
+    if (localPet == 0) maintask=.true.
+    if (maintask) call ufs_trace_init_wrapper()
+    if (maintask) call ufs_trace_wrapper("cmeps", "SetServices", "B")
+
     !------------------
     ! the NUOPC model component mediator_routine_SS will register the generic methods
     !------------------
@@ -555,6 +567,7 @@ subroutine SetServices(gcomp, rc)
 
     if (profile_memory) call ESMF_VMLogMemInfo("Leaving "//trim(subname))
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "SetServices", "E")
   end subroutine SetServices
 
   !-----------------------------------------------------------------------------
@@ -592,6 +605,7 @@ subroutine InitializeP0(gcomp, importState, exportState, clock, rc)
     call ESMF_LogWrite(trim(subname)//": called", ESMF_LOGMSG_INFO)
 
     if (profile_memory) call ESMF_VMLogMemInfo("Entering "//trim(subname))
+    if (maintask) call ufs_trace_wrapper("cmeps", "InitializeP0", "B")
     call ESMF_GridCompGet(gcomp, vm=vm, rc=rc)
     if (ChkErr(rc,__LINE__,u_FILE_u)) return
     call ESMF_VMGet(vm, localPet=localPet, rc=rc)
@@ -662,6 +676,8 @@ subroutine InitializeP0(gcomp, importState, exportState, clock, rc)
     if (profile_memory) call ESMF_VMLogMemInfo("Leaving "//trim(subname))
     call ESMF_LogWrite(trim(subname)//": done", ESMF_LOGMSG_INFO)
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "InitializeP0", "E")
+
   end subroutine InitializeP0
 
   !-----------------------------------------------------------------------
@@ -701,6 +717,7 @@ subroutine AdvertiseFields(gcomp, importState, exportState, clock, rc)
     character(len=*), parameter :: subname = '('//__FILE__//':AdvertiseFields)'
     !-----------------------------------------------------------
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "AdvertiseFields", "B")
     call ESMF_LogWrite(trim(subname)//": called", ESMF_LOGMSG_INFO)
     rc = ESMF_SUCCESS
     if (profile_memory) call ESMF_VMLogMemInfo("Entering "//trim(subname))
@@ -980,6 +997,7 @@ subroutine AdvertiseFields(gcomp, importState, exportState, clock, rc)
     if (profile_memory) call ESMF_VMLogMemInfo("Leaving "//trim(subname))
     call ESMF_LogWrite(trim(subname)//": done", ESMF_LOGMSG_INFO)
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "AdvertiseFields", "E")
   end subroutine AdvertiseFields
 
   !-----------------------------------------------------------------------------
@@ -1006,6 +1024,7 @@ subroutine RealizeFieldsWithTransferProvided(gcomp, importState, exportState, cl
     integer                    :: n
     character(len=*), parameter :: subname = '('//__FILE__//':RealizeFieldsWithTransferProvided)'
     !-----------------------------------------------------------
+    if (maintask) call ufs_trace_wrapper("cmeps", "RealizeFieldsWithTransferProvided", "B")
 
     call ESMF_LogWrite(trim(subname)//": called", ESMF_LOGMSG_INFO)
     rc = ESMF_SUCCESS
@@ -1043,6 +1062,7 @@ subroutine RealizeFieldsWithTransferProvided(gcomp, importState, exportState, cl
 
     if (profile_memory) call ESMF_VMLogMemInfo("Leaving "//trim(subname))
     call ESMF_LogWrite(trim(subname)//": done", ESMF_LOGMSG_INFO)
+    if (maintask) call ufs_trace_wrapper("cmeps", "RealizeFieldsWithTransferProvided", "E")
 
   end subroutine RealizeFieldsWithTransferProvided
 
@@ -1067,6 +1087,7 @@ subroutine ModifyDecompofMesh(gcomp, importState, exportState, clock, rc)
     integer :: n1
     character(len=*), parameter :: subname = '('//__FILE__//':ModifyDecompofMesh)'
     !-----------------------------------------------------------
+    if (maintask) call ufs_trace_wrapper("cmeps", "ModifyDecompofMesh", "B")
 
     call ESMF_LogWrite(trim(subname)//": called", ESMF_LOGMSG_INFO)
     rc = ESMF_SUCCESS
@@ -1095,6 +1116,7 @@ subroutine ModifyDecompofMesh(gcomp, importState, exportState, clock, rc)
     enddo
     if (profile_memory) call ESMF_VMLogMemInfo("Leaving "//trim(subname))
     call ESMF_LogWrite(trim(subname)//": done", ESMF_LOGMSG_INFO)
+    if (maintask) call ufs_trace_wrapper("cmeps", "ModifyDecompofMesh", "E")
 
   contains  !- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
 
@@ -1392,6 +1414,7 @@ subroutine RealizeFieldsWithTransferAccept(gcomp, importState, exportState, cloc
     integer             :: n1
     character(len=*), parameter :: subname = '('//__FILE__//':RealizeFieldsWithTransferAccept)'
     !-----------------------------------------------------------
+    if (maintask) call ufs_trace_wrapper("cmeps", "RealizeFieldsWithTransferAccept", "B")
 
     call ESMF_LogWrite(trim(subname)//": called", ESMF_LOGMSG_INFO)
 
@@ -1431,6 +1454,7 @@ subroutine RealizeFieldsWithTransferAccept(gcomp, importState, exportState, cloc
 
     if (profile_memory) call ESMF_VMLogMemInfo("Leaving "//trim(subname))
     call ESMF_LogWrite(trim(subname)//": done", ESMF_LOGMSG_INFO)
+    if (maintask) call ufs_trace_wrapper("cmeps", "RealizeFieldsWithTransferAccept", "E")
 
   contains  !- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
 
@@ -1655,6 +1679,7 @@ subroutine DataInitialize(gcomp, rc)
     character(len=CX)                  :: msgString
     character(len=*), parameter :: subname = '('//__FILE__//':DataInitialize)'
     !-----------------------------------------------------------
+    if (maintask) call ufs_trace_wrapper("cmeps", "DataInitialize", "B")
 
     call ESMF_LogWrite(trim(subname)//": called", ESMF_LOGMSG_INFO)
     rc = ESMF_SUCCESS
@@ -1963,6 +1988,7 @@ subroutine DataInitialize(gcomp, rc)
       ! the correct timestamps, which also indicates that the actual
       ! data has been transferred reliably, and CMEPS can safely use it.
 
+      if (maintask) call ufs_trace_wrapper("cmeps", "DataInitialize", "E")
       RETURN
 
     endif  ! end first_call if-block
@@ -2254,6 +2280,7 @@ subroutine DataInitialize(gcomp, rc)
       call ESMF_LogWrite(trim(subname)//": done", ESMF_LOGMSG_INFO)
     endif
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "DataInitialize", "E")
   end subroutine DataInitialize
 
   !-----------------------------------------------------------------------------

mediator/med_phases_history_mod.F90

@@ -24,6 +24,8 @@ module med_phases_history_mod
   use perf_mod              , only : t_startf, t_stopf
   use pio                   , only : file_desc_t
   use shr_log_mod           , only : shr_log_error
+  use med_ufs_trace_wrapper_mod, only : ufs_trace_wrapper
+
   implicit none
   private
 
@@ -188,6 +190,7 @@ subroutine med_phases_history_write(gcomp, rc)
     !---------------------------------------
 
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write", "B")
     call t_startf('MED:'//subname)
 
     ! Get the internal state
@@ -383,6 +386,7 @@ subroutine med_phases_history_write(gcomp, rc)
 
     call t_stopf('MED:'//subname)
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write", "E")
   end subroutine med_phases_history_write
 
   !===============================================================================
@@ -420,6 +424,7 @@ subroutine med_phases_history_write_med(gcomp, rc)
     character(len=*), parameter :: subname='(med_phases_history_write_med)'
     !---------------------------------------
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write_med", "B")
 
     ! Get the internal state
     nullify(is_local%wrap)
@@ -526,6 +531,7 @@ subroutine med_phases_history_write_med(gcomp, rc)
        end if ! end of if-write_now block
     end if  ! end of if-active block
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write_med", "E")
   end subroutine med_phases_history_write_med
 
   !===============================================================================
@@ -567,6 +573,7 @@ subroutine med_phases_history_write_lnd2glc(gcomp, fldbun_lnd, rc, fldbun_glc)
     !---------------------------------------
 
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write_lnd2glc", "B")
 
     ! Get the internal state
     nullify(is_local%wrap)
@@ -655,6 +662,7 @@ subroutine med_phases_history_write_lnd2glc(gcomp, fldbun_lnd, rc, fldbun_glc)
     call med_io_close(io_file, rc=rc)
     if (ChkErr(rc,__LINE__,u_FILE_u)) return
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write_lnd2glc", "E")
   end subroutine med_phases_history_write_lnd2glc
 
   !===============================================================================
@@ -668,6 +676,7 @@ subroutine med_phases_history_write_comp(gcomp, compid, rc)
     integer            , intent(out)   :: rc
     !---------------------------------------
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write_comp", "B")
 
     call med_phases_history_write_comp_inst(gcomp, compid, instfiles(compid), rc=rc)
     if (ChkErr(rc,__LINE__,u_FILE_u)) return
@@ -676,6 +685,7 @@ subroutine med_phases_history_write_comp(gcomp, compid, rc)
     call med_phases_history_write_comp_aux(gcomp, compid, auxcomp(compid), rc=rc)
     if (ChkErr(rc,__LINE__,u_FILE_u)) return
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_history_write_comp", "E")
   end subroutine med_phases_history_write_comp
 
   !===============================================================================

mediator/med_phases_ocnalb_mod.F90

@@ -11,6 +11,8 @@ module med_phases_ocnalb_mod
   use shr_orb_mod           , only : shr_orb_cosz, shr_orb_decl
   use shr_orb_mod           , only : shr_orb_params, SHR_ORB_UNDEF_INT, SHR_ORB_UNDEF_REAL
   use shr_log_mod           , only : shr_log_unit, shr_log_error
+  use med_ufs_trace_wrapper_mod, only : ufs_trace_wrapper
+
   implicit none
   private
 
@@ -314,6 +316,7 @@ subroutine med_phases_ocnalb_run(gcomp, rc)
     !---------------------------------------
 
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_ocnalb_run", "B")
 
     ! Determine main task
     call ESMF_GridCompGet(gcomp, vm=vm, rc=rc)
@@ -507,6 +510,7 @@ subroutine med_phases_ocnalb_run(gcomp, rc)
     end if
     call t_stopf('MED:'//subname)
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_ocnalb_run", "E")
   end subroutine med_phases_ocnalb_run
 
 !===============================================================================

mediator/med_phases_post_atm_mod.F90

@@ -28,13 +28,14 @@ subroutine med_phases_post_atm(gcomp, rc)
     use ESMF                  , only : ESMF_GridComp, ESMF_GridCompGet, ESMF_FieldBundleGet
     use ESMF                  , only : ESMF_LogWrite, ESMF_LOGMSG_INFO, ESMF_SUCCESS
     use med_kind_mod          , only : CX=>SHR_KIND_CX, CS=>SHR_KIND_CS, CL=>SHR_KIND_CL, R8=>SHR_KIND_R8
-    use med_internalstate_mod , only : InternalState
+    use med_internalstate_mod , only : InternalState, maintask
     use med_phases_history_mod, only : med_phases_history_write_comp
     use med_map_mod           , only : med_map_field_packed
     use med_constants_mod     , only : dbug_flag => med_constants_dbug_flag
     use med_utils_mod         , only : chkerr    => med_utils_ChkErr
     use med_internalstate_mod , only : compocn, compatm, compice, complnd, compwav
     use perf_mod              , only : t_startf, t_stopf
+    use med_ufs_trace_wrapper_mod, only : ufs_trace_wrapper
 
     ! input/output variables
     type(ESMF_GridComp)  :: gcomp
@@ -47,6 +48,7 @@ subroutine med_phases_post_atm(gcomp, rc)
     !-------------------------------------------------------------------------------
 
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_atm", "B")
 
     call t_startf('MED:'//subname)
     if (dbug_flag > 20) then
@@ -126,6 +128,7 @@ subroutine med_phases_post_atm(gcomp, rc)
     end if
     call t_stopf('MED:'//subname)
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_atm", "E")
   end subroutine med_phases_post_atm
 
 end module med_phases_post_atm_mod

mediator/med_phases_post_ice_mod.F90

@@ -28,10 +28,11 @@ subroutine med_phases_post_ice(gcomp, rc)
     use med_methods_mod       , only : FB_diagnose => med_methods_FB_diagnose
     use med_map_mod           , only : med_map_field_packed
     use med_fraction_mod      , only : med_fraction_set
-    use med_internalstate_mod , only : InternalState
+    use med_internalstate_mod , only : InternalState, maintask
     use med_phases_history_mod, only : med_phases_history_write_comp
     use med_internalstate_mod , only : compice, compocn, compwav
     use perf_mod              , only : t_startf, t_stopf
+    use med_ufs_trace_wrapper_mod, only : ufs_trace_wrapper
 
     ! input/output variables
     type(ESMF_GridComp)  :: gcomp
@@ -43,6 +44,7 @@ subroutine med_phases_post_ice(gcomp, rc)
     character(len=*),parameter :: subname='(med_phases_post_ice)'
     !-------------------------------------------------------------------------------
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_ice", "B")
     call t_startf('MED:'//subname)
     rc = ESMF_SUCCESS
 
@@ -99,6 +101,7 @@ subroutine med_phases_post_ice(gcomp, rc)
        call ESMF_LogWrite(subname//' done', ESMF_LOGMSG_INFO)
     end if
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_ice", "E")
   end subroutine med_phases_post_ice
 
 end module med_phases_post_ice_mod

mediator/med_phases_post_ocn_mod.F90

@@ -26,11 +26,12 @@ subroutine med_phases_post_ocn(gcomp, rc)
     use med_utils_mod           , only : chkerr      => med_utils_ChkErr
     use med_constants_mod       , only : dbug_flag   => med_constants_dbug_flag
     use med_map_mod             , only : med_map_field_packed
-    use med_internalstate_mod   , only : InternalState
+    use med_internalstate_mod   , only : InternalState, maintask
     use med_internalstate_mod   , only : compice, compocn, compwav
     use med_phases_history_mod  , only : med_phases_history_write_comp
     use med_phases_prep_glc_mod , only : med_phases_prep_glc_accum_ocn
     use perf_mod                , only : t_startf, t_stopf
+    use med_ufs_trace_wrapper_mod, only : ufs_trace_wrapper
 
     ! input/output variables
     type(ESMF_GridComp)  :: gcomp
@@ -43,6 +44,7 @@ subroutine med_phases_post_ocn(gcomp, rc)
     !---------------------------------------
 
     rc = ESMF_SUCCESS
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_ocn", "B")
 
     call t_startf('MED:'//subname)
     if (dbug_flag > 20) then
@@ -101,6 +103,7 @@ subroutine med_phases_post_ocn(gcomp, rc)
     end if
     call t_stopf('MED:'//subname)
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_ocn", "E")
   end subroutine med_phases_post_ocn
 
 end module med_phases_post_ocn_mod

mediator/med_phases_post_wav_mod.F90

@@ -23,10 +23,11 @@ subroutine med_phases_post_wav(gcomp, rc)
     use med_utils_mod         , only : chkerr      => med_utils_ChkErr
     use med_methods_mod       , only : FB_diagnose => med_methods_FB_diagnose
     use med_map_mod           , only : med_map_field_packed
-    use med_internalstate_mod , only : InternalState
+    use med_internalstate_mod , only : InternalState, maintask
     use med_internalstate_mod , only : compwav, compatm, compocn, compice
     use med_phases_history_mod, only : med_phases_history_write_comp
     use perf_mod              , only : t_startf, t_stopf
+    use med_ufs_trace_wrapper_mod, only : ufs_trace_wrapper
 
     ! input/output variables
     type(ESMF_GridComp)  :: gcomp
@@ -38,6 +39,7 @@ subroutine med_phases_post_wav(gcomp, rc)
     character(len=*),parameter :: subname='(med_phases_post_wav)'
     !-------------------------------------------------------------------------------
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_wav", "B")
     call t_startf('MED:'//subname)
     rc = ESMF_SUCCESS
 
@@ -97,6 +99,7 @@ subroutine med_phases_post_wav(gcomp, rc)
        call ESMF_LogWrite(subname//' done', ESMF_LOGMSG_INFO)
     end if
 
+    if (maintask) call ufs_trace_wrapper("cmeps", "med_phases_post_wav", "E")
   end subroutine med_phases_post_wav
 
 end module med_phases_post_wav_mod