time.F90 17.2 KB
Newer Older
1 2 3 4 5 6
!--------------------------------------------------------------------------------
! Copyright (c) 2016 Peter Grünberg Institut, Forschungszentrum Jülich, Germany
! This file is part of FLEUR and available as free software under the conditions
! of the MIT license as expressed in the LICENSE file in more detail.
!--------------------------------------------------------------------------------

7 8 9 10 11 12 13 14 15 16 17 18 19 20 21
MODULE m_juDFT_time
  !*****************************************************************
  !     DESC:Timer module for measuring the execution times of different
  !     parts of the code
  !     timestart and timestop should be
  !     called with suitable names for timers
  !     Daniel Wortmann, Fri Sep  6 11:53:08 2002
  !*****************************************************************
  USE m_xmlOutput
  IMPLICIT NONE
  !     List of different timers
  PRIVATE
  INTEGER,PARAMETER         :: max_subtimer=5 ! blocks of subtimers are allocated in this size
  REAL                      :: min_time=0.02 ! minimal time to display in output (part of total)
  LOGICAL                   :: l_debug  !write out each start& stop of timer
22
  REAL                      :: debugtimestart=-1.0
23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41
  TYPE t_p
     TYPE(t_timer),POINTER:: p
  END TYPE t_p

  TYPE t_timer
     REAL                  :: starttime
     REAL                  :: time
     CHARACTER(LEN=60)     :: name
     INTEGER               :: n_subtimers
     TYPE(t_p),ALLOCATABLE :: subtimer(:)
     TYPE(t_timer),POINTER :: parenttimer
  END TYPE t_timer

  TYPE(t_timer),POINTER,SAVE:: globaltimer=>NULL()
  TYPE(t_timer),POINTER,SAVE:: current_timer=>NULL()
  CHARACTER(LEN=256),SAVE   :: lastfile=""
  INTEGER           ,SAVE   :: lastline=0

  PUBLIC timestart,timestop,writetimes,writelocation,writeTimesXML
42
  PUBLIC resetIterationDependentTimers,check_time_for_next_iteration
43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63
  PUBLIC juDFT_time_lastlocation !should not be used

CONTAINS



  SUBROUTINE priv_new_timer(name)
    IMPLICIT NONE
    CHARACTER(LEN=*),INTENT(IN)          ::name



    TYPE(t_timer),POINTER      ::t
    TYPE(t_p),ALLOCATABLE      :: tmp(:)


    ALLOCATE(t)
    t%starttime=cputime()
    t%time=0.0
    t%name=name
    t%n_subtimers=0
64
    t%parenttimer=>null()
65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
    ALLOCATE(t%subtimer(max_subtimer))

    IF (ASSOCIATED(current_timer)) THEN
       ALLOCATE(t%parenttimer)
       t%parenttimer=>current_timer
       !now add timer to list of subtimers of parenttimer
       IF (current_timer%n_subtimers+1>SIZE(current_timer%subtimer)) THEN
          ALLOCATE(tmp(SIZE(current_timer%subtimer)))
          tmp=current_timer%subtimer
          DEALLOCATE(current_timer%subtimer)
          ALLOCATE(current_timer%subtimer(SIZE(tmp)+max_subtimer))
          current_timer%subtimer(:SIZE(tmp))=tmp
          DEALLOCATE(tmp)
       ENDIF

       current_timer%n_subtimers=current_timer%n_subtimers+1

       current_timer%subtimer(current_timer%n_subtimers)%p => t
    ELSE
       globaltimer=>t
    ENDIF
    current_timer=>t

  END SUBROUTINE priv_new_timer

  !<-- S: timestart(timer)

  SUBROUTINE timestart(ttimer,file,line)
    USE m_judft_args
    IMPLICIT NONE
    CHARACTER(LEN =*),INTENT(IN)          :: ttimer
    CHARACTER(LEN=*),INTENT(IN),OPTIONAL  :: file
    INTEGER,INTENT(IN),OPTIONAL           :: line

    INTEGER::n
