profilermodule Module Reference

Data Types
type	measuredsectiontype
type	profilertype
	A public type for profiling performance in the application. The ProfilerType is used to measure and record the performance of various parts of the application. It provides mechanisms to start, stop, and. More...

Functions/Subroutines
subroutine	pre_init (this)
subroutine	initialize (this)
integer(i4b) function	add_section (this, title, parent_id)
	Add a new timed section to the tree, passing the parent id will add it as a child. More...
subroutine	start (this, title, section_id)
	Start section timing, add when not exist yet (i.e. when id < 1) More...
subroutine	stop (this, section_id)
subroutine	print (this, output_unit)
recursive subroutine	print_section (this, section_id, level)
subroutine	print_total (this, subtitle)
real(dp) function	aggregate_walltime (this, title)
	Aggregate walltime over sections with a certain title. More...
integer(i4b) function	aggregate_counts (this, title)
	Aggregate counts over sections with a certain title. More...
subroutine	set_print_option (this, profile_option)
	Set the profile option from the user input. More...
subroutine	destroy (this)
	Clean up the CPU timer object. More...
integer(i4b) function	largest_title_length (this)
	Calculate the largest title length. More...
subroutine	sort_by_walltime (this, idxs)
	Sort section indexes based on walltime. More...

Variables
integer(i4b), parameter	max_sections_per_sln = 40
integer(i4b), parameter, public	len_section_title = 128
type(profilertype), public	g_prof
	the global timer object (to reduce trivial lines of code) More...

Function/Subroutine Documentation

add_section()

integer(i4b) function profilermodule::add_section ( class(profilertype)  this, character(len=*)  title, integer(i4b)  parent_id  )

private

Definition at line 140 of file Profiler.f90.

    use simmodule, only: ustop
    class(ProfilerType) :: this
    character(len=*) :: title
    integer(I4B) :: parent_id
    integer(I4B) :: section_id
 
    ! increment to new section id
    this%nr_sections = this%nr_sections + 1
    section_id = this%nr_sections
    if (section_id > size(this%all_sections)) then
      write (*, *) "Internal error: Too many profiled sections, "&
        &"disable profiling to circumvent."
      call ustop()
    end if
 
    ! initialize new section
    this%all_sections(section_id)%title = title
    this%all_sections(section_id)%walltime = dzero
    this%all_sections(section_id)%status = 0
 
    ! if parent, otherwise root section
    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)
    else
      ! this is the root, assume there's only one!
      this%all_sections(section_id)%parent_id = 0
      this%root_id = section_id
    end if
 

Here is the call graph for this function:

aggregate_counts()

integer(i4b) function profilermodule::aggregate_counts ( class(profilertype)  this, character(len=*)  title  )

private

Definition at line 366 of file Profiler.f90.

    class(ProfilerType) :: 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
 

aggregate_walltime()

real(dp) function profilermodule::aggregate_walltime ( class(profilertype)  this, character(len=*)  title  )

private

Definition at line 348 of file Profiler.f90.

    class(ProfilerType) :: 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
 

Here is the caller graph for this function:

destroy()

subroutine profilermodule::destroy ( class(profilertype)  this )

private

Definition at line 403 of file Profiler.f90.

    class(ProfilerType) :: this
    ! local
    integer(I4B) :: i
 
    call this%callstack%destroy()
 
    do i = 1, size(this%all_sections)
      call this%all_sections(i)%children%destroy()
    end do
    deallocate (this%all_sections)
    nullify (this%all_sections)
 

initialize()

subroutine profilermodule::initialize ( class(profilertype)  this )

private

Definition at line 84 of file Profiler.f90.

    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
    this%tmr_update = -1
    this%tmr_finalize = -1
    this%tmr_prep_tstp = -1
    this%tmr_do_tstp = -1
    this%tmr_final_tstp = -1
    this%tmr_output = -1
    this%tmr_nc_export = -1
 
    call this%callstack%init()
 
    ! 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
      this%all_sections(i)%count = 0
      this%all_sections(i)%parent_id = 0
      call this%all_sections(i)%children%init()
    end do
 
    this%nr_sections = 0
    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
 

