Commit 7f919dd2 authored by Daniel Wortmann's avatar Daniel Wortmann

Updated timing routines

parent 57254036
......@@ -25,7 +25,7 @@ SUBROUTINE w_inpXML(&
& numSpecies,enpara)
USE m_types
USE m_juDFT_init
USE m_juDFT
USE m_constants
USE m_xmlOutput
......
......@@ -16,4 +16,5 @@ juDFT/init.F90
juDFT/juDFT.F90
juDFT/stop.F90
juDFT/time.F90
juDFT/args.F90
)
......@@ -8,28 +8,9 @@
USE m_judft_time
IMPLICIT NONE
PRIVATE
PUBLIC juDFT_init,juDFT_was_argument
PUBLIC juDFT_init
CONTAINS
FUNCTION juDFT_was_argument(arg) RESULT(OK)
IMPLICIT NONE
CHARACTER(len=*),INTENT(IN)::arg
LOGICAL ok
INTEGER:: i
CHARACTER(LEN=30)::str
ok=.false.
DO i=1,command_argument_count()
CALL get_command_argument(i,str)
IF(adjustl(str)==adjustl(arg)) ok=.true.
ENDDO
IF (ok) return
!Test for environment variable as well
CALL get_environment_variable("juDFT",str,status=i)
IF (i==0) ok=index(str,adjustl(arg))>0
END FUNCTION
SUBROUTINE juDFT_init()
CALL signal_handler()
END SUBROUTINE juDFT_init
......
......@@ -8,5 +8,6 @@
USE m_juDFT_stop
USE m_juDFT_time
USE m_juDFT_init
USE m_judft_args
END MODULE m_juDFT
......@@ -4,23 +4,24 @@
! of the MIT license as expressed in the LICENSE file in more detail.
!--------------------------------------------------------------------------------
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
!*****************************************************************
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
! 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
TYPE t_p
TYPE(t_timer),POINTER:: p
END TYPE
END TYPE t_p
TYPE t_timer
REAL :: starttime
......@@ -29,7 +30,7 @@
INTEGER :: n_subtimers
TYPE(t_p),ALLOCATABLE :: subtimer(:)
TYPE(t_timer),POINTER :: parenttimer
END TYPE
END TYPE t_timer
TYPE(t_timer),POINTER,SAVE:: globaltimer=>NULL()
TYPE(t_timer),POINTER,SAVE:: current_timer=>NULL()
......@@ -40,7 +41,7 @@
PUBLIC resetIterationDependentTimers
PUBLIC juDFT_time_lastlocation !should not be used
CONTAINS
CONTAINS
......@@ -61,16 +62,16 @@
t%n_subtimers=0
ALLOCATE(t%subtimer(max_subtimer))
IF (associated(current_timer)) THEN
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)))
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
ALLOCATE(current_timer%subtimer(SIZE(tmp)+max_subtimer))
current_timer%subtimer(:SIZE(tmp))=tmp
DEALLOCATE(tmp)
ENDIF
......@@ -87,6 +88,7 @@
!<-- 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
......@@ -95,39 +97,30 @@
INTEGER::n
#ifdef CPP_MPI
INTEGER::irank,ierr
include 'mpif.h'
INCLUDE 'mpif.h'
#endif
IF (present(file)) lastfile=file
IF (present(line)) lastline=line
IF (.NOT.associated(current_timer)) THEN
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
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()
#ifdef CPP_DEBUG
#ifdef CPP_MPI
CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,ierr)
#endif
WRITE(*,"(i3,3a,i10)") irank," started: ",current_timer%name," at:",cputime()
#endif
CALL priv_debug_output(" started ",current_timer%name)
RETURN
ENDIF
ENDDO
!new subtimer
CALL priv_new_timer(ttimer)
#ifdef CPP_DEBUG
#ifdef CPP_MPI
CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,ierr)
#endif
WRITE(*,*) irank," started: ",current_timer%name
#endif
CALL priv_debug_output(" started ",current_timer%name)
END SUBROUTINE timestart
!>
......@@ -136,7 +129,7 @@
SUBROUTINE timestop(ttimer)
CHARACTER(LEN =*),INTENT(IN) :: ttimer
IF (.NOT.trim(ttimer)==trim(current_timer%name)) THEN
IF (.NOT.TRIM(ttimer)==TRIM(current_timer%name)) THEN
WRITE(*,*)"Current timer:",current_timer%name," could not stop:",ttimer
STOP "BUG:timestop"
ENDIF
......@@ -147,13 +140,27 @@
current_timer%time=current_timer%time+cputime()-current_timer%starttime
current_timer%starttime=-1
#ifdef CPP_DEBUG
CALL priv_writetimes(current_timer,5,6)
#endif
CALL priv_debug_output(" stopped ",current_timer%name)
current_timer=>current_timer%parenttimer
END SUBROUTINE timestop
!>
SUBROUTINE priv_debug_output(startstop,name)
IMPLICIT NONE
CHARACTER(LEN=*),INTENT(IN):: startstop,name
#ifdef CPP_MPI
INTEGER::irank,ierr
INCLUDE 'mpif.h'
#endif
IF (.NOT.l_debug) RETURN
#ifdef CPP_MPI
CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,ierr)
WRITE(*,"(i3,3a,f10.3)") irank,startstop,name," at:",cputime()
#else
WRITE(*,"(3a,f10.3)") startstop,name," at:",cputime()
#endif
END SUBROUTINE priv_debug_output
RECURSIVE SUBROUTINE priv_writetimes_longest(timer,fid,timernames,timertimes)
IMPLICIT NONE
......@@ -164,10 +171,10 @@
REAL,ALLOCATABLE ::times(:)
CHARACTER(LEN=60),ALLOCATABLE ::names(:)
real ::sum_time
REAL ::sum_time
integer :: n,i
IF (.NOT.present(timernames)) THEN
INTEGER :: n,i
IF (.NOT.PRESENT(timernames)) THEN
ALLOCATE(times(10),names(10))
times=0.0
names=""
......@@ -178,9 +185,9 @@
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)
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
......@@ -196,16 +203,16 @@
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
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
ENDIF
timertimes(i)=sum_time
ENDIF
END SUBROUTINE
END SUBROUTINE priv_writetimes_longest
RECURSIVE SUBROUTINE priv_writetimes(timer,level,fid,debug)
IMPLICIT NONE
......@@ -217,7 +224,7 @@
REAL :: time
CHARACTER(LEN=30):: timername,indentstring
WRITE(timername,"(i0)") level-1
WRITE(indentstring,"(100a)") (" ",n=2,(min(level,5))),trim(timername)
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."
......@@ -226,16 +233,16 @@
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
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)
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
......@@ -249,11 +256,11 @@
IMPLICIT NONE
TYPE(t_timer),INTENT(IN),OPTIONAL::location
IF (.NOT.present(location)) THEN
IF (associated(current_timer)) CALL writelocation(current_timer)
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)
IF (ASSOCIATED(location%parenttimer)) CALL writelocation(location%parenttimer)
ENDIF
END SUBROUTINE writelocation
......@@ -265,14 +272,14 @@
INTEGER :: fn,irank=0
LOGICAL :: l_out
#ifdef CPP_MPI
include "mpif.h"
INCLUDE "mpif.h"
INTEGER::err,isize
CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
#endif
IF (.NOT.associated(globaltimer)) RETURN !write nothing if no timing recorded
IF (.NOT.ASSOCIATED(globaltimer)) RETURN !write nothing if no timing recorded
l_out=.FALSE.
IF (present(stdout)) l_out=stdout
IF (PRESENT(stdout)) l_out=stdout
IF (l_out) THEN
fn=6
ELSE
......@@ -285,11 +292,11 @@
globaltimer%time=cputime()-globaltimer%starttime
globaltimer%starttime=-1
ENDIF
write(fn,"('Total execution time: ',i0,'sec')") int(globaltimer%time)
WRITE(fn,"('Total execution time: ',i0,'sec')") INT(globaltimer%time)
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)
INT(globaltimer%time),INT(min_time*globaltimer%time)
#ifdef CPP_MPI
CALL MPI_COMM_SIZE(MPI_COMM_WORLD,isize,err)
WRITE(fn,*) "Program used ",isize," PE"
......@@ -304,7 +311,7 @@
WRITE(fn,*) "Total timings:"
min_time=0.0
CALL priv_writetimes(globaltimer,1,fn)
flush(fn)
FLUSH(fn)
IF (.NOT.l_out) CLOSE(2)
END SUBROUTINE writetimes
......@@ -318,13 +325,13 @@
LOGICAL :: l_out
TYPE(t_timer), POINTER :: timer
#ifdef CPP_MPI
include "mpif.h"
INCLUDE "mpif.h"
INTEGER::err,isize
CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
#endif
IF (irank.NE.0) RETURN
IF (.NOT.associated(globaltimer)) RETURN !write nothing if no timing recorded
IF (.NOT.ASSOCIATED(globaltimer)) RETURN !write nothing if no timing recorded
timer => globaltimer
DO WHILE (TRIM(ADJUSTL(timer%name)).NE.'Iteration')
......@@ -375,10 +382,10 @@
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/)))
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/)))
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
......@@ -394,13 +401,13 @@
LOGICAL :: l_out
TYPE(t_timer), POINTER :: timer, parenttimer
#ifdef CPP_MPI
include "mpif.h"
INCLUDE "mpif.h"
INTEGER::err,isize
CALL MPI_COMM_RANK(MPI_COMM_WORLD,irank,err)
#endif
IF (irank.NE.0) RETURN
IF (.NOT.associated(globaltimer)) RETURN !write nothing if no timing recorded
IF (.NOT.ASSOCIATED(globaltimer)) RETURN !write nothing if no timing recorded
timer => globaltimer
DO WHILE (TRIM(ADJUSTL(timer%name)).NE.'Iteration')
......@@ -437,23 +444,23 @@
REAL,INTENT(IN) :: time,ttime
CHARACTER*(90) :: timestring
INTEGER,INTENT(IN) ::level
! .. Local Scalars ..
! .. Local Scalars ..
REAL :: rest,seconds
INTEGER :: ihours,iminutes
CHARACTER(LEN=90)::formatstring
rest = time
ihours = int(rest/3600.0)
rest = rest - real(ihours)*3600
ihours = INT(rest/3600.0)
rest = rest - REAL(ihours)*3600
iminutes = int(rest/60.0)
seconds = rest - real(iminutes)*60
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)
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
WRITE (timestring,FMT = formatstring) time,ihours,iminutes,INT(seconds),time/ttime*100.0
ENDIF
END FUNCTION timestring
......@@ -462,7 +469,7 @@
!<-- F: cputime()
!Private function to return the cpu_time in sec
FUNCTION cputime()
!$ use omp_lib
!$ use omp_lib
#ifdef __INTEL_COMPILER
USE ifport
#endif
......@@ -472,7 +479,7 @@
#endif
REAL::cputime
!TRY TO USE mpi OR openmp wall-clock functions
!TRY TO USE mpi OR openmp wall-clock functions
#ifdef CPP_MPI
cputime=MPI_WTIME()
#elif __INTEL_COMPILER
......@@ -481,7 +488,7 @@
cputime = omp_get_wtime ( )
#else
!use f95 intrinsic function
CALL cpu_time(cputime)
CALL CPU_TIME(cputime)
#endif
END FUNCTION cputime
!>
......@@ -489,9 +496,9 @@
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,"File:",TRIM(lastfile),":",lastline
WRITE(0,*) PE,"*****************************************"
ENDIF
END SUBROUTINE juDFT_time_lastlocation
END MODULE m_juDFT_time
END MODULE m_juDFT_time
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment