Merge branch 'worleyph/driver-mct/add_io-related_timers2' (PR #4561)

SCORPIO has introduced some new timers. Unfortunately, the existing
timers in driver-mct are not sufficient to localize where the SCORPIO calls
are coming from. Here new timers are added to provide the missing
context. A few timers are also added to provide context for these
added timers and for some of the already existing timers.

While 25 new timers are introduced, in normal usage only 7 to 11 new
timers appear in the timing files.

Four existing timers were renamed in order to add a CPL prefix:

comp_init_cc_iac => CPL:comp_init_cc_iac
driver_rofpost_histaux => CPL:seq_hist_writeaux-r2x
DRIVER_ROFPOST_BARRIER => CPL:ROFPOST_BARRIER
DRIVER_ROFPOST => CPL:ROFPOST

Two existing timers were renamed to eliminate collisions
from the previous renamings:

CPL:ROFPOST_BARRIER => CPL:ROFRUNPOST_BARRIER
CPL:ROFPOST => CPL:ROFRUNPOST

Fixes #4522

[BFB]

Author: rljacob

driver-mct/main/cime_comp_mod.F90

@@ -1060,12 +1060,15 @@ subroutine cime_pre_init2()
     !| Initialize infodata
     !----------------------------------------------------------
 
+    call t_startf('CPL:seq_infodata_init')
     if (len_trim(cpl_inst_tag) > 0) then
        call seq_infodata_init(infodata,nlfilename, GLOID, pioid, &
             cpl_tag=cpl_inst_tag)
     else
        call seq_infodata_init(infodata,nlfilename, GLOID, pioid)
     end if
+    call t_stopf('CPL:seq_infodata_init')
+
     call seq_infodata_GetData(infodata, cime_model=cime_model)
 
     !----------------------------------------------------------
@@ -1234,11 +1237,13 @@ subroutine cime_pre_init2()
     !| Initialize time manager
     !----------------------------------------------------------
 
+    call t_startf('CPL:seq_timemgr_clockInit')
     call seq_timemgr_clockInit(seq_SyncClock, nlfilename, &
          read_restart, rest_file, pioid, mpicom_gloid,           &
          EClock_d, EClock_a, EClock_l, EClock_o,          &
          EClock_i, Eclock_g, Eclock_r, Eclock_w, Eclock_e, &
          EClock_z)
+    call t_stopf('CPL:seq_timemgr_clockInit')
 
     if (iamroot_CPLID) then
        call seq_timemgr_clockPrint(seq_SyncClock)
@@ -1463,11 +1468,11 @@ subroutine cime_init()
     call t_adj_detailf(-2)
     call t_stopf('CPL:comp_init_cc_esp')
 
-    call t_startf('comp_init_cc_iac')
+    call t_startf('CPL:comp_init_cc_iac')
     call t_adj_detailf(+2)
     call component_init_cc(Eclock_z, iac, iac_init, infodata, NLFilename)
     call t_adj_detailf(-2)
-    call t_stopf('comp_init_cc_iac')
+    call t_stopf('CPL:comp_init_cc_iac')
 
     call t_startf('CPL:comp_init_cx_all')
     call t_adj_detailf(+2)
@@ -2317,14 +2322,19 @@ subroutine cime_init()
 
     call seq_diag_zero_mct(mode='all')
     if (read_restart .and. iamin_CPLID) then
+
        if (iamroot_CPLID) then
           write(logunit,103) subname,' Reading restart file ',trim(rest_file)
           call shr_sys_flush(logunit)
        end if
+       
+       call t_startf('CPL:seq_rest_read-init')
        call seq_rest_read(rest_file, infodata, &
             atm, lnd, ice, ocn, rof, glc, wav, esp, iac, &
             fractions_ax, fractions_lx, fractions_ix, fractions_ox, &
             fractions_rx, fractions_gx, fractions_wx, fractions_zx)
+       call t_stopf('CPL:seq_rest_read-init')
+
     endif
 
     call t_adj_detailf(-2)
@@ -2380,10 +2390,14 @@ subroutine cime_init()
              write(logunit,104) ' Write history file at ',ymd,tod
              call shr_sys_flush(logunit)
           endif
+
+          call t_startf('CPL:seq_hist_write-init')
           call seq_hist_write(infodata, EClock_d, &
                atm, lnd, ice, ocn, rof, glc, wav, iac, &
                fractions_ax, fractions_lx, fractions_ix, fractions_ox, &
                fractions_rx, fractions_gx, fractions_wx, fractions_zx, trim(cpl_inst_tag))
+          call t_stopf('CPL:seq_hist_write-init')
+
           if (drv_threading) call seq_comm_setnthreads(nthreads_GLOID)
 
           call t_adj_detailf(-2)
@@ -2970,23 +2984,27 @@ subroutine cime_run()
        endif
        if (rof_present) then
           if (iamin_CPLID) then
-             call cime_comp_barriers(mpicom=mpicom_CPLID, timer='DRIVER_ROFPOST_BARRIER')
-             call t_drvstartf  ('DRIVER_ROFPOST',cplrun=.true.,barrier=mpicom_CPLID)
+
+             call cime_comp_barriers(mpicom=mpicom_CPLID, timer='CPL:ROFPOST_BARRIER')
+             call t_drvstartf  ('CPL:ROFPOST',cplrun=.true.,barrier=mpicom_CPLID)
              if (drv_threading) call seq_comm_setnthreads(nthreads_CPLID)
              if (do_hist_r2x) then
-                call t_drvstartf ('driver_rofpost_histaux', barrier=mpicom_CPLID)
                 ! Write coupler's hr2x file at 24 hour marks,
                 ! and at the end of the run interval, even if that's not at a 24 hour mark.
                 write_hist_alarm = t24hr_alarm .or. stop_alarm
+
+                call t_startf('CPL:seq_hist_writeaux-r2x')
                 do eri = 1,num_inst_rof
                    inst_suffix =  component_get_suffix(rof(eri))
                    call seq_hist_writeaux(infodata, EClock_d, rof(eri), flow='c2x', &
                         aname='r2x',dname='domrb',inst_suffix=trim(inst_suffix),  &
                         nx=rof_nx, ny=rof_ny, nt=1, write_now=write_hist_alarm)
                 enddo
-                call t_drvstopf ('driver_rofpost_histaux')
+                call t_stopf('CPL:seq_hist_writeaux-r2x')
+
              endif
-             call t_drvstopf  ('DRIVER_ROFPOST', cplrun=.true.)
+             call t_drvstopf  ('CPL:ROFPOST', cplrun=.true.)
+
           endif
        endif
        !----------------------------------------------------------
@@ -3238,10 +3256,19 @@ subroutine cime_run()
              call shr_sys_flush(logunit)
           end if
           if (iamin_CPLID) then
+
+             call cime_comp_barriers(mpicom=mpicom_CPLID, timer='CPL:RESTART_READ_BARRIER')
+             call t_drvstartf ('CPL:RESTART_READ',cplrun=.true.,barrier=mpicom_CPLID)
+
+             call t_startf('CPL:seq_rest_read')
              call seq_rest_read(drv_resume_file, infodata,                     &
                   atm, lnd, ice, ocn, rof, glc, wav, esp, iac,                 &
                   fractions_ax, fractions_lx, fractions_ix, fractions_ox,      &
                   fractions_rx, fractions_gx, fractions_wx, fractions_zx)
+             call t_stopf('CPL:seq_rest_read')
+
+             call t_drvstopf  ('CPL:RESTART_READ',cplrun=.true.)
+
           end if
           ! Clear the resume file so we don't try to read it again
           drv_resume = .FALSE.
@@ -4382,8 +4409,10 @@ subroutine cime_run_rof_recv_post()
     ! rof post
     !----------------------------------------------------------
     if (iamin_CPLID) then
-       call cime_comp_barriers(mpicom=mpicom_CPLID, timer='CPL:ROFPOST_BARRIER')
-       call t_drvstartf  ('CPL:ROFPOST',cplrun=.true.,barrier=mpicom_CPLID)
+
+       call cime_comp_barriers(mpicom=mpicom_CPLID, timer='CPL:ROFRUNPOST_BARRIER')
+       call t_drvstartf ('CPL:ROFRUNPOST',cplrun=.true.,barrier=mpicom_CPLID)
+
        if (drv_threading) call seq_comm_setnthreads(nthreads_CPLID)
 
        call component_diag(infodata, rof, flow='c2x', comment= 'recv rof', &
@@ -4394,7 +4423,9 @@ subroutine cime_run_rof_recv_post()
           if (rof_c2_ice) call prep_ice_calc_r2x_ix(timer='CPL:rofpost_rof2ice')
           if (rof_c2_ocn) call prep_ocn_calc_r2x_ox(timer='CPL:rofpost_rof2ocn')
        end if
-       call t_drvstopf  ('CPL:ROFPOST', cplrun=.true.)
+
+       call t_drvstopf  ('CPL:ROFRUNPOST', cplrun=.true.)
+
     endif
 
   end subroutine cime_run_rof_recv_post
@@ -4713,28 +4744,38 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
 
        call cime_comp_barriers(mpicom=mpicom_CPLID, timer='CPL:HISTORY_BARRIER')
        call t_drvstartf ('CPL:HISTORY',cplrun=.true.,barrier=mpicom_CPLID)
+       call t_startf('CPL:cime_run_write_history')
+
        if ( history_alarm) then
           if (drv_threading) call seq_comm_setnthreads(nthreads_CPLID)
           if (iamroot_CPLID) then
              write(logunit,104) ' Write history file at ',ymd,tod
              call shr_sys_flush(logunit)
           endif
 
+          call t_startf('CPL:seq_hist_write')
           call seq_hist_write(infodata, EClock_d, &
                atm, lnd, ice, ocn, rof, glc, wav, iac, &
                fractions_ax, fractions_lx, fractions_ix, fractions_ox,     &
                fractions_rx, fractions_gx, fractions_wx, fractions_zx, trim(cpl_inst_tag))
+          call t_stopf('CPL:seq_hist_write')
 
           if (drv_threading) call seq_comm_setnthreads(nthreads_GLOID)
        endif
 
        if (do_histavg) then
+
+          call t_startf('CPL:seq_hist_writeavg')
           call seq_hist_writeavg(infodata, EClock_d, &
                atm, lnd, ice, ocn, rof, glc, wav, iac, histavg_alarm, &
                trim(cpl_inst_tag))
+          call t_stopf('CPL:seq_hist_writeavg')
+
        endif
 
        if (do_hist_a2x) then
+
+          call t_startf('CPL:seq_hist_writeaux-a2x')
           do eai = 1,num_inst_atm
              inst_suffix =  component_get_suffix(atm(eai))
              if (trim(hist_a2x_flds) == 'all') then
@@ -4747,9 +4788,13 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      nx=atm_nx, ny=atm_ny, nt=ncpl, flds=hist_a2x_flds)
              endif
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-a2x')
+
        endif
 
        if (do_hist_a2x1hri .and. t1hr_alarm) then
+
+          call t_startf('CPL:seq_hist_writeaux-a2x1hri')
           do eai = 1,num_inst_atm
              inst_suffix =  component_get_suffix(atm(eai))
              if (trim(hist_a2x1hri_flds) == 'all') then
@@ -4762,9 +4807,13 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      nx=atm_nx, ny=atm_ny, nt=24, flds=hist_a2x1hri_flds)
              endif
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-a2x1hri')
+
        endif
 
        if (do_hist_a2x1hr) then