100
#ifdef CPP_MPI
101 102
    INTEGER::irank,ierr
    INCLUDE 'mpif.h'
103
#endif
104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151
    IF (PRESENT(file)) lastfile=file
    IF (PRESENT(line)) lastline=line
    IF (.NOT.ASSOCIATED(current_timer)) THEN
       CALL priv_new_timer("Total Run")
       l_debug=judft_was_Argument("-debugtime")
    ENDIF

    DO n=1,current_timer%n_subtimers
       IF (TRIM(ttimer)==TRIM(current_timer%subtimer(n)%p%name)) THEN
          current_timer=>current_timer%subtimer(n)%p
          IF (current_timer%starttime>0) THEN
             WRITE(*,*) "Timer already running:",ttimer
             STOP "BUG:starttime"
          ENDIF
          current_timer%starttime=cputime()
          CALL priv_debug_output(" started ",current_timer%name)
          RETURN
       ENDIF
    ENDDO
    !new subtimer
    CALL priv_new_timer(ttimer)
    CALL priv_debug_output(" started ",current_timer%name)
  END SUBROUTINE timestart

  !>
  !<-- S:timestop(timer)

  SUBROUTINE timestop(ttimer)
    CHARACTER(LEN =*),INTENT(IN) :: ttimer

    IF (.NOT.TRIM(ttimer)==TRIM(current_timer%name)) THEN
       WRITE(*,*)"Current timer:",current_timer%name," could not stop:",ttimer
       STOP "BUG:timestop"
    ENDIF
    IF (current_timer%starttime<0) THEN
       WRITE(*,*)   "Timer not initialized:"//ttimer
       STOP "BUG:timestop"
    ENDIF
    current_timer%time=current_timer%time+cputime()-current_timer%starttime
    current_timer%starttime=-1

    CALL priv_debug_output(" stopped ",current_timer%name)

    current_timer=>current_timer%parenttimer
  END SUBROUTINE timestop

  !>
  SUBROUTINE priv_debug_output(startstop,name)
152
    USE m_judft_sysinfo
153 154
    IMPLICIT NONE
    CHARACTER(LEN=*),INTENT(IN):: startstop,name
155
#ifdef CPP_MPI
156 157
    INTEGER::irank,ierr
    INCLUDE 'mpif.h'
158
#endif
159
    IF (.NOT.l_debug) RETURN
160
    if (debugtimestart<0) debugtimestart=cputime()
161
#ifdef CPP_MPI
162
    CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,ierr)
163
    WRITE(*,"(i3,3a,f20.2,5x,a)") irank,startstop,name," at:",cputime()-debugtimestart,memory_usage_string()
164
#else
165
    WRITE(*,"(3a,f20.2,5x,a)") startstop,name," at:",cputime()-debugtimestart,memory_usage_string()
166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197
#endif      
  END SUBROUTINE priv_debug_output

  RECURSIVE SUBROUTINE priv_writetimes_longest(timer,fid,timernames,timertimes)
    IMPLICIT NONE
    TYPE(t_timer),INTENT(IN) :: timer
    INTEGER,INTENT(IN),OPTIONAL              :: fid
    CHARACTER(LEN=60),INTENT(INOUT),OPTIONAL ::timernames(10)
    REAL,INTENT(INOUT),OPTIONAL              ::timertimes(10)

    REAL,ALLOCATABLE              ::times(:)
    CHARACTER(LEN=60),ALLOCATABLE ::names(:)
    REAL                          ::sum_time

    INTEGER :: n,i
    IF (.NOT.PRESENT(timernames)) THEN
       ALLOCATE(times(10),names(10))
       times=0.0
       names=""
       CALL priv_writetimes_longest(timer,timernames=names,timertimes=times)
       WRITE(fid,*)
       WRITE(fid,*) "-------------------------------------------------"
       WRITE(fid,*)
       WRITE(fid,*) "most relevant subroutines:"
       sum_time=0.0
       DO n=1,10
          IF (MAXVAL(times)<1E-4) EXIT
          i=MAXLOC(times,dim=1)
          WRITE(fid,"(a,T7,a,T46,a)") " ",TRIM(names(i)),timestring(times(i),timer%time,2)
          sum_time=sum_time+times(i)
          times(i)=0.0
       ENDDO