Here is the call graph for this function:

largest_title_length()

integer(i4b) function profilermodule::largest_title_length ( class(profilertype)  this )

private

Definition at line 420 of file Profiler.f90.

    class(ProfilerType) :: this
    integer(I4B) :: max_length
    integer(I4B) :: i
 
    max_length = 0
    do i = 1, this%nr_sections
      max_length = max(max_length, len_trim(this%all_sections(i)%title))
    end do
 

pre_init()

subroutine profilermodule::pre_init ( class(profilertype)  this )

private

Definition at line 75 of file Profiler.f90.

    class(ProfilerType) :: this
 
    call cpu_time(this%sim_start_time)
 

print()

subroutine profilermodule::print ( class(profilertype)  this, integer(i4b), intent(in)  output_unit  )

private

Definition at line 227 of file Profiler.f90.

    class(ProfilerType) :: this
    integer(I4B), intent(in) :: output_unit
    ! local
    integer(I4B) :: level, i, top_idx
    integer(I4B), dimension(:), allocatable :: sorted_idxs
 
    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)/)
    call this%sort_by_walltime(sorted_idxs)
    do i = 1, this%nr_sections
      if (this%all_sections(sorted_idxs(i))%children%size == 0) then ! leaf node
        if (top_idx > 3) exit
        this%top_three(top_idx) = sorted_idxs(i)
        top_idx = top_idx + 1
      end if
    end do
 
    this%max_title_len = this%largest_title_length()
 
    if (this%pr_option > 1) then
      ! print timing call stack
      level = 0
      write (this%iout, '(/1x,a/)') &
        repeat('-', 18)//" Profiler: Call Stack "//repeat('-', 18)
      call this%print_section(this%root_id, level)
    end if
 
    ! print walltime per category from substring (if exist)
    ! note: the sections containing the substring should not be nested,
    !       otherwise the walltime will be counted multiple times
    write (this%iout, '(1x,a/)') &
      repeat('-', 20)//" Profiler: Totals "//repeat('-', 20)
    call this%print_total("Formulate")
    call this%print_total("Linear solve")
    call this%print_total("Calculate flows")
    call this%print_total("Calculate budgets")
    call this%print_total("Write output")
    call this%print_total("Parallel Solution")
    call this%print_total("MPI_WaitAll")
    write (this%iout, '(/1x,a/)') &
      repeat('-', 22)//" End Profiler "//repeat('-', 22)
 

Here is the caller graph for this function:

print_section()

recursive subroutine profilermodule::print_section ( class(profilertype)  this, integer(i4b)  section_id, integer(i4b)  level  )

private

Definition at line 277 of file Profiler.f90.

    use arrayhandlersmodule, only: ifind
    class(ProfilerType) :: this
    integer(I4B) :: section_id
    integer(I4B) :: level
    ! local
    integer(I4B) :: i, new_level, nr_padding, idx_top
    real(DP) :: percent
    type(MeasuredSectionType), pointer :: section
    character(len=:), allocatable :: title_padded
    character(len=LINELENGTH) :: top_marker
 
    section => this%all_sections(section_id)
 
    ! calculate percentage
    percent = 1.0_dp
    if (section%parent_id /= 0) then
      percent = section%walltime / this%all_sections(this%root_id)%walltime
    end if
    percent = percent * 100.0_dp
 
    ! determine if section should be marked as top three
    top_marker = ""
    idx_top = ifind(this%top_three, section_id)
    if (idx_top > 0) then
      nr_padding = max(0, 32 - level * 4)
      write (top_marker, '(a,i0)') repeat(" ", nr_padding)//"<== #", idx_top
    end if
 
    ! print section timing
    nr_padding = this%max_title_len - len_trim(section%title) + 2
    title_padded = trim(section%title)//":"//repeat(' ', nr_padding)
    write (this%iout, '(3a,f6.2,2a,f14.6,2a,i0,a,a)') " ", &
      repeat('....', level), "[", percent, "%] ", title_padded, &
      section%walltime, "s", " (", section%count, "x)", trim(top_marker)
 
    ! print children
    new_level = level + 1
    do i = 1, section%children%size
      call this%print_section(section%children%at(i), new_level)
    end do
 
    if (level == 0) write (this%iout, *)
 

