Add tracing instrumentation to nuopc driver

CMakeLists.txt

@@ -275,13 +275,16 @@ target_compile_definitions(${DYCORE_TARGET} PRIVATE "${_ufsatm_defs_private}")
 
 set_target_properties(${DYCORE_TARGET} PROPERTIES Fortran_MODULE_DIRECTORY ${CMAKE_CURRENT_BINARY_DIR}/mod)
 target_include_directories(${DYCORE_TARGET} INTERFACE $<BUILD_INTERFACE:${CMAKE_CURRENT_BINARY_DIR}/mod>
-                                                  $<INSTALL_INTERFACE:mod>)
+                                                      $<INSTALL_INTERFACE:mod>)
 # link target
 if (FV3)
   target_link_libraries(${DYCORE_TARGET} PUBLIC fv3
                                          fv3ccpp
-					 stochastic_physics
-					 fms)
+                                         stochastic_physics
+                                         fms)
+  if(UFS_TRACING)
+    target_link_libraries(${DYCORE_TARGET} PUBLIC ufs_tracing)
+  endif()
   if(INLINE_POST)
     target_link_libraries(${DYCORE_TARGET} PUBLIC upp::upp)
   endif()
@@ -299,8 +302,8 @@ endif()
 # Always include EMC libraries in dycore install
 target_link_libraries(${DYCORE_TARGET} PUBLIC w3emc::w3emc_d
                                               sp::sp_d
-					      bacio::bacio_4
-					      ESMF::ESMF)
+                                              bacio::bacio_4
+                                              ESMF::ESMF)
 
 # OpenMP
 if(OPENMP)

fv3/module_fcst_grid_comp.F90

@@ -83,6 +83,9 @@ module module_fcst_grid_comp
   use module_cdeps_inline,    only: cdeps_stream_init
   use module_cdeps_inline,    only: cdeps_stream_run
 #endif
+#ifdef UFS_TRACING
+  use ufs_trace_mod
+#endif
 !
 !-----------------------------------------------------------------------
 !
@@ -111,7 +114,7 @@ module module_fcst_grid_comp
 
   integer, allocatable :: frestart(:)
 
-  integer :: mype
+  integer :: mype = -1
 !
 !-----------------------------------------------------------------------
 !
@@ -128,8 +131,20 @@ subroutine SetServices(fcst_comp, rc)
     type(ESMF_GridComp)  :: fcst_comp
     integer, intent(out) :: rc
 
+    type(ESMF_VM)               :: vm
+
     rc = ESMF_SUCCESS
 
+    call ESMF_GridCompGet(fcst_comp, vm=vm, rc=rc)
+    if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
+
+    call ESMF_VMGet(vm, localpet=mype, rc=rc)
+    if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
+
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace_init()
+#endif
+
     call ESMF_GridCompSetEntryPoint(fcst_comp, ESMF_METHOD_INITIALIZE, &
                                     userRoutine=fcst_initialize, phase=1, rc=rc)
     if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
@@ -621,6 +636,9 @@ subroutine fcst_initialize(fcst_comp, importState, exportState, clock, rc)
 !
     timeis = mpi_wtime()
     rc     = ESMF_SUCCESS
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace("fv3", "fcst_initialize", "B")
+#endif
 !
     call ESMF_VMGetCurrent(vm=vm,rc=rc)
     if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
@@ -1121,6 +1139,9 @@ subroutine fcst_initialize(fcst_comp, importState, exportState, clock, rc)
       if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
 
       if (mype == 0) write(*,*)'fcst_initialize total time: ', mpi_wtime() - timeis
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace("fv3", "fcst_initialize", "E")
+#endif
 !
 !-----------------------------------------------------------------------
 !
@@ -1245,6 +1266,9 @@ subroutine fcst_advertise(fcst_comp, importState, exportState, clock, rc)
 !***********************************************************************
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace("fv3", "fcst_advertise", "B")
+#endif
     call ESMF_VMGetCurrent(vm=vm,rc=rc)
     if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
 