198
       WRITE(fid,"(t77,'Sum: ',f5.1,'%')") sum_time/timer%time*100.
199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273
       WRITE(fid,*)
       WRITE(fid,*) "-------------------------------------------------"
       WRITE(fid,*)
       RETURN
    ENDIF

    sum_time=timer%time
    DO n=1,timer%n_subtimers
       CALL priv_writetimes_longest(timer%subtimer(n)%p,timernames=timernames,timertimes=timertimes)
       sum_time=sum_time-timer%subtimer(n)%p%time
    ENDDO
    IF (sum_time>MINVAL(timertimes)) THEN
       i=MINLOC(timertimes,dim=1)
       IF (ASSOCIATED(timer%parenttimer)) THEN
          WRITE(timernames(i),"(a18,'->',a40)") timer%parenttimer%name,timer%name
       ELSE
          timernames(i)=timer%name
       ENDIF
       timertimes(i)=sum_time
    ENDIF
  END SUBROUTINE priv_writetimes_longest

  RECURSIVE SUBROUTINE priv_writetimes(timer,level,fid,debug)
    IMPLICIT NONE
    TYPE(t_timer),INTENT(IN)    :: timer
    INTEGER,INTENT(IN)          :: level,fid
    LOGICAL,INTENT(IN),OPTIONAL ::debug

    INTEGER          :: n
    REAL             :: time
    CHARACTER(LEN=30):: timername,indentstring
    WRITE(timername,"(i0)") level-1
    WRITE(indentstring,"(100a)") (" ",n=2,(MIN(level,5))),TRIM(timername)
    IF (timer%starttime>0) THEN
       time=timer%time+cputime()-timer%starttime
       timername=timer%name//" not term."
    ELSE
       time=timer%time
       timername=timer%name
    ENDIF
    IF (time<min_time*globaltimer%time) RETURN !do not print parts that take less than min_time
    WRITE(fid,"(a,T7,a,T46,a)") TRIM(indentstring),TRIM(timername),timestring(time,globaltimer%time,level)
    FLUSH(fid)
    IF (PRESENT(debug).OR.timer%n_subtimers==0) RETURN

    time=0
    DO n=1,timer%n_subtimers
       time=time+timer%subtimer(n)%p%time
    ENDDO
    WRITE(fid,"(a,a,T46,a)") TRIM(indentstring)," measured in submodules:",timestring(time,-.1,level)
    FLUSH(fid)
    DO n=1,timer%n_subtimers
       CALL priv_writetimes(timer%subtimer(n)%p,level+1,fid)
    ENDDO
  END SUBROUTINE priv_writetimes

  !<-- S:writetimes()

  RECURSIVE SUBROUTINE writelocation(location)
    !writes the stack of current timers to std-out
    !usefull for debugging and error messages
    IMPLICIT NONE
    TYPE(t_timer),INTENT(IN),OPTIONAL::location

    IF (.NOT.PRESENT(location)) THEN
       IF (ASSOCIATED(current_timer)) CALL writelocation(current_timer)
    ELSE
       WRITE(*,*) "Timer:",location%name
       IF (ASSOCIATED(location%parenttimer)) CALL writelocation(location%parenttimer)
    ENDIF
  END SUBROUTINE writelocation


  ! writes all times to file
  SUBROUTINE writetimes(stdout)
274
    USE m_judft_usage