print_total()

subroutine profilermodule::print_total	(	class(profilertype)	this,
		character(len=*)	subtitle
	)

Definition at line 323 of file Profiler.f90.

    class(ProfilerType) :: this
    character(len=*) :: subtitle
    ! local
    integer(I4B) :: count
    real(DP) :: walltime, percent
    integer(I4B) :: nr_padding
    character(len=:), allocatable :: title_padded
 
    ! get maximum length of title
    nr_padding = this%max_title_len - len_trim(subtitle)
    title_padded = trim(subtitle)//repeat(' ', nr_padding)
 
    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 (this%iout, '(2a,f6.2,3a,f14.6,2a,i0,a)') " ", "[", percent, &
        "%] ", title_padded, ": ", walltime, "s", " (", count, "x)"
    end if
 

Here is the call graph for this function:

set_print_option()

subroutine profilermodule::set_print_option ( class(profilertype)  this, character(len=*), intent(in)  profile_option  )

private

Definition at line 384 of file Profiler.f90.

    class(ProfilerType) :: this
    character(len=*), intent(in) :: profile_option
 
    select case (trim(profile_option))
    case ("NONE")
      this%pr_option = 0
    case ("SUMMARY")
      this%pr_option = 1
    case ("DETAIL")
      this%pr_option = 2
    case default
      this%pr_option = 0
    end select
 

sort_by_walltime()

subroutine profilermodule::sort_by_walltime ( class(profilertype)  this, integer(i4b), dimension(:), allocatable  idxs  )

private

Parameters

idxs	array with unsorted section idxs

Definition at line 434 of file Profiler.f90.

    class(ProfilerType) :: this
    integer(I4B), dimension(:), allocatable :: idxs !< array with unsorted section idxs
    integer(I4B) :: i, j, temp
 
    ! Simple bubble sort for demonstration purposes
    do i = 1, size(idxs) - 1
      do j = 1, size(idxs) - i
        if (this%all_sections(idxs(j))%walltime < &
            this%all_sections(idxs(j + 1))%walltime) then
          temp = idxs(j)
          idxs(j) = idxs(j + 1)
          idxs(j + 1) = temp
        end if
      end do
    end do
 

start()

subroutine profilermodule::start	(	class(profilertype)	this,
		character(len=*)	title,
		integer(i4b)	section_id
	)

Definition at line 176 of file Profiler.f90.

    class(ProfilerType) :: this
    character(len=*) :: title
    integer(I4B) :: section_id
    ! local
    integer(I4B) :: parent_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
      ! add section if not exist
      parent_id = 0 ! root
      if (this%callstack%size() > 0) then
        parent_id = this%callstack%top()
      end if
      section_id = this%add_section(title, parent_id)
    end if
    call this%callstack%push(section_id)
 
    section => this%all_sections(section_id)
    section%count = section%count + 1
    section%status = 1
    section%walltime = section%walltime - start_time
 

stop()

subroutine profilermodule::stop ( class(profilertype)  this, integer(i4b)  section_id  )

private

Definition at line 206 of file Profiler.f90.

    class(ProfilerType) :: this
    integer(I4B) :: section_id
    ! local
    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)
    section => this%all_sections(section_id)
    section%status = 0
    section%walltime = section%walltime + end_time
 
    ! pop from call stack
    call this%callstack%pop()
 

Variable Documentation

g_prof

type(profilertype), public profilermodule::g_prof

Definition at line 70 of file Profiler.f90.

  type(ProfilerType), public :: g_prof !< the global timer object (to reduce trivial lines of code)

len_section_title

integer(i4b), parameter, public profilermodule::len_section_title = 128

Definition at line 15 of file Profiler.f90.

  integer(I4B), public, parameter :: LEN_SECTION_TITLE = 128

max_sections_per_sln

integer(i4b), parameter profilermodule::max_sections_per_sln = 40

private

Definition at line 14 of file Profiler.f90.

  integer(I4B), parameter :: MAX_SECTIONS_PER_SLN = 40