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

Last change on this file since 1815 was 1809, checked in by raasch, 9 years ago

last commit documented

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