fix(profiling): profiling crashes for large number of solution and can't be turned off

doc/ReleaseNotes/develop.toml

@@ -117,3 +117,8 @@ description = "Numerical error in the iterative subcell exit solution can leave
 section = "fixes"
 subsection = "model"
 description = "The PRT PRP package previously failed to correctly load release settings configured by period block. This could prevent particles from being released as configured. It could also cause excess particles to be released, as empty period blocks intended to stop fill-forward at a certain period were not properly recognized. The package has been updated to correctly load period block release settings."
+
+[[items]]
+section = "fixes"
+subsection = "basic"
+description = "Fixes a bug where the internal profiler caused certain (multi-species) simulations to stop with an error."

src/Distributed/MpiRunControl.F90

@@ -9,7 +9,6 @@ module MpiRunControlModule
   use MpiWorldModule
   use SimVariablesModule, only: proc_id, nr_procs
   use SimStagesModule
-  use ProfilerModule
   use KindModule, only: I4B, LGP, DP
   use STLVecIntModule
   use NumericalSolutionModule
@@ -43,20 +42,13 @@ end function create_mpi_run_control
 
   subroutine mpi_ctrl_start(this)
     use ErrorUtilModule, only: pstop_alternative
-    ! local
-    integer(I4B) :: tmr_init_par
-
     class(MpiRunControlType) :: this
     ! local
     integer :: ierr
     character(len=*), parameter :: petsc_db_file = '.petscrc'
     logical(LGP) :: petsc_db_exists, wait_dbg, is_parallel_mode
     type(MpiWorldType), pointer :: mpi_world
 
-    ! add timed section for parallel initialization
-    tmr_init_par = -1
-    call g_prof%start("Initialize MPI and PETSc", tmr_init_par)
-
     ! set mpi abort function
     pstop_alternative => mpi_stop
 
@@ -108,9 +100,6 @@ subroutine mpi_ctrl_start(this)
     ! possibly wait to attach debugger here
     if (wait_dbg) call this%wait_for_debugger()
 
-    ! done with parallel pre-work
-    call g_prof%stop(tmr_init_par)
-
     ! start everything else by calling parent
     call this%RunControlType%start()
 
@@ -138,11 +127,6 @@ subroutine mpi_ctrl_finish(this)
     class(MpiRunControlType) :: this
     ! local
     integer :: ierr
-    integer(I4B) :: tmr_final_par
-
-    ! timer
-    tmr_final_par = -1
-    call g_prof%start("Finalize MPI and PETSc", tmr_final_par)
 
     ! release MPI related memory in router before MPI_Finalize
     call this%virtual_data_mgr%router%finalize()
@@ -160,8 +144,6 @@ subroutine mpi_ctrl_finish(this)
 
     pstop_alternative => null()
 
-    call g_prof%stop(tmr_final_par)
-
     ! finish everything else by calling parent
     call this%RunControlType%finish()
 

src/SimulationCreate.f90

@@ -98,13 +98,12 @@ subroutine options_create()
     use MemoryManagerModule, only: mem_setptr
     use SimVariablesModule, only: idm_context
     use MemoryManagerModule, only: mem_set_print_option
-    use ProfilerModule, only: g_prof
     use SimVariablesModule, only: isimcontinue, isimcheck
     ! -- dummy
     ! -- locals
     character(len=LENMEMPATH) :: input_mempath
     integer(I4B), pointer :: simcontinue, nocheck, maxerror
-    character(len=:), pointer :: prmem, prprof
+    character(len=:), pointer :: prmem
     character(len=LINELENGTH) :: errmsg
     !
     ! -- set input memory path
@@ -114,7 +113,6 @@ subroutine options_create()
     call mem_setptr(simcontinue, 'CONTINUE', input_mempath)
     call mem_setptr(nocheck, 'NOCHECK', input_mempath)
     call mem_setptr(prmem, 'PRMEM', input_mempath)
