Changeset 1318 for palm/trunk/SOURCE/cpulog.f90

Timestamp:

Mar 17, 2014 1:35:16 PM (10 years ago)

Author:

raasch

Message:

former files/routines cpu_log and cpu_statistics combined to one module,
which also includes the former data module cpulog from the modules-file,
module interfaces removed

File:

• palm/trunk/SOURCE/cpulog.f90 (moved) (moved from palm/trunk/SOURCE/cpu_log.f90) (3 diffs)

palm/trunk/SOURCE/cpulog.f90

@@ -1 @@
- SUBROUTINE cpu_log( log_event, place, modus, barrierwait )
+ MODULE cpulog
 
 !--------------------------------------------------------------------------------!
@@ -20 +20 @@
 ! Current revisions:
 ! -----------------
-! 
+! former files/routines cpu_log and cpu_statistics combined to one module,
+! which also includes the former data module cpulog from the modules-file
 !
 ! Former revisions:
@@ -55 +56 @@
 
     USE control_parameters
-    USE cpulog
+    USE indices,  ONLY: nx, ny, nz
     USE pegrid
 
     IMPLICIT NONE
 
-    CHARACTER (LEN=*)           ::  modus, place
-    CHARACTER (LEN=*), OPTIONAL ::  barrierwait
-    LOGICAL, SAVE               ::  first = .TRUE.
-    REAL                        ::  mtime = 0.0, mtimevec = 0.0
-    TYPE(logpoint)              ::  log_event
+    PRIVATE
+    PUBLIC   cpu_log, cpu_log_barrierwait, cpu_log_nowait, cpu_statistics, &
+             initial_wallclock_time, log_point, log_point_s
+
+    INTERFACE cpu_log
+       MODULE PROCEDURE cpu_log
+    END INTERFACE cpu_log
+
+    INTERFACE cpu_statistics
+       MODULE PROCEDURE cpu_statistics
+    END INTERFACE cpu_statistics
+
+    INTEGER, PARAMETER ::  cpu_log_continue = 0, cpu_log_pause = 1, &
+                           cpu_log_start = 2, cpu_log_stop = 3
+
+    LOGICAL            ::  cpu_log_barrierwait = .FALSE.
+    LOGICAL, PARAMETER ::  cpu_log_nowait = .FALSE.
+
+    REAL ::  initial_wallclock_time
+
+    TYPE logpoint
+       REAL               ::  isum, ivect, mean, mtime, mtimevec, sum, vector
+       INTEGER            ::  counts
+       CHARACTER (LEN=20) ::  place
+    END TYPE logpoint
+
+    TYPE(logpoint), DIMENSION(100) ::  log_point = logpoint( 0.0, 0.0, 0.0,   &
+                                       0.0, 0.0, 0.0, 0.0, 0, ' ' ),          &
+                                       log_point_s = logpoint( 0.0, 0.0, 0.0, &
+                                       0.0, 0.0, 0.0, 0.0, 0, ' ' )
+
+    SAVE
+
+ CONTAINS
+
+    SUBROUTINE cpu_log( log_event, place, modus, barrierwait )
+
+       IMPLICIT NONE
+
+       CHARACTER (LEN=*)           ::  modus, place
+       LOGICAL                     ::  wait_allowed
+       LOGICAL, OPTIONAL           ::  barrierwait
+       LOGICAL, SAVE               ::  first = .TRUE.
+       REAL                        ::  mtime = 0.0, mtimevec = 0.0
+       TYPE(logpoint)              ::  log_event
 
 #if defined( __lc ) || defined( __decalpha )
-    INTEGER(8)                  ::  count, count_rate
+       INTEGER(8)                  ::  count, count_rate
 #elif defined( __nec )
-    INTEGER                     ::  count, count_rate
+       INTEGER                     ::  count, count_rate
 #elif defined( __ibm )
