Add timers to libforcing. COSIMA/access-om2#242

atm/src/atm.F90

@@ -38,6 +38,8 @@ program atm
     type(simple_timer_type) :: coupler_put_timer
     type(simple_timer_type) :: init_oasis_timer, init_model_timer
     type(simple_timer_type) :: parse_forcing_fields_timer
+    type(simple_timer_type) :: main_loop_timer
+    type(simple_timer_type) :: extras_timer
 
     namelist /atm_nml/ forcing_file, accessom2_config_dir
 
@@ -73,6 +75,10 @@ program atm
                                 accessom2%simple_timers_enabled())
     call parse_forcing_fields_timer%init('parse_forcing_fields', accessom2%logger, &
                                 accessom2%simple_timers_enabled())
+    call main_loop_timer%init('main_loop_timer', accessom2%logger, &
+                                accessom2%simple_timers_enabled())
+    call extras_timer%init('extras_timer', accessom2%logger, &
+                                accessom2%simple_timers_enabled())
     call init_model_timer%start()
 
     ! Initialise forcing object, this reads config and
@@ -158,9 +164,12 @@ program atm
 
     do while (.not. accessom2%run_finished())
 
+        call extras_timer%start()
         cur_runtime_in_seconds = int(accessom2%get_cur_runtime_in_seconds())
+        call extras_timer%stop()
 
         ! Send each forcing field
+        call main_loop_timer%start()
         do i=1, num_atm_to_ice_fields
             ri = to_runoff_map(i)
 
@@ -189,6 +198,9 @@ program atm
             endif
             call coupler_put_timer%stop()
         enddo
+        call main_loop_timer%stop()
+
+        call extras_timer%start()
 
         ! Block until we receive from ice. Ice will do a nonblocking send immediately
         ! after receiving the above fields. This prevents the atm from sending continuously.