-    call mem_setptr(prprof, 'PRPROF', input_mempath)
     call mem_setptr(maxerror, 'MAXERRORS', input_mempath)
     !
     ! -- update sim options
@@ -135,9 +133,6 @@ subroutine options_create()
       end if
     end if
 
-    ! set profiler print option
-    call g_prof%set_print_option(prprof)
-
     !
     ! -- log values to list file
     if (iout > 0) then

src/Utilities/Performance/Profiler.f90

@@ -1,13 +1,17 @@
 module ProfilerModule
   use KindModule, only: I4B, DP, LGP
   use ConstantsModule, only: DNODATA, DZERO, LENMEMPATH, LINELENGTH
+  use SimVariablesModule, only: idm_context
+  use MemoryHelperModule, only: create_mem_path
+  use MemoryManagerModule, only: mem_setptr
   use STLStackIntModule
   use STLVecIntModule
+  use CharacterStringModule
   implicit none
   private
 
   ! constants for memory allocation
-  integer(I4B), parameter :: MAX_NR_TIMED_SECTIONS = 75
+  integer(I4B), parameter :: MAX_SECTIONS_PER_SLN = 40
   integer(I4B), public, parameter :: LEN_SECTION_TITLE = 128
 
   ! data structure to store measurements for a section
@@ -25,6 +29,7 @@ module ProfilerModule
   !! parts of the application. It provides mechanisms to start, stop, and
   !< report on the performance metrics collected during execution.
   type, public :: ProfilerType
+    real(DP) :: sim_start_time !< the simulation start time which lies before initialization of the profiler
     ! handles for the global simulation structure (with no simulation objects to store them)
     integer(I4B) :: tmr_run !< handle to timed section "Run"
     integer(I4B) :: tmr_init !< handle to timed section "Initialize"
@@ -45,15 +50,15 @@ module ProfilerModule
     type(MeasuredSectionType), dimension(:), pointer :: all_sections => null() !< all timed sections (up to MAX_NR_TIMED_SECTIONS)
     type(STLStackInt) :: callstack !< call stack of section ids
   contains
+    procedure :: pre_init
     procedure :: initialize
-    procedure :: add_section
     procedure :: start
     procedure :: stop
     procedure :: print
     procedure :: destroy
-    procedure :: is_initialized
-    procedure :: set_print_option
     ! private
+    procedure, private :: set_print_option
+    procedure, private :: add_section
     procedure, private :: print_section
     procedure, private :: print_total
     procedure, private :: aggregate_walltime
@@ -66,12 +71,26 @@ module ProfilerModule
 
 contains
 
+  !< @brief To save the start time before initialization
+  subroutine pre_init(this)
+    class(ProfilerType) :: this
+
+    call cpu_time(this%sim_start_time)
+
+  end subroutine pre_init
+
   !< @brief Initialize the CPU timer object
   !<
   subroutine initialize(this)
     class(ProfilerType) :: this
     ! local
+    character(len=LENMEMPATH) :: input_mempath
+    type(CharacterStringType), dimension(:), contiguous, &
+      pointer :: slntype
+    character(len=:), pointer :: prprof
     integer(I4B) :: i
+    integer(I4B) :: max_sections
+    integer(I4B) :: nr_solutions
 
     this%tmr_run = -1
     this%tmr_init = -1
@@ -85,8 +104,16 @@ subroutine initialize(this)
 
     call this%callstack%init()
 
-    allocate (this%all_sections(MAX_NR_TIMED_SECTIONS))
-    do i = 1, MAX_NR_TIMED_SECTIONS
+    ! get nr of solutions from input context
+    input_mempath = create_mem_path('SIM', 'NAM', idm_context)
+    call mem_setptr(slntype, 'SLNTYPE', input_mempath)
+    nr_solutions = size(slntype)
+    call mem_setptr(prprof, 'PRPROF', input_mempath)
+    call this%set_print_option(prprof)
+
+    max_sections = MAX_SECTIONS_PER_SLN * nr_solutions
+    allocate (this%all_sections(max_sections))
+    do i = 1, max_sections
       this%all_sections(i)%title = "undefined"
       this%all_sections(i)%status = 0
       this%all_sections(i)%walltime = DZERO
