added timing functionality

src/dataIO/mod_logging.f08

@@ -42,6 +42,7 @@ module mod_logging
   public :: print_whitespace
   public :: str
   public :: exp_fmt, dp_fmt, int_fmt
+  public :: override_prefix_to_false
 
 contains
 

src/main.f08

@@ -14,45 +14,56 @@ program legolas
   use mod_output, only: datfile_name, create_datfile
   use mod_logging, only: log_message, str, print_console_info, print_whitespace
   use mod_inspections, only: handle_spurious_eigenvalues
-  use mod_timing, only: tic, toc
+  use mod_timing, only: timer_t, new_timer
   implicit none
 
   !> A matrix in eigenvalue problem wBX = AX
   type(matrix_t) :: matrix_A
   !> B matrix in eigenvalue problem wBX = AX
   type(matrix_t) :: matrix_B
+  !> timer used by the whole program
+  type(timer_t) :: timer
   !> array with eigenvalues
   complex(dp), allocatable  :: omega(:)
   !> matrix with right eigenvectors, column indices correspond to omega indices
   complex(dp), allocatable  :: eigenvecs_right(:, :)
-  !> start time of eigenvalue solver
-  integer                   :: start_time_evp
 
+  timer = new_timer()
+
+  call timer%start_timer()
   call initialisation()
+  timer%init_time = timer%end_timer()
+
   call print_console_info()
 
+  call timer%start_timer()
   call build_matrices(matrix_B, matrix_A)
+  timer%matrix_time = timer%end_timer()
 
   if (.not. dry_run) then
     call log_message("solving eigenvalue problem...", level="info")
-
-    call tic(start_time_evp)
+    call timer%start_timer()
     call solve_evp(matrix_A, matrix_B, omega, eigenvecs_right)
-    call toc("solved eigenvalue problem", start_time_evp, level="info")
+    timer%evp_time = timer%end_timer()
   else
     call log_message( &
       "running dry, overriding parfile and setting eigenvalues to zero", level="info"  &
     )
     omega = (0.0d0, 0.0d0)
   end if
 
-  call handle_spurious_eigenvalues(omega)
-
+  call timer%start_timer()
   call create_eigenfunctions()
+  timer%eigenfunction_time = timer%end_timer()
+
+  call timer%start_timer()
   call create_datfile(omega, matrix_A, matrix_B, eigenvecs_right)
+  timer%datfile_time = timer%end_timer()
 
   call cleanup()
 
