Merge pull request #1938 from GEOS-ESM/feature/mathomp4/1930-profiler…

…-output Create MAPL.profiler logger
GEOS-ESM · Feb 13, 2023 · 4e17985 · 4e17985
2 parents 4b0d4a3 + 23e71b0
commit 4e17985
Show file tree

Hide file tree

Showing 4 changed files with 54 additions and 49 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -28,6 +28,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   Rather, these default values are encapsulated where they belong in `Sun_Mod` in `base/MAPL_sun_uc.F90`
   and are now explicitly named and commented on at the head of the module. This is a structural
   zero-diff change.
+- Created `MAPL.profiler` logger and moved throughput, per-component, and global timers to use it
 - Moved most of the MAPL_GetResource generic subroutine to a new module, MAPL_ResourceMod, in base.
   The specific subroutines remain in MAPL_GenericMod to maintain the interface in one module, but
   most of the functionality is in MAPL_ResourceMod now.

diff --git a/base/ApplicationSupport.F90 b/base/ApplicationSupport.F90
@@ -23,7 +23,7 @@ subroutine MAPL_Initialize(unusable,comm,logging_config,rc)
 
       character(:), allocatable :: logging_configuration_file
       integer :: comm_world,status
-     
+
       _UNUSED_DUMMY(unusable)
 
       if (present(logging_config)) then
@@ -55,7 +55,7 @@ subroutine MAPL_Finalize(unusable,comm,rc)
       integer :: comm_world,status
 
       _UNUSED_DUMMY(unusable)
-      
+
       if (present(comm)) then
          comm_world = comm
       else
@@ -137,7 +137,7 @@ subroutine initialize_pflogger(unusable,comm,logging_config,rc)
 
          if (rank == 0) then
             lgr => logging%get_logger('MAPL')
-            call lgr%warning('No configure file specified for logging layer.  Using defaults.')            
+            call lgr%warning('No configure file specified for logging layer.  Using defaults.')
          end if
 
       end if
@@ -158,6 +158,7 @@ subroutine report_global_profiler(unusable,comm,rc)
       integer :: npes, my_rank, ierror
       character(1) :: empty(0)
       class (BaseProfiler), pointer :: t_p
+      type(Logger), pointer :: lgr
 
       _UNUSED_DUMMY(unusable)
       if (present(comm)) then
@@ -185,13 +186,14 @@ subroutine report_global_profiler(unusable,comm,rc)
       call MPI_Comm_Rank(world_comm, my_rank, ierror)
 
       if (my_rank == 0) then
-            report_lines = reporter%generate_report(t_p)
-            write(*,'(a,1x,i0)')'Report on process: ', my_rank
-            do i = 1, size(report_lines)
-               write(*,'(a)') report_lines(i)
-            end do
-       end if
-       call MPI_Barrier(world_comm, ierror)
+         report_lines = reporter%generate_report(t_p)
+         lgr => logging%get_logger('MAPL.profiler')
+         call lgr%info('Report on process: %i0', my_rank)
+         do i = 1, size(report_lines)
+            call lgr%info('%a', report_lines(i))
+         end do
+      end if
+      call MPI_Barrier(world_comm, ierror)
 
    end subroutine report_global_profiler
 

diff --git a/generic/MAPL_Generic.F90 b/generic/MAPL_Generic.F90
@@ -2278,10 +2278,13 @@ subroutine report_generic_profile( rc )
          type (MultiColumn) :: min_multi, mean_multi, max_multi, pe_multi, n_cyc_multi
          type (ESMF_VM) :: vm
          character(1) :: empty(0)
+         class(Logger), pointer :: lgr
 
          call ESMF_VmGetCurrent(vm, rc=status)
          _VERIFY(status)
 
+         lgr => logging%get_logger('MAPL.profiler')
+
          ! Generate stats _across_ processes covered by this timer
          ! Requires consistent call trees for now.
 
@@ -2326,12 +2329,12 @@ subroutine report_generic_profile( rc )
 
 
             report = reporter%generate_report(state%t_profiler)
-            write(OUTPUT_UNIT,*)''
-            write(OUTPUT_UNIT,*)'Times for component <' // trim(comp_name) // '>'
+            call lgr%info('')
+            call lgr%info('Times for component <%a~>', trim(comp_name))
             do i = 1, size(report)
-               write(OUTPUT_UNIT,'(a)')report(i)
+               call lgr%info('%a', report(i))
             end do
-            write(OUTPUT_UNIT,*)''
+            call lgr%info('')
          end if
 
          _RETURN(ESMF_SUCCESS)