@@ -99,6 +126,12 @@ subroutine initialize(this)
     this%root_id = 0
     this%top_three = [0, 0, 0]
 
+    ! start root section here with previously recorded start time
+    if (this%pr_option > 0) then
+      call this%start("Run", this%tmr_run)
+      this%all_sections(this%tmr_run)%walltime = -this%sim_start_time
+    end if
+
   end subroutine initialize
 
   !> @brief Add a new timed section to the tree,
@@ -116,7 +149,7 @@ function add_section(this, title, parent_id) result(section_id)
     section_id = this%nr_sections
     if (section_id > size(this%all_sections)) then
       write (*, *) "Internal error: Too many profiled sections, "&
-        &"increase MAX_NR_TIMED_SECTIONS"
+        &"disable profiling to circumvent."
       call ustop()
     end if
 
@@ -149,6 +182,8 @@ subroutine start(this, title, section_id)
     real(DP) :: start_time
     type(MeasuredSectionType), pointer :: section
 
+    if (this%pr_option == 0) return
+
     call cpu_time(start_time)
 
     if (section_id == -1) then
@@ -164,7 +199,7 @@ subroutine start(this, title, section_id)
     section => this%all_sections(section_id)
     section%count = section%count + 1
     section%status = 1
-    section%walltime = section%walltime - start_time
+    section%walltime = -start_time
 
   end subroutine start
 
@@ -175,6 +210,8 @@ subroutine stop(this, section_id)
     real(DP) :: end_time
     type(MeasuredSectionType), pointer :: section
 
+    if (this%pr_option == 0) return
+
     call cpu_time(end_time)
 
     ! nett result (c.f. start(...)) is adding (dt = end_time - start_time)
@@ -194,9 +231,10 @@ subroutine print(this, output_unit)
     integer(I4B) :: level, i, top_idx
     integer(I4B), dimension(:), allocatable :: sorted_idxs
 
-    this%iout = output_unit
     if (this%pr_option == 0) return
 
+    this%iout = output_unit
+
     ! get top three leaf sections based on walltime
     top_idx = 1
     sorted_idxs = (/(i, i=1, this%nr_sections)/)
@@ -369,22 +407,14 @@ subroutine destroy(this)
 
     call this%callstack%destroy()
 
-    do i = 1, MAX_NR_TIMED_SECTIONS
+    do i = 1, size(this%all_sections)
       call this%all_sections(i)%children%destroy()
     end do
     deallocate (this%all_sections)
     nullify (this%all_sections)
 
   end subroutine destroy
 
-  function is_initialized(this) result(initialized)
-    class(ProfilerType) :: this
-    logical(LGP) :: initialized
-
-    initialized = associated(this%all_sections)
-
-  end function is_initialized
-
   !> @brief Calculate the largest title length
   !<
   function largest_title_length(this) result(max_length)

src/mf6core.f90

@@ -73,10 +73,7 @@ subroutine Mf6Initialize()
     use SimulationCreateModule, only: simulation_cr
     use SourceLoadModule, only: export_cr
 
-    ! init timer and start
-    call g_prof%initialize()
-    call g_prof%start("Run", g_prof%tmr_run)
-    call g_prof%start("Initialize", g_prof%tmr_init)
+    call g_prof%pre_init()
 
     ! -- get the run controller for sequential or parallel builds
     run_ctrl => create_run_control()
@@ -91,6 +88,10 @@ subroutine Mf6Initialize()
     ! -- load input context
     call static_input_load()
 
+    ! init timer and start
+    call g_prof%initialize()
+    call g_prof%start("Initialize", g_prof%tmr_init)
+
     ! -- create
     call simulation_cr()