Add tracing instrumentation to nuopc driver (#162)

* adds calls to ufs tracing routines that will create a trace file which can then be visualized, 
  which is found to be useful in identifying various performance issues.

Author: DusanJovic-NOAA

config_src/drivers/nuopc_cap/mom_cap.F90

@@ -97,6 +97,7 @@ module MOM_cap_mod
 #ifndef CESMCOUPLED
 use shr_is_restart_fh_mod, only : init_is_restart_fh, is_restart_fh, is_restart_fh_type
 #endif
+use mom_ufs_trace_wrapper_mod, only: ufs_trace_init_wrapper, ufs_trace_wrapper
 
 implicit none; private
 
@@ -165,6 +166,7 @@ module MOM_cap_mod
 character(len=16) :: inst_suffix = ''
 logical           :: pointer_date = .true. ! append date to rpointer
 real(8) :: timere
+integer :: mype = -1
 
 contains
 
@@ -182,8 +184,18 @@ subroutine SetServices(gcomp, rc)
   ! local variables
   character(len=*),parameter  :: subname='(MOM_cap:SetServices)'
 
+  type(ESMF_VM)               :: vm
+
   rc = ESMF_SUCCESS
 
+  call ESMF_GridCompGet(gcomp, vm=vm, rc=rc)
+  if (ChkErr(rc,__LINE__,u_FILE_u)) return
+  call ESMF_VMGet(vm, localpet=mype, rc=rc)
+  if (ChkErr(rc,__LINE__,u_FILE_u)) return
+
+  if (mype == 0) call ufs_trace_init_wrapper()
+  if (mype == 0) call ufs_trace_wrapper("mom", "SetServices", "B")
+
   ! the NUOPC model component will register the generic methods
   call NUOPC_CompDerive(gcomp, model_routine_SS, rc=rc)
   if (ChkErr(rc,__LINE__,u_FILE_u)) return
@@ -223,6 +235,8 @@ subroutine SetServices(gcomp, rc)
        specRoutine=ocean_model_finalize, rc=rc)
   if (ChkErr(rc,__LINE__,u_FILE_u)) return
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "SetServices", "E")
+
 end subroutine SetServices
 
 !> First initialize subroutine called by NUOPC.  The purpose
@@ -249,10 +263,11 @@ subroutine InitializeP0(gcomp, importState, exportState, clock, rc)
   character(len=64)           :: value, logmsg
   character(len=*),parameter  :: subname='(MOM_cap:InitializeP0)'
   type(ESMF_VM)               :: vm
-  integer                     :: mype
 
   rc = ESMF_SUCCESS
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "InitializeP0", "B")
+
   ! Switch to IPDv03 by filtering all other phaseMap entries
   call NUOPC_CompFilterPhaseMap(gcomp, ESMF_METHOD_INITIALIZE, &
        acceptStringList=(/"IPDv03p"/), rc=rc)
@@ -415,6 +430,8 @@ subroutine InitializeP0(gcomp, importState, exportState, clock, rc)
      if (trim(value) .eq. '.true.') restart_eor = .true.
   end if
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "InitializeP0", "E")
+
 end subroutine
 
 !> Called by NUOPC to advertise import and export fields.  "Advertise"
@@ -484,6 +501,9 @@ subroutine InitializeAdvertise(gcomp, importState, exportState, clock, rc)
 !--------------------------------
 
   rc = ESMF_SUCCESS
+
+  if (mype == 0) call ufs_trace_wrapper("mom", "InitializeAdvertise", "B")
+
   if(write_runtimelog) timeiads = MPI_Wtime()
 
   call ESMF_LogWrite(subname//' enter', ESMF_LOGMSG_INFO)
@@ -927,6 +947,8 @@ subroutine InitializeAdvertise(gcomp, importState, exportState, clock, rc)
   enddo
   if(write_runtimelog .and. is_root_pe()) write(stdout,*) 'In ',trim(subname),' time ', MPI_Wtime()-timeiads
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "InitializeAdvertise", "E")
+
 end subroutine InitializeAdvertise
 
 !> Called by NUOPC to realize import and export fields.  "Realizing" a field
@@ -1020,6 +1042,9 @@ subroutine InitializeRealize(gcomp, importState, exportState, clock, rc)
   !--------------------------------
 
   rc = ESMF_SUCCESS
+
+  if (mype == 0) call ufs_trace_wrapper("mom", "InitializeRealize", "B")
+
   if(write_runtimelog) timeirls = MPI_Wtime()
 
   call shr_log_setLogUnit (stdout)
