From f5b1b0f1a01bfedb458540ba2365a59c027d01e2 Mon Sep 17 00:00:00 2001 From: Matthew Thompson Date: Thu, 19 Jan 2023 15:10:44 -0500 Subject: [PATCH 1/2] Create MAPL.profiler logger --- CHANGELOG.md | 1 + base/ApplicationSupport.F90 | 22 +++++++------ generic/MAPL_Generic.F90 | 13 +++++--- gridcomps/Cap/MAPL_Cap.F90 | 66 ++++++++++++++++++------------------- 4 files changed, 54 insertions(+), 48 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 28a8c6f7ff7..77cb0fff591 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,6 +27,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 ### Fixed diff --git a/base/ApplicationSupport.F90 b/base/ApplicationSupport.F90 index 0eac83a95c4..9cb744b7e7e 100644 --- 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 index d29db2dcce8..a8eb7bd9a81 100644 --- a/generic/MAPL_Generic.F90 +++ b/generic/MAPL_Generic.F90 @@ -2277,10 +2277,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. @@ -2325,12 +2328,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) @@ -4082,7 +4085,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 index 624257ffdb5..31da5adba1f 100644 --- 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() @@ -336,14 +336,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,7 +357,7 @@ 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) @@ -365,7 +365,7 @@ subroutine initialize_cap_gc(this, unusable, n_run_phases, rc) _VERIFY(status) _RETURN(_SUCCESS) end subroutine initialize_cap_gc - + subroutine step_model(this, rc) class(MAPL_Cap), intent(inout) :: this @@ -374,7 +374,7 @@ 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 @@ -382,14 +382,14 @@ subroutine rewind_model(this, time, 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 @@ -397,7 +397,7 @@ integer function create_member_subcommunicator(this, comm, unusable, rc) result( !!$ 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 +408,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 +459,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 +488,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 From 525fdc75f52213450e42bf9da85cd68277699fdb Mon Sep 17 00:00:00 2001 From: Matthew Thompson Date: Wed, 1 Feb 2023 10:28:56 -0500 Subject: [PATCH 2/2] Remove comment --- gridcomps/Cap/MAPL_Cap.F90 | 1 - 1 file changed, 1 deletion(-) diff --git a/gridcomps/Cap/MAPL_Cap.F90 b/gridcomps/Cap/MAPL_Cap.F90 index 31da5adba1f..438107c6a54 100644 --- a/gridcomps/Cap/MAPL_Cap.F90 +++ b/gridcomps/Cap/MAPL_Cap.F90 @@ -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)