-    INTEGER(8)                  ::  IRTC
-#endif
-
-
-!
-!-- Initialize and check, respectively, point of measurement
-    IF ( log_event%place == ' ' )  THEN
-       log_event%place = place
-    ELSEIF ( log_event%place /= place )  THEN
-       WRITE( message_string, * ) 'wrong argument & expected: ', &
-                         TRIM(log_event%place), '  given: ',  TRIM( place )
-       CALL message( 'cpu_log', 'PA0174', 1, 2, 0, 6, 0 )
-    ENDIF
-
-!
-!-- Take current time
+       INTEGER(8)                  ::  IRTC
+#endif
+
+
+!
+!--    Initialize and check, respectively, point of measurement
+       IF ( log_event%place == ' ' )  THEN
+          log_event%place = place
+       ELSEIF ( log_event%place /= place )  THEN
+          WRITE( message_string, * ) 'wrong argument & expected: ', &
+                            TRIM(log_event%place), '  given: ',  TRIM( place )
+          CALL message( 'cpu_log', 'PA0174', 1, 2, 0, 6, 0 )
+       ENDIF
+
+!
+!--    Determine, if barriers are allowed to set
+       IF ( PRESENT( barrierwait ) )  THEN
+          wait_allowed = barrierwait
+       ELSE
+          wait_allowed = .TRUE.
+       ENDIF
+
+!
+!--    MPI barrier, if requested, in order to avoid measuring wait times
+!--    caused by MPI routines waiting for other MPI routines of other
+!--    PEs that have not yet finished
+#if defined( __parallel )
+       IF ( cpu_log_barrierwait  .AND.  wait_allowed  .AND.  &
+            ( modus == 'start'  .OR.  modus == 'continue' ) )  THEN
+          CALL MPI_BARRIER( comm2d, ierr )
+       ENDIF
+#endif
+
+!
+!--    Take current time
 #if defined( __lc ) || defined( __decalpha ) || defined( __nec )
-    CALL SYSTEM_CLOCK( count, count_rate )
-    mtime = REAL( count ) / REAL( count_rate )
+       CALL SYSTEM_CLOCK( count, count_rate )
+       mtime = REAL( count ) / REAL( count_rate )
 #elif defined( __ibm )
-    mtime = IRTC( ) * 1E-9
+       mtime = IRTC( ) * 1E-9
 #else