275 276 277 278
    IMPLICIT NONE
    LOGICAL,INTENT(IN),OPTIONAL::stdout
    INTEGER :: fn,irank=0
    LOGICAL :: l_out
279
#ifdef CPP_MPI
280 281
    INCLUDE "mpif.h"
    INTEGER::err,isize
282

283
    CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
284
#endif
285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300
    IF (.NOT.ASSOCIATED(globaltimer)) RETURN !write nothing if no timing recorded
    l_out=.FALSE.
    IF (PRESENT(stdout)) l_out=stdout
    IF (l_out) THEN
       fn=6
    ELSE
       IF (irank>0) RETURN
       fn=2
       OPEN(2,FILE ='juDFT_times',STATUS="replace")
    ENDIF
    !Stop globaltimer if still running
    IF (globaltimer%starttime>-1) THEN
       globaltimer%time=cputime()-globaltimer%starttime
       globaltimer%starttime=-1
    ENDIF
    WRITE(fn,"('Total execution time: ',i0,'sec')") INT(globaltimer%time)
301
    CALL add_usage_data("Runtime",INT(globaltimer%time))
302 303 304 305
    CALL priv_writetimes_longest(globaltimer,fid=fn)

    WRITE(fn,"('Total execution time: ',i0,'sec, minimal timing printed:',i0,'sec')") &
         INT(globaltimer%time),INT(min_time*globaltimer%time)
306
#ifdef CPP_MPI
307 308
    CALL MPI_COMM_SIZE(MPI_COMM_WORLD,isize,err)
    WRITE(fn,*) "Program used ",isize," PE"
309
#endif
310
    CALL priv_writetimes(globaltimer,1,fn)
311 312 313



314 315 316 317 318 319 320 321
    WRITE(fn,*)
    WRITE(fn,*) "-------------------------------------------------"
    WRITE(fn,*)
    WRITE(fn,*) "Total timings:"
    min_time=0.0
    CALL priv_writetimes(globaltimer,1,fn)
    FLUSH(fn)
    IF (.NOT.l_out) CLOSE(2)
322

323
  END SUBROUTINE writetimes
324

325 326
  ! writes all times to out.xml file
  SUBROUTINE writeTimesXML()
327

328
    IMPLICIT NONE
329

330 331 332
    INTEGER                :: fn,irank=0
    LOGICAL                :: l_out
    TYPE(t_timer), POINTER :: timer
333
#ifdef CPP_MPI
334 335
    INCLUDE "mpif.h"
    INTEGER::err,isize
336

337
    CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
338
#endif
339

340 341 342
    IF (irank.NE.0) RETURN
    IF (.NOT.ASSOCIATED(globaltimer)) RETURN !write nothing if no timing recorded

343 344 345
    timer => NULL()
    CALL findIterationTimer(globaltimer,timer)
    IF(.NOT.ASSOCIATED(timer)) RETURN
346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400

    CALL openXMLElement('timing',(/'units'/),(/'sec'/))
    CALL privWriteTimesXML(timer,1)
    CALL closeXMLElement('timing')

  END SUBROUTINE writeTimesXML

  RECURSIVE SUBROUTINE privWriteTimesXML(timer,level)

    IMPLICIT NONE

    TYPE(t_timer),INTENT(IN)    :: timer
    INTEGER,INTENT(IN)          :: level

    INTEGER            :: n, timerNameLength
    REAL               :: time
    CHARACTER(LEN=50)  :: timername
    CHARACTER(LEN=50)  :: attributes(2)

    IF (timer%starttime>0) THEN
       time=timer%time+cputime()-timer%starttime
    ELSE
       time=timer%time
    END IF
    timername=''
    DO n = 1, level-2
       timername = timername(1:3*(n-1))//'|  '
    END DO
    IF (level.GE.2) THEN
       timername = timername(1:3*(level-2))//'+--'
    END IF
    timername=TRIM(ADJUSTL(timername))//TRIM(ADJUSTL(timer%name))
    timerNameLength = LEN(TRIM(ADJUSTL(timername)))

    DO n = 1, timerNameLength
       IF (timername(n:n).EQ.'&') THEN
          timername(n:n) = '+'
       END IF
    END DO

    WRITE(attributes(1),'(a)') TRIM(ADJUSTL(timername))
    WRITE(attributes(2),'(f12.3)') time
    IF(timer%n_subtimers.EQ.0) THEN
       CALL writeXMLElementForm('timer',(/'name ','value'/),attributes,&
            RESHAPE((/14+20-3*level,55-timerNameLength,timerNameLength,12/),(/2,2/)))
    ELSE
       CALL openXMLElementForm('compositeTimer',(/'name ','value'/),attributes,&
            RESHAPE((/5+20-3*level,55-timerNameLength,timerNameLength,12/),(/2,2/)))
       DO n = 1, timer%n_subtimers
          CALL privWriteTimesXML(timer%subtimer(n)%p,level+1)
       END DO
       CALL closeXMLElement('compositeTimer')
    END IF
  END SUBROUTINE privWriteTimesXML

