Changeset 10425 for NEMO/trunk/src/OCE/timing.F90
- Timestamp:
- 2018-12-19T22:54:16+01:00 (5 years ago)
- File:
-
- 1 edited
-
NEMO/trunk/src/OCE/timing.F90 (modified) (20 diffs)
Legend:
- Unmodified
- Added
- Removed
-
NEMO/trunk/src/OCE/timing.F90
r10068 r10425 38 38 TYPE timer 39 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 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 41 43 INTEGER :: ncount, ncount_max, ncount_rate 42 44 INTEGER :: niter … … 49 51 TYPE alltimer 50 52 CHARACTER(LEN=20), DIMENSION(:), POINTER :: cname => NULL() 51 52 53 53 REAL(wp), DIMENSION(:), POINTER :: tsum_cpu => NULL() 54 REAL(wp), DIMENSION(:), POINTER :: tsum_clock => NULL() 55 INTEGER, DIMENSION(:), POINTER :: niter => NULL() 54 56 TYPE(alltimer), POINTER :: next => NULL() 55 57 TYPE(alltimer), POINTER :: prev => NULL() … … 58 60 TYPE(timer), POINTER :: s_timer_root => NULL() 59 61 TYPE(timer), POINTER :: s_timer => NULL() 62 TYPE(timer), POINTER :: s_timer_old => NULL() 63 60 64 TYPE(timer), POINTER :: s_wrk => NULL() 61 65 REAL(wp) :: t_overclock, t_overcpu … … 90 94 CHARACTER(len=*), INTENT(in) :: cdinfo 91 95 ! 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 96 106 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 102 110 s_timer%l_tdone = .FALSE. 103 111 s_timer%niter = s_timer%niter + 1 … … 114 122 CALL SYSTEM_CLOCK(COUNT = s_timer%ncount) 115 123 #endif 124 ! write(*,*) 'end of start ', s_timer%cname 125 116 126 ! 117 127 END SUBROUTINE timing_start … … 127 137 ! 128 138 INTEGER :: ifinal_count, iperiods 129 REAL(wp) :: zcpu_end, zmpitime 139 REAL(wp) :: zcpu_end, zmpitime,zcpu_raw,zclock_raw 130 140 ! 131 141 s_wrk => NULL() … … 140 150 CALL CPU_TIME( zcpu_end ) 141 151 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 146 161 147 162 ! 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 150 167 ! clock time correction 151 168 #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 153 171 #else 154 172 iperiods = ifinal_count - s_timer%ncount 155 173 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 158 177 #endif 178 ! IF(s_timer%cname==trim('lbc_lnk_2d')) write(*,*) zclock_raw , s_timer%tsub_clock 159 179 160 180 ! Correction of parent section 161 181 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 168 186 ENDIF 169 187 … … 186 204 s_timer%l_tdone = .TRUE. 187 205 ! 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 188 212 END SUBROUTINE timing_stop 189 213 … … 211 235 WRITE(numtime,*) ' NEMO team' 212 236 WRITE(numtime,*) ' Ocean General Circulation Model' 213 WRITE(numtime,*) ' version 4.0 (2018) '237 WRITE(numtime,*) ' version 3.6 (2015) ' 214 238 WRITE(numtime,*) 215 239 WRITE(numtime,*) ' Timing Informations ' … … 263 287 TYPE(timer), POINTER :: s_temp 264 288 INTEGER :: idum, iperiods, icode 289 INTEGER :: ji 265 290 LOGICAL :: ll_ord, ll_averep 266 291 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 268 296 ll_averep = .TRUE. 269 297 … … 292 320 END DO 293 321 idum = nsize 294 IF(lk_mpp) CALL mpp_sum(idum)322 CALL mpp_sum('timing', idum) 295 323 IF( idum/jpnij /= nsize ) THEN 296 324 IF( lwriter ) WRITE(numtime,*) ' ===> W A R N I N G: ' … … 340 368 & ctime(2)(1:2), ctime(2)(3:4), ctime(2)(5:6), & 341 369 & 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 342 397 343 398 IF( lwriter ) CLOSE(numtime) … … 459 514 sl_timer_ave_root%next => NULL() 460 515 sl_timer_ave_root%prev => NULL() 516 ALLOCATE(sl_timer_ave) 461 517 sl_timer_ave => sl_timer_ave_root 462 518 ENDIF … … 490 546 s_timer => s_timer%next 491 547 END DO 492 493 WRITE(*,*) 'ARPDBG: timing: done gathers'494 548 495 549 IF( narea == 1 ) THEN … … 514 568 sl_timer_glob => sl_timer_glob%next 515 569 END DO 516 517 WRITE(*,*) 'ARPDBG: timing: done computing stats'518 570 519 571 ! reorder the averaged list by CPU time … … 567 619 ENDIF 568 620 ! 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 !574 621 DEALLOCATE(sl_timer_glob_root) 575 622 ! … … 676 723 s_timer => s_timer_root 677 724 ! 725 ALLOCATE(s_wrk) 678 726 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 680 748 ELSE 681 749 s_timer => s_timer_root 682 750 ! case of already existing area (typically inside a loop) 751 ! write(*,*) 'in ini_var for routine : ', cdinfo 683 752 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 685 757 s_timer => s_timer%next 686 758 END DO 687 759 688 760 ! end of the chain 689 761 s_timer => s_timer_root … … 691 763 s_timer => s_timer%next 692 764 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 695 771 s_timer%next%cname = cdinfo 696 772 s_timer%next%t_cpu = 0._wp … … 713 789 s_timer%next%next => NULL() 714 790 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 ! 728 794 END SUBROUTINE timing_ini_var 729 795 … … 738 804 ! IF(lwp) WRITE(numout,*) 'timing_reset : instrumented routines for timing' 739 805 ! IF(lwp) WRITE(numout,*) '~~~~~~~~~~~~' 740 !CALL timing_list(s_timer_root)806 CALL timing_list(s_timer_root) 741 807 ! WRITE(numout,*) 742 808 !
Note: See TracChangeset
for help on using the changeset viewer.
