source: palm/trunk/SOURCE/cpulog.f90 @ 1682

Last change on this file since 1682 was 1682, checked in by knoop, 9 years ago

Code annotations made doxygen readable

  • Property svn:keywords set to Id
File size: 21.8 KB
Line 
1!> @file cpulog.f90
2!--------------------------------------------------------------------------------!
3! This file is part of PALM.
4!
5! PALM is free software: you can redistribute it and/or modify it under the terms
6! of the GNU General Public License as published by the Free Software Foundation,
7! either version 3 of the License, or (at your option) any later version.
8!
9! PALM is distributed in the hope that it will be useful, but WITHOUT ANY
10! WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR
11! A PARTICULAR PURPOSE.  See the GNU General Public License for more details.
12!
13! You should have received a copy of the GNU General Public License along with
14! PALM. If not, see <http://www.gnu.org/licenses/>.
15!
16! Copyright 1997-2014 Leibniz Universitaet Hannover
17!--------------------------------------------------------------------------------!
18!
19! Current revisions:
20! -----------------
21! Code annotations made doxygen readable
22!
23! Former revisions:
24! -----------------
25! $Id: cpulog.f90 1682 2015-10-07 23:56:08Z knoop $
26!
27! 1402 2014-05-09 14:25:13Z raasch
28! location messages added
29!
30! 1369 2014-04-24 05:57:38Z raasch
31! routine description added
32!
33! 1353 2014-04-08 15:21:23Z heinze
34! REAL constants provided with KIND-attribute
35!
36! 1322 2014-03-20 16:38:49Z raasch
37! REAL functions provided with KIND-attribute
38!
39! 1320 2014-03-20 08:40:49Z raasch
40! ONLY-attribute added to USE-statements,
41! kind-parameters added to all INTEGER and REAL declaration statements,
42! kinds are defined in new module kinds,
43! revision history before 2012 removed,
44! comment fields (!:) to be used for variable explanations added to
45! all variable declaration statements
46!
47! 1318 2014-03-17 13:35:16Z raasch
48! former files/routines cpu_log and cpu_statistics combined to one module,
49! which also includes the former data module cpulog from the modules-file
50!
51! 1036 2012-10-22 13:43:42Z raasch
52! code put under GPL (PALM 3.9)
53!
54! Revision 1.1  1997/07/24 11:12:29  raasch
55! Initial revision
56!
57!
58! Description:
59! ------------
60!> CPU-time measurements for any program part whatever. Results of the
61!> measurements are output at the end of the run in local file CPU_MEASURES.
62!>
63!> To measure the CPU-time (better to say the wallclock time) of a specific code
64!> segment, two calls of cpu_log have to be used as brackets in front and at the
65!> end of the segment:
66!>
67!>     CALL cpu_log( log_point(n), 'any identifier', 'start' )
68!>       ... code segment ...
69!>     CALL cpu_log( log_point(n), 'any identifier', 'stop' )
70!>
71!> Parts of the code segment can be excluded from the measurement by additional
72!> call of cpu_log:
73!>
74!>       ... first segment to be measured
75!>     CALL cpu_log( log_point(n), 'any identifier', 'pause' )
76!>       ... oart of segment to be excluded from measurement
77!>     CALL cpu_log( log_point(n), 'any identifier', 'continue' )
78!>       ... second segment to be mesasured
79!>
80!> n is an INTEGER within the interval [1,100] defining the id of the specific
81!> code segment, 'any identifier' is a string describing the code segment to be
82!> measured. It can be freely chosen and results will appear under this name in
83!> file CPU_MEASURES. ids can only be used once. If you like to do a
84!> measurement of a new part of the code, please look for an id which is unused
85!> ao far.
86!>
87!> d3par-parameter cpu_log_barrierwait can be used to set an MPI barrier at the
88!> beginning of the measurement (modus 'start' or 'continue'), to avoid that
89!> idle times (due to MPI calls in the code segment, which are
90!> waiting for other processes to be finished) affect the measurements.
91!> If barriers shall not be used at all, a fourth, optional parameter has to be
92!> given:
93!>
94!>     CALL cpu_log( ..., ..., 'start', cpu_log_nowait )
95!>
96!> Variable log_point should be used for non-overlapping code segments, and they
97!> should sum up to the total cpu-time required by the complete run.
98!> Variable log_point_s can be used for any other special (s) measurements.
99!------------------------------------------------------------------------------!
100 MODULE cpulog
101 
102
103    USE control_parameters,                                                    &
104        ONLY: message_string, nr_timesteps_this_run, run_description_header,   &
105              synchronous_exchange
106               
107    USE indices,                                                               &
108        ONLY: nx, ny, nz
109       
110    USE kinds
111   
112    USE pegrid
113
114    IMPLICIT NONE
115
116    PRIVATE
117    PUBLIC   cpu_log, cpu_log_barrierwait, cpu_log_nowait, cpu_statistics,     &
118             initial_wallclock_time, log_point, log_point_s
119
120    INTERFACE cpu_log
121       MODULE PROCEDURE cpu_log
122    END INTERFACE cpu_log
123
124    INTERFACE cpu_statistics
125       MODULE PROCEDURE cpu_statistics
126    END INTERFACE cpu_statistics
127
128    INTEGER(iwp), PARAMETER ::  cpu_log_continue = 0  !<
129    INTEGER(iwp), PARAMETER ::  cpu_log_pause = 1     !<
130    INTEGER(iwp), PARAMETER ::  cpu_log_start = 2     !<
131    INTEGER(iwp), PARAMETER ::  cpu_log_stop = 3      !<
132
133    LOGICAL            ::  cpu_log_barrierwait = .FALSE.  !<
134    LOGICAL, PARAMETER ::  cpu_log_nowait = .FALSE.       !<
135
136    REAL(wp) ::  initial_wallclock_time  !<
137
138    TYPE logpoint
139       REAL(wp)           ::  isum       !<
140       REAL(wp)           ::  ivect      !<
141       REAL(wp)           ::  mean       !<
142       REAL(wp)           ::  mtime      !<
143       REAL(wp)           ::  mtimevec   !<
144       REAL(wp)           ::  sum        !<
145       REAL(wp)           ::  vector     !<
146       INTEGER(iwp)       ::  counts     !<
147       CHARACTER (LEN=20) ::  place      !<
148    END TYPE logpoint
149
150    TYPE(logpoint), DIMENSION(100) ::  log_point = logpoint( 0.0_wp, 0.0_wp,   &
151                                       0.0_wp, 0.0_wp, 0.0_wp, 0.0_wp, 0.0_wp, &
152                                       0, ' ' ),                               &
153                                       log_point_s = logpoint( 0.0_wp, 0.0_wp, &
154                                       0.0_wp, 0.0_wp, 0.0_wp, 0.0_wp, 0.0_wp, &
155                                       0, ' ' )
156
157    SAVE
158
159 CONTAINS
160
161!------------------------------------------------------------------------------!
162! Description:
163! ------------
164!> @todo Missing subroutine description.
165!------------------------------------------------------------------------------!
166    SUBROUTINE cpu_log( log_event, place, modus, barrierwait )
167
168       IMPLICIT NONE
169
170       CHARACTER (LEN=*) ::  modus              !<
171       CHARACTER (LEN=*) ::  place              !<
172       
173       LOGICAL           ::  wait_allowed       !<
174       LOGICAL, OPTIONAL ::  barrierwait        !<
175       LOGICAL, SAVE     ::  first = .TRUE.     !<
176       
177       REAL(wp)          ::  mtime = 0.0_wp     !<
178       REAL(wp)          ::  mtimevec = 0.0_wp  !<
179       TYPE(logpoint)    ::  log_event          !<
180
181#if defined( __lc ) || defined( __decalpha )
182       INTEGER(idp)     ::  count        !<
183       INTEGER(idp)     ::  count_rate   !<
184#elif defined( __nec )
185       INTEGER(iwp)      ::  count       !<
186       INTEGER(iwp)      ::  count_rate  !<
187#elif defined( __ibm )
188       INTEGER(idp)     ::  IRTC         !<
189#endif
190
191
192!
193!--    Initialize and check, respectively, point of measurement
194       IF ( log_event%place == ' ' )  THEN
195          log_event%place = place
196       ELSEIF ( log_event%place /= place )  THEN
197          WRITE( message_string, * ) 'wrong argument & expected: ',            &
198                            TRIM(log_event%place), '  given: ',  TRIM( place )
199          CALL message( 'cpu_log', 'PA0174', 1, 2, 0, 6, 0 )
200       ENDIF
201
202!
203!--    Determine, if barriers are allowed to set
204       IF ( PRESENT( barrierwait ) )  THEN
205          wait_allowed = barrierwait
206       ELSE
207          wait_allowed = .TRUE.
208       ENDIF
209
210!
211!--    MPI barrier, if requested, in order to avoid measuring wait times
212!--    caused by MPI routines waiting for other MPI routines of other
213!--    PEs that have not yet finished
214#if defined( __parallel )
215       IF ( cpu_log_barrierwait  .AND.  wait_allowed  .AND.                    &
216            ( modus == 'start'  .OR.  modus == 'continue' ) )  THEN
217          CALL MPI_BARRIER( comm2d, ierr )
218       ENDIF
219#endif
220
221!
222!--    Take current time
223#if defined( __lc ) || defined( __decalpha ) || defined( __nec )
224       CALL SYSTEM_CLOCK( count, count_rate )
225       mtime = REAL( count, KIND=wp ) / REAL( count_rate, KIND=wp )
226#elif defined( __ibm )
227       mtime = IRTC( ) * 1E-9_wp
228#else
229       message_string = 'no time measurement defined on this host'
230       CALL message( 'cpu_log', 'PA0175', 1, 2, 0, 6, 0 )
231#endif
232
233!
234!--    Start, stop or pause measurement
235       IF ( modus == 'start'  .OR.  modus == 'continue' )  THEN
236          log_event%mtime    = mtime
237          log_event%mtimevec = mtimevec
238       ELSEIF ( modus == 'pause' )  THEN
239          IF ( ( mtime - log_event%mtime ) < 0.0  .AND.  first )  THEN
240             WRITE( message_string, * ) 'negative time interval occured',      &
241                         ' &PE',myid,' L=PAUSE "',TRIM(log_event%place),       &
242                         '" new=', mtime,' last=',log_event%mtime
243             CALL message( 'cpu_log', 'PA0176', 0, 1, -1, 6, 0 )
244             first = .FALSE.
245          ENDIF
246          log_event%isum     = log_event%isum + mtime - log_event%mtime
247          log_event%ivect    = log_event%ivect  + mtimevec - log_event%mtimevec
248       ELSEIF ( modus == 'stop' )  THEN
249          IF ( ( mtime - log_event%mtime + log_event%isum ) < 0.0  .AND.       &
250               first )  THEN
251             WRITE( message_string, * ) 'negative time interval occured',      &
252                         ' &PE',myid,' L=STOP "',TRIM(log_event%place),'" new=', &
253                         mtime,' last=',log_event%mtime,' isum=',log_event%isum
254             CALL message( 'cpu_log', 'PA0177', 0, 1, -1, 6, 0 )
255             first = .FALSE.
256          ENDIF
257          log_event%mtime    = mtime    - log_event%mtime    + log_event%isum
258          log_event%mtimevec = mtimevec - log_event%mtimevec + log_event%ivect
259          log_event%sum      = log_event%sum  + log_event%mtime
260          IF ( log_event%sum < 0.0  .AND.  first )  THEN
261             WRITE( message_string, * ) 'negative time interval occured',      &
262                         ' &PE',myid,' L=STOP "',TRIM(log_event%place),'" sum=', &
263                                         log_event%sum,' mtime=',log_event%mtime
264             CALL message( 'cpu_log', 'PA0178', 0, 1, -1, 6, 0 )
265             first = .FALSE.
266          ENDIF
267          log_event%vector   = log_event%vector + log_event%mtimevec
268          log_event%counts   = log_event%counts + 1
269          log_event%isum     = 0.0_wp
270          log_event%ivect    = 0.0_wp
271       ELSE
272          message_string = 'unknown modus of time measurement: ' // TRIM( modus )
273          CALL message( 'cpu_log', 'PA0179', 0, 1, -1, 6, 0 )
274       ENDIF
275
276    END SUBROUTINE cpu_log
277
278
279!------------------------------------------------------------------------------!
280! Description:
281! ------------
282!> Analysis and output of the cpu-times measured. All PE results are collected
283!> on PE0 in order to calculate the mean cpu-time over all PEs and other
284!> statistics. The output is sorted according to the amount of cpu-time consumed
285!> and output on PE0.
286!------------------------------------------------------------------------------!
287 
288    SUBROUTINE cpu_statistics
289
290       IMPLICIT NONE
291
292       INTEGER(iwp)    ::  i               !<
293       INTEGER(iwp)    ::  ii(1)           !<
294       INTEGER(iwp)    ::  iii             !<
295       INTEGER(iwp)    ::  sender          !<
296       REAL(wp)       ::  average_cputime  !<
297       REAL(wp), SAVE ::  norm = 1.0_wp    !<
298       REAL(wp), DIMENSION(:),   ALLOCATABLE ::  pe_max        !<
299       REAL(wp), DIMENSION(:),   ALLOCATABLE ::  pe_min        !<
300       REAL(wp), DIMENSION(:),   ALLOCATABLE ::  pe_rms        !<
301       REAL(wp), DIMENSION(:),   ALLOCATABLE ::  sum           !<
302       REAL(wp), DIMENSION(:,:), ALLOCATABLE ::  pe_log_points !<
303
304
305       CALL location_message( 'calculating cpu statistics', .FALSE. )
306
307!
308!--    Compute cpu-times in seconds
309       log_point%mtime  = log_point%mtime  / norm
310       log_point%sum    = log_point%sum    / norm
311       log_point%vector = log_point%vector / norm
312       WHERE ( log_point%counts /= 0 )
313          log_point%mean = log_point%sum / log_point%counts
314       END WHERE
315
316
317!
318!--    Collect cpu-times from all PEs and calculate statistics
319       IF ( myid == 0 )  THEN
320!
321!--       Allocate and initialize temporary arrays needed for statistics
322          ALLOCATE( pe_max( SIZE( log_point ) ), pe_min( SIZE( log_point ) ),  &
323                    pe_rms( SIZE( log_point ) ),                               &
324                    pe_log_points( SIZE( log_point ), 0:numprocs-1 ) )
325          pe_min = log_point%sum
326          pe_max = log_point%sum    ! need to be set in case of 1 PE
327          pe_rms = 0.0_wp
328
329#if defined( __parallel )
330!
331!--       Receive data from all PEs
332          DO  i = 1, numprocs-1
333             CALL MPI_RECV( pe_max(1), SIZE( log_point ), MPI_REAL,            &
334                            i, i, comm2d, status, ierr )
335             sender = status(MPI_SOURCE)
336             pe_log_points(:,sender) = pe_max
337          ENDDO
338          pe_log_points(:,0) = log_point%sum   ! Results from PE0
339!
340!--       Calculate mean of all PEs, store it on log_point%sum
341!--       and find minimum and maximum
342          DO  iii = 1, SIZE( log_point )
343             DO  i = 1, numprocs-1
344                log_point(iii)%sum = log_point(iii)%sum + pe_log_points(iii,i)
345                pe_min(iii) = MIN( pe_min(iii), pe_log_points(iii,i) )
346                pe_max(iii) = MAX( pe_max(iii), pe_log_points(iii,i) )
347             ENDDO
348             log_point(iii)%sum = log_point(iii)%sum / numprocs
349!
350!--          Calculate rms
351             DO  i = 0, numprocs-1
352                pe_rms(iii) = pe_rms(iii) + (                                  &
353                                    pe_log_points(iii,i) - log_point(iii)%sum  &
354                                            )**2
355             ENDDO
356             pe_rms(iii) = SQRT( pe_rms(iii) / numprocs )
357          ENDDO
358       ELSE
359!
360!--       Send data to PE0 (pe_max is used as temporary storage to send
361!--       the data in order to avoid sending the data type log)
362          ALLOCATE( pe_max( SIZE( log_point ) ) )
363          pe_max = log_point%sum
364          CALL MPI_SEND( pe_max(1), SIZE( log_point ), MPI_REAL, 0, myid, comm2d, &
365                         ierr )
366#endif
367
368       ENDIF
369
370!
371!--    Write cpu-times
372       IF ( myid == 0 )  THEN
373!
374!--       Re-store sums
375          ALLOCATE( sum( SIZE( log_point ) ) )
376          WHERE ( log_point%counts /= 0 )
377             sum = log_point%sum
378          ELSEWHERE
379             sum = -1.0_wp
380          ENDWHERE
381
382!
383!--       Get total time in order to calculate CPU-time per gridpoint and timestep
384          IF ( nr_timesteps_this_run /= 0 )  THEN
385             average_cputime = log_point(1)%sum / REAL( (nx+1) * (ny+1) * nz, KIND=wp ) / &
386                               REAL( nr_timesteps_this_run, KIND=wp ) * 1E6_wp  ! in micro-sec
387          ELSE
388             average_cputime = -1.0_wp
389          ENDIF
390
391!
392!--       Write cpu-times sorted by size
393          CALL check_open( 18 )
394#if defined( __parallel )
395          WRITE ( 18, 100 )  TRIM( run_description_header ),                          &
396                             numprocs * threads_per_task, pdims(1), pdims(2),         &
397                             threads_per_task, nx+1, ny+1, nz, nr_timesteps_this_run, &
398                             average_cputime
399
400          IF ( num_acc_per_node /= 0 )  WRITE ( 18, 108 )  num_acc_per_node
401          WRITE ( 18, 110 )
402#else
403          WRITE ( 18, 100 )  TRIM( run_description_header ),                          &
404                             numprocs * threads_per_task, 1, 1,                       &
405                             threads_per_task, nx+1, ny+1, nz, nr_timesteps_this_run, &
406                             average_cputime
407
408          IF ( num_acc_per_node /= 0 )  WRITE ( 18, 109 )  num_acc_per_node
409          WRITE ( 18, 110 )
410#endif
411          DO
412             ii = MAXLOC( sum )
413             i = ii(1)
414             IF ( sum(i) /= -1.0_wp )  THEN
415                WRITE ( 18, 102 ) &
416              log_point(i)%place, log_point(i)%sum,                            &
417                   log_point(i)%sum / log_point(1)%sum * 100.0_wp,             &
418                   log_point(i)%counts, pe_min(i), pe_max(i), pe_rms(i)
419                sum(i) = -1.0_wp
420             ELSE
421                EXIT
422             ENDIF
423          ENDDO
424       ENDIF
425
426
427!
428!--    The same procedure again for the individual measurements.
429!
430!--    Compute cpu-times in seconds
431       log_point_s%mtime  = log_point_s%mtime  / norm
432       log_point_s%sum    = log_point_s%sum    / norm
433       log_point_s%vector = log_point_s%vector / norm
434       WHERE ( log_point_s%counts /= 0 )
435          log_point_s%mean = log_point_s%sum / log_point_s%counts
436       END WHERE
437
438!
439!--    Collect cpu-times from all PEs and calculate statistics
440#if defined( __parallel )
441!
442!--    Set barrier in order to avoid that PE0 receives log_point_s-data
443!--    while still busy with receiving log_point-data (see above)
444       CALL MPI_BARRIER( comm2d, ierr )
445#endif
446       IF ( myid == 0 )  THEN
447!
448!--       Initialize temporary arrays needed for statistics
449          pe_min = log_point_s%sum
450          pe_max = log_point_s%sum    ! need to be set in case of 1 PE
451          pe_rms = 0.0_wp
452
453#if defined( __parallel )
454!
455!--       Receive data from all PEs
456          DO  i = 1, numprocs-1
457             CALL MPI_RECV( pe_max(1), SIZE( log_point ), MPI_REAL, &
458                            MPI_ANY_SOURCE, MPI_ANY_TAG, comm2d, status, ierr )
459             sender = status(MPI_SOURCE)
460             pe_log_points(:,sender) = pe_max
461          ENDDO
462          pe_log_points(:,0) = log_point_s%sum   ! Results from PE0
463!
464!--       Calculate mean of all PEs, store it on log_point_s%sum
465!--       and find minimum and maximum
466          DO  iii = 1, SIZE( log_point )
467             DO  i = 1, numprocs-1
468                log_point_s(iii)%sum = log_point_s(iii)%sum + pe_log_points(iii,i)
469                pe_min(iii) = MIN( pe_min(iii), pe_log_points(iii,i) )
470                pe_max(iii) = MAX( pe_max(iii), pe_log_points(iii,i) )
471             ENDDO
472             log_point_s(iii)%sum = log_point_s(iii)%sum / numprocs
473!
474!--          Calculate rms
475             DO  i = 0, numprocs-1
476                pe_rms(iii) = pe_rms(iii) + (                                  &
477                                    pe_log_points(iii,i) - log_point_s(iii)%sum &
478                                            )**2
479             ENDDO
480             pe_rms(iii) = SQRT( pe_rms(iii) / numprocs )
481          ENDDO
482       ELSE
483!
484!--       Send data to PE0 (pe_max is used as temporary storage to send
485!--       the data in order to avoid sending the data type log)
486          pe_max = log_point_s%sum
487          CALL MPI_SEND( pe_max(1), SIZE( log_point ), MPI_REAL, 0, 0, comm2d, &
488                         ierr )
489#endif
490
491       ENDIF
492
493!
494!--    Write cpu-times
495       IF ( myid == 0 )  THEN
496!
497!--       Re-store sums
498          WHERE ( log_point_s%counts /= 0 )
499             sum = log_point_s%sum
500          ELSEWHERE
501             sum = -1.0_wp
502          ENDWHERE
503
504!
505!--       Write cpu-times sorted by size
506          WRITE ( 18, 101 )
507          DO
508             ii = MAXLOC( sum )
509             i = ii(1)
510             IF ( sum(i) /= -1.0_wp )  THEN
511                WRITE ( 18, 102 )                                              &
512                   log_point_s(i)%place, log_point_s(i)%sum,                   &
513                   log_point_s(i)%sum / log_point(1)%sum * 100.0_wp,           &
514                   log_point_s(i)%counts, pe_min(i), pe_max(i), pe_rms(i)
515                sum(i) = -1.0_wp
516             ELSE
517                EXIT
518             ENDIF
519          ENDDO
520
521!
522!--       Output of handling of MPI operations
523          IF ( collective_wait )  THEN
524             WRITE ( 18, 103 )
525          ELSE
526             WRITE ( 18, 104 )
527          ENDIF
528          IF ( cpu_log_barrierwait )  WRITE ( 18, 111 )
529          IF ( synchronous_exchange )  THEN
530             WRITE ( 18, 105 )
531          ELSE
532             WRITE ( 18, 106 )
533          ENDIF
534
535!
536!--       Empty lines in order to create a gap to the results of the model
537!--       continuation runs
538          WRITE ( 18, 107 )
539
540!
541!--       Unit 18 is not needed anymore
542          CALL close_file( 18 )
543
544       ENDIF
545
546       CALL location_message( 'finished', .TRUE. )
547
548   100 FORMAT (A/11('-')//'CPU measures for ',I5,' PEs (',I5,'(x) * ',I5,'(y', &
549               &') tasks *',I5,' threads):'//                                  &
550               'gridpoints (x/y/z): ',20X,I5,' * ',I5,' * ',I5/                &
551               'nr of timesteps: ',22X,I6/                                     &
552               'cpu time per grid point and timestep: ',5X,F8.5,' * 10**-6 s')
553
554   101 FORMAT (/'special measures:'/ &
555               &'-----------------------------------------------------------', &
556               &'--------------------')
557
558   102 FORMAT (A20,2X,F9.3,2X,F7.2,1X,I7,3(1X,F9.3))
559   103 FORMAT (/'Barriers are set in front of collective operations')
560   104 FORMAT (/'No barriers are set in front of collective operations')
561   105 FORMAT (/'Exchange of ghostpoints via MPI_SENDRCV')
562   106 FORMAT (/'Exchange of ghostpoints via MPI_ISEND/MPI_IRECV')
563   107 FORMAT (//)
564   108 FORMAT ('Accelerator boards per node: ',14X,I2)
565   109 FORMAT ('Accelerator boards: ',23X,I2)
566   110 FORMAT ('----------------------------------------------------------',   &
567               &'------------'//&
568               &'place:                        mean        counts      min  ', &
569               &'     max       rms'/ &
570               &'                           sec.      %                sec. ', &
571               &'     sec.      sec.'/  &
572               &'-----------------------------------------------------------', &
573               &'-------------------')
574   111 FORMAT (/'Barriers are set at beginning (start/continue) of measurements')
575
576    END SUBROUTINE cpu_statistics
577
578 END MODULE cpulog
Note: See TracBrowser for help on using the repository browser.