+
+          call t_startf('CPL:seq_hist_writeaux-a2x1hr')
           do eai = 1,num_inst_atm
              inst_suffix =  component_get_suffix(atm(eai))
              if (trim(hist_a2x1hr_flds) == 'all') then
@@ -4777,9 +4826,13 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      nx=atm_nx, ny=atm_ny, nt=24, write_now=t1hr_alarm, flds=hist_a2x1hr_flds)
              endif
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-a2x1hr')
+
        endif
 
        if (do_hist_a2x3hr) then
+
+          call t_startf('CPL:seq_hist_writeaux-a2x3hr')
           do eai = 1,num_inst_atm
              inst_suffix =  component_get_suffix(atm(eai))
              if (trim(hist_a2x3hr_flds) == 'all') then
@@ -4792,9 +4845,13 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      nx=atm_nx, ny=atm_ny, nt=8, write_now=t3hr_alarm, flds=hist_a2x3hr_flds)
              endif
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-a2x3hr')
+
        endif
 
        if (do_hist_a2x3hrp) then
+
+          call t_startf('CPL:seq_hist_writeaux-a2x3hrp')
           do eai = 1,num_inst_atm
              inst_suffix = component_get_suffix(atm(eai))
              if (trim(hist_a2x3hrp_flds) == 'all') then
