diff --git a/components/lfric-xios/source/lfric_xios_context_mod.f90 b/components/lfric-xios/source/lfric_xios_context_mod.f90 index 7f3d0e429..d00fab628 100644 --- a/components/lfric-xios/source/lfric_xios_context_mod.f90 +++ b/components/lfric-xios/source/lfric_xios_context_mod.f90 @@ -25,6 +25,7 @@ module lfric_xios_context_mod use lfric_xios_file_mod, only : lfric_xios_file_type use linked_list_mod, only : linked_list_type, linked_list_item_type use model_clock_mod, only : model_clock_type + use io_config_mod, only : subroutine_timers use timer_mod, only : timer use xios, only : xios_context, & xios_context_initialize, & @@ -119,6 +120,7 @@ subroutine initialise_xios_context( this, communicator, & write(log_scratch_space, "(A)") & "Initialising XIOS context: " // this%get_context_name() call log_event(log_scratch_space, log_level_debug) + if ( subroutine_timers ) call timer('lfric_xios_init_context') if (present(start_at_zero)) then zero_start = start_at_zero @@ -140,7 +142,12 @@ subroutine initialise_xios_context( this, communicator, & ! Close the context definition - no more I/O operations can be defined ! after this point + if ( subroutine_timers ) call timer('xios_close_context_definition') + call log_event('XIOS context definition closing', log_level_debug) call xios_close_context_definition() + if ( subroutine_timers ) call timer('xios_close_context_definition') + call log_event('XIOS context definition closed', log_level_debug) + this%xios_context_initialised = .true. ! Read all files that need to be read from @@ -155,6 +162,7 @@ subroutine initialise_xios_context( this, communicator, & loop => loop%next end do end if + if ( subroutine_timers ) call timer('lfric_xios_init_context') end subroutine initialise_xios_context @@ -177,6 +185,7 @@ subroutine finalise_xios_context( this ) type(linked_list_item_type), pointer :: loop => null() type(lfric_xios_file_type), pointer :: file => null() + if ( subroutine_timers ) call timer('lfric_xios_finalise_context') if (this%xios_context_initialised) then ! Perform final write if (this%filelist%get_length() > 0) then @@ -195,7 +204,9 @@ subroutine finalise_xios_context( this ) ! will be closed. write(log_scratch_space, "(A)") "Finalising XIOS context: " // this%get_context_name() call log_event(log_scratch_space, log_level_debug) + if ( subroutine_timers ) call timer('xios_context_finalize') call xios_context_finalize() + if ( subroutine_timers ) call timer('xios_context_finalize') ! We have closed the context on our end, but we need to make sure that XIOS ! has closed the files for all servers before we process them. @@ -217,6 +228,7 @@ subroutine finalise_xios_context( this ) end if nullify(loop) nullify(file) + if ( subroutine_timers ) call timer('lfric_xios_finalise_context') end subroutine finalise_xios_context diff --git a/components/lfric-xios/source/lfric_xios_read_mod.F90 b/components/lfric-xios/source/lfric_xios_read_mod.F90 index ad8051a33..a6837b2f5 100644 --- a/components/lfric-xios/source/lfric_xios_read_mod.F90 +++ b/components/lfric-xios/source/lfric_xios_read_mod.F90 @@ -38,6 +38,8 @@ module lfric_xios_read_mod LOG_LEVEL_INFO, & LOG_LEVEL_ERROR, & LOG_LEVEL_TRACE + use io_config_mod, only: subroutine_timers + use timer_mod, only: timer #ifdef UNIT_TEST use lfric_xios_mock_mod, only: xios_recv_field, & xios_get_domain_attr, & @@ -85,6 +87,8 @@ subroutine checkpoint_read_xios(xios_field_name, file_name, field_proxy) integer(i_def) :: undf integer(i_def) :: fs_id + if ( subroutine_timers ) call timer('lfric_xios_chkpt_readf') + ! We only read in up to undf for the partition undf = field_proxy%vspace%get_last_dof_owned() @@ -103,6 +107,7 @@ subroutine checkpoint_read_xios(xios_field_name, file_name, field_proxy) call log_event( "Invalid type for input field proxy", LOG_LEVEL_ERROR ) end select + if ( subroutine_timers ) call timer('lfric_xios_chkpt_readf') end subroutine checkpoint_read_xios @@ -115,6 +120,8 @@ subroutine checkpoint_read_value(io_value, value_name) character(str_def) :: restart_id integer(i_def) :: array_dims + if ( subroutine_timers ) call timer('lfric_xios_chkpt_readv') + if(present(value_name)) then restart_id = trim(value_name) else @@ -129,6 +136,7 @@ subroutine checkpoint_read_value(io_value, value_name) call log_event( 'No XIOS field with id="'//trim(restart_id)//'" is defined', & LOG_LEVEL_ERROR ) end if + if ( subroutine_timers ) call timer('lfric_xios_chkpt_readv') end subroutine checkpoint_read_value @@ -169,6 +177,8 @@ subroutine read_field_generic(xios_field_name, field_proxy) real(dp_xios), allocatable :: xios_data(:) logical(l_def) :: legacy + if ( subroutine_timers ) call timer('lfric_xios_read_fldg') + undf = field_proxy%vspace%get_last_dof_owned() ! total dimension vdim = field_proxy%vspace%get_ndata() * size(field_proxy%vspace%get_levels()) @@ -198,6 +208,8 @@ subroutine read_field_generic(xios_field_name, field_proxy) deallocate(xios_data) + if ( subroutine_timers ) call timer('lfric_xios_read_fldg') + end subroutine read_field_generic !> @brief Read a time-varying field, with given time dimension, in UGRID format using XIOS diff --git a/components/lfric-xios/source/lfric_xios_write_mod.F90 b/components/lfric-xios/source/lfric_xios_write_mod.F90 index ea1d25e68..09aa375f5 100644 --- a/components/lfric-xios/source/lfric_xios_write_mod.F90 +++ b/components/lfric-xios/source/lfric_xios_write_mod.F90 @@ -44,6 +44,8 @@ module lfric_xios_write_mod LOG_LEVEL_WARNING, & LOG_LEVEL_ERROR use lfric_string_mod, only: split_string + use io_config_mod, only: subroutine_timers + use timer_mod, only: timer #ifdef UNIT_TEST use lfric_xios_mock_mod, only: xios_send_field, & xios_get_domain_attr, & @@ -123,6 +125,8 @@ subroutine write_field_generic(field_name, field_proxy) ! without doing anything if (.not. field_is_active(field_name, .true.)) return + if ( subroutine_timers ) call timer('lfric_xios_write_fldg') + undf = field_proxy%vspace%get_last_dof_owned() ! total dimension vdim = field_proxy%vspace%get_ndata() * size(field_proxy%vspace%get_levels()) @@ -152,6 +156,8 @@ subroutine write_field_generic(field_name, field_proxy) deallocate(xios_data) + if ( subroutine_timers ) call timer('lfric_xios_write_fldg') + end subroutine write_field_generic !> @brief Graceful failure if an empty field is attempted to be written diff --git a/infrastructure/source/field/field_mod.t90 b/infrastructure/source/field/field_mod.t90 index 50eed4d7a..f034c5f54 100644 --- a/infrastructure/source/field/field_mod.t90 +++ b/infrastructure/source/field/field_mod.t90 @@ -42,6 +42,8 @@ module field_{{kind}}_mod use pure_abstract_field_mod, & only: pure_abstract_field_type + use io_config_mod, only: subroutine_timers + use timer_mod, only: timer implicit none @@ -275,6 +277,8 @@ contains ! Depth of halo to allocate data array integer(i_def) :: field_halo_depth + if ( subroutine_timers ) call timer('field.initialise') + mesh => null() if ( present(name) ) then @@ -334,6 +338,8 @@ contains end if + if ( subroutine_timers ) call timer('field.initialise') + end subroutine field_initialiser !> Initialise a {{kind}} field pointer @@ -602,6 +608,8 @@ contains character(str_def) :: name_used + if ( subroutine_timers ) call timer('field.write') + if (present(field_name)) then name_used = field_name @@ -624,6 +632,8 @@ contains ', write_method not set up', LOG_LEVEL_ERROR ) end if + if ( subroutine_timers ) call timer('field.write') + end subroutine write_field !> Calls the underlying IO implementation for reading into the field @@ -638,6 +648,8 @@ contains type( field_{{kind}}_proxy_type ) :: tmp_proxy + if ( subroutine_timers ) call timer('field.read') + if (associated(self%read_method)) then tmp_proxy = self%get_proxy() @@ -655,6 +667,8 @@ contains ', read_method not set up', LOG_LEVEL_ERROR ) end if + if ( subroutine_timers ) call timer('field.read') + end subroutine read_field !> Reads a checkpoint file into the field @@ -670,6 +684,7 @@ contains type( field_{{kind}}_proxy_type ) :: tmp_proxy + if ( subroutine_timers ) call timer('field.read_chkpt') if (associated(self%checkpoint_read_method)) then @@ -688,6 +703,8 @@ contains ', checkpoint_read_method not set up', LOG_LEVEL_ERROR ) end if + if ( subroutine_timers ) call timer('field.read_chkpt') + end subroutine read_checkpoint !> Writes a checkpoint file @@ -724,12 +741,17 @@ contains class( field_{{kind}}_proxy_type ), target, intent(inout) :: self integer(i_def), intent(in) :: depth type(halo_routing_type), pointer :: halo_routing => null() + character(len=str_def) :: timer_name if ( self%vspace%is_writable() ) then if ( depth > self%get_field_proxy_halo_depth() ) & call log_event( 'Error in field: '// & 'attempt to exchange halos with depth out of range.', & LOG_LEVEL_ERROR ) + write(timer_name, '(I4)') depth + timer_name = 'field.halo_ex_' // adjustl(trim(timer_name)) + if ( subroutine_timers ) call timer(trim(adjustl(timer_name))) + ! Start a blocking (synchronous) halo exchange halo_routing => self%get_halo_routing() @@ -740,6 +762,9 @@ contains self%halo_dirty(1:depth) = 0 ! If a halo counter has been set up, increment it if (allocated(halo_calls)) call halo_calls%counter_inc() + + if ( subroutine_timers ) call timer(trim(adjustl(timer_name))) + else call log_event( 'Error in field: '// & 'attempt to exchange halos (a write operation) on a read-only field.', & diff --git a/infrastructure/source/field/halo_routing_collection_mod.f90 b/infrastructure/source/field/halo_routing_collection_mod.f90 index a9dd80612..05d3715cf 100644 --- a/infrastructure/source/field/halo_routing_collection_mod.f90 +++ b/infrastructure/source/field/halo_routing_collection_mod.f90 @@ -23,6 +23,8 @@ module halo_routing_collection_mod use linked_list_mod, only: linked_list_type, & linked_list_item_type use mesh_mod, only: mesh_type + use io_config_mod, only: subroutine_timers + use timer_mod, only: timer implicit none @@ -118,6 +120,8 @@ function get_halo_routing( self, & integer(i_def) :: last_owned_dof integer(i_def) :: mesh_id + if ( subroutine_timers ) call timer('halo_routing_creation') + nullify( function_space ) halo_routing => get_halo_routing_from_list( self, & @@ -190,6 +194,8 @@ function get_halo_routing( self, & end if + if ( subroutine_timers ) call timer('halo_routing_creation') + return end function get_halo_routing diff --git a/infrastructure/source/function_space/function_space_mod.F90 b/infrastructure/source/function_space/function_space_mod.F90 index 4fa65796e..778ad6846 100644 --- a/infrastructure/source/function_space/function_space_mod.F90 +++ b/infrastructure/source/function_space/function_space_mod.F90 @@ -35,6 +35,8 @@ module function_space_mod use linked_list_data_mod, only : linked_list_data_type use linked_list_mod, only : linked_list_type, linked_list_item_type use mesh_collection_mod, only : mesh_collection + use io_config_mod, only : subroutine_timers + use timer_mod, only : timer implicit none @@ -444,6 +446,8 @@ function fs_constructor( mesh_id, & integer(i_def) :: id + if ( subroutine_timers ) call timer('fs.constructor') + if ( present(ndata_first) ) then instance%ndata_first = ndata_first else @@ -474,6 +478,8 @@ function fs_constructor( mesh_id, & end if call init_function_space(instance) + if ( subroutine_timers ) call timer('fs.constructor') + end function fs_constructor