From c3c90bea0dd06041a3b766f71cf6d0fb4990075f Mon Sep 17 00:00:00 2001 From: mjr-deltares Date: Thu, 23 Jan 2025 19:40:02 +0100 Subject: [PATCH] - add timed sections on the go - print aggregates --- src/Distributed/MpiRouter.f90 | 18 ++- src/Distributed/MpiRunControl.F90 | 12 +- src/Distributed/RouterBase.f90 | 1 + src/Distributed/RouterFactory.F90 | 6 +- src/Distributed/VirtualDataManager.f90 | 2 +- src/RunControl.f90 | 5 +- src/Solution/NumericalSolution.f90 | 27 ++--- src/Utilities/STLVecInt.f90 | 13 +++ src/Utilities/Timer/CpuTimer.f90 | 156 +++++++++++++++++-------- src/mf6core.f90 | 19 ++- 10 files changed, 178 insertions(+), 81 deletions(-) diff --git a/src/Distributed/MpiRouter.f90 b/src/Distributed/MpiRouter.f90 index aa581dba662..cec227e558d 100644 --- a/src/Distributed/MpiRouter.f90 +++ b/src/Distributed/MpiRouter.f90 @@ -4,7 +4,7 @@ module MpiRouterModule use CpuTimerModule, only: g_timer use STLVecIntModule use SimVariablesModule, only: proc_id, nr_procs - use SimStagesModule, only: STG_TO_STR + use SimStagesModule, only: STG_TO_STR, NR_SIM_STAGES use VirtualDataListsModule, only: virtual_model_list, & virtual_exchange_list use VirtualBaseModule, only: NR_VDC_ELEMENT_MAPS @@ -33,6 +33,7 @@ module MpiRouterModule type(MpiWorldType), pointer :: mpi_world => null() integer(I4B) :: imon !< the output file unit for the mpi monitor logical(LGP) :: enable_monitor !< when true, log diagnostics + integer(I4B), dimension(:,:), allocatable :: tmr_mpi_wait !< array with timer handles for MPI_Wait calls contains procedure :: initialize => mr_initialize procedure :: route_all => mr_route_all @@ -74,6 +75,10 @@ subroutine mr_initialize(this) class(VirtualDataContainerType), pointer :: vdc character(len=LINELENGTH) :: monitor_file + ! allocate timer handles: global + nr. solutions + allocate (this%tmr_mpi_wait(NR_SIM_STAGES, this%nr_virt_solutions + 1)) + this%tmr_mpi_wait = -1 + ! routing over all when starting this%halo_activated = .false. @@ -323,7 +328,10 @@ subroutine route_active(this, unit, stage) end do ! wait for exchange of all messages + call g_timer%start("MPI_WaitAll ("//trim(STG_TO_STR(stage))//")", & + this%tmr_mpi_wait(stage, unit + 1)) call MPI_WaitAll(this%senders%size, rcv_req, rcv_stat, ierr) + call g_timer%stop(this%tmr_mpi_wait(stage, unit + 1)) call CHECK_MPI(ierr) deallocate (rcv_req, snd_req, rcv_stat) @@ -439,7 +447,10 @@ subroutine compose_messages(this, unit, stage, body_snd_t, body_rcv_t) end do ! wait for exchange of all headers + call g_timer%start("MPI_WaitAll ("//trim(STG_TO_STR(stage))//")", & + this%tmr_mpi_wait(stage, unit + 1)) call MPI_WaitAll(this%receivers%size, rcv_req, rcv_stat, ierr) + call g_timer%stop(this%tmr_mpi_wait(stage, unit + 1)) call CHECK_MPI(ierr) ! reinit handles @@ -509,7 +520,10 @@ subroutine compose_messages(this, unit, stage, body_snd_t, body_rcv_t) end do ! wait on receiving maps + call g_timer%start("MPI_WaitAll ("//trim(STG_TO_STR(stage))//")", & + this%tmr_mpi_wait(stage, unit + 1)) call MPI_WaitAll(this%receivers%size, rcv_req, rcv_stat, ierr) + call g_timer%stop(this%tmr_mpi_wait(stage, unit + 1)) call CHECK_MPI(ierr) ! print maps @@ -713,6 +727,8 @@ subroutine mr_destroy(this) deallocate (this%all_models) deallocate (this%all_exchanges) + deallocate (this%tmr_mpi_wait) + end subroutine mr_destroy end module MpiRouterModule diff --git a/src/Distributed/MpiRunControl.F90 b/src/Distributed/MpiRunControl.F90 index 254b67b7e1b..2c3a6613e7d 100644 --- a/src/Distributed/MpiRunControl.F90 +++ b/src/Distributed/MpiRunControl.F90 @@ -58,10 +58,10 @@ subroutine mpi_ctrl_start(this) tmr_func => mpi_walltime call set_timer_func(tmr_func) call g_timer%initialize() - tmr_init_par = g_timer%add_section("Init parallel", SECTION_INIT) - call g_timer%start(SECTION_RUN) - call g_timer%start(SECTION_INIT) - call g_timer%start(tmr_init_par) + call g_timer%start("Run", SECTION_RUN) + call g_timer%start("Initialize", SECTION_INIT) + tmr_init_par = -1 + call g_timer%start("Initialize parallel", tmr_init_par) ! set mpi abort function pstop_alternative => mpi_stop @@ -147,8 +147,8 @@ subroutine mpi_ctrl_finish(this) integer(I4B) :: tmr_final_par ! timer - tmr_final_par = g_timer%add_section("Finalize parallel", SECTION_FINALIZE) - call g_timer%start(tmr_final_par) + tmr_final_par = -1 + call g_timer%start("Finalize parallel", tmr_final_par) ! finish mpi #if defined(__WITH_PETSC__) diff --git a/src/Distributed/RouterBase.f90 b/src/Distributed/RouterBase.f90 index e08db1c0be4..4bbeaa1d154 100644 --- a/src/Distributed/RouterBase.f90 +++ b/src/Distributed/RouterBase.f90 @@ -6,6 +6,7 @@ module RouterBaseModule type, abstract, public :: RouterBaseType logical(LGP) :: halo_activated !< when true, the halo has been activated + integer(I4B) :: nr_virt_solutions !< number of virtual solution to be routed !< (allowing more efficient routing of virtual data) contains procedure(initialize_if), deferred :: initialize diff --git a/src/Distributed/RouterFactory.F90 b/src/Distributed/RouterFactory.F90 index b8c1218bed3..49ce6a4f0ba 100644 --- a/src/Distributed/RouterFactory.F90 +++ b/src/Distributed/RouterFactory.F90 @@ -1,4 +1,5 @@ module RouterFactoryModule + use KindModule, only: I4B use RouterBaseModule use SerialRouterModule, only: create_serial_router #if defined(__WITH_MPI__) @@ -15,15 +16,18 @@ module RouterFactoryModule !! simulation mode (parallel or sequential) and type !! of build (with or without mpi) !< - function create_router(sim_mode) result(router) + function create_router(sim_mode, nr_sols) result(router) character(len=*) :: sim_mode !< simulation mode: SEQUENTIAL or PARALLEL + integer(I4B) :: nr_sols !< nr. of solutions class(RouterBaseType), pointer :: router !< the router object if (sim_mode == 'SEQUENTIAL') then router => create_serial_router() + router%nr_virt_solutions = nr_sols #if defined(__WITH_MPI__) else if (sim_mode == 'PARALLEL') then router => create_mpi_router() + router%nr_virt_solutions = nr_sols #endif else router => null() diff --git a/src/Distributed/VirtualDataManager.f90 b/src/Distributed/VirtualDataManager.f90 index e92b8883d99..5c5a62975ca 100644 --- a/src/Distributed/VirtualDataManager.f90 +++ b/src/Distributed/VirtualDataManager.f90 @@ -66,7 +66,7 @@ subroutine vds_create(this, sim_mode) this%nr_solutions = 0 ! create a router, sequential or parallel - this%router => create_router(sim_mode) + this%router => create_router(sim_mode, nr_sol) end subroutine vds_create diff --git a/src/RunControl.f90 b/src/RunControl.f90 index 76303f253a5..5232a783111 100644 --- a/src/RunControl.f90 +++ b/src/RunControl.f90 @@ -20,6 +20,7 @@ module RunControlModule procedure :: at_stage => ctrl_at_stage procedure :: finish => ctrl_finish procedure :: after_con_cr => ctrl_after_con_cr + ! private procedure, private :: init_handler procedure, private :: before_con_df @@ -42,8 +43,8 @@ subroutine ctrl_start(this) ! initialize and start timers, if not done so in the derived class if (.not. g_timer%is_initialized()) then call g_timer%initialize() - call g_timer%start(SECTION_RUN) - call g_timer%start(SECTION_INIT) + call g_timer%start("Run", SECTION_RUN) + call g_timer%start("Initialize", SECTION_INIT) end if allocate (this%virtual_data_mgr) diff --git a/src/Solution/NumericalSolution.f90 b/src/Solution/NumericalSolution.f90 index 8997fadb925..75888ab50b5 100644 --- a/src/Solution/NumericalSolution.f90 +++ b/src/Solution/NumericalSolution.f90 @@ -135,6 +135,7 @@ module NumericalSolutionModule integer(I4B) :: tmr_final_solve !< timer - finalize solve integer(I4B) :: tmr_formulate !< timer - formulate integer(I4B) :: tmr_linsolve !< timer - linear solve + character(len=24) :: id_postfix !< solution id based postfix for timer titles ! ! -- adaptive time step real(DP), pointer :: atsfrac => null() !< adaptive time step faction @@ -434,7 +435,6 @@ subroutine sln_df(this) integer(I4B), allocatable, dimension(:) :: rowmaxnnz integer(I4B) :: ncol, irow_start, irow_end integer(I4B) :: mod_offset - character(len=LEN_SECTION_TITLE) :: sec_title ! ! -- set sol id and determine nr. of equation in this solution do i = 1, this%modellist%Count() @@ -504,15 +504,12 @@ subroutine sln_df(this) call this%sln_connect() ! add timers - write(sec_title,'(a,i0,a)') "Prepare solve (", this%id, ")" - this%tmr_prep_solve = g_timer%add_section(sec_title, SECTION_DO_TSTP) - write(sec_title,'(a,i0,a)') "Solve (", this%id, ")" - this%tmr_solve = g_timer%add_section(sec_title, SECTION_DO_TSTP) - write(sec_title,'(a,i0,a)') "Finalize solve (", this%id, ")" - this%tmr_final_solve = g_timer%add_section(sec_title, SECTION_DO_TSTP) - - this%tmr_formulate = g_timer%add_section("Formulate", this%tmr_solve) - this%tmr_linsolve = g_timer%add_section("Linear solve", this%tmr_solve) + write(this%id_postfix,'(a,i0,a)') " (", this%id, ")" + this%tmr_prep_solve = -1 + this%tmr_solve = -1 + this%tmr_final_solve = -1 + this%tmr_formulate = -1 + this%tmr_linsolve = -1 end subroutine sln_df @@ -1443,7 +1440,7 @@ subroutine prepareSolve(this) class(NumericalModelType), pointer :: mp => null() ! start timer - call g_timer%start(this%tmr_prep_solve) + call g_timer%start("Prepare solve"//this%id_postfix, this%tmr_prep_solve) ! synchronize for AD call this%synchronize(STG_BFR_EXG_AD, this%synchronize_ctx) @@ -1522,7 +1519,7 @@ subroutine solve(this, kiter) real(DP) :: outer_hncg ! start timer - call g_timer%start(this%tmr_solve) + call g_timer%start("Solve"//this%id_postfix, this%tmr_solve) ! ! -- initialize local variables @@ -1577,7 +1574,7 @@ subroutine solve(this, kiter) end if ! call code_timer(0, ttform, this%ttform) - call g_timer%start(this%tmr_formulate) + call g_timer%start("Formulate", this%tmr_formulate) ! ! -- (re)build the solution matrix call this%sln_buildsystem(kiter, inewton=1) @@ -1595,7 +1592,7 @@ subroutine solve(this, kiter) ! ! -- linear solve call code_timer(0, ttsoln, this%ttsoln) - call g_timer%start(this%tmr_linsolve) + call g_timer%start("Linear solve", this%tmr_linsolve) call this%sln_ls(kiter, kstp, kper, iter, iptc, ptcf) call g_timer%stop(this%tmr_linsolve) call code_timer(1, ttsoln, this%ttsoln) @@ -1861,7 +1858,7 @@ subroutine finalizeSolve(this, kiter, isgcnvg, isuppress_output) &' STRESS PERIOD ',I0,/1X,I0,' TOTAL ITERATIONS')" ! start timer - call g_timer%start(this%tmr_final_solve) + call g_timer%start("Finalize solve"//this%id_postfix, this%tmr_final_solve) ! ! -- finalize the outer iteration table diff --git a/src/Utilities/STLVecInt.f90 b/src/Utilities/STLVecInt.f90 index 7431da49026..5bc7e62c65e 100644 --- a/src/Utilities/STLVecInt.f90 +++ b/src/Utilities/STLVecInt.f90 @@ -17,6 +17,7 @@ module STLVecIntModule procedure, pass(this) :: init !< allocate memory, init size and capacity procedure, pass(this) :: push_back !< adds an element at the end of the vector procedure, pass(this) :: push_back_unique !< adds an element at the end of the vector, if not present yet + procedure, pass(this) :: pop !< removes the last element procedure, pass(this) :: add_array !< adds elements of array at the end of the vector procedure, pass(this) :: add_array_unique !< adds elements of array at the end of the vector, if not present yet procedure, pass(this) :: at !< random access, unsafe, no bounds checking @@ -72,6 +73,18 @@ subroutine push_back_unique(this, newValue) end subroutine push_back_unique + subroutine pop(this) + class(STLVecInt), intent(inout) :: this + + if (this%size > 0) then + this%size = this%size - 1 + else + write (*, *) 'STLVecInt exception: cannot pop from an empty array' + call ustop() + end if + + end subroutine + subroutine add_array(this, array) class(STLVecInt), intent(inout) :: this integer(I4B), dimension(:), pointer :: array diff --git a/src/Utilities/Timer/CpuTimer.f90 b/src/Utilities/Timer/CpuTimer.f90 index c721104a904..05b4407b76f 100644 --- a/src/Utilities/Timer/CpuTimer.f90 +++ b/src/Utilities/Timer/CpuTimer.f90 @@ -5,24 +5,25 @@ module CpuTimerModule implicit none private - ! predefined sections as integers - ! root: - integer(I4B), public :: SECTION_RUN + ! predefined skeleton of section ids + ! level 0 (root): + integer(I4B), public :: SECTION_RUN = -1 ! level 1 (BMI): - integer(I4B), public :: SECTION_INIT - integer(I4B), public :: SECTION_UPDATE - integer(I4B), public :: SECTION_FINALIZE + integer(I4B), public :: SECTION_INIT = -1 + integer(I4B), public :: SECTION_UPDATE = -1 + integer(I4B), public :: SECTION_FINALIZE = -1 ! level 2 (XMI): - integer(I4B), public :: SECTION_PREP_TSTP - integer(I4B), public :: SECTION_DO_TSTP - integer(I4B), public :: SECTION_FINAL_TSTP + integer(I4B), public :: SECTION_PREP_TSTP = -1 + integer(I4B), public :: SECTION_DO_TSTP = -1 + integer(I4B), public :: SECTION_FINAL_TSTP = -1 ! constants for memory allocation - integer(I4B), parameter :: MAX_NR_TIMED_SECTIONS = 20 + integer(I4B), parameter :: MAX_NR_TIMED_SECTIONS = 50 integer(I4B), public, parameter :: LEN_SECTION_TITLE = 128 + ! data structure to store measurements for a section type, private :: TimedSectionType character(len=LEN_SECTION_TITLE) :: title !< title to identify timed section in log real(DP) :: walltime !< walltime spent in section @@ -32,11 +33,13 @@ module CpuTimerModule type(STLVecInt) :: children !< ids of children end type TimedSectionType + ! this is the timer object type, public :: CpuTimerType private integer(I4B) :: nr_sections - integer(I4B) :: root_id - type(TimedSectionType), dimension(:), pointer :: all_sections => null() + integer(I4B) :: root_id !< + type(TimedSectionType), dimension(:), pointer :: all_sections => null() !< all timed sections, dynamic up to MAX_NR_TIMED_SECTIONS + type(STLVecInt) :: callstack !< call stack of section ids contains procedure :: initialize procedure :: add_section @@ -46,8 +49,10 @@ module CpuTimerModule procedure :: destroy procedure :: is_initialized ! private - procedure, private :: get_section_id procedure, private :: print_section + procedure, private :: print_total + procedure, private :: aggregate_walltime + procedure, private :: aggregate_counts end type CpuTimerType type(CpuTimerType), public :: g_timer !< the global timer object (to reduce trivial lines of code) @@ -80,6 +85,8 @@ subroutine initialize(this) ! local integer(I4B) :: i + call this%callstack%init() + allocate(this%all_sections(MAX_NR_TIMED_SECTIONS)) do i = 1, MAX_NR_TIMED_SECTIONS this%all_sections(i)%title = "undefined" @@ -93,16 +100,6 @@ subroutine initialize(this) this%nr_sections = 0 this%root_id = 0 - SECTION_RUN = g_timer%add_section("Run") - - SECTION_INIT = g_timer%add_section("Init", SECTION_RUN) - SECTION_UPDATE = g_timer%add_section("Update", SECTION_RUN) - SECTION_FINALIZE = g_timer%add_section("Finalize", SECTION_RUN) - - SECTION_PREP_TSTP = g_timer%add_section("Prepare timestep", SECTION_UPDATE) - SECTION_DO_TSTP = g_timer%add_section("Do timestep", SECTION_UPDATE) - SECTION_FINAL_TSTP = g_timer%add_section("Finalize timestep", SECTION_UPDATE) - end subroutine initialize !> @brief Add a new timed section to the tree, @@ -111,7 +108,7 @@ end subroutine initialize function add_section(this, title, parent_id) result(section_id) class(CpuTimerType) :: this character(len=*) :: title - integer(I4B), optional :: parent_id + integer(I4B) :: parent_id integer(I4B) :: section_id ! increment to new section id @@ -124,7 +121,7 @@ function add_section(this, title, parent_id) result(section_id) this%all_sections(section_id)%status = 0 ! if parent, otherwise root section - if (present(parent_id)) then + if (parent_id > 0) then ! add child to parent this%all_sections(section_id)%parent_id = parent_id call this%all_sections(parent_id)%children%push_back(section_id) @@ -136,35 +133,28 @@ function add_section(this, title, parent_id) result(section_id) end function add_section - !> @brief Return section id for title, 0 when not found - !! @note Currently not used, but could be useful later on, else remove + !> @brief Start section timing, add when not exist yet (i.e. when id < 1) !< - function get_section_id(this, title) result(section_id) + subroutine start(this, title, section_id) class(CpuTimerType) :: this character(len=*) :: title - integer(I4B) :: section_id - ! local - integer(I4B) :: i - - section_id = 0 - do i = 1, this%nr_sections - if (this%all_sections(i)%title == title) then - section_id = i - exit - end if - end do - - end function get_section_id - - subroutine start(this, section_id) - class(CpuTimerType) :: this - integer(I4B) :: section_id + integer(I4B) :: section_id, parent_id ! local real(DP) :: start_time type(TimedSectionType), pointer :: section call cpu_time(start_time) + if (section_id < 1) then + ! add section if not exist + parent_id = 0 ! root + if (this%callstack%size > 0) then + parent_id = this%callstack%at(this%callstack%size) + end if + section_id = this%add_section(title, parent_id) + end if + call this%callstack%push_back(section_id) + section => this%all_sections(section_id) section%count = section%count + 1 section%status = 1 @@ -186,6 +176,9 @@ subroutine stop(this, section_id) section%status = 0 section%walltime = section%walltime + end_time + ! pop from call stack + call this%callstack%pop() + end subroutine stop subroutine print_timings(this) @@ -195,10 +188,15 @@ subroutine print_timings(this) ! print timing call stack level = 0 + write(*,'(a/)') "-------------------- Timing: Call Stack --------------------" call this%print_section(this%root_id, level) - ! print walltime per category - + ! print walltime per category from substring (if exist) + write(*,'(a/)') "-------------------- Timing: Cumulative --------------------" + call this%print_total("Formulate") + call this%print_total("Linear solve") + call this%print_total("MPI_WaitAll") + write(*,'(/a/)') "------------------------------------------------------------" end subroutine print_timings @@ -214,10 +212,11 @@ recursive subroutine print_section(this, section_id, level) section => this%all_sections(section_id) ! calculate percentage - percent = 100.0_DP + percent = 1.0_DP if (section%parent_id /= 0) then - percent = section%walltime / this%all_sections(this%root_id)%walltime * 100.0_DP + percent = section%walltime / this%all_sections(this%root_id)%walltime end if + percent = percent * 100.0_DP ! print section timing write(*,'(3a,f0.2,3a,f14.6,2a,i0,a)') & @@ -235,11 +234,70 @@ recursive subroutine print_section(this, section_id, level) end subroutine print_section + subroutine print_total(this, subtitle) + class(CpuTimerType) :: this + character(len=*) :: subtitle + ! local + integer(I4B) :: count + real(DP) :: walltime, percent + + count = this%aggregate_counts(subtitle) + if (count > 0) then + walltime = aggregate_walltime(this, subtitle) + percent = (walltime / this%all_sections(this%root_id)%walltime) * 100.0_DP + write(*,'(2a,f0.2,3a,f14.6,2a,i0,a)') & + " ", "[", percent, "%] ", & + trim(subtitle), ": ", walltime, "s", " (", & + count, "x)" + end if + + end subroutine print_total + + !> @brief Aggregate walltime over sections with a certain title + !< + function aggregate_walltime(this, title) result(walltime) + class(CpuTimerType) :: this + character(len=*) :: title + real(DP) :: walltime + ! local + integer(I4B) :: i + + walltime = DZERO + do i = 1, this%nr_sections + if (index(this%all_sections(i)%title, trim(title)) > 0) then + walltime = walltime + this%all_sections(i)%walltime + end if + end do + + end function aggregate_walltime + + !> @brief Aggregate counts over sections with a certain title + !< + function aggregate_counts(this, title) result(counts) + class(CpuTimerType) :: this + character(len=*) :: title + integer(I4B) :: counts + ! local + integer(I4B) :: i + + counts = 0 + do i = 1, this%nr_sections + if (index(this%all_sections(i)%title, trim(title)) > 0) then + counts = counts + this%all_sections(i)%count + end if + end do + + end function aggregate_counts + + !> @brief Clean up the CPU timer object + !< subroutine destroy(this) class(CpuTimerType) :: this ! local integer(I4B) :: i + call this%callstack%destroy() + do i = 1, this%nr_sections call this%all_sections(i)%children%destroy() end do diff --git a/src/mf6core.f90 b/src/mf6core.f90 index 0e05bf6ae37..f501b2b94b1 100644 --- a/src/mf6core.f90 +++ b/src/mf6core.f90 @@ -113,7 +113,7 @@ end subroutine Mf6Initialize function Mf6Update() result(hasConverged) logical(LGP) :: hasConverged ! start timer - call g_timer%start(SECTION_UPDATE) + call g_timer%start("Update", SECTION_UPDATE) ! ! -- prepare timestep call Mf6PrepareTimestep() @@ -155,9 +155,10 @@ subroutine Mf6Finalize() class(BaseModelType), pointer :: mp => null() class(BaseExchangeType), pointer :: ep => null() class(SpatialModelConnectionType), pointer :: mc => null() + integer(I4B) :: tmr_dealloc ! start timer - call g_timer%start(SECTION_FINALIZE) + call g_timer%start("Finalize", SECTION_FINALIZE) ! ! -- FINAL PROCESSING (FP) @@ -178,6 +179,11 @@ subroutine Mf6Finalize() sp => GetBaseSolutionFromList(basesolutionlist, is) call sp%sln_fp() end do + + ! start timer for deallocation + tmr_dealloc = -1 + call g_timer%start("Deallocate", tmr_dealloc) + ! ! -- DEALLOCATE (DA) ! -- Deallocate tdis @@ -223,7 +229,8 @@ subroutine Mf6Finalize() call simulation_da() call lists_da() - ! stop timer + ! stop timers + call g_timer%stop(tmr_dealloc) call g_timer%stop(SECTION_FINALIZE) ! finish gently (No calls after this) @@ -510,7 +517,7 @@ subroutine Mf6PrepareTimestep() integer(I4B) :: is ! start timer - call g_timer%start(SECTION_PREP_TSTP) + call g_timer%start("Initialize time step", SECTION_PREP_TSTP) ! ! -- initialize fmt @@ -618,7 +625,7 @@ subroutine Mf6DoTimestep() logical :: finishedTrying ! start timer - call g_timer%start(SECTION_DO_TSTP) + call g_timer%start("Do time step", SECTION_DO_TSTP) ! -- By default, the solution groups will be solved once, and ! may fail. But if adaptive stepping is active, then @@ -723,7 +730,7 @@ function Mf6FinalizeTimestep() result(hasConverged) line = 'end timestep' ! start timer - call g_timer%start(SECTION_FINAL_TSTP) + call g_timer%start("Finalize time step", SECTION_FINAL_TSTP) ! ! -- evaluate simulation mode