@@ -4083,7 +4086,7 @@ subroutine MAPL_GenericStateGet (STATE, IM, JM, LM, VERTDIM,                &
          if(.not.MAPL_SunOrbitCreated(STATE%ORBIT)) then
 
             call ESMF_GridGet(STATE%GRID%ESMFGRID,name=gname,_RC)
-            FIX_SUN = (index(gname,"DP")>0) 
+            FIX_SUN = (index(gname,"DP")>0)
 
             ! create the orbit object
             STATE%ORBIT = MAPL_SunOrbitCreateFromConfig (STATE%CF, STATE%CLOCK, FIX_SUN, _RC)

diff --git a/gridcomps/Cap/MAPL_Cap.F90 b/gridcomps/Cap/MAPL_Cap.F90
@@ -26,11 +26,11 @@ module MAPL_CapMod
       character(:), allocatable :: name
       procedure(), nopass, pointer :: set_services => null()
       logical :: non_dso = .false.
-      integer :: comm_world 
+      integer :: comm_world
       integer :: rank
       integer :: npes_member
       character(:), allocatable :: root_dso
- 
+
       type (MAPL_CapOptions), allocatable :: cap_options
       ! misc
       logical :: mpi_already_initialized = .false.
@@ -60,7 +60,7 @@ module MAPL_CapMod
       procedure :: get_cap_gc
       procedure :: get_cap_rc_file
       procedure :: get_egress_file
-           
+
    end type MAPL_Cap
 
    interface MAPL_Cap
@@ -85,7 +85,7 @@ function new_MAPL_Cap_from_set_services(name, set_services, unusable, cap_option
       class (KeywordEnforcer),  optional, intent(in) :: unusable
       type ( MAPL_CapOptions), optional, intent(in) :: cap_options
       integer, optional, intent(out) :: rc
-      integer :: status    
+      integer :: status
 
       cap%name = name
       cap%set_services => set_services
@@ -112,7 +112,7 @@ function new_MAPL_Cap_from_set_services(name, set_services, unusable, cap_option
                            rc=status)
       _VERIFY(status)
 
-      _RETURN(_SUCCESS)     
+      _RETURN(_SUCCESS)
       _UNUSED_DUMMY(unusable)
 
     end function new_MAPL_Cap_from_set_services
@@ -123,7 +123,7 @@ function new_MAPL_Cap_from_dso(name, unusable, cap_options, rc) result(cap)
       class (KeywordEnforcer),  optional, intent(in) :: unusable
       type ( MAPL_CapOptions), optional, intent(in) :: cap_options
       integer, optional, intent(out) :: rc
-      integer :: status    
+      integer :: status
 
       cap%name = name
 
@@ -148,12 +148,12 @@ function new_MAPL_Cap_from_dso(name, unusable, cap_options, rc) result(cap)
                            rc=status)
       _VERIFY(status)
 
-      _RETURN(_SUCCESS)     
+      _RETURN(_SUCCESS)
       _UNUSED_DUMMY(unusable)
 
     end function new_MAPL_Cap_from_dso
 
-   
+
    ! 3. Run the ensemble (default is 1 member)
    ! 4. Finalize MPI if initialized locally.
    subroutine run(this, unusable, rc)
@@ -162,7 +162,7 @@ subroutine run(this, unusable, rc)
       integer, optional, intent(out) :: rc
       integer :: status
 !
-   
+
 
       _UNUSED_DUMMY(unusable)
 
@@ -172,7 +172,7 @@ subroutine run(this, unusable, rc)
       _RETURN(_SUCCESS)
 
     end subroutine run
-    
+
 
    ! This layer splits the communicator to support running a
    ! multi-member ensemble.
@@ -185,7 +185,7 @@ subroutine run_ensemble(this, unusable, rc)
       integer :: subcommunicator
 
       _UNUSED_DUMMY(unusable)
-      
+
       subcommunicator = this%create_member_subcommunicator(this%comm_world, rc=status); _VERIFY(status)
       if (subcommunicator /= MPI_COMM_NULL) then
          call this%initialize_io_clients_servers(subcommunicator, rc = status); _VERIFY(status)
@@ -195,7 +195,7 @@ subroutine run_ensemble(this, unusable, rc)
       end if
 
       _RETURN(_SUCCESS)
-      
+
    end subroutine run_ensemble
 
 
@@ -214,7 +214,7 @@ subroutine finalize_io_clients_servers(this, unusable, rc)
      end select
      call this%cap_server%finalize()
      _RETURN(_SUCCESS)
- 
+
    end subroutine finalize_io_clients_servers
 
    subroutine initialize_io_clients_servers(this, comm, unusable, rc)
@@ -241,14 +241,14 @@ subroutine initialize_io_clients_servers(this, comm, unusable, rc)
      _RETURN(_SUCCESS)
 
    end subroutine initialize_io_clients_servers
-     
+
    ! This layer splits the communicator to support separate i/o servers
    ! and runs the model via a CapGridComp.
    subroutine run_member(this, rc)
       use MAPL_CFIOMod
       class (MAPL_Cap), intent(inout) :: this
       integer, optional, intent(out) :: rc
-      
+
       integer :: status
       type(SplitCommunicator) :: split_comm
 
@@ -257,7 +257,7 @@ subroutine run_member(this, rc)
       case('model')
          call this%run_model(comm=split_comm%get_subcommunicator(), rc=status); _VERIFY(status)
       end select
-                  
+
      _RETURN(_SUCCESS)
 
    end subroutine run_member
@@ -273,7 +273,7 @@ subroutine run_model(this, comm, unusable, rc)
       integer(kind=INT64) :: start_tick, stop_tick, tick_rate
       integer :: status
       class(Logger), pointer :: lgr
-      
+
       _UNUSED_DUMMY(unusable)
 
       call start_timer()
@@ -306,7 +306,6 @@ subroutine run_model(this, comm, unusable, rc)
       _VERIFY(status)
       call stop_timer()
 
-      ! W.J note : below reporting will be remove soon
       call report_throughput()
 
       _RETURN(_SUCCESS)
@@ -336,14 +335,14 @@ subroutine report_throughput(rc)
             model_days_per_day = model_duration / wall_time
 
 
-            lgr => logging%get_logger('MAPL')
+            lgr => logging%get_logger('MAPL.profiler')
             call lgr%info("Model Throughput: %f12.3 days per day", model_days_per_day)
          end if
-         
+
       end subroutine report_throughput
 
    end subroutine run_model
-   
+
    subroutine initialize_cap_gc(this, unusable, n_run_phases, rc)
      class(MAPL_Cap), intent(inout) :: this
      class (KeywordEnforcer), optional, intent(in) :: unusable
@@ -357,15 +356,15 @@ subroutine initialize_cap_gc(this, unusable, n_run_phases, rc)
      if (this%non_dso) then
         call MAPL_CapGridCompCreate(this%cap_gc, this%get_cap_rc_file(), &
            this%name, this%get_egress_file(), n_run_phases=n_run_phases, root_set_services = this%set_services,rc=status)
-     else 
+     else
         _ASSERT(this%cap_options%root_dso /= 'none',"No set services specified, must pass a dso")
         call MAPL_CapGridCompCreate(this%cap_gc, this%get_cap_rc_file(), &
            this%name, this%get_egress_file(), n_run_phases=n_run_phases, root_dso = this%cap_options%root_dso,rc=status)
      end if
      _VERIFY(status)
      _RETURN(_SUCCESS)
    end subroutine initialize_cap_gc
-   
+
 
    subroutine step_model(this, rc)
      class(MAPL_Cap), intent(inout) :: this
@@ -374,30 +373,30 @@ subroutine step_model(this, rc)
      call this%cap_gc%step(rc = status); _VERIFY(status)
      _RETURN(_SUCCESS)
    end subroutine step_model
-  
+
    subroutine rewind_model(this, time, rc)
      class(MAPL_Cap), intent(inout) :: this
      type(ESMF_Time), intent(inout) :: time
      integer, intent(out) :: rc
      integer :: status
      call this%cap_gc%rewind_clock(time,rc = status); _VERIFY(status)
      _RETURN(_SUCCESS)
-   end subroutine rewind_model 
+   end subroutine rewind_model
 
    integer function create_member_subcommunicator(this, comm, unusable, rc) result(subcommunicator)
       class (MAPL_Cap), intent(inout) :: this
       integer, intent(in) :: comm
       class (KeywordEnforcer), optional, intent(in) :: unusable
       integer, optional, intent(out) :: rc
-      
+
       type (SplitCommunicator) :: split_comm
 
       integer :: status
       character(:), allocatable :: dir_name
 !!$      external :: chdir
 
       _UNUSED_DUMMY(unusable)
-      
+
       subcommunicator = MPI_COMM_NULL ! in case of failure
       this%splitter = SimpleCommSplitter(comm, this%cap_options%n_members, this%npes_member, base_name=this%cap_options%ensemble_subdir_prefix)
       split_comm = this%splitter%split(rc=status); _VERIFY(status)
@@ -408,9 +407,9 @@ integer function create_member_subcommunicator(this, comm, unusable, rc) result(
          status = c_chdir(dir_name)
          _VERIFY(status)
       end if
-      
+
       _RETURN(_SUCCESS)
-      
+
    end function create_member_subcommunicator
 
 
@@ -459,13 +458,13 @@ subroutine chdir(path, err)
       character(*) :: path
       integer, optional, intent(out) :: err
       integer :: loc_err
-      
+
       loc_err =  c_chdir(path//c_null_char)
-      
+
       if (present(err)) err = loc_err
-      
+
    end subroutine chdir
-   
+
    subroutine finalize_mpi(this, unusable, rc)
       class (MAPL_Cap), intent(in) :: this
       class (KeywordEnforcer), optional, intent(in) :: unusable
@@ -488,7 +487,7 @@ function get_npes_model(this) result(npes_model)
      integer :: npes_model
      npes_model = this%cap_options%npes_model
    end function get_npes_model
-    
+
    function get_comm_world(this) result(comm_world)
      class(MAPL_Cap), intent(in) :: this
      integer :: comm_world