@@ -1259,6 +1283,9 @@ subroutine fcst_advertise(fcst_comp, importState, exportState, clock, rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace("fv3", "fcst_advertise", "E")
+#endif
    end subroutine fcst_advertise
 !
 !-----------------------------------------------------------------------
@@ -1286,6 +1313,9 @@ subroutine fcst_realize(fcst_comp, importState, exportState, clock, rc)
 !***********************************************************************
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace("fv3", "fcst_realize", "B")
+#endif
     call ESMF_VMGetCurrent(vm=vm,rc=rc)
     if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
 
@@ -1309,6 +1339,9 @@ subroutine fcst_realize(fcst_comp, importState, exportState, clock, rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+    if (mype == 0) call ufs_trace("fv3", "fcst_realize", "E")
+#endif
    end subroutine fcst_realize
 !
 !-----------------------------------------------------------------------
@@ -1338,6 +1371,9 @@ subroutine fcst_run_phase_1(fcst_comp, importState, exportState,clock,rc)
 !***********************************************************************
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace("fv3", "fcst_run_phase_1", "B")
+#endif
       tbeg1 = mpi_wtime()
       rc    = ESMF_SUCCESS
 !
@@ -1387,6 +1423,9 @@ subroutine fcst_run_phase_1(fcst_comp, importState, exportState,clock,rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace("fv3", "fcst_run_phase_1", "E")
+#endif
    end subroutine fcst_run_phase_1
 !
 !-----------------------------------------------------------------------
@@ -1420,6 +1459,9 @@ subroutine fcst_run_phase_2(fcst_comp, importState, exportState,clock,rc)
 !***********************************************************************
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace("fv3", "fcst_run_phase_2", "B")
+#endif
       tbeg1 = mpi_wtime()
       rc    = ESMF_SUCCESS
 !
@@ -1496,6 +1538,9 @@ subroutine fcst_run_phase_2(fcst_comp, importState, exportState,clock,rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace("fv3", "fcst_run_phase_2", "E")
+#endif
    end subroutine fcst_run_phase_2
 !
 !-----------------------------------------------------------------------
@@ -1523,6 +1568,9 @@ subroutine fcst_finalize(fcst_comp, importState, exportState,clock,rc)
 !***********************************************************************
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace("fv3", "fcst_finalize", "B")
+#endif
       tbeg1 = mpi_wtime()
       rc    = ESMF_SUCCESS
 
@@ -1536,6 +1584,9 @@ subroutine fcst_finalize(fcst_comp, importState, exportState,clock,rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace("fv3", "fcst_finalize", "E")
+#endif
   end subroutine fcst_finalize
 !
 !#######################################################################

io/module_wrt_grid_comp.F90

@@ -51,6 +51,9 @@ module module_wrt_grid_comp
 #ifdef INLINE_POST
      use post_fv3,            only : post_run_fv3
 #endif
+#ifdef UFS_TRACING
+      use ufs_trace_mod
+#endif
 !
 !-----------------------------------------------------------------------
 !
@@ -78,6 +81,8 @@ module module_wrt_grid_comp
      integer,allocatable,save      :: frestart(:)
      integer,save      :: calendar_type = 3
      logical           :: lprnt
+     integer           :: mype = -1
+     character(len=10) :: comp_name ! FIXME wrtComp_XX
 !
 !-----------------------------------------------------------------------
 !
@@ -116,8 +121,21 @@ subroutine SetServices(wrt_comp, rc)
        type(ESMF_GridComp)  :: wrt_comp
        integer, intent(out) :: rc
 
+       type(ESMF_VM)               :: vm
+
        rc = ESMF_SUCCESS
 
+       call ESMF_GridCompGet(wrt_comp, name=comp_name, vm=vm, rc=rc)
+       if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
+
+       call ESMF_VMGet(vm, localpet=mype, rc=rc)
+       if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
+
+#ifdef UFS_TRACING
+       if (mype == 0) call ufs_trace_init()
+       if (mype == 0) call ufs_trace(comp_name, "SetServices", "B")
+#endif
+
        call ESMF_GridCompSetEntryPoint(wrt_comp, ESMF_METHOD_INITIALIZE, phase=1, &
                                        userRoutine=wrt_initialize_p1, rc=rc)
        if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
@@ -138,6 +156,9 @@ subroutine SetServices(wrt_comp, rc)
                                        userRoutine=wrt_finalize, rc=rc)
        if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
 
+#ifdef UFS_TRACING
+       if (mype == 0) call ufs_trace(comp_name, "SetServices", "E")
+#endif
      end subroutine SetServices
 !
 !-----------------------------------------------------------------------
@@ -229,6 +250,9 @@ subroutine wrt_initialize_p1(wrt_comp, imp_state_write, exp_state_write, clock,
 !-----------------------------------------------------------------------
 !
      rc = ESMF_SUCCESS
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_initialize_p1", "B")
+#endif
 !
 !-----------------------------------------------------------------------
 !***  initialize the write component timers.
@@ -1444,6 +1468,9 @@ subroutine wrt_initialize_p1(wrt_comp, imp_state_write, exp_state_write, clock,
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_initialize_p1", "E")
+#endif
      end subroutine wrt_initialize_p1
 !
 !-----------------------------------------------------------------------
@@ -1480,6 +1507,9 @@ subroutine wrt_initialize_p2(wrt_comp, imp_state_write, exp_state_write, clock,
 !-----------------------------------------------------------------------
 !
      rc = ESMF_SUCCESS
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_initialize_p2", "B")
+#endif
 !
      call ESMF_InfoGetFromHost(imp_state_write, info=info, rc=rc)
      if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
@@ -1544,6 +1574,9 @@ subroutine wrt_initialize_p2(wrt_comp, imp_state_write, exp_state_write, clock,
 
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_initialize_p2", "E")
+#endif
      end subroutine wrt_initialize_p2
 !
 !-----------------------------------------------------------------------
@@ -1581,6 +1614,9 @@ subroutine wrt_initialize_p3(wrt_comp, imp_state_write, exp_state_write, clock,
 !-----------------------------------------------------------------------
 !
      rc = ESMF_SUCCESS
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_initialize_p3", "B")
+#endif
 !
      call ESMF_InfoGetFromHost(imp_state_write, info=info, rc=rc)
      if (ESMF_LogFoundError(rcToCheck=rc, msg=ESMF_LOGERR_PASSTHRU, line=__LINE__, file=__FILE__)) return
@@ -1643,6 +1679,9 @@ subroutine wrt_initialize_p3(wrt_comp, imp_state_write, exp_state_write, clock,
 
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_initialize_p3", "E")
+#endif
      end subroutine wrt_initialize_p3
 !
 !-----------------------------------------------------------------------
@@ -1679,7 +1718,7 @@ subroutine wrt_run(wrt_comp, imp_state_write, exp_state_write,clock,rc)
      type(write_wrap)                      :: wrap
      type(wrt_internal_state),pointer      :: wrt_int_state
 !
-     integer                               :: i,j,n,m, mype,nolog, grid_id, localPet
+     integer                               :: i,j,n,m, nolog, grid_id, localPet
 !
      integer                               :: nf_hours,nf_seconds,nf_minutes
      integer                               :: fcst_seconds
@@ -1736,6 +1775,9 @@ subroutine wrt_run(wrt_comp, imp_state_write, exp_state_write,clock,rc)
 !-----------------------------------------------------------------------
 !
      tbeg = MPI_Wtime()
+#ifdef UFS_TRACING
+     if (mype == 0) call ufs_trace(comp_name, "wrt_run", "B")
+#endif
      rc   = esmf_success
 !
 !-----------------------------------------------------------------------
@@ -1758,7 +1800,6 @@ subroutine wrt_run(wrt_comp, imp_state_write, exp_state_write,clock,rc)
 
      call ESMF_VMGetCurrent(VM,rc=RC)
 
-     mype = wrt_int_state%mype
 !    print *,'in wrt run, mype=',mype,'lead_write_task=',lead_write_task
 
      call ESMF_InfoGetFromHost(imp_state_write, info=info, rc=rc)
@@ -2501,6 +2542,9 @@ subroutine wrt_run(wrt_comp, imp_state_write, exp_state_write,clock,rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace(comp_name, "wrt_run", "E")
+#endif
       END SUBROUTINE wrt_run
 !
 !-----------------------------------------------------------------------
@@ -2533,6 +2577,9 @@ subroutine wrt_finalize(wrt_comp, imp_state_write, exp_state_write, clock, rc)
 !-----------------------------------------------------------------------
 !
       rc=ESMF_SUCCESS
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace(comp_name, "wrt_finalize", "B")
+#endif
 !
 !-----------------------------------------------------------------------
 !***  retrieve the write component's esmf internal state(used later for
@@ -2551,6 +2598,9 @@ subroutine wrt_finalize(wrt_comp, imp_state_write, exp_state_write, clock, rc)
 !
 !-----------------------------------------------------------------------
 !
+#ifdef UFS_TRACING
+      if (mype == 0) call ufs_trace(comp_name, "wrt_finalize", "E")
+#endif
     end subroutine wrt_finalize
 !
 !-----------------------------------------------------------------------