Instrumenting user methods - setservices, initialize and run

generic3g/CMakeLists.txt

@@ -81,7 +81,7 @@ esma_add_fortran_submodules(
           set_geom.F90 set_vertical_grid.F90 get_vertical_grid.F90 get_registry.F90
           get_component_spec.F90 get_internal_state.F90 get_logger.F90
           get_user_gc_driver.F90 connect_all.F90 set_entry_point.F90
-          finalize.F90)
+          finalize.F90 start_timer.F90 stop_timer.F90)
 
 esma_add_fortran_submodules(
   TARGET MAPL.generic3g

generic3g/MAPL_Generic.F90

@@ -65,7 +65,6 @@ module mapl3g_Generic
    public :: MAPL_GridCompGetOuterMeta
    public :: MAPL_GridCompGetRegistry
 
-
    ! These should be available to users
    public :: MAPL_GridCompAddVarSpec
    public :: MAPL_GridCompAddSpec
@@ -103,6 +102,10 @@ module mapl3g_Generic
    public :: MAPL_GridCompReexport
    public :: MAPL_GridCompConnectAll
 
+   ! Timers
+   public :: MAPL_GridCompTimerStart
+   public :: MAPL_GridCompTimerStop
+
    ! Spec types
    public :: MAPL_STATEITEM_STATE, MAPL_STATEITEM_FIELDBUNDLE
 
@@ -211,6 +214,14 @@ module mapl3g_Generic
       procedure :: gridcomp_connect_all
    end interface MAPL_GridCompConnectAll
 
+   interface MAPL_GridCompTimerStart
+      procedure :: gridcomp_timer_start
+   end interface MAPL_GridCompTimerStart
+
+   interface MAPL_GridCompTimerStop
+      procedure :: gridcomp_timer_stop
+   end interface MAPL_GridCompTimerStop
+
    interface MAPL_ClockGet
       procedure :: clock_get_dt
    end interface MAPL_ClockGet
@@ -279,7 +290,6 @@ subroutine gridcomp_get(gridcomp, unusable, &
         num_levels, &
         num_children, &
         rc)
-
       type(ESMF_GridComp), intent(inout) :: gridcomp
       class(KeywordEnforcer), optional, intent(in) :: unusable
       character(:), optional, allocatable :: name
@@ -604,7 +614,6 @@ subroutine gridcomp_add_spec( &
       _UNUSED_DUMMY(unusable)
    end subroutine gridcomp_add_spec
 
-
    subroutine gridcomp_advertise_variable(gridcomp, var_spec, rc)
       type(esmf_GridComp), intent(inout) :: gridcomp
       type(VariableSpec), intent(in) :: var_spec
@@ -1079,7 +1088,6 @@ subroutine gridcomp_add_simple_connectivity(gridcomp, unusable, src_comp, src_na
       _UNUSED_DUMMY(unusable)
    end subroutine gridcomp_add_simple_connectivity
 
-
    subroutine gridcomp_reexport(gridcomp, unusable, src_comp, src_name, src_intent, new_name, rc)
       type(ESMF_GridComp), intent(inout) :: gridcomp
       class(KeywordEnforcer), optional, intent(in) :: unusable
@@ -1102,6 +1110,34 @@ subroutine gridcomp_reexport(gridcomp, unusable, src_comp, src_name, src_intent,
       _UNUSED_DUMMY(unusable)
    end subroutine gridcomp_reexport
 
+   subroutine gridcomp_timer_start(gridcomp, name, rc)
+      type(ESMF_GridComp), intent(inout) :: gridcomp
+      character(len=*), intent(in) :: name
+      integer, optional, intent(out) :: rc
+
+      type(OuterMetaComponent), pointer :: outer_meta
+      integer :: status
+
+      call MAPL_GridCompGetOuterMeta(gridcomp, outer_meta, _RC)
+      call outer_meta%start_timer(name, _RC)
+
+      _RETURN(_SUCCESS)
+   end subroutine gridcomp_timer_start
+
+   subroutine gridcomp_timer_stop(gridcomp, name, rc)
+      type(ESMF_GridComp), intent(inout) :: gridcomp
+      character(len=*), intent(in) :: name
+      integer, optional, intent(out) :: rc
+
+      type(OuterMetaComponent), pointer :: outer_meta
+      integer :: status
+
+      call MAPL_GridCompGetOuterMeta(gridcomp, outer_meta, _RC)
+      call outer_meta%stop_timer(name, _RC)
+
+      _RETURN(_SUCCESS)
+   end subroutine gridcomp_timer_stop
+
    subroutine clock_get_dt(clock, dt, rc)
       type(ESMF_Clock), intent(in) :: clock
       real(ESMF_KIND_R4), intent(out) :: dt ! timestep in seconds

generic3g/OuterMetaComponent.F90

@@ -1,6 +1,7 @@
 #include "MAPL.h"
 
 module mapl3g_OuterMetaComponent
+
    use mapl3g_UserSetServices, only: AbstractUserSetServices
    use mapl3g_ComponentSpec
    use mapl3g_VariableSpec
@@ -17,6 +18,7 @@ module mapl3g_OuterMetaComponent
    use mapl3g_SimpleAlarm
    use gFTL2_StringVector
    use mapl_keywordEnforcer, only: KE => KeywordEnforcer
+   use MAPL_Profiler, only: DistributedProfiler
    use esmf
    use pflogger, only: Logger
 
@@ -56,6 +58,7 @@ module mapl3g_OuterMetaComponent
       integer :: counter
 
       type(SimpleAlarm) :: user_run_alarm
+      type(DistributedProfiler) :: profiler
 
    contains
 
@@ -91,6 +94,9 @@ module mapl3g_OuterMetaComponent
       procedure :: finalize
       procedure :: write_restart
 
+      procedure :: start_timer
+      procedure :: stop_timer
+
       ! Hierarchy
       procedure, private :: add_child_by_spec
       procedure, private :: get_child_by_name
@@ -123,7 +129,6 @@ module mapl3g_OuterMetaComponent
       type(OuterMetaComponent), pointer :: outer_meta
    end type OuterMetaWrapper
 
-
    interface get_outer_meta
       module procedure :: get_outer_meta_from_outer_gc
    end interface get_outer_meta
@@ -378,6 +383,18 @@ module recursive subroutine write_restart(this, importState, exportState, clock,
          integer, optional, intent(out) :: rc
       end subroutine write_restart
 
+      module subroutine start_timer(this, name, rc)
+         class(OuterMetaComponent), intent(inout) :: this
+         character(len=*), intent(in) :: name
+         integer, optional, intent(out) :: rc
+      end subroutine start_timer
+
+      module subroutine stop_timer(this, name, rc)
+         class(OuterMetaComponent), intent(inout) :: this
+         character(len=*), intent(in) :: name
+         integer, optional, intent(out) :: rc
+      end subroutine stop_timer
+
       module function get_name(this, rc) result(name)
          character(:), allocatable :: name
          class(OuterMetaComponent), intent(in) :: this
@@ -453,13 +470,12 @@ module function get_checkpoint_subdir(hconfig, currTime, rc) result(subdir)
          integer, optional, intent(out) :: rc
       end function get_checkpoint_subdir
 
-   end interface
+   end interface ! submodule interfaces
 
    interface OuterMetaComponent
       module procedure new_outer_meta
    end interface OuterMetaComponent
 
-
    interface recurse
       module procedure recurse_
    end interface recurse

generic3g/OuterMetaComponent/SetServices.F90

@@ -8,6 +8,7 @@
    use mapl3g_BasicVerticalGrid
    use mapl3g_GriddedComponentDriverMap
    use mapl_ErrorHandling
+   use pflogger, only: logger_t => logger
    implicit none
 
 contains
@@ -32,13 +33,17 @@ recursive module subroutine SetServices_(this, rc)
 
       integer :: status
       type(ESMF_GridComp) :: user_gridcomp
+      class(logger_t), pointer :: logger
 
       ! Note that Parent component should set timestep and offset in outer meta before calling SetServices.
       this%component_spec = parse_component_spec(this%hconfig, this%registry, this%user_timeStep, this%user_offset, _RC)
 
       user_gridcomp = this%user_gc_driver%get_gridcomp()
       call attach_inner_meta(user_gridcomp, this%self_gridcomp, _RC)
+      logger => this%get_logger()
+      call logger%info("SetServices:: starting...")
       call this%user_setservices%run(user_gridcomp, _RC)
+      call logger%info("SetServices:: ...completed")
       call add_children(this, _RC)
       call run_children_setservices(this, _RC)
 

generic3g/OuterMetaComponent/finalize.F90

@@ -1,10 +1,16 @@
 #include "MAPL.h"
 
 submodule (mapl3g_OuterMetaComponent) finalize_smod
+
    use mapl3g_GriddedComponentDriverMap
    use mapl3g_GenericPhases
    use mapl_ErrorHandling
-   use mapl3g_Generic
+   use MAPL_CommsMod, only: MAPL_Am_I_Root
+   use MAPL_Profiler, only: ProfileReporter
+   use MAPL_Profiler, only: MultiColumn, NameColumn, FormattedTextColumn, PercentageColumn
+   use MAPL_Profiler, only: InclusiveColumn, ExclusiveColumn, SeparatorColumn, NumCyclesColumn
+   use pflogger, only: logger_t => logger
+
    implicit none (type, external)
 
 contains
@@ -20,21 +26,24 @@ module recursive subroutine finalize(this, importState, exportState, clock, unus
 
       type(GriddedComponentDriver), pointer :: child
       type(GriddedComponentDriverMapIterator) :: iter
-      integer :: phase_idx, status
       character(*), parameter :: PHASE_NAME = 'GENERIC::FINALIZE_USER'
       type(StringVector), pointer :: finalize_phases
       logical :: found
+      integer :: phase_idx, status
 
       call recurse_finalize_(this, phase_idx=GENERIC_FINALIZE_USER, _RC)
 
-      ! User gridcomp may not have any given phase; not an error condition if not found.
+      ! Finalize profiler
+      call this%profiler%stop(_RC)
+      call report_generic_profile(this, _RC)
+
+      ! User gridcomp may not have any given phase; not an error condition if not found
       finalize_phases => this%user_phases_map%at(ESMF_METHOD_FINALIZE, _RC)
       phase_idx = get_phase_index(finalize_phases, phase_name=phase_name, found=found)
       _RETURN_UNLESS(found)
 
       call this%run_custom(ESMF_METHOD_FINALIZE, PHASE_NAME, _RC)
 
-      ! TODO - component profile
       ! TODO - release resources
 
       _RETURN(ESMF_SUCCESS)
@@ -62,4 +71,72 @@ recursive subroutine recurse_finalize_(this, phase_idx, rc)
       _RETURN(_SUCCESS)
    end subroutine recurse_finalize_
 
+   subroutine report_generic_profile(this, rc)
+      class(OuterMetaComponent), target, intent(inout) :: this
+      integer, optional, intent(out) :: rc
+
+      character(:), allocatable :: report(:)
+      type(ProfileReporter) :: reporter
+      type(MultiColumn) :: min_multi, mean_multi, max_multi, pe_multi, n_cyc_multi
+      type(ESMF_VM) :: vm
+      character(1) :: empty(0)
+      class(logger_t), pointer :: logger
+      integer :: index, status
+
+      logger => this%get_logger()
+
+      ! Generate stats _across_ processes covered by this timer
+      ! Requires consistent call trees for now.
+      call this%profiler%reduce()
+
+      call ESMF_VmGetCurrent(vm, _RC)
+      if  (MAPL_AM_I_Root(vm)) then
+         reporter = ProfileReporter(empty)
+         call reporter%add_column(NameColumn(25, separator=" "))
+
+         min_multi = MultiColumn(['Min'], separator='=')
+         call min_multi%add_column(FormattedTextColumn('   %  ','(f6.2)', 6, PercentageColumn(ExclusiveColumn('MIN')), separator='-'))
+         call min_multi%add_column(FormattedTextColumn('inclusive', '(f10.2)', 10, InclusiveColumn('MIN'), separator='-'))
+         call min_multi%add_column(FormattedTextColumn('exclusive', '(f10.2)',10, ExclusiveColumn('MIN'), separator='-'))
+
+         mean_multi = MultiColumn(['Mean'], separator='=')
+         call mean_multi%add_column(FormattedTextColumn('   %  ','(f6.2)', 6, PercentageColumn(ExclusiveColumn('MEAN')), separator='-'))
+         call mean_multi%add_column(FormattedTextColumn('inclusive', '(f10.2)', 10, InclusiveColumn('MEAN'), separator='-'))
+         call mean_multi%add_column(FormattedTextColumn('exclusive', '(f10.2)', 10, ExclusiveColumn('MEAN'), separator='-'))
+
+         max_multi = MultiColumn(['Max'], separator='=')
+         call max_multi%add_column(FormattedTextColumn('   %  ','(f6.2)', 6, PercentageColumn(ExclusiveColumn('MAX')), separator='-'))
+         call max_multi%add_column(FormattedTextColumn('inclusive', '(f10.2)', 10, InclusiveColumn('MAX'), separator='-'))
+         call max_multi%add_column(FormattedTextColumn('exclusive', '(f10.2)', 10, ExclusiveColumn('MAX'), separator='-'))
+
+         pe_multi = MultiColumn(['PE'], separator='=')
+         call pe_multi%add_column(FormattedTextColumn('max','(1x,i5.5)', 6, ExclusiveColumn('MAX_PE'), separator='-'))
+         call pe_multi%add_column(FormattedTextColumn('min','(1x,i5.5)', 6, ExclusiveColumn('MIN_PE'),separator='-'))
+
+         n_cyc_multi = MultiColumn(['# cycles'], separator='=')
+         call n_cyc_multi%add_column(FormattedTextColumn('', '(i8.0)', 8, NumCyclesColumn(),separator=' '))
+
+         call reporter%add_column(SeparatorColumn('|'))
+         call reporter%add_column(min_multi)
+         call reporter%add_column(SeparatorColumn('|'))
+         call reporter%add_column(mean_multi)
+         call reporter%add_column(SeparatorColumn('|'))
+         call reporter%add_column(max_multi)
+         call reporter%add_column(SeparatorColumn('|'))
+         call reporter%add_column(pe_multi)
+         call reporter%add_column(SeparatorColumn('|'))
+         call reporter%add_column(n_cyc_multi)
+
+         report = reporter%generate_report(this%profiler)
+         call logger%info('')
+         call logger%info('Times for component <%a~>', this%user_gc_driver%get_name())
+         do index = 1, size(report)
+            call logger%info('%a', report(index))
+         end do
+         call logger%info('')
+      end if
+
+      _RETURN(ESMF_SUCCESS)
+   end subroutine report_generic_profile
+
 end submodule finalize_smod

generic3g/OuterMetaComponent/initialize_geom_a.F90

@@ -1,11 +1,14 @@
 #include "MAPL.h"
 
 submodule (mapl3g_OuterMetaComponent) initialize_geom_a_smod
+
    use mapl3g_GenericPhases
    use mapl3g_GeometrySpec
    use mapl3g_Geom_API
    use mapl3g_GriddedComponentDriver
    use mapl_ErrorHandling
+   use MAPL_MpiTimerGauge, only: MpiTimerGauge
+
    implicit none(type,external)
 
 contains
@@ -17,13 +20,14 @@ module recursive subroutine initialize_geom_a(this, unusable, rc)
       class(KE), optional, intent(in) :: unusable
       integer, optional, intent(out) :: rc
 
-      integer :: status
       character(*), parameter :: PHASE_NAME = 'GENERIC::INIT_GEOM_A'
       class(GriddedComponentDriver), pointer :: provider
       type(ESMF_GridComp) :: provider_gc
       type(OuterMetaComponent), pointer :: provider_meta
       type(MaplGeom), pointer :: mapl_geom
       type(GeomManager), pointer :: geom_mgr
+      type(ESMF_VM) :: vm
+      integer :: comm, status
 
       ! Handle case where component provides its own geometry.
        associate (geometry_spec => this%component_spec%geometry_spec)
@@ -37,6 +41,12 @@ module recursive subroutine initialize_geom_a(this, unusable, rc)
         end if
       end associate
 
+      ! Initialize profiler
+      call ESMF_VMGetCurrent(vm, _RC)
+      call ESMF_VMGet(vm, mpiCommunicator=comm, _RC)
+      this%profiler = DistributedProfiler(this%user_gc_driver%get_name(), MpiTimerGauge(), comm=comm)
+      call this%profiler%start(_RC)
+
       call this%run_custom(ESMF_METHOD_INITIALIZE, PHASE_NAME, _RC)
       call recurse(this, phase_idx=GENERIC_INIT_GEOM_A, _RC)
 

generic3g/OuterMetaComponent/initialize_read_restart.F90

@@ -42,12 +42,16 @@ module recursive subroutine initialize_read_restart(this, unusable, rc)
 
       if (this%component_spec%misc%restart_controls%import) then
          filename = mapl_PathJoin(subdir, driver%get_name() // '_import.nc')
+         call this%start_timer("ReadImportRestart", _RC)
          call restart_handler%read(states%importState, filename, _RC)
+         call this%stop_timer("ReadImportRestart", _RC)
       end if
 
       if (this%component_spec%misc%restart_controls%internal) then
          filename = mapl_PathJoin(subdir, driver%get_name() // '_internal.nc')
+         call this%start_timer("ReadInternalRestart", _RC)
          call restart_handler%read(states%internalState, filename, _RC)
+         call this%stop_timer("ReadInternalRestart", _RC)
       end if
 
       call this%run_custom(ESMF_METHOD_INITIALIZE, PHASE_NAME, _RC)