401 402 403 404 405
  SUBROUTINE check_time_for_next_iteration(it,l_cont)
    USE m_judft_args
    IMPLICIT NONE
    INTEGER,INTENT(IN)     :: it
    LOGICAL,INTENT(INOUT)  :: l_cont
406
    CHARACTER(len=1000)::wtime_string
407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435
    INTEGER          :: wtime,time_used,time_per_iter
    INTEGER:: irank=0
#ifdef CPP_MPI
    INCLUDE "mpif.h"
    INTEGER::err,isize
    CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
#endif

    IF (.NOT.l_cont) RETURN !stop anyway
    IF (.NOT.ASSOCIATED(globaltimer)) RETURN !do nothing if no timing recorded
    IF (judft_was_argument("-wtime")) THEN
       wtime_string=judft_string_for_argument("-wtime")
       READ(wtime_string,*) wtime
       time_used=FLOOR((cputime()-globaltimer%starttime)/60.0)+1
       time_per_iter=FLOOR((cputime()-globaltimer%starttime)/60.0/it)+1
       IF (irank==0) THEN
          WRITE(*,*) "Test for time of next iteration:"
          WRITE(*,*) "Time provided (min):",wtime
          WRITE(*,*) "Time used     (min):",time_used
          WRITE(*,*) "Time per iter (min):",time_per_iter
       ENDIF
       IF (time_used+time_per_iter>wtime) THEN
          l_cont=.FALSE.
          IF (irank==0) WRITE(*,*) "No further iterations"
       ENDIF
    END IF
  END SUBROUTINE check_time_for_next_iteration


436 437 438
  SUBROUTINE resetIterationDependentTimers()

    IMPLICIT NONE
439
   
440 441 442
    INTEGER                :: fn,irank=0
    LOGICAL                :: l_out
    TYPE(t_timer), POINTER :: timer, parenttimer
443
#ifdef CPP_MPI
444 445
    INCLUDE "mpif.h"
    INTEGER::err,isize
446
  
447

448
    CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
449
#endif
450 451 452
    !Check if not enough time for another iteration is left
    
       
453 454 455
    IF (irank.NE.0) RETURN
    IF (.NOT.ASSOCIATED(globaltimer)) RETURN !write nothing if no timing recorded

456 457 458 459
    timer => NULL()
    CALL findIterationTimer(globaltimer,timer)
    IF(.NOT.ASSOCIATED(timer)) RETURN

460 461 462 463 464 465 466 467 468 469 470
    DO WHILE (TRIM(ADJUSTL(timer%name)).NE.'Iteration')
       IF(timer%n_subtimers.EQ.0) RETURN
       timer => timer%subtimer(1)%p
    END DO

    parenttimer => timer%parenttimer
    CALL resetSubtimers(timer%parenttimer)
    ALLOCATE(parenttimer%subtimer(5))

  END SUBROUTINE resetIterationDependentTimers