@@ -4807,9 +4864,13 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      nx=atm_nx, ny=atm_ny, nt=8, write_now=t3hr_alarm, flds=hist_a2x3hrp_flds)
              endif
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-a2x3hrp')
+
        endif
 
        if (do_hist_a2x24hr) then
+
+          call t_startf('CPL:seq_hist_writeaux-a2x24hr')
           do eai = 1,num_inst_atm
              inst_suffix = component_get_suffix(atm(eai))
              if (trim(hist_a2x24hr_flds) == 'all') then
@@ -4822,6 +4883,8 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      nx=atm_nx, ny=atm_ny, nt=1, write_now=t24hr_alarm, flds=hist_a2x24hr_flds)
              endif
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-a2x24hr')
+
        endif
 
        if (do_hist_l2x1yrg) then
@@ -4865,6 +4928,8 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
              call shr_cal_ymds2rday_offset(etime=etime_curr, &
                   rdays_offset = tbnds1_offset, &
                   years_offset = -1)
+
+             call t_startf('CPL:seq_hist_writeaux-l2x1yrg')
              do eli = 1,num_inst_lnd
                 inst_suffix = component_get_suffix(lnd(eli))
                 ! Use yr_offset=-1 so the file with fields from year 1 has time stamp
@@ -4875,18 +4940,25 @@ subroutine cime_run_write_history(lnd2glc_averaged_now)
                      tbnds1_offset = tbnds1_offset, yr_offset=-1, &
                      av_to_write=prep_glc_get_l2gacc_lx_one_instance(eli))
              enddo