+  call print_timelog()
+
   if (show_results) then
     call print_whitespace(1)
     call execute_command_line("python3 pylbo_wrapper.py -i " // trim(datfile_name))
@@ -160,4 +171,38 @@ subroutine cleanup()
     call eigenfunctions_clean()
   end subroutine cleanup
 
+
+  subroutine print_timelog()
+    use mod_logging, only: override_prefix_to_false
+    real(dp) :: total_time
+
+    call print_whitespace(1)
+    call log_message("---------------------------------------------")
+    override_prefix_to_false = .true.
+    total_time = timer%get_total_time()
+
+    call log_message("                << Time log >>")
+    call log_message( &
+      "Legolas finished in " // str(total_time) // " seconds", level="info" &
+    )
+    call log_message( &
+      "   initialisation: " // str(timer%init_time) // " sec", level="info" &
+    )
+    call log_message( &
+      "   matrix construction: " // str(timer%matrix_time) // " sec", &
+      level="info" &
+    )
+    call log_message( &
+      "   eigenvalue problem: " // str(timer%evp_time) // " sec", &
+      level="info" &
+    )
+    call log_message( &
+      "   eigenfunction assembly: " // str(timer%eigenfunction_time) // " sec", &
+      level="info" &
+    )
+    call log_message( &
+      "   datfile creation: " // str(timer%datfile_time) // " sec", level="info" &
+    )
+  end subroutine print_timelog
+
 end program legolas

src/utils/mod_timing.f08

@@ -40,15 +40,65 @@ module mod_timing
   private
   public tic, toc, cputic, cputoc
 
-  !> Wall clock time at last call of `tic()`.
-  !! Intially -1000 to more easily detect incorrect use.
+  !> Wall clock time at last call of `tic()`, init -1000 to easily detect incorrect use.
   integer, save :: wall_clock_tic = -1000
-  !> CPU time at last call of `cputic()`.
-  !! Intially -1000 to more easily detect incorrect use.
-  real,    save :: cpu_clock_tic = -1000.0
+  !> CPU time at last call of `cputic()`, init -1000 to easily detect incorrect use.
+  real(dp), save :: cpu_clock_tic = -1000.0_dp
+
+  type, public :: timer_t
+    integer, private :: start_time
+    integer, private :: program_start_time
+    real(dp) :: init_time
+    real(dp) :: matrix_time
+    real(dp) :: evp_time
+    real(dp) :: eigenfunction_time
+    real(dp) :: datfile_time
+
+    contains
+
+    procedure :: start_timer
+    procedure :: end_timer
+    procedure :: get_total_time
+  end type timer_t
+
+  public :: new_timer
 
 contains
 
+  function new_timer() result(timer)
+    type(timer_t) :: timer
+    timer%start_time = -1000
+    call system_clock(timer%program_start_time)
+  end function new_timer
+
+
+  subroutine start_timer(this)
+    class(timer_t), intent(inout) :: this
+    call system_clock(this%start_time)
+  end subroutine start_timer
+
+
+  function end_timer(this) result(elapsed_time)
+    class(timer_t), intent(inout) :: this
+    integer :: end_time, rate
+    real(dp) :: elapsed_time
+
+    call system_clock(end_time, rate)
+    elapsed_time = real(end_time - this%start_time, kind=dp) / rate
+    this%start_time = -1000
+  end function end_timer
+
+
+  function get_total_time(this) result(total_time)
+    class(timer_t), intent(in) :: this
+    integer :: end_time, rate
+    real(dp) :: total_time
+
+    call system_clock(end_time, rate)
+    total_time = real(end_time - this%program_start_time, kind=dp) / rate
+  end function get_total_time
+
+
   !> Subroutine to start a wall clock timer.
   !!
   !! `tic()` starts the wall clock timer. The subroutines records the wall clock
@@ -114,8 +164,10 @@ subroutine toc(message, start_time, level)
     call system_clock(end_time, rate)
 
     elapsed_time = real(end_time - selected_start_time, kind=dp) / rate
-    call log_message(message // " (" // str(elapsed_time, fmt="f20.3") // " s)", &
-                   & level=loglevel)
+    call log_message( &
+      message // " (" // str(elapsed_time, fmt="f20.3") // " s)", &
+      level=loglevel &
+      )
   end subroutine toc
 
   !> Subroutine to start a CPU timer.
@@ -160,12 +212,12 @@ subroutine cputoc(message, start_time, level)
     character(len=*), intent(in)           :: message
     !> Optional starting time. If not present the time recorded in
     !! the module variable is used.
-    real, intent(in), optional             :: start_time
+    real(dp), intent(in), optional :: start_time
     !> The level (severity) of the message, default is <tt>"debug"</tt>.
     character(len=*), intent(in), optional :: level
 
-    real                      :: selected_start_time, end_time
-    real(dp)                  :: elapsed_time
+    real(dp) :: selected_start_time, end_time
+    real(dp) :: elapsed_time
     character(:), allocatable :: loglevel
 
     if (present(start_time)) then
@@ -183,8 +235,10 @@ subroutine cputoc(message, start_time, level)
     call cpu_time(end_time)
 
     elapsed_time = end_time - selected_start_time
-    call log_message(message // " (" // str(elapsed_time, fmt="f20.3") // " s, CPU time)", &
-                   & level=loglevel)
+    call log_message( &
+      message // " (" // str(elapsed_time, fmt="f20.3") // " s, CPU time)", &
+      level=loglevel &
+    )
   end subroutine cputoc
 
 end module mod_timing