@@ -204,6 +216,8 @@ program atm
         !call accessom2%logger%write(LOG_INFO, '{ "modeltime_over_walltime_hour_per_hour" : "" ',
 
         call accessom2%progress_date(dt)
+
+        call extras_timer%stop()
     enddo
 
     call field_read_timer%write_stats()
@@ -214,9 +228,15 @@ program atm
     call init_oasis_timer%write_stats()
     call init_model_timer%write_stats()
     call parse_forcing_fields_timer%write_stats()
+    call main_loop_timer%write_stats()
+    call extras_timer%write_stats()
 
     call accessom2%logger%write(LOG_INFO, 'Run complete, calling deinit')
 
+    do i=1, num_atm_to_ice_fields
+        call forcing_fields(i)%deinit()
+    enddo
+
     call coupler%deinit()
     call accessom2%deinit(finalize=.true.)
     call forcing_config%deinit()

libforcing/src/forcing_field.F90

@@ -9,6 +9,7 @@ module forcing_field_mod
                                      FORCING_PERTURBATION_TYPE_SEPARABLE
 use ncvar_mod, only : ncvar_type => ncvar
 use util_mod, only : filename_for_date
+use simple_timer_mod, only : simple_timer_type => simple_timer
 
 implicit none
 private
@@ -35,19 +36,26 @@ module forcing_field_mod
             separated_perturbations
 
     type(logger_type), pointer :: logger
+
+    type(simple_timer_type) :: get_time_index_timer
+    type(simple_timer_type) :: apply_perturbations_timer
+    type(simple_timer_type) :: calculate_field_timer
+
 contains
     procedure, pass(self), public :: init => forcing_field_init
     procedure, pass(self), public :: update => forcing_field_update
     procedure, pass(self), private :: calculate => forcing_field_calculate
     procedure, pass(self), private :: apply_perturbations => &
                 forcing_field_apply_perturbations
     procedure, pass(self), public :: get_shape
+    procedure, pass(self), public :: deinit => forcing_field_deinit
 endtype forcing_field
 
 contains
 
-subroutine forcing_field_init(self, name_list, filename_template_list, cname, realm, &
-                              start_date, product_name, loggerin, dt, calendar)
+subroutine forcing_field_init(self, name_list, filename_template_list, cname, &
+                              realm, start_date, product_name, loggerin, &
+                              dt, calendar)
     class(forcing_field), intent(inout) :: self
     character(len=*), dimension(:), intent(in) :: name_list
     character(len=*), dimension(:), intent(in) :: filename_template_list
@@ -62,6 +70,14 @@ subroutine forcing_field_init(self, name_list, filename_template_list, cname, re
     character(len=1024) :: filename
     integer :: num_file_inputs, i
 
+    self%logger => loggerin
+    call self%get_time_index_timer%init('get_time_index_timer', &
+                                        loggerin, .true.)
+    call self%apply_perturbations_timer%init('apply_perturbations_timer', &
+                                             loggerin,.true.)
+    call self%calculate_field_timer%init('calculate_field_timer', &
+                                        loggerin,.true.)
+
     num_file_inputs = size(name_list)
 
     allocate(self%names(num_file_inputs))
@@ -80,7 +96,6 @@ subroutine forcing_field_init(self, name_list, filename_template_list, cname, re
     endif
 
     self%product_name = trim(product_name)
-    self%logger => loggerin
 
     do i=1, num_file_inputs
         filename = filename_for_date(self%filename_templates(i), &
@@ -122,6 +137,8 @@ subroutine forcing_field_update(self, forcing_date, experiment_date)
     integer :: indx, test_indx
     integer :: num_file_inputs, i
 
+    call self%get_time_index_timer%start()
+
     num_file_inputs = size(self%ncvars)
 
     do i=1, num_file_inputs
@@ -160,8 +177,12 @@ subroutine forcing_field_update(self, forcing_date, experiment_date)
         enddo
     endif
 
+    call self%get_time_index_timer%stop()
+
     call self%calculate(indx, self%data_array)
+    call self%apply_perturbations_timer%start()
     call self%apply_perturbations(forcing_date, experiment_date)
+    call self%apply_perturbations_timer%stop()
 
 end subroutine forcing_field_update
 
@@ -194,8 +215,10 @@ subroutine forcing_field_calculate(self, file_index, result_array)
             ! Rain is calculated as mcpr
             ! (mean convective precipitation rate [kg m**-2 s**-1]) plus
             ! mlspr (mean large-scale precipitation rate [kg m**-2 s**-1])
+            call self%calculate_field_timer%start()
             call self%ncvars(1)%read_data(file_index, tmp1)
             call self%ncvars(2)%read_data(file_index, tmp2)
+            call self%calculate_field_timer%stop()
             result_array(:, :) = tmp1(:, :) + tmp2(:, :)
 
         elseif (trim(self%coupling_name) == 'qair_ai') then
@@ -206,8 +229,10 @@ subroutine forcing_field_calculate(self, file_index, result_array)
             call assert(self%ncvars(2)%name == 'sp', &
                         'Unexpected name for surface pressure')
 
+            call self%calculate_field_timer%start()
             call self%ncvars(1)%read_data(file_index, tmp1)
             call self%ncvars(2)%read_data(file_index, tmp2)
+            call self%calculate_field_timer%stop()
             Td => tmp1
             sp => tmp2
 
@@ -219,7 +244,9 @@ subroutine forcing_field_calculate(self, file_index, result_array)
             result_array(:, :) = (RDRY/RVAP)*E / (sp-((1-RDRY/RVAP)*E))
             deallocate(E)
         else
+            call self%calculate_field_timer%start()
             call self%ncvars(1)%read_data(file_index, result_array)
+            call self%calculate_field_timer%stop()
         endif
 
         deallocate(tmp1, tmp2)
@@ -350,11 +377,21 @@ subroutine forcing_field_apply_perturbations(self, forcing_date, experiment_date
 
 endsubroutine forcing_field_apply_perturbations
 
+subroutine forcing_field_deinit(self)
+    class(forcing_field), intent(inout) :: self
+
+    call self%get_time_index_timer%write_stats()
+    call self%apply_perturbations_timer%write_stats()
+    call self%calculate_field_timer%write_stats()
+
+endsubroutine forcing_field_deinit
+
 function get_shape(self)
     class(forcing_field), intent(in) :: self
     integer, dimension(2) :: get_shape
 
     get_shape = shape(self%data_array)
 endfunction
 
+
 endmodule forcing_field_mod