+             call t_stopf('CPL:seq_hist_writeaux-l2x1yrg')
+
           endif
        endif
 
        if (do_hist_l2x) then
+
+          call t_startf('CPL:seq_hist_writeaux-l2x')
           do eli = 1,num_inst_lnd
              inst_suffix =  component_get_suffix(lnd(eli))
              call seq_hist_writeaux(infodata, EClock_d, lnd(eli), flow='c2x', &
                   aname='l2x',dname='doml',inst_suffix=trim(inst_suffix),  &
                   nx=lnd_nx, ny=lnd_ny, nt=ncpl)
           enddo
+          call t_stopf('CPL:seq_hist_writeaux-l2x')
+
        endif
 
+       call t_stopf('CPL:cime_run_write_history')
        call t_drvstopf  ('CPL:HISTORY',cplrun=.true.)
 
     end if
@@ -4913,24 +4985,30 @@ subroutine cime_run_write_restart(drv_pause, write_restart, drv_resume_file)
        if ( (restart_alarm .or. drv_pause)) then
           call cime_comp_barriers(mpicom=mpicom_CPLID, timer='CPL:RESTART_BARRIER')
           call t_drvstartf ('CPL:RESTART',cplrun=.true.,barrier=mpicom_CPLID)
+          call t_startf('CPL:cime_run_write_restart')
+
           if (drv_threading) call seq_comm_setnthreads(nthreads_CPLID)
           if (iamroot_CPLID) then
              write(logunit,104) ' Write restart file at ',ymd,tod
              call shr_sys_flush(logunit)
           endif
 
+          call t_startf('CPL:seq_rest_write')
           call seq_rest_write(EClock_d, seq_SyncClock, infodata,       &
                atm, lnd, ice, ocn, rof, glc, wav, esp, iac,            &
                fractions_ax, fractions_lx, fractions_ix, fractions_ox, &
                fractions_rx, fractions_gx, fractions_wx, fractions_zx, &
                trim(cpl_inst_tag), drv_resume_file)