-    message_string = 'no time measurement defined on this host'
-    CALL message( 'cpu_log', 'PA0175', 1, 2, 0, 6, 0 )
-#endif
-
-!
-!-- Start, stop or pause measurement
-    IF ( modus == 'start'  .OR.  modus == 'continue' )  THEN
-       log_event%mtime    = mtime
-       log_event%mtimevec = mtimevec
-    ELSEIF ( modus == 'pause' )  THEN
-       IF ( ( mtime - log_event%mtime ) < 0.0  .AND.  first )  THEN
-          WRITE( message_string, * ) 'negative time interval occured',         &
-                      ' &PE',myid,' L=PAUSE "',TRIM(log_event%place),'" new=', &
-                      mtime,' last=',log_event%mtime
-          CALL message( 'cpu_log', 'PA0176', 0, 1, -1, 6, 0 )
-          first = .FALSE.
-       ENDIF
-       log_event%isum     = log_event%isum + mtime - log_event%mtime
-       log_event%ivect    = log_event%ivect  + mtimevec - log_event%mtimevec
-    ELSEIF ( modus == 'stop' )  THEN
-       IF ( ( mtime - log_event%mtime + log_event%isum ) < 0.0  .AND. &
-            first )  THEN
-          WRITE( message_string, * ) 'negative time interval occured',        &
-                      ' &PE',myid,' L=STOP "',TRIM(log_event%place),'" new=', &
-                      mtime,' last=',log_event%mtime,' isum=',log_event%isum
-          CALL message( 'cpu_log', 'PA0177', 0, 1, -1, 6, 0 )
-          first = .FALSE.
-       ENDIF
-       log_event%mtime    = mtime    - log_event%mtime    + log_event%isum
-       log_event%mtimevec = mtimevec - log_event%mtimevec + log_event%ivect
-       log_event%sum      = log_event%sum  + log_event%mtime
-       IF ( log_event%sum < 0.0  .AND.  first )  THEN
-          WRITE( message_string, * ) 'negative time interval occured',        &
-                      ' &PE',myid,' L=STOP "',TRIM(log_event%place),'" sum=', &
-                                      log_event%sum,' mtime=',log_event%mtime
-          CALL message( 'cpu_log', 'PA0178', 0, 1, -1, 6, 0 )
-          first = .FALSE.
-       ENDIF
-       log_event%vector   = log_event%vector + log_event%mtimevec
-       log_event%counts   = log_event%counts + 1
-       log_event%isum     = 0.0
-       log_event%ivect    = 0.0
-    ELSE
-       message_string = 'unknown modus of time measurement: ' // TRIM( modus )
-       CALL message( 'cpu_log', 'PA0179', 0, 1, -1, 6, 0 )
-    ENDIF
-
-
- END SUBROUTINE cpu_log
+       message_string = 'no time measurement defined on this host'
+       CALL message( 'cpu_log', 'PA0175', 1, 2, 0, 6, 0 )
+#endif
+
+!
+!--    Start, stop or pause measurement
+       IF ( modus == 'start'  .OR.  modus == 'continue' )  THEN
+          log_event%mtime    = mtime
+          log_event%mtimevec = mtimevec
+       ELSEIF ( modus == 'pause' )  THEN
+          IF ( ( mtime - log_event%mtime ) < 0.0  .AND.  first )  THEN
+             WRITE( message_string, * ) 'negative time interval occured',         &
+                         ' &PE',myid,' L=PAUSE "',TRIM(log_event%place),'" new=', &
+                         mtime,' last=',log_event%mtime
+             CALL message( 'cpu_log', 'PA0176', 0, 1, -1, 6, 0 )
+             first = .FALSE.
+          ENDIF
+          log_event%isum     = log_event%isum + mtime - log_event%mtime
+          log_event%ivect    = log_event%ivect  + mtimevec - log_event%mtimevec
+       ELSEIF ( modus == 'stop' )  THEN
+          IF ( ( mtime - log_event%mtime + log_event%isum ) < 0.0  .AND. &
+               first )  THEN
+             WRITE( message_string, * ) 'negative time interval occured',        &
+                         ' &PE',myid,' L=STOP "',TRIM(log_event%place),'" new=', &
+                         mtime,' last=',log_event%mtime,' isum=',log_event%isum
+             CALL message( 'cpu_log', 'PA0177', 0, 1, -1, 6, 0 )
+             first = .FALSE.
+          ENDIF
+          log_event%mtime    = mtime    - log_event%mtime    + log_event%isum
+          log_event%mtimevec = mtimevec - log_event%mtimevec + log_event%ivect
+          log_event%sum      = log_event%sum  + log_event%mtime
+          IF ( log_event%sum < 0.0  .AND.  first )  THEN
+             WRITE( message_string, * ) 'negative time interval occured',        &
+                         ' &PE',myid,' L=STOP "',TRIM(log_event%place),'" sum=', &
+                                         log_event%sum,' mtime=',log_event%mtime
+             CALL message( 'cpu_log', 'PA0178', 0, 1, -1, 6, 0 )
+             first = .FALSE.
+          ENDIF
+          log_event%vector   = log_event%vector + log_event%mtimevec
+          log_event%counts   = log_event%counts + 1
+          log_event%isum     = 0.0
+          log_event%ivect    = 0.0
+       ELSE
+          message_string = 'unknown modus of time measurement: ' // TRIM( modus )
+          CALL message( 'cpu_log', 'PA0179', 0, 1, -1, 6, 0 )
+       ENDIF
+
+    END SUBROUTINE cpu_log
+
+
+    SUBROUTINE cpu_statistics
+!------------------------------------------------------------------------------!
+! Description:
+! ------------
+! Analysis and output of the cpu-times measured. All PE results are collected
+! on PE0 in order to calculate the mean cpu-time over all PEs and other
+! statistics. The output is sorted according to the amount of cpu-time consumed
+! and output on PE0.
+!------------------------------------------------------------------------------!
+
+       IMPLICIT NONE
+
+       INTEGER    ::  i, ii(1), iii, sender
+       REAL       ::  average_cputime
+       REAL, SAVE ::  norm = 1.0
+       REAL, DIMENSION(:),   ALLOCATABLE ::  pe_max, pe_min, pe_rms, sum
+       REAL, DIMENSION(:,:), ALLOCATABLE ::  pe_log_points
+
+
+!
+!--    Compute cpu-times in seconds
+       log_point%mtime  = log_point%mtime  / norm
+       log_point%sum    = log_point%sum    / norm
+       log_point%vector = log_point%vector / norm
+       WHERE ( log_point%counts /= 0 )
+          log_point%mean = log_point%sum / log_point%counts
+       END WHERE
+
+
+!
+!--    Collect cpu-times from all PEs and calculate statistics
+       IF ( myid == 0 )  THEN
+!
+!--       Allocate and initialize temporary arrays needed for statistics
+          ALLOCATE( pe_max( SIZE( log_point ) ), pe_min( SIZE( log_point ) ), &
+                    pe_rms( SIZE( log_point ) ),                              &
+                    pe_log_points( SIZE( log_point ), 0:numprocs-1 ) )
+          pe_min = log_point%sum
+          pe_max = log_point%sum    ! need to be set in case of 1 PE
+          pe_rms = 0.0
+
+#if defined( __parallel )
+!
+!--       Receive data from all PEs
+          DO  i = 1, numprocs-1
+             CALL MPI_RECV( pe_max(1), SIZE( log_point ), MPI_REAL, &
+                            i, i, comm2d, status, ierr )
+             sender = status(MPI_SOURCE)
+             pe_log_points(:,sender) = pe_max
+          ENDDO
+          pe_log_points(:,0) = log_point%sum   ! Results from PE0
+!
+!--       Calculate mean of all PEs, store it on log_point%sum
+!--       and find minimum and maximum
+          DO  iii = 1, SIZE( log_point )
+             DO  i = 1, numprocs-1
+                log_point(iii)%sum = log_point(iii)%sum + pe_log_points(iii,i)
+                pe_min(iii) = MIN( pe_min(iii), pe_log_points(iii,i) )
+                pe_max(iii) = MAX( pe_max(iii), pe_log_points(iii,i) )
+             ENDDO
+             log_point(iii)%sum = log_point(iii)%sum / numprocs
+!
+!--          Calculate rms
+             DO  i = 0, numprocs-1
+                pe_rms(iii) = pe_rms(iii) + ( &
+                                    pe_log_points(iii,i) - log_point(iii)%sum &
+                                            )**2
+             ENDDO
+             pe_rms(iii) = SQRT( pe_rms(iii) / numprocs )
+          ENDDO
+       ELSE
+!
+!--       Send data to PE0 (pe_max is used as temporary storage to send
+!--       the data in order to avoid sending the data type log)
+          ALLOCATE( pe_max( SIZE( log_point ) ) )
+          pe_max = log_point%sum
+          CALL MPI_SEND( pe_max(1), SIZE( log_point ), MPI_REAL, 0, myid, comm2d, &
+                         ierr )
+#endif
+
+       ENDIF
+
+!
+!--    Write cpu-times
+       IF ( myid == 0 )  THEN
+!
+!--       Re-store sums
+          ALLOCATE( sum( SIZE( log_point ) ) )
+          WHERE ( log_point%counts /= 0 )
+             sum = log_point%sum
+          ELSEWHERE
+             sum = -1.0
+          ENDWHERE
+
+!
+!--       Get total time in order to calculate CPU-time per gridpoint and timestep
+          IF ( nr_timesteps_this_run /= 0 )  THEN
+             average_cputime = log_point(1)%sum / REAL( (nx+1) * (ny+1) * nz ) / &
+                               REAL( nr_timesteps_this_run ) * 1E6  ! in micro-sec
+          ELSE
+             average_cputime = -1.0
+          ENDIF
+
+!
+!--       Write cpu-times sorted by size
+          CALL check_open( 18 )
+#if defined( __parallel )
+          WRITE ( 18, 100 )  TRIM( run_description_header ),                          &
+                             numprocs * threads_per_task, pdims(1), pdims(2),         &
+                             threads_per_task, nx+1, ny+1, nz, nr_timesteps_this_run, &
+                             average_cputime
+
+          IF ( num_acc_per_node /= 0 )  WRITE ( 18, 108 )  num_acc_per_node
+          WRITE ( 18, 110 )
+#else
+          WRITE ( 18, 100 )  TRIM( run_description_header ),                          &
+                             numprocs * threads_per_task, 1, 1,                       &
+                             threads_per_task, nx+1, ny+1, nz, nr_timesteps_this_run, &
+                             average_cputime
+
+          IF ( num_acc_per_node /= 0 )  WRITE ( 18, 109 )  num_acc_per_node
+          WRITE ( 18, 110 )
+#endif
+          DO
+             ii = MAXLOC( sum )
+             i = ii(1)
+             IF ( sum(i) /= -1.0 )  THEN
+                WRITE ( 18, 102 ) &
+              log_point(i)%place, log_point(i)%sum,                &
+                   log_point(i)%sum / log_point(1)%sum * 100.0,         &
+                   log_point(i)%counts, pe_min(i), pe_max(i), pe_rms(i)
+                sum(i) = -1.0
+             ELSE
+                EXIT
+             ENDIF
+          ENDDO
+       ENDIF
+
+
+!
+!--    The same procedure again for the individual measurements.
+!
+!--    Compute cpu-times in seconds
+       log_point_s%mtime  = log_point_s%mtime  / norm
+       log_point_s%sum    = log_point_s%sum    / norm
+       log_point_s%vector = log_point_s%vector / norm
+       WHERE ( log_point_s%counts /= 0 )
+          log_point_s%mean = log_point_s%sum / log_point_s%counts
+       END WHERE
+
+!
+!--    Collect cpu-times from all PEs and calculate statistics
+#if defined( __parallel )
+!
+!--    Set barrier in order to avoid that PE0 receives log_point_s-data
+!--    while still busy with receiving log_point-data (see above)
+       CALL MPI_BARRIER( comm2d, ierr )
+#endif
+       IF ( myid == 0 )  THEN
+!
+!--       Initialize temporary arrays needed for statistics
+          pe_min = log_point_s%sum
+          pe_max = log_point_s%sum    ! need to be set in case of 1 PE
+          pe_rms = 0.0
+
+#if defined( __parallel )
+!
+!--       Receive data from all PEs
+          DO  i = 1, numprocs-1
+             CALL MPI_RECV( pe_max(1), SIZE( log_point ), MPI_REAL, &
+                            MPI_ANY_SOURCE, MPI_ANY_TAG, comm2d, status, ierr )
+             sender = status(MPI_SOURCE)
+             pe_log_points(:,sender) = pe_max
+          ENDDO
+          pe_log_points(:,0) = log_point_s%sum   ! Results from PE0
+!
+!--       Calculate mean of all PEs, store it on log_point_s%sum
+!--       and find minimum and maximum
+          DO  iii = 1, SIZE( log_point )
+             DO  i = 1, numprocs-1
+                log_point_s(iii)%sum = log_point_s(iii)%sum + pe_log_points(iii,i)
+                pe_min(iii) = MIN( pe_min(iii), pe_log_points(iii,i) )
+                pe_max(iii) = MAX( pe_max(iii), pe_log_points(iii,i) )
+             ENDDO
+             log_point_s(iii)%sum = log_point_s(iii)%sum / numprocs
+!
+!--          Calculate rms
+             DO  i = 0, numprocs-1
+                pe_rms(iii) = pe_rms(iii) + ( &
+                                    pe_log_points(iii,i) - log_point_s(iii)%sum &
+                                            )**2
+             ENDDO
+             pe_rms(iii) = SQRT( pe_rms(iii) / numprocs )
+          ENDDO
+       ELSE
+!
+!--       Send data to PE0 (pe_max is used as temporary storage to send
+!--       the data in order to avoid sending the data type log)
+          pe_max = log_point_s%sum
+          CALL MPI_SEND( pe_max(1), SIZE( log_point ), MPI_REAL, 0, 0, comm2d, &
+                         ierr )
+#endif
+
+       ENDIF
+
+!
+!--    Write cpu-times
+       IF ( myid == 0 )  THEN
+!
+!--       Re-store sums
+          WHERE ( log_point_s%counts /= 0 )
+             sum = log_point_s%sum
+          ELSEWHERE
+             sum = -1.0
+          ENDWHERE
+
+!
+!--       Write cpu-times sorted by size
+          WRITE ( 18, 101 )
+          DO
+             ii = MAXLOC( sum )
+             i = ii(1)
+             IF ( sum(i) /= -1.0 )  THEN
+                WRITE ( 18, 102 ) &
+                   log_point_s(i)%place, log_point_s(i)%sum, &
+                   log_point_s(i)%sum / log_point(1)%sum * 100.0, &
+                   log_point_s(i)%counts, pe_min(i), pe_max(i), pe_rms(i)
+                sum(i) = -1.0
+             ELSE
+                EXIT
+             ENDIF
+          ENDDO
+
+!
+!--       Output of handling of MPI operations
+          IF ( collective_wait )  THEN
+             WRITE ( 18, 103 )
+          ELSE
+             WRITE ( 18, 104 )
+          ENDIF
+          IF ( cpu_log_barrierwait )  WRITE ( 18, 111 )
+          IF ( synchronous_exchange )  THEN
+             WRITE ( 18, 105 )
+          ELSE
+             WRITE ( 18, 106 )
+          ENDIF
+
+!
+!--       Empty lines in order to create a gap to the results of the model
+!--       continuation runs
+          WRITE ( 18, 107 )
+
+!
+!--       Unit 18 is not needed anymore
+          CALL close_file( 18 )
+
+       ENDIF
+
+
+   100 FORMAT (A/11('-')//'CPU measures for ',I5,' PEs (',I5,'(x) * ',I5,'(y', &
+               &') tasks *',I5,' threads):'//                                  &
+               'gridpoints (x/y/z): ',20X,I5,' * ',I5,' * ',I5/                &
+               'nr of timesteps: ',22X,I6/                                     &
+               'cpu time per grid point and timestep: ',5X,F8.5,' * 10**-6 s')
+
+   101 FORMAT (/'special measures:'/ &
+               &'-----------------------------------------------------------', &
+               &'--------------------')
+
+   102 FORMAT (A20,2X,F9.3,2X,F7.2,1X,I7,3(1X,F9.3))
+   103 FORMAT (/'Barriers are set in front of collective operations')
+   104 FORMAT (/'No barriers are set in front of collective operations')
+   105 FORMAT (/'Exchange of ghostpoints via MPI_SENDRCV')
+   106 FORMAT (/'Exchange of ghostpoints via MPI_ISEND/MPI_IRECV')
+   107 FORMAT (//)
+   108 FORMAT ('Accelerator boards per node: ',14X,I2)
+   109 FORMAT ('Accelerator boards: ',23X,I2)
+   110 FORMAT ('----------------------------------------------------------',   &
+               &'------------'//&
+               &'place:                        mean        counts      min  ', &
+               &'     max       rms'/ &
+               &'                           sec.      %                sec. ', &
+               &'     sec.      sec.'/  &
+               &'-----------------------------------------------------------', &
+               &'-------------------')
+   111 FORMAT (/'Barriers are set at beginning (start/continue) of measurements')
+
+    END SUBROUTINE cpu_statistics
+
+ END MODULE cpulog