New URL for NEMO forge!   http://forge.nemo-ocean.eu

Since March 2022 along with NEMO 4.2 release, the code development moved to a self-hosted GitLab.
This present forge is now archived and remained online for history.
timing.F90 in branches/2011/dev_r2769_LOCEAN_dynamic_mem/NEMOGCM/NEMO/OPA_SRC – NEMO

source: branches/2011/dev_r2769_LOCEAN_dynamic_mem/NEMOGCM/NEMO/OPA_SRC/timing.F90 @ 2775

Last change on this file since 2775 was 2771, checked in by rblod, 13 years ago

First implementation of timing, with tvd as an example, see ticket #829

  • Property svn:executable set to *
File size: 30.7 KB
Line 
1MODULE timing
2   !!========================================================================
3   !!                     ***  MODULE  timing  ***
4   !!========================================================================
5   !! History : 4.0  ! 2001-05  (R. Benshila)   
6   !!------------------------------------------------------------------------
7
8   !!------------------------------------------------------------------------
9   !!   timming_init    : initialize timing process
10   !!   timing_start    : start Timer
11   !!   timing_stop     : stop  Timer
12   !!   timing_reset    : end timing variable creation
13   !!   timing_finalize : compute stats and write output in calling w*_info
14   !!   timing_ini_var  : create timing variables
15   !!   timing_listing  : print instumented subroutines in ocean.output
16   !!   wcurrent_info   : compute and print detailed stats on the current CPU
17   !!   wave_info       : compute and print averaged statson all processors
18   !!   wmpi_info       : compute and write global stats 
19   !!   supress         : suppress an element of the timing linked list 
20   !!   insert          : insert an element of the timing linked list 
21   !!------------------------------------------------------------------------
22   USE in_out_manager  ! I/O manager
23   USE dom_oce         ! ocean domain
24   USE lib_mpp         
25   
26   IMPLICIT NONE
27   PRIVATE
28
29   PUBLIC   timing_init, timing_finalize   ! called in nemogcm module
30   PUBLIC   timing_reset                   ! called in step module
31   PUBLIC   timing_start, timing_stop      ! called in each routine to time
32   
33#if defined key_mpp_mpi
34   INCLUDE 'mpif.h'
35#endif
36
37   ! Variables for fine grain timing
38   TYPE timer
39      CHARACTER(LEN=20)  :: cname
40        REAL(wp)  :: t_cpu, t_clock, tsum_cpu, tsum_clock, tmax_cpu, tmax_clock, tmin_cpu, tmin_clock, tsub_cpu, tsub_clock
41      INTEGER :: ncount, ncount_max, ncount_rate 
42      INTEGER :: niter
43      LOGICAL :: l_tdone
44      TYPE(timer), POINTER :: next => NULL()
45      TYPE(timer), POINTER :: prev => NULL()
46      TYPE(timer), POINTER :: parent_section => NULL()
47   END TYPE timer
48   
49   TYPE alltimer
50      CHARACTER(LEN=20), DIMENSION(:), POINTER :: cname => NULL()
51        REAL(wp), DIMENSION(:), POINTER :: tsum_cpu   => NULL()
52        REAL(wp), DIMENSION(:), POINTER :: tsum_clock => NULL()
53        INTEGER, DIMENSION(:), POINTER :: niter => NULL()
54      TYPE(alltimer), POINTER :: next => NULL()
55      TYPE(alltimer), POINTER :: prev => NULL()
56   END TYPE alltimer 
57 
58   TYPE(timer), POINTER :: s_timer_root => NULL()
59   TYPE(timer), POINTER :: s_timer      => NULL()
60   TYPE(timer), POINTER :: s_wrk        => NULL()
61   REAL(wp) :: t_overclock, t_overcpu
62   LOGICAL :: l_initdone = .FALSE.
63   INTEGER :: nsize
64   
65   ! Variables for coarse grain timing
66   REAL(wp) :: tot_etime, tot_ctime
67   REAL(kind=wp), DIMENSION(2)     :: t_elaps, t_cpu
68   REAL(wp), ALLOCATABLE, DIMENSION(:) :: all_etime, all_ctime
69   INTEGER :: nfinal_count, ncount, ncount_rate, ncount_max
70   INTEGER, DIMENSION(8)           :: nvalues
71   CHARACTER(LEN=8), DIMENSION(2)  :: cdate
72   CHARACTER(LEN=10), DIMENSION(2) :: ctime
73   CHARACTER(LEN=5)                :: czone
74   
75   ! From of ouput file (1/proc or one global)   !RB to put in nammpp or namctl
76   LOGICAL :: ln_onefile = .TRUE. 
77   LOGICAL :: lwriter
78
79   !!----------------------------------------------------------------------
80   !! NEMO/OPA 4.0 , NEMO Consortium (2011)
81   !! $Id:$
82   !! Software governed by the CeCILL licence     (NEMOGCM/NEMO_CeCILL.txt)
83   !!----------------------------------------------------------------------
84CONTAINS
85
86   SUBROUTINE timing_start(cdinfo)
87      !!----------------------------------------------------------------------
88      !!               ***  ROUTINE timing_start  ***
89      !! ** Purpose :   collect execution time
90      !!----------------------------------------------------------------------
91      CHARACTER(len=*), INTENT(in) :: cdinfo
92      !
93       
94      ! Create timing structure at first call
95      IF( .NOT. l_initdone ) THEN
96         CALL timing_ini_var(cdinfo)
97      ELSE
98         s_timer => s_timer_root
99         DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) ) 
100            IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next
101         END DO
102      ENDIF         
103      s_timer%l_tdone = .FALSE.
104      s_timer%niter = s_timer%niter + 1
105      s_timer%t_cpu = 0.
106      s_timer%t_clock = 0.
107                 
108      ! CPU time collection
109      CALL CPU_TIME( s_timer%t_cpu  )
110      ! clock time collection
111#if defined key_mpp_mpi
112      s_timer%t_clock= MPI_Wtime()
113#else
114      CALL SYSTEM_CLOCK(COUNT_RATE=s_timer%ncount_rate, COUNT_MAX=s_timer%ncount_max)
115      CALL SYSTEM_CLOCK(COUNT = s_timer%ncount)
116#endif
117      !
118   END SUBROUTINE timing_start
119
120
121   SUBROUTINE timing_stop(cdinfo, csection)
122      !!----------------------------------------------------------------------
123      !!               ***  ROUTINE timing_stop  ***
124      !! ** Purpose :   finalize timing and output
125      !!----------------------------------------------------------------------
126      CHARACTER(len=*), INTENT(in) :: cdinfo
127      CHARACTER(len=*), INTENT(in), OPTIONAL :: csection
128      !
129      INTEGER  :: ifinal_count, iperiods   
130      REAL(wp) :: zcpu_end, zmpitime
131
132      ! clock time collection
133#if defined key_mpp_mpi
134      zmpitime = MPI_Wtime()
135#else
136      CALL SYSTEM_CLOCK(COUNT = ifinal_count)
137#endif
138      ! CPU time collection
139      CALL CPU_TIME( zcpu_end )
140
141      s_timer => s_timer_root
142      DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) ) 
143         IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next
144      END DO
145 
146      ! CPU time correction
147      s_timer%t_cpu  = zcpu_end - s_timer%t_cpu - t_overcpu - s_timer%tsub_cpu
148 
149      ! clock time correction
150#if defined key_mpp_mpi
151      s_timer%t_clock = zmpitime - s_timer%t_clock - t_overclock - s_timer%tsub_clock
152#else
153      iperiods = ifinal_count - s_timer%ncount
154      IF( ifinal_count < s_timer%ncount )  &
155          iperiods = iperiods + s_timer%ncount_max 
156      s_timer%t_clock  = REAL(iperiods) / s_timer%ncount_rate - t_overclock - s_timer%tsub_clock
157#endif
158     
159      ! Correction of parent section
160      IF( ASSOCIATED(s_timer%parent_section) .AND. .NOT. PRESENT(csection) ) THEN
161         s_timer%parent_section%tsub_cpu   = s_timer%parent_section%tsub_cpu   + s_timer%t_cpu 
162         s_timer%parent_section%tsub_clock = s_timer%parent_section%tsub_clock + s_timer%t_clock 
163      ENDIF
164     
165      ! time diagnostics
166      s_timer%tsum_clock = s_timer%tsum_clock + s_timer%t_clock 
167      s_timer%tsum_cpu   = s_timer%tsum_cpu   + s_timer%t_cpu
168!RB to use to get min/max during a time integration
169!      IF( .NOT. l_initdone ) THEN
170!         s_timer%tmin_clock = s_timer%t_clock
171!         s_timer%tmin_cpu   = s_timer%t_cpu
172!      ELSE
173!         s_timer%tmin_clock = MIN( s_timer%tmin_clock, s_timer%t_clock )
174!         s_timer%tmin_cpu   = MIN( s_timer%tmin_cpu  , s_timer%t_cpu   )
175!      ENDIF   
176!      s_timer%tmax_clock = MAX( s_timer%tmax_clock, s_timer%t_clock )
177!      s_timer%tmax_cpu   = MAX( s_timer%tmax_cpu  , s_timer%t_cpu   ) 
178      !
179      s_timer%tsub_clock = 0.
180      s_timer%tsub_cpu = 0.
181      s_timer%l_tdone = .TRUE.
182      !
183   END SUBROUTINE timing_stop
184 
185 
186   SUBROUTINE timing_init
187      !!----------------------------------------------------------------------
188      !!               ***  ROUTINE timing_init  ***
189      !! ** Purpose :   open timing output file
190      !!----------------------------------------------------------------------
191      INTEGER :: iperiods, istart_count, ifinal_count
192      REAL(wp) :: zdum
193      LOGICAL :: ll_f
194             
195      IF( ln_onefile ) THEN
196         IF( lwp) CALL ctl_opn( numtime, 'timing.output', 'REPLACE', 'FORMATTED', 'SEQUENTIAL', -1, numout,.TRUE., narea )
197         lwriter = lwp
198      ELSE
199         CALL ctl_opn( numtime, 'timing.output', 'REPLACE', 'FORMATTED', 'SEQUENTIAL', -1, numout,.FALSE., narea )
200         lwriter = .TRUE.
201      ENDIF
202     
203      IF( lwriter) THEN     
204         WRITE(numtime,*)
205         WRITE(numtime,*) '      CNRS - NERC - Met OFFICE - MERCATOR-ocean - CMCC - INGV'
206         WRITE(numtime,*) '                             NEMO team'
207         WRITE(numtime,*) '                  Ocean General Circulation Model'
208         WRITE(numtime,*) '                        version 3.3  (2010) '
209         WRITE(numtime,*)
210         WRITE(numtime,*) '                        Timing Informations '
211         WRITE(numtime,*)
212         WRITE(numtime,*)
213      ENDIF   
214     
215      ! Compute clock function overhead
216#if defined key_mpp_mpi       
217      t_overclock = MPI_WTIME()
218      t_overclock = MPI_WTIME() - t_overclock
219#else       
220      CALL SYSTEM_CLOCK(COUNT_RATE=ncount_rate, COUNT_MAX=ncount_max)
221      CALL SYSTEM_CLOCK(COUNT = istart_count)
222      CALL SYSTEM_CLOCK(COUNT = ifinal_count)
223      iperiods = ifinal_count - istart_count
224      IF( ifinal_count < istart_count )  &
225          iperiods = iperiods + ncount_max 
226      t_overclock = REAL(iperiods) / ncount_rate
227#endif
228
229      ! Compute cpu_time function overhead
230      CALL CPU_TIME(zdum)
231      CALL CPU_TIME(t_overcpu)
232     
233      ! End overhead omputation 
234      t_overcpu = t_overcpu - zdum       
235      t_overclock = t_overcpu + t_overclock       
236
237      ! Timing on date and time
238      CALL DATE_AND_TIME(cdate(1),ctime(1),czone,nvalues)
239   
240      CALL CPU_TIME(t_cpu(1))     
241#if defined key_mpp_mpi       
242      ! Start elapsed and CPU time counters
243      t_elaps(1) = MPI_WTIME()
244#else
245      CALL SYSTEM_CLOCK(COUNT_RATE=ncount_rate, COUNT_MAX=ncount_max)
246      CALL SYSTEM_CLOCK(COUNT = ncount)
247#endif                 
248      !
249   END SUBROUTINE timing_init
250
251
252   SUBROUTINE timing_finalize
253      !!----------------------------------------------------------------------
254      !!               ***  ROUTINE timing_finalize ***
255      !! ** Purpose :  compute average time
256      !!               write timing output file
257      !!----------------------------------------------------------------------
258      TYPE(timer), POINTER :: s_temp
259      INTEGER :: idum, iperiods, icode
260      LOGICAL :: ll_ord, ll_averep
261      CHARACTER(len=120) :: clfmt           
262     
263      ll_averep = .TRUE.
264   
265      ! total CPU and elapse
266      CALL CPU_TIME(t_cpu(2))
267      t_cpu(2)   = t_cpu(2)    - t_cpu(1)   - t_overcpu
268#if defined key_mpp_mpi
269      t_elaps(2) = MPI_WTIME() - t_elaps(1) - t_overclock
270#else
271      CALL SYSTEM_CLOCK(COUNT = nfinal_count)
272      iperiods = nfinal_count - ncount
273      IF( nfinal_count < ncount )  &
274          iperiods = iperiods + ncount_max 
275      t_elaps(2) = REAL(iperiods) / ncount_rate - t_overclock
276#endif     
277
278      ! End of timings on date & time
279      CALL DATE_AND_TIME(cdate(2),ctime(2),czone,nvalues)
280       
281      ! Compute the numer of routines
282      nsize = 0 
283      s_timer => s_timer_root
284      DO WHILE( ASSOCIATED(s_timer) )
285         nsize = nsize + 1
286         s_timer => s_timer%next
287      END DO
288      idum = nsize
289      IF(lk_mpp) CALL mpp_sum(idum)
290      IF( idum/jpnij /= nsize ) THEN
291         IF( lwriter ) WRITE(numtime,*) '        ===> W A R N I N G: '
292         IF( lwriter ) WRITE(numtime,*) ' Some CPU have different number of routines instrumented for timing'
293         IF( lwriter ) WRITE(numtime,*) ' No detailed report on averaged timing can be provided'
294         IF( lwriter ) WRITE(numtime,*) ' The following detailed report only deals with the current processor'
295         IF( lwriter ) WRITE(numtime,*)
296         ll_averep = .FALSE.
297      ENDIF   
298
299#if defined key_mpp_mpi     
300      ! in MPI gather some info
301      ALLOCATE( all_etime(jpnij), all_ctime(jpnij) )
302      CALL MPI_ALLGATHER(t_elaps(2), 1, MPI_DOUBLE_PRECISION,   &
303                         all_etime , 1, MPI_DOUBLE_PRECISION,   &
304                         MPI_COMM_OPA, icode)
305      CALL MPI_ALLGATHER(t_cpu(2) , 1, MPI_DOUBLE_PRECISION,   &
306                         all_ctime, 1, MPI_DOUBLE_PRECISION,   &
307                         MPI_COMM_OPA, icode)
308      tot_etime = SUM(all_etime(:))
309      tot_ctime = SUM(all_ctime(:))
310#else
311      tot_etime = t_elaps(2)
312      tot_ctime = t_cpu  (2)           
313#endif
314
315      ! write output file
316      IF( lwriter ) WRITE(numtime,*) 'Total timing (sum) :'
317      IF( lwriter ) WRITE(numtime,*) '--------------------'
318      IF( lwriter ) WRITE(numtime,*) 'Elapsed Time (s)  ','CPU Time (s)'
319      IF( lwriter ) WRITE(numtime,'(5x,f12.3,2x,f12.3)')  tot_etime, tot_ctime
320      IF( lwriter ) WRITE(numtime,*) 
321#if defined key_mpp_mpi
322      IF( ll_averep ) CALL waver_info
323      CALL wmpi_info
324#endif     
325      IF( lwriter ) CALL wcurrent_info
326     
327      clfmt='(1X,"Timing started on ",2(A2,"/"),A4," at ",2(A2,":"),A2," MET ",A3,":",A2," from GMT")'
328      IF( lwriter ) WRITE(numtime, TRIM(clfmt)) &           
329      &       cdate(1)(7:8), cdate(1)(5:6), cdate(1)(1:4),   &
330      &       ctime(1)(1:2), ctime(1)(3:4), ctime(1)(5:6),   &
331      &       czone(1:3),    czone(4:5)                     
332      clfmt='(1X,  "Timing   ended on ",2(A2,"/"),A4," at ",2(A2,":"),A2," MET ",A3,":",A2," from GMT")'
333      IF( lwriter ) WRITE(numtime, TRIM(clfmt)) &           
334      &       cdate(2)(7:8), cdate(2)(5:6), cdate(2)(1:4),   &
335      &       ctime(2)(1:2), ctime(2)(3:4), ctime(2)(5:6),   &
336      &       czone(1:3),    czone(4:5)
337
338      IF( lwriter ) CLOSE(numtime) 
339      !
340   END SUBROUTINE timing_finalize
341   
342
343   SUBROUTINE wcurrent_info
344      !!----------------------------------------------------------------------
345      !!               ***  ROUTINE wcurrent_info ***
346      !! ** Purpose :  compute and write timing output file
347      !!----------------------------------------------------------------------
348      LOGICAL :: ll_ord
349      CHARACTER(len=2048) :: clfmt           
350   
351      ! reorder the current list by elapse time     
352      s_wrk => NULL()
353      s_timer => s_timer_root
354      DO
355         ll_ord = .TRUE.
356         s_timer => s_timer_root
357         DO WHILE ( ASSOCIATED( s_timer%next ) )
358         IF (.NOT. ASSOCIATED(s_timer%next)) EXIT
359            IF ( s_timer%tsum_clock < s_timer%next%tsum_clock ) THEN
360               ALLOCATE(s_wrk)
361               s_wrk = s_timer%next
362               CALL insert  (s_timer, s_timer_root, s_wrk)
363               CALL suppress(s_timer%next)           
364               ll_ord = .FALSE.
365               CYCLE           
366            ENDIF           
367         IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next
368         END DO         
369         IF( ll_ord ) EXIT
370      END DO
371           
372      ! write current info
373      WRITE(numtime,*) 'Detailed timing for proc :', narea-1
374      WRITE(numtime,*) '--------------------------'
375      WRITE(numtime,*) 'Section             ',            &
376      &   'Elapsed Time (s)  ','Elapsed Time (%)  ',   &
377      &   'CPU Time(s)  ','CPU Time (%)  ','CPU/Elapsed  ','Frequency' 
378      s_timer => s_timer_root 
379      clfmt = '(1x,a,4x,f12.3,6x,f12.3,x,f12.3,2x,f12.3,6x,f7.3,2x,i9)'
380      DO WHILE ( ASSOCIATED(s_timer) )
381         WRITE(numtime,TRIM(clfmt))   s_timer%cname,   &
382         &   s_timer%tsum_clock,s_timer%tsum_clock*100./t_elaps(2),            &
383         &   s_timer%tsum_cpu  ,s_timer%tsum_cpu*100./t_cpu(2)    ,            &
384         &   s_timer%tsum_cpu/s_timer%tsum_clock, s_timer%niter
385         s_timer => s_timer%next
386      END DO
387      WRITE(numtime,*)
388      !                 
389   END SUBROUTINE wcurrent_info
390
391#if defined key_mpp_mpi     
392   SUBROUTINE waver_info
393      !!----------------------------------------------------------------------
394      !!               ***  ROUTINE wcurrent_info ***
395      !! ** Purpose :  compute and write averaged timing informations
396      !!----------------------------------------------------------------------
397      TYPE(alltimer), POINTER :: sl_timer_glob_root => NULL()
398      TYPE(alltimer), POINTER :: sl_timer_glob      => NULL()
399      TYPE(timer), POINTER :: sl_timer_ave_root => NULL()
400      TYPE(timer), POINTER :: sl_timer_ave      => NULL()
401      INTEGER :: icode
402      LOGICAL :: ll_ord           
403      CHARACTER(len=200) :: clfmt             
404                 
405      ! Initialised the global strucutre   
406      ALLOCATE(sl_timer_glob_root)
407      ALLOCATE(sl_timer_glob_root%cname     (jpnij))
408      ALLOCATE(sl_timer_glob_root%tsum_cpu  (jpnij))
409      ALLOCATE(sl_timer_glob_root%tsum_clock(jpnij))
410      ALLOCATE(sl_timer_glob_root%niter     (jpnij))
411      sl_timer_glob_root%cname(:)       = ''
412      sl_timer_glob_root%tsum_cpu(:)   = 0._wp
413      sl_timer_glob_root%tsum_clock(:) = 0._wp
414      sl_timer_glob_root%niter(:)      = 0
415      sl_timer_glob_root%next => NULL()
416      sl_timer_glob_root%prev => NULL()
417      ALLOCATE(sl_timer_glob)
418      ALLOCATE(sl_timer_glob%cname     (jpnij))
419      ALLOCATE(sl_timer_glob%tsum_cpu  (jpnij))
420      ALLOCATE(sl_timer_glob%tsum_clock(jpnij))
421      ALLOCATE(sl_timer_glob%niter     (jpnij))
422      sl_timer_glob => sl_timer_glob_root
423      !
424      IF( narea .EQ. 1 ) THEN
425         ALLOCATE(sl_timer_ave_root)
426         sl_timer_ave_root%cname       = ''
427         sl_timer_ave_root%t_cpu      = 0._wp
428         sl_timer_ave_root%t_clock    = 0._wp
429         sl_timer_ave_root%tsum_cpu   = 0._wp
430         sl_timer_ave_root%tsum_clock = 0._wp
431         sl_timer_ave_root%tmax_cpu   = 0._wp
432         sl_timer_ave_root%tmax_clock = 0._wp
433         sl_timer_ave_root%tmin_cpu   = 0._wp
434         sl_timer_ave_root%tmin_clock = 0._wp
435         sl_timer_ave_root%tsub_cpu   = 0._wp
436         sl_timer_ave_root%tsub_clock = 0._wp
437         sl_timer_ave_root%ncount      = 0
438         sl_timer_ave_root%ncount_rate = 0
439         sl_timer_ave_root%ncount_max  = 0
440         sl_timer_ave_root%niter       = 0
441         sl_timer_ave_root%l_tdone  = .FALSE.
442         sl_timer_ave_root%next => NULL()
443         sl_timer_ave_root%prev => NULL()
444         ALLOCATE(sl_timer_ave)
445         sl_timer_ave => sl_timer_ave_root           
446      ENDIF 
447     
448      ! Gather info from all processors
449      s_timer => s_timer_root
450      DO WHILE ( ASSOCIATED(s_timer) )
451         CALL MPI_GATHER(s_timer%cname     , 20, MPI_CHARACTER,   &
452                         sl_timer_glob%cname, 20, MPI_CHARACTER,   &
453                         0, MPI_COMM_OPA, icode)
454         CALL MPI_GATHER(s_timer%tsum_clock     , 1, MPI_DOUBLE_PRECISION,   &
455                         sl_timer_glob%tsum_clock, 1, MPI_DOUBLE_PRECISION,   &
456                         0, MPI_COMM_OPA, icode)
457         CALL MPI_GATHER(s_timer%tsum_cpu     , 1, MPI_DOUBLE_PRECISION,   &
458                         sl_timer_glob%tsum_cpu, 1, MPI_DOUBLE_PRECISION,   &
459                         0, MPI_COMM_OPA, icode)
460         CALL MPI_GATHER(s_timer%niter     , 1, MPI_INTEGER,   &
461                         sl_timer_glob%niter, 1, MPI_INTEGER,   &
462                         0, MPI_COMM_OPA, icode)
463         IF( narea == 1 .AND. ASSOCIATED(s_timer%next) ) THEN
464            ALLOCATE(sl_timer_glob%next)
465            ALLOCATE(sl_timer_glob%next%cname     (jpnij))
466            ALLOCATE(sl_timer_glob%next%tsum_cpu  (jpnij))
467            ALLOCATE(sl_timer_glob%next%tsum_clock(jpnij))
468            ALLOCATE(sl_timer_glob%next%niter     (jpnij))
469            sl_timer_glob%next%prev => sl_timer_glob
470            sl_timer_glob%next%next => NULL()
471            sl_timer_glob           => sl_timer_glob%next
472         ENDIF             
473         s_timer => s_timer%next
474      END DO     
475     
476      IF( narea == 1 ) THEN   
477         ! Compute some stats
478         sl_timer_glob => sl_timer_glob_root
479         DO WHILE( ASSOCIATED(sl_timer_glob) )
480            sl_timer_ave%cname  = sl_timer_glob%cname(1)
481            sl_timer_ave%tsum_cpu   = SUM   (sl_timer_glob%tsum_cpu  (:)) / jpnij
482            sl_timer_ave%tsum_clock = SUM   (sl_timer_glob%tsum_clock(:)) / jpnij
483            sl_timer_ave%tmax_cpu   = MAXVAL(sl_timer_glob%tsum_cpu  (:))
484            sl_timer_ave%tmax_clock = MAXVAL(sl_timer_glob%tsum_clock(:))
485            sl_timer_ave%tmin_cpu   = MINVAL(sl_timer_glob%tsum_cpu  (:))
486            sl_timer_ave%tmin_clock = MINVAL(sl_timer_glob%tsum_clock(:))
487            sl_timer_ave%niter      = SUM   (sl_timer_glob%niter     (:))
488            !
489            IF( ASSOCIATED(sl_timer_glob%next) ) THEN
490               ALLOCATE(sl_timer_ave%next)         
491               sl_timer_ave%next%prev => sl_timer_ave
492               sl_timer_ave%next%next => NULL()           
493               sl_timer_ave           => sl_timer_ave%next
494            ENDIF
495            sl_timer_glob => sl_timer_glob%next                               
496         END DO         
497     
498         ! reorder the avearged list by CPU time     
499         s_wrk => NULL()
500         sl_timer_ave => sl_timer_ave_root
501         DO
502            ll_ord = .TRUE.
503            sl_timer_ave => sl_timer_ave_root
504            DO WHILE( ASSOCIATED( sl_timer_ave%next ) )
505            IF( .NOT. ASSOCIATED(sl_timer_ave%next) ) EXIT
506               IF ( sl_timer_ave%tsum_clock < sl_timer_ave%next%tsum_clock ) THEN
507                  ALLOCATE(s_wrk)
508                  s_wrk = sl_timer_ave%next
509                  CALL insert  (sl_timer_ave, sl_timer_ave_root, s_wrk)
510                  CALL suppress(sl_timer_ave%next)           
511                  ll_ord = .FALSE.
512                  CYCLE           
513               ENDIF           
514            IF( ASSOCIATED(sl_timer_ave%next) ) sl_timer_ave => sl_timer_ave%next
515            END DO         
516           IF( ll_ord ) EXIT
517         END DO
518
519         ! write averaged info
520         WRITE(numtime,*) 'Averaged timing on all processors :'
521         WRITE(numtime,*) '-----------------------------------'
522         WRITE(numtime,*) 'Section             ',                &
523         &   'Elapsed Time (s)  ','Elapsed Time (%)  ',          &
524         &   'CPU Time(s)  ','CPU Time (%)  ','CPU/Elapsed  ',   &
525         &   'Max Elapsed (%)  ','Min elapsed (%)  ',            &           
526         &   'Frequency' 
527         sl_timer_ave => sl_timer_ave_root 
528         clfmt = '(1x,a,4x,f12.3,6x,f12.3,x,f12.3,2x,f12.3,6x,f7.3,5x,f12.3,5x,f12.3,2x,f9.2)'
529         DO WHILE ( ASSOCIATED(sl_timer_ave) )
530            WRITE(numtime,TRIM(clfmt))   sl_timer_ave%cname,                            &
531            &   sl_timer_ave%tsum_clock,sl_timer_ave%tsum_clock*100.*jpnij/tot_etime,   &
532            &   sl_timer_ave%tsum_cpu  ,sl_timer_ave%tsum_cpu*100.*jpnij/tot_ctime  ,   &
533            &   sl_timer_ave%tsum_cpu/sl_timer_ave%tsum_clock,                          &
534            &   sl_timer_ave%tmax_clock*100.*jpnij/tot_etime,                           &
535            &   sl_timer_ave%tmin_clock*100.*jpnij/tot_etime,                           &                                               
536            &   sl_timer_ave%niter/REAL(jpnij)
537            sl_timer_ave => sl_timer_ave%next
538         END DO
539         WRITE(numtime,*)
540         !
541         DEALLOCATE(sl_timer_ave_root)
542      ENDIF
543      !
544      DEALLOCATE(sl_timer_glob_root)
545      !                 
546   END SUBROUTINE waver_info
547 
548 
549   SUBROUTINE wmpi_info
550      !!----------------------------------------------------------------------
551      !!               ***  ROUTINE wmpi_time  ***
552      !! ** Purpose :   compute and write a summary of MPI infos
553      !!----------------------------------------------------------------------   
554      !   
555      INTEGER                            :: idum, icode
556      INTEGER, ALLOCATABLE, DIMENSION(:) :: iall_rank
557      REAL(wp) :: ztot_ratio
558      REAL(wp) :: zmax_etime, zmax_ctime, zmax_ratio, zmin_etime, zmin_ctime, zmin_ratio
559      REAL(wp) :: zavg_etime, zavg_ctime, zavg_ratio
560      REAL(wp), ALLOCATABLE, DIMENSION(:) :: zall_ratio
561      CHARACTER(LEN=128), dimension(8) :: cllignes
562      CHARACTER(LEN=128)               :: clhline, clstart_date, clfinal_date
563      CHARACTER(LEN=2048)              :: clfmt   
564   
565      ! Gather all times
566      ALLOCATE( zall_ratio(jpnij), iall_rank(jpnij) )
567      IF( narea == 1 ) THEN
568         iall_rank(:) = (/ (idum,idum=0,jpnij-1) /)
569   
570         ! Compute elapse user time
571         zavg_etime = tot_etime/REAL(jpnij,wp)
572         zmax_etime = MAXVAL(all_etime(:))
573         zmin_etime = MINVAL(all_etime(:))
574
575         ! Compute CPU user time
576         zavg_ctime = tot_ctime/REAL(jpnij,wp)
577         zmax_ctime = MAXVAL(all_ctime(:))
578         zmin_ctime = MINVAL(all_ctime(:))
579   
580         ! Compute cpu/elapsed ratio
581         zall_ratio(:) = all_ctime(:) / all_etime(:)
582         ztot_ratio    = SUM(zall_ratio(:))
583         zavg_ratio    = ztot_ratio/REAL(jpnij,wp)
584         zmax_ratio    = MAXVAL(zall_ratio(:))
585         zmin_ratio    = MINVAL(zall_ratio(:))   
586   
587         ! Output Format
588         clhline    ='1x,13("-"),"|",18("-"),"|",14("-"),"|",18("-"),/,'
589         cllignes(1)='(1x,"MPI summary report :",/,'
590         cllignes(2)='1x,"--------------------",//,'
591         cllignes(3)='1x,"Process Rank |"," Elapsed Time (s) |"," CPU Time (s) |"," Ratio CPU/Elapsed",/,'
592         cllignes(4)='    (1x,i4,9x,"|",f12.3,6x,"|",f12.3,2x,"|",4x,f7.3,/),'
593         WRITE(cllignes(4)(1:4),'(I4)') jpnij
594         cllignes(5)='1x,"Total        |",f12.3,6x,"|",F12.3,2x,"|",4x,f7.3,/,'
595         cllignes(6)='1x,"Minimum      |",f12.3,6x,"|",F12.3,2x,"|",4x,f7.3,/,'
596         cllignes(7)='1x,"Maximum      |",f12.3,6x,"|",F12.3,2x,"|",4x,f7.3,/,'
597         cllignes(8)='1x,"Average      |",f12.3,6x,"|",F12.3,2x,"|",4x,f7.3)'
598         clfmt=TRIM(cllignes(1))// TRIM(cllignes(2))//TRIM(cllignes(3))//          &
599           & TRIM(clhline)//TRIM(cllignes(4))//TRIM(clhline)//TRIM(cllignes(5))//  &
600           & TRIM(clhline)//TRIM(cllignes(6))//TRIM(clhline)//TRIM(cllignes(7))//  &
601           & TRIM(clhline)//TRIM(cllignes(8))
602         WRITE(numtime, TRIM(clfmt)) &
603             (iall_rank(idum),all_etime(idum),all_ctime(idum),zall_ratio(idum),idum=1, jpnij), &
604             tot_etime,     tot_ctime,     ztot_ratio,   &
605             zmin_etime,    zmin_ctime,    zmin_ratio,   &
606             zmax_etime,    zmax_ctime,    zmax_ratio,   &
607             zavg_etime,    zavg_ctime,    zavg_ratio
608         WRITE(numtime,*)   
609      END IF
610      !
611      DEALLOCATE(zall_ratio, iall_rank)
612      !
613   END SUBROUTINE wmpi_info
614#endif   
615
616
617   SUBROUTINE timing_ini_var(cdinfo)
618      !!----------------------------------------------------------------------
619      !!               ***  ROUTINE timing_ini_var  ***
620      !! ** Purpose :   create timing structure
621      !!----------------------------------------------------------------------
622      CHARACTER(len=*), INTENT(in) :: cdinfo
623      LOGICAL :: ll_section
624       
625      !
626      IF( .NOT. ASSOCIATED(s_timer_root) ) THEN
627         ALLOCATE(s_timer_root)
628         s_timer_root%cname       = cdinfo
629         s_timer_root%t_cpu      = 0._wp
630         s_timer_root%t_clock    = 0._wp
631         s_timer_root%tsum_cpu   = 0._wp
632         s_timer_root%tsum_clock = 0._wp
633         s_timer_root%tmax_cpu   = 0._wp
634         s_timer_root%tmax_clock = 0._wp
635         s_timer_root%tmin_cpu   = 0._wp
636         s_timer_root%tmin_clock = 0._wp
637         s_timer_root%tsub_cpu   = 0._wp
638         s_timer_root%tsub_clock = 0._wp
639         s_timer_root%ncount      = 0
640         s_timer_root%ncount_rate = 0
641         s_timer_root%ncount_max  = 0
642         s_timer_root%niter       = 0
643         s_timer_root%l_tdone  = .FALSE.
644         s_timer_root%next => NULL()
645         s_timer_root%prev => NULL()
646         s_timer => s_timer_root
647         !
648         ALLOCATE(s_wrk)
649         s_wrk => NULL()
650         
651      ELSE
652         s_timer => s_timer_root
653         ! case of already existing area (typically inside a loop)
654         DO WHILE( ASSOCIATED(s_timer) ) 
655            IF( TRIM(s_timer%cname) .EQ. TRIM(cdinfo) ) RETURN
656            s_timer => s_timer%next
657         END DO
658         
659         ! end of the chain
660         s_timer => s_timer_root
661         DO WHILE( ASSOCIATED(s_timer%next) )
662            s_timer => s_timer%next
663         END DO
664         
665         ALLOCATE(s_timer%next)     
666         s_timer%next%cname       = cdinfo
667         s_timer%next%t_cpu      = 0._wp
668         s_timer%next%t_clock    = 0._wp
669         s_timer%next%tsum_cpu   = 0._wp
670         s_timer%next%tsum_clock = 0._wp 
671         s_timer%next%tmax_cpu   = 0._wp
672         s_timer%next%tmax_clock = 0._wp
673         s_timer%next%tmin_cpu   = 0._wp
674         s_timer%next%tmin_clock = 0._wp
675         s_timer%next%tsub_cpu   = 0._wp
676         s_timer%next%tsub_clock = 0._wp
677         s_timer%next%ncount      = 0
678         s_timer%next%ncount_rate = 0
679         s_timer%next%ncount_max  = 0
680         s_timer%next%niter       = 0
681         s_timer%next%l_tdone  = .FALSE.
682         s_timer%next%parent_section => NULL()
683         s_timer%next%prev => s_timer
684         s_timer%next%next => NULL()
685         s_timer => s_timer%next
686
687         ! are we inside a section
688         s_wrk => s_timer%prev
689         ll_section = .FALSE.
690         DO WHILE( ASSOCIATED(s_wrk) .AND. .NOT. ll_section )
691            IF( .NOT. s_wrk%l_tdone ) THEN
692               ll_section = .TRUE.
693               s_timer%parent_section => s_wrk 
694            ENDIF
695            s_wrk => s_wrk%prev
696         END DO
697      ENDIF         
698      !
699   END SUBROUTINE timing_ini_var
700
701
702   SUBROUTINE timing_reset
703      !!----------------------------------------------------------------------
704      !!               ***  ROUTINE timing_reset  ***
705      !! ** Purpose :   go to root of timing tree
706      !!----------------------------------------------------------------------
707      l_initdone = .TRUE. 
708      IF(lwp) WRITE(numout,*)
709      IF(lwp) WRITE(numout,*) 'timing_reset : instrumented routines for timing'
710      IF(lwp) WRITE(numout,*) '~~~~~~~~~~~~'
711      CALL timing_list(s_timer_root)
712      WRITE(*,*)
713      !
714   END SUBROUTINE timing_reset
715
716
717   RECURSIVE SUBROUTINE timing_list(ptr)
718   
719      TYPE(timer), POINTER, INTENT(inout) :: ptr
720      !
721      IF( ASSOCIATED(ptr%next) ) CALL timing_list(ptr%next)
722      IF(lwp) WRITE(numout,*)'   ', ptr%cname   
723      !
724   END SUBROUTINE timing_list
725
726
727   SUBROUTINE insert(sd_current, sd_root ,sd_ptr)
728      !!----------------------------------------------------------------------
729      !!               ***  ROUTINE insert  ***
730      !! ** Purpose :   insert an element in  imer structure
731      !!----------------------------------------------------------------------
732      TYPE(timer), POINTER, INTENT(inout) :: sd_current, sd_root, sd_ptr
733      !
734     
735      IF( ASSOCIATED( sd_current, sd_root ) ) THEN
736         sd_root => sd_ptr
737      ELSE
738         sd_current%prev%next => sd_ptr
739      END IF
740      sd_ptr%next     => sd_current
741      sd_ptr%prev     => sd_current%prev
742      sd_current%prev => sd_ptr
743      !   
744   END SUBROUTINE insert
745 
746 
747   SUBROUTINE suppress(sd_ptr)
748      !!----------------------------------------------------------------------
749      !!               ***  ROUTINE suppress  ***
750      !! ** Purpose :   supress an element in timer structure
751      !!----------------------------------------------------------------------
752      TYPE(timer), POINTER, INTENT(inout) :: sd_ptr
753      !
754      TYPE(timer), POINTER :: sl_temp
755   
756      sl_temp => sd_ptr
757      sd_ptr => sd_ptr%next   
758      IF ( ASSOCIATED(sl_temp%next) ) sl_temp%next%prev => sl_temp%prev
759      DEALLOCATE(sl_temp)
760      !
761    END SUBROUTINE suppress
762
763   !!=====================================================================
764END MODULE timing
Note: See TracBrowser for help on using the repository browser.