+          call t_stopf('CPL:seq_rest_write')
 
           if (iamroot_CPLID) then
              write(logunit,103) ' Restart filename: ',trim(drv_resume_file)
              call shr_sys_flush(logunit)
           endif
 
           if (drv_threading) call seq_comm_setnthreads(nthreads_GLOID)
+
+          call t_stopf('CPL:cime_run_write_restart')
           call t_drvstopf  ('CPL:RESTART',cplrun=.true.)
        else
           drv_resume_file = ' '

driver-mct/main/component_mod.F90

@@ -495,10 +495,13 @@ subroutine component_init_aream(infodata, rof_c2_ocn, samegrid_ao, samegrid_al,
           dom_s   => component_get_dom_cx(ocn(1))   ! dom_ox
           dom_d   => component_get_dom_cx(atm(1))   ! dom_ax
 
+          call t_startf('CPL:seq_map_readdata-ocn2atm')
           call seq_map_readdata('seq_maps.rc','ocn2atm_fmapname:', mpicom_CPLID, CPLID, &
                gsmap_s=gsmap_s, av_s=dom_s%data, avfld_s='aream', filefld_s='area_a', &
                gsmap_d=gsmap_d, av_d=dom_d%data, avfld_d='aream', filefld_d='area_b', &
                string='ocn2atm aream initialization')
+          call t_stopf('CPL:seq_map_readdata-ocn2atm')
+
        endif
     end if
 
@@ -514,13 +517,18 @@ subroutine component_init_aream(infodata, rof_c2_ocn, samegrid_ao, samegrid_al,
           gsmap_s => component_get_gsmap_cx(rof(1)) ! gsmap_rx
           dom_s   => component_get_dom_cx(rof(1))   ! dom_rx
 
+          call t_startf('CPL:seq_map_readdata-rof2ocn_liq')
           call seq_map_readdata('seq_maps.rc', 'rof2ocn_liq_rmapname:',mpicom_CPLID, CPLID, &
                gsmap_s=gsmap_s, av_s=dom_s%data, avfld_s='aream', filefld_s='area_a', &
                string='rof2ocn liq aream initialization')
+          call t_stopf('CPL:seq_map_readdata-rof2ocn_liq')
 
+          call t_startf('CPL:seq_map_readdata-rof2ocn_ice')
           call seq_map_readdata('seq_maps.rc', 'rof2ocn_ice_rmapname:',mpicom_CPLID, CPLID, &
                gsmap_s=gsmap_s, av_s=dom_s%data, avfld_s='aream', filefld_s='area_a', &
                string='rof2ocn ice aream initialization')
+          call t_stopf('CPL:seq_map_readdata-rof2ocn_ice')
+
        endif
     end if
 
@@ -534,9 +542,12 @@ subroutine component_init_aream(infodata, rof_c2_ocn, samegrid_ao, samegrid_al,
           gsmap_d => component_get_gsmap_cx(lnd(1)) ! gsmap_lx
           dom_d   => component_get_dom_cx(lnd(1))   ! dom_lx
 
+          call t_startf('CPL:seq_map_readdata-atm2lnd')
           call seq_map_readdata('seq_maps.rc','atm2lnd_fmapname:',mpicom_CPLID, CPLID, &
                gsmap_d=gsmap_d, av_d=dom_d%data, avfld_d='aream', filefld_d='area_b', &
                string='atm2lnd aream initialization')
+          call t_stopf('CPL:seq_map_readdata-atm2lnd')
+
        endif
     end if
 
@@ -550,9 +561,12 @@ subroutine component_init_aream(infodata, rof_c2_ocn, samegrid_ao, samegrid_al,
           gsmap_d => component_get_gsmap_cx(glc(1)) ! gsmap_gx
           dom_d   => component_get_dom_cx(glc(1))   ! dom_gx
 
+          call t_startf('CPL:seq_map_readdata-lnd2glc')
           call seq_map_readdata('seq_maps.rc','lnd2glc_fmapname:',mpicom_CPLID, CPLID, &
                gsmap_d=gsmap_d, av_d=dom_d%data, avfld_d='aream', filefld_d='area_b', &
                string='lnd2glc aream initialization')
+          call t_stopf('CPL:seq_map_readdata-lnd2glc')
+
        endif
     endif