@@ -1610,6 +1635,8 @@ subroutine InitializeRealize(gcomp, importState, exportState, clock, rc)
   timere = 0.
   if(write_runtimelog .and. is_root_pe()) write(stdout,*) 'In ',trim(subname),' time ', MPI_Wtime()-timeirls
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "InitializeRealize", "E")
+
 end subroutine InitializeRealize
 
 !> TODO
@@ -1641,6 +1668,8 @@ subroutine DataInitialize(gcomp, rc)
   real(8)                                :: MPI_Wtime, timedis
   !--------------------------------
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "DataInitialize", "B")
+
   if(write_runtimelog) timedis = MPI_Wtime()
 
   ! query the Component for its clock, importState and exportState
@@ -1705,6 +1734,8 @@ subroutine DataInitialize(gcomp, rc)
 
   if(write_runtimelog .and. is_root_pe()) write(stdout,*) 'In ',trim(subname),' time ', MPI_Wtime()-timedis
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "DataInitialize", "E")
+
 end subroutine DataInitialize
 
 !> Called by NUOPC to advance the model a single timestep.
@@ -1761,6 +1792,9 @@ subroutine ModelAdvance(gcomp, rc)
   logical                                :: write_restart_eor
 
   rc = ESMF_SUCCESS
+
+  if (mype == 0) call ufs_trace_wrapper("mom", "ModelAdvance", "B")
+
   if(profile_memory) call ESMF_VMLogMemInfo("Entering MOM Model_ADVANCE: ")
   if(write_runtimelog) then
      timers = MPI_Wtime()
@@ -2048,6 +2082,8 @@ subroutine ModelAdvance(gcomp, rc)
 
   if(profile_memory) call ESMF_VMLogMemInfo("Leaving MOM Model_ADVANCE: ")
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "ModelAdvance", "E")
+
 end subroutine ModelAdvance
 
 
@@ -2076,6 +2112,8 @@ subroutine ModelSetRunClock(gcomp, rc)
 
   rc = ESMF_SUCCESS
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "ModelSetRunClock", "B")
+
   ! query the Component for its clock, importState and exportState
   call NUOPC_ModelGet(gcomp, driverClock=dclock, modelClock=mclock, rc=rc)
   if (ChkErr(rc,__LINE__,u_FILE_u)) return
@@ -2231,6 +2269,8 @@ subroutine ModelSetRunClock(gcomp, rc)
   call ESMF_ClockSet(mclock, currTime=dcurrtime, timeStep=dtimestep, stopTime=mstoptime, rc=rc)
   if (ChkErr(rc,__LINE__,u_FILE_u)) return
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "ModelSetRunClock", "E")
+
 end subroutine ModelSetRunClock
 
 !===============================================================================
@@ -2257,6 +2297,8 @@ subroutine ocean_model_finalize(gcomp, rc)
   character(len=*),parameter  :: subname='(MOM_cap:ocean_model_finalize)'
   real(8)                                :: MPI_Wtime, timefs
 
+  if (mype == 0) call ufs_trace_wrapper("mom", "ocean_model_finalize", "B")
+
   if (is_root_pe()) then
     write(stdout,*) 'MOM: --- finalize called ---'
   endif
@@ -2298,6 +2340,8 @@ subroutine ocean_model_finalize(gcomp, rc)
 
   if(write_runtimelog .and. is_root_pe()) write(stdout,*) 'In ',trim(subname),' time ', MPI_Wtime()-timefs
 
+  if(mype == 0) call ufs_trace_wrapper("mom", "ocean_model_finalize", "E")
+
 end subroutine ocean_model_finalize
 
 

config_src/drivers/nuopc_cap/mom_ufs_trace_wrapper.F90

@@ -0,0 +1,39 @@
+module mom_ufs_trace_wrapper_mod
+
+#ifdef UFS_TRACING
+  use ufs_trace_mod, only: ufs_trace_init, ufs_trace, ufs_trace_finalize
+#endif
+
+  implicit none
+
+  private
+
+  public ufs_trace_init_wrapper
+  public ufs_trace_wrapper
+  public ufs_trace_finalize_wrapper
+
+contains
+
+  subroutine ufs_trace_init_wrapper()
+#ifdef UFS_TRACING
+    call ufs_trace_init
+#endif
+    return
+  end subroutine ufs_trace_init_wrapper
+
+  subroutine ufs_trace_wrapper(component, routine, ph)
+    character(len=*), intent(in) :: component, routine, ph
+#ifdef UFS_TRACING
+    call ufs_trace(component, routine, ph)
+#endif
+    return
+  end subroutine ufs_trace_wrapper
+
+  subroutine ufs_trace_finalize_wrapper()
+#ifdef UFS_TRACING
+    call ufs_trace_finalize
+#endif
+    return
+  end subroutine ufs_trace_finalize_wrapper
+
+end module mom_ufs_trace_wrapper_mod