Ignore:
Timestamp:
2018-12-19T22:54:16+01:00 (2 years ago)
Author:
smasson
Message:

trunk: merge back dev_r10164_HPC09_ESIWACE_PREP_MERGE@10424 into the trunk

File:
1 edited

Legend:

Unmodified
Added
Removed
  • NEMO/trunk/src/OCE/timing.F90

    r10068 r10425  
    3838   TYPE timer 
    3939      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 
     40      CHARACTER(LEN=20)  :: surname 
     41      INTEGER :: rank 
     42      REAL(wp)  :: t_cpu, t_clock, tsum_cpu, tsum_clock, tmax_cpu, tmax_clock, tmin_cpu, tmin_clock, tsub_cpu, tsub_clock 
    4143      INTEGER :: ncount, ncount_max, ncount_rate   
    4244      INTEGER :: niter 
     
    4951   TYPE alltimer 
    5052      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() 
     53      REAL(wp), DIMENSION(:), POINTER :: tsum_cpu   => NULL() 
     54      REAL(wp), DIMENSION(:), POINTER :: tsum_clock => NULL() 
     55      INTEGER, DIMENSION(:), POINTER :: niter => NULL() 
    5456      TYPE(alltimer), POINTER :: next => NULL() 
    5557      TYPE(alltimer), POINTER :: prev => NULL() 
     
    5860   TYPE(timer), POINTER :: s_timer_root => NULL() 
    5961   TYPE(timer), POINTER :: s_timer      => NULL() 
     62   TYPE(timer), POINTER :: s_timer_old      => NULL() 
     63 
    6064   TYPE(timer), POINTER :: s_wrk        => NULL() 
    6165   REAL(wp) :: t_overclock, t_overcpu 
     
    9094      CHARACTER(len=*), INTENT(in) :: cdinfo 
    9195      ! 
    92         
    93       ! Create timing structure at first call 
    94       IF( .NOT. l_initdone ) THEN 
    95          CALL timing_ini_var(cdinfo) 
     96       IF(ASSOCIATED(s_timer) ) s_timer_old => s_timer 
     97       ! 
     98      ! Create timing structure at first call of the routine  
     99       CALL timing_ini_var(cdinfo) 
     100   !   write(*,*) 'after inivar ', s_timer%cname 
     101 
     102      ! ici timing_ini_var a soit retrouve s_timer et fait return soit ajoute un maillon 
     103      ! maintenant on regarde si le call d'avant corrsspond a un parent ou si il est ferme 
     104      IF( .NOT. s_timer_old%l_tdone ) THEN       
     105         s_timer%parent_section => s_timer_old 
    96106      ELSE 
    97          s_timer => s_timer_root 
    98          DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) )  
    99             IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next 
    100          END DO 
    101       ENDIF          
     107         s_timer%parent_section => NULL() 
     108      ENDIF     
     109 
    102110      s_timer%l_tdone = .FALSE. 
    103111      s_timer%niter = s_timer%niter + 1 
     
    114122      CALL SYSTEM_CLOCK(COUNT = s_timer%ncount) 
    115123#endif 
     124!      write(*,*) 'end of start ', s_timer%cname 
     125 
    116126      ! 
    117127   END SUBROUTINE timing_start 
     
    127137      ! 
    128138      INTEGER  :: ifinal_count, iperiods     
    129       REAL(wp) :: zcpu_end, zmpitime 
     139      REAL(wp) :: zcpu_end, zmpitime,zcpu_raw,zclock_raw 
    130140      ! 
    131141      s_wrk => NULL() 
     
    140150      CALL CPU_TIME( zcpu_end ) 
    141151 
    142       s_timer => s_timer_root 
    143       DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) )  
    144          IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next 
    145       END DO 
     152!!$      IF(associated(s_timer%parent_section))then 
     153!!$        write(*,*) s_timer%cname,' <-- ', s_timer%parent_section%cname 
     154!!$      ENDIF   
     155 
     156 !     No need to search ... : s_timer has the last value defined in start 
     157 !     s_timer => s_timer_root 
     158 !     DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) )  
     159 !        IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next 
     160 !     END DO 
    146161  
    147162      ! CPU time correction 
    148       s_timer%t_cpu  = zcpu_end - s_timer%t_cpu - t_overcpu - s_timer%tsub_cpu 
    149    
     163      zcpu_raw = zcpu_end - s_timer%t_cpu - t_overcpu ! total time including child 
     164      s_timer%t_cpu  = zcpu_raw - s_timer%tsub_cpu 
     165  !    IF(s_timer%cname==trim('lbc_lnk_2d'))  write(*,*) s_timer%tsub_cpu,zcpu_end 
     166 
    150167      ! clock time correction 
    151168#if defined key_mpp_mpi 
    152       s_timer%t_clock = zmpitime - s_timer%t_clock - t_overclock - s_timer%tsub_clock 
     169      zclock_raw = zmpitime - s_timer%t_clock - t_overclock ! total time including child 
     170      s_timer%t_clock = zclock_raw - t_overclock - s_timer%tsub_clock 
    153171#else 
    154172      iperiods = ifinal_count - s_timer%ncount 
    155173      IF( ifinal_count < s_timer%ncount )  & 
    156           iperiods = iperiods + s_timer%ncount_max  
    157       s_timer%t_clock  = REAL(iperiods) / s_timer%ncount_rate - t_overclock - s_timer%tsub_clock 
     174         iperiods = iperiods + s_timer%ncount_max  
     175         zclock_raw = REAL(iperiods) / s_timer%ncount_rate !- t_overclock    
     176         s_timer%t_clock  = zclock_raw - s_timer%tsub_clock 
    158177#endif 
     178 !     IF(s_timer%cname==trim('lbc_lnk_2d')) write(*,*) zclock_raw , s_timer%tsub_clock 
    159179       
    160180      ! Correction of parent section 
    161181      IF( .NOT. PRESENT(csection) ) THEN 
    162          s_wrk => s_timer 
    163          DO WHILE ( ASSOCIATED(s_wrk%parent_section ) ) 
    164             s_wrk => s_wrk%parent_section 
    165             s_wrk%tsub_cpu   = s_wrk%tsub_cpu   + s_timer%t_cpu  
    166             s_wrk%tsub_clock = s_wrk%tsub_clock + s_timer%t_clock               
    167          END DO 
     182         IF ( ASSOCIATED(s_timer%parent_section ) ) THEN 
     183            s_timer%parent_section%tsub_cpu   = zcpu_raw   + s_timer%parent_section%tsub_cpu  
     184            s_timer%parent_section%tsub_clock = zclock_raw + s_timer%parent_section%tsub_clock              
     185         ENDIF 
    168186      ENDIF 
    169187             
     
    186204      s_timer%l_tdone = .TRUE. 
    187205      ! 
     206      ! 
     207      ! we come back 
     208      IF ( ASSOCIATED(s_timer%parent_section ) ) s_timer => s_timer%parent_section 
     209      
     210!      write(*,*) 'end of stop ', s_timer%cname 
     211 
    188212   END SUBROUTINE timing_stop 
    189213  
     
    211235         WRITE(numtime,*) '                             NEMO team' 
    212236         WRITE(numtime,*) '                  Ocean General Circulation Model' 
    213          WRITE(numtime,*) '                        version 4.0  (2018) ' 
     237         WRITE(numtime,*) '                        version 3.6  (2015) ' 
    214238         WRITE(numtime,*) 
    215239         WRITE(numtime,*) '                        Timing Informations ' 
     
    263287      TYPE(timer), POINTER :: s_temp 
    264288      INTEGER :: idum, iperiods, icode 
     289      INTEGER :: ji 
    265290      LOGICAL :: ll_ord, ll_averep 
    266291      CHARACTER(len=120) :: clfmt             
    267        
     292      REAL(wp), DIMENSION(:), ALLOCATABLE ::   timing_glob 
     293      REAL(wp) ::   zsypd   ! simulated years per day (Balaji 2017) 
     294      REAL(wp) ::   zperc, ztot 
     295 
    268296      ll_averep = .TRUE. 
    269297     
     
    292320      END DO 
    293321      idum = nsize 
    294       IF(lk_mpp) CALL mpp_sum(idum) 
     322      CALL mpp_sum('timing', idum) 
    295323      IF( idum/jpnij /= nsize ) THEN 
    296324         IF( lwriter ) WRITE(numtime,*) '        ===> W A R N I N G: ' 
     
    340368      &       ctime(2)(1:2), ctime(2)(3:4), ctime(2)(5:6),   & 
    341369      &       czone(1:3),    czone(4:5) 
     370 
     371#if defined key_mpp_mpi 
     372      ALLOCATE(timing_glob(4*jpnij), stat=icode) 
     373      CALL MPI_GATHER( (/compute_time, waiting_time(1), waiting_time(2), elapsed_time/),   & 
     374         &             4, MPI_DOUBLE_PRECISION, timing_glob, 4, MPI_DOUBLE_PRECISION, 0, MPI_COMM_OCE, icode) 
     375      IF( narea == 1 ) THEN 
     376         WRITE(numtime,*) ' ' 
     377         WRITE(numtime,*) ' Report on time spent on waiting MPI messages ' 
     378         WRITE(numtime,*) '    total timing measured between nit000+1 and nitend-1 ' 
     379         WRITE(numtime,*) '    warning: includes restarts writing time if output before nitend... ' 
     380         WRITE(numtime,*) ' ' 
     381         DO ji = 1, jpnij 
     382            ztot = SUM( timing_glob(4*ji-3:4*ji-1) ) 
     383            WRITE(numtime,'(A28,F11.6,            A34,I8)') 'Computing       time : ',timing_glob(4*ji-3), ' on MPI rank : ', ji 
     384            IF ( ztot /= 0. ) zperc = timing_glob(4*ji-2) / ztot * 100. 
     385            WRITE(numtime,'(A28,F11.6,A2, F4.1,A3,A25,I8)') 'Waiting lbc_lnk time : ',timing_glob(4*ji-2)   & 
     386               &                                                         , ' (',      zperc,' %)',   ' on MPI rank : ', ji 
     387            IF ( ztot /= 0. ) zperc = timing_glob(4*ji-1) / ztot * 100. 
     388            WRITE(numtime,'(A28,F11.6,A2, F4.1,A3,A25,I8)') 'Waiting  global time : ',timing_glob(4*ji-1)   & 
     389               &                                                         , ' (',      zperc,' %)',   ' on MPI rank : ', ji 
     390            zsypd = rn_rdt * REAL(nitend-nit000-1, wp) / (timing_glob(4*ji) * 365.) 
     391            WRITE(numtime,'(A28,F11.6,A7,F10.3,A2,A15,I8)') 'Total           time : ',timing_glob(4*ji  )   & 
     392               &                                                         , ' (SYPD: ', zsypd, ')',   ' on MPI rank : ', ji 
     393         END DO 
     394      ENDIF 
     395      DEALLOCATE(timing_glob) 
     396#endif       
    342397 
    343398      IF( lwriter ) CLOSE(numtime)  
     
    459514         sl_timer_ave_root%next => NULL() 
    460515         sl_timer_ave_root%prev => NULL() 
     516         ALLOCATE(sl_timer_ave) 
    461517         sl_timer_ave => sl_timer_ave_root             
    462518      ENDIF  
     
    490546         s_timer => s_timer%next 
    491547      END DO       
    492  
    493          WRITE(*,*) 'ARPDBG: timing: done gathers' 
    494548       
    495549      IF( narea == 1 ) THEN     
     
    514568            sl_timer_glob => sl_timer_glob%next                                 
    515569         END DO 
    516  
    517          WRITE(*,*) 'ARPDBG: timing: done computing stats' 
    518570       
    519571         ! reorder the averaged list by CPU time       
     
    567619      ENDIF 
    568620      ! 
    569       DEALLOCATE(sl_timer_glob_root%cname     , & 
    570                  sl_timer_glob_root%tsum_cpu  , & 
    571                  sl_timer_glob_root%tsum_clock, & 
    572                  sl_timer_glob_root%niter) 
    573       ! 
    574621      DEALLOCATE(sl_timer_glob_root) 
    575622      !                   
     
    676723         s_timer => s_timer_root 
    677724         ! 
     725         ALLOCATE(s_wrk) 
    678726         s_wrk => NULL() 
    679           
     727         ! 
     728         ALLOCATE(s_timer_old) 
     729         s_timer_old%cname       = cdinfo 
     730         s_timer_old%t_cpu      = 0._wp 
     731         s_timer_old%t_clock    = 0._wp 
     732         s_timer_old%tsum_cpu   = 0._wp 
     733         s_timer_old%tsum_clock = 0._wp 
     734         s_timer_old%tmax_cpu   = 0._wp 
     735         s_timer_old%tmax_clock = 0._wp 
     736         s_timer_old%tmin_cpu   = 0._wp 
     737         s_timer_old%tmin_clock = 0._wp 
     738         s_timer_old%tsub_cpu   = 0._wp 
     739         s_timer_old%tsub_clock = 0._wp 
     740         s_timer_old%ncount      = 0 
     741         s_timer_old%ncount_rate = 0 
     742         s_timer_old%ncount_max  = 0 
     743         s_timer_old%niter       = 0 
     744         s_timer_old%l_tdone  = .TRUE. 
     745         s_timer_old%next => NULL() 
     746         s_timer_old%prev => NULL() 
     747 
    680748      ELSE 
    681749         s_timer => s_timer_root 
    682750         ! case of already existing area (typically inside a loop) 
     751   !         write(*,*) 'in ini_var for routine : ', cdinfo 
    683752         DO WHILE( ASSOCIATED(s_timer) )  
    684             IF( TRIM(s_timer%cname) .EQ. TRIM(cdinfo) ) RETURN 
     753            IF( TRIM(s_timer%cname) .EQ. TRIM(cdinfo) ) THEN 
     754 !             write(*,*) 'in ini_var for routine : ', cdinfo,' we return'            
     755               RETURN ! cdinfo is already in the chain 
     756            ENDIF 
    685757            s_timer => s_timer%next 
    686758         END DO 
    687           
     759 
    688760         ! end of the chain 
    689761         s_timer => s_timer_root 
     
    691763            s_timer => s_timer%next 
    692764         END DO 
    693            
    694          ALLOCATE(s_timer%next)       
     765 
     766    !     write(*,*) 'after search', s_timer%cname 
     767         ! cdinfo is not part of the chain so we add it with initialisation           
     768          ALLOCATE(s_timer%next) 
     769    !     write(*,*) 'after allocation of next' 
     770   
    695771         s_timer%next%cname       = cdinfo 
    696772         s_timer%next%t_cpu      = 0._wp 
     
    713789         s_timer%next%next => NULL() 
    714790         s_timer => s_timer%next 
    715  
    716          ! are we inside a section 
    717          s_wrk => s_timer%prev 
    718          ll_section = .FALSE. 
    719          DO WHILE( ASSOCIATED(s_wrk) .AND. .NOT. ll_section ) 
    720             IF( .NOT. s_wrk%l_tdone ) THEN 
    721                ll_section = .TRUE. 
    722                s_timer%parent_section => s_wrk  
    723             ENDIF 
    724             s_wrk => s_wrk%prev 
    725          END DO  
    726       ENDIF          
    727       ! 
     791      ENDIF  
     792      !    write(*,*) 'after allocation' 
     793     ! 
    728794   END SUBROUTINE timing_ini_var 
    729795 
     
    738804!      IF(lwp) WRITE(numout,*) 'timing_reset : instrumented routines for timing' 
    739805!      IF(lwp) WRITE(numout,*) '~~~~~~~~~~~~' 
    740 !      CALL timing_list(s_timer_root) 
     806      CALL timing_list(s_timer_root) 
    741807!      WRITE(numout,*) 
    742808      ! 
Note: See TracChangeset for help on using the changeset viewer.