471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489 490 491
  RECURSIVE SUBROUTINE findIterationTimer (parent, result)

    IMPLICIT NONE

    TYPE(t_timer),POINTER,INTENT(IN)    :: parent
    TYPE(t_timer),POINTER,INTENT(OUT)   :: result

    INTEGER numSubtimers, i

    IF(TRIM(ADJUSTL(parent%name)).EQ.'Iteration') THEN
       result => parent
    ELSE
       numSubtimers = parent%n_subtimers
       DO i = 1, numSubtimers
          CALL findIterationTimer(parent%subtimer(i)%p,result)
          IF (ASSOCIATED(result)) RETURN
       END DO
    END IF

  END SUBROUTINE findIterationTimer

492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540
  RECURSIVE SUBROUTINE resetSubtimers (timer)

    IMPLICIT NONE

    TYPE(t_timer),INTENT(INOUT)    :: timer

    INTEGER :: n

    DO n = 1, timer%n_subtimers
       CALL resetSubtimers (timer%subtimer(n)%p)
       DEALLOCATE(timer%subtimer(n)%p)
    END DO
    DEALLOCATE(timer%subtimer)
    timer%n_subtimers = 0
  END SUBROUTINE resetSubtimers

  !>
  !<-- private function timestring

  FUNCTION timestring(time,ttime,level)
    REAL,INTENT(IN)    :: time,ttime
    CHARACTER*(90)     :: timestring
    INTEGER,INTENT(IN) ::level
    !     .. Local Scalars ..
    REAL :: rest,seconds
    INTEGER :: ihours,iminutes
    CHARACTER(LEN=90)::formatstring
    rest = time

    ihours = INT(rest/3600.0)
    rest = rest - REAL(ihours)*3600

    iminutes = INT(rest/60.0)
    seconds = rest - REAL(iminutes)*60
    IF (ttime<0) THEN
       formatstring="(f9.2,'sec = ',i3,'h ',i2,'min ',i2,'sec')"
       WRITE (timestring,FMT = formatstring) time,ihours,iminutes,INT(seconds)
    ELSE
       WRITE(formatstring,"(a,i0,a)") "(f9.2,'sec= ',i3,'h ',i2,'min ',i2,'sec ->',",(2*level-1),"x,f5.1,'%')"
       WRITE (timestring,FMT = formatstring) time,ihours,iminutes,INT(seconds),time/ttime*100.0
    ENDIF

  END FUNCTION timestring

  !>
  !<-- F: cputime()
  !Private function to return the cpu_time in sec
  FUNCTION cputime()
    !$    use omp_lib
541
#ifdef __INTEL_COMPILER
542
    USE ifport
543
#endif
544
    IMPLICIT NONE
545
#ifdef CPP_MPI
546
    INCLUDE 'mpif.h'
547
#endif
548
    REAL::cputime
549

550
    !TRY TO USE mpi OR openmp wall-clock functions
551
#ifdef CPP_MPI
552
    cputime=MPI_WTIME()
553
#elif __INTEL_COMPILER
554
    cputime=rtc()
555
#elif _OPENMP
556
    cputime = omp_get_wtime ( )
557
#else
558 559
    !use f95 intrinsic function
    CALL CPU_TIME(cputime)
560
#endif
561 562 563 564 565 566 567 568 569 570 571
  END FUNCTION cputime
  !>
  SUBROUTINE juDFT_time_lastlocation(PE)
    CHARACTER(LEN=4),INTENT(IN):: PE
    IF (lastline>0) THEN
       WRITE(0,*) PE,"Last kown location:"
       WRITE(0,*) PE,"File:",TRIM(lastfile),":",lastline
       WRITE(0,*) PE,"*****************************************"
    ENDIF
  END SUBROUTINE juDFT_time_lastlocation
END MODULE m_juDFT_time
572