Index: NEMO/trunk/src/OCE/timing.F90
===================================================================
--- NEMO/trunk/src/OCE/timing.F90	(revision 10068)
+++ NEMO/trunk/src/OCE/timing.F90	(revision 10425)
@@ -38,5 +38,7 @@
    TYPE timer
       CHARACTER(LEN=20)  :: cname
-   	  REAL(wp)  :: t_cpu, t_clock, tsum_cpu, tsum_clock, tmax_cpu, tmax_clock, tmin_cpu, tmin_clock, tsub_cpu, tsub_clock
+      CHARACTER(LEN=20)  :: surname
+      INTEGER :: rank
+      REAL(wp)  :: t_cpu, t_clock, tsum_cpu, tsum_clock, tmax_cpu, tmax_clock, tmin_cpu, tmin_clock, tsub_cpu, tsub_clock
       INTEGER :: ncount, ncount_max, ncount_rate  
       INTEGER :: niter
@@ -49,7 +51,7 @@
    TYPE alltimer
       CHARACTER(LEN=20), DIMENSION(:), POINTER :: cname => NULL()
-   	  REAL(wp), DIMENSION(:), POINTER :: tsum_cpu   => NULL()
-   	  REAL(wp), DIMENSION(:), POINTER :: tsum_clock => NULL()
-   	  INTEGER, DIMENSION(:), POINTER :: niter => NULL()
+      REAL(wp), DIMENSION(:), POINTER :: tsum_cpu   => NULL()
+      REAL(wp), DIMENSION(:), POINTER :: tsum_clock => NULL()
+      INTEGER, DIMENSION(:), POINTER :: niter => NULL()
       TYPE(alltimer), POINTER :: next => NULL()
       TYPE(alltimer), POINTER :: prev => NULL()
@@ -58,4 +60,6 @@
    TYPE(timer), POINTER :: s_timer_root => NULL()
    TYPE(timer), POINTER :: s_timer      => NULL()
+   TYPE(timer), POINTER :: s_timer_old      => NULL()
+
    TYPE(timer), POINTER :: s_wrk        => NULL()
    REAL(wp) :: t_overclock, t_overcpu
@@ -90,14 +94,18 @@
       CHARACTER(len=*), INTENT(in) :: cdinfo
       !
-       
-      ! Create timing structure at first call
-      IF( .NOT. l_initdone ) THEN
-         CALL timing_ini_var(cdinfo)
+       IF(ASSOCIATED(s_timer) ) s_timer_old => s_timer
+       !
+      ! Create timing structure at first call of the routine 
+       CALL timing_ini_var(cdinfo)
+   !   write(*,*) 'after inivar ', s_timer%cname
+
+      ! ici timing_ini_var a soit retrouve s_timer et fait return soit ajoute un maillon
+      ! maintenant on regarde si le call d'avant corrsspond a un parent ou si il est ferme
+      IF( .NOT. s_timer_old%l_tdone ) THEN      
+         s_timer%parent_section => s_timer_old
       ELSE
-         s_timer => s_timer_root
-         DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) ) 
-            IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next
-         END DO
-      ENDIF         
+         s_timer%parent_section => NULL()
+      ENDIF    
+
       s_timer%l_tdone = .FALSE.
       s_timer%niter = s_timer%niter + 1
@@ -114,4 +122,6 @@
       CALL SYSTEM_CLOCK(COUNT = s_timer%ncount)
 #endif
+!      write(*,*) 'end of start ', s_timer%cname
+
       !
    END SUBROUTINE timing_start
@@ -127,5 +137,5 @@
       !
       INTEGER  :: ifinal_count, iperiods    
-      REAL(wp) :: zcpu_end, zmpitime
+      REAL(wp) :: zcpu_end, zmpitime,zcpu_raw,zclock_raw
       !
       s_wrk => NULL()
@@ -140,30 +150,38 @@
       CALL CPU_TIME( zcpu_end )
 
-      s_timer => s_timer_root
-      DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) ) 
-         IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next
-      END DO
+!!$      IF(associated(s_timer%parent_section))then
+!!$        write(*,*) s_timer%cname,' <-- ', s_timer%parent_section%cname
+!!$      ENDIF  
+
+ !     No need to search ... : s_timer has the last value defined in start
+ !     s_timer => s_timer_root
+ !     DO WHILE( TRIM(s_timer%cname) /= TRIM(cdinfo) ) 
+ !        IF( ASSOCIATED(s_timer%next) ) s_timer => s_timer%next
+ !     END DO
  
       ! CPU time correction
-      s_timer%t_cpu  = zcpu_end - s_timer%t_cpu - t_overcpu - s_timer%tsub_cpu
-  
+      zcpu_raw = zcpu_end - s_timer%t_cpu - t_overcpu ! total time including child
+      s_timer%t_cpu  = zcpu_raw - s_timer%tsub_cpu
+  !    IF(s_timer%cname==trim('lbc_lnk_2d'))  write(*,*) s_timer%tsub_cpu,zcpu_end
+
       ! clock time correction
 #if defined key_mpp_mpi
-      s_timer%t_clock = zmpitime - s_timer%t_clock - t_overclock - s_timer%tsub_clock
+      zclock_raw = zmpitime - s_timer%t_clock - t_overclock ! total time including child
+      s_timer%t_clock = zclock_raw - t_overclock - s_timer%tsub_clock
 #else
       iperiods = ifinal_count - s_timer%ncount
       IF( ifinal_count < s_timer%ncount )  &
-          iperiods = iperiods + s_timer%ncount_max 
-      s_timer%t_clock  = REAL(iperiods) / s_timer%ncount_rate - t_overclock - s_timer%tsub_clock
+         iperiods = iperiods + s_timer%ncount_max 
+         zclock_raw = REAL(iperiods) / s_timer%ncount_rate !- t_overclock   
+         s_timer%t_clock  = zclock_raw - s_timer%tsub_clock
 #endif
+ !     IF(s_timer%cname==trim('lbc_lnk_2d')) write(*,*) zclock_raw , s_timer%tsub_clock
       
       ! Correction of parent section
       IF( .NOT. PRESENT(csection) ) THEN
-         s_wrk => s_timer
-         DO WHILE ( ASSOCIATED(s_wrk%parent_section ) )
-            s_wrk => s_wrk%parent_section
-            s_wrk%tsub_cpu   = s_wrk%tsub_cpu   + s_timer%t_cpu 
-            s_wrk%tsub_clock = s_wrk%tsub_clock + s_timer%t_clock              
-         END DO
+         IF ( ASSOCIATED(s_timer%parent_section ) ) THEN
+            s_timer%parent_section%tsub_cpu   = zcpu_raw   + s_timer%parent_section%tsub_cpu 
+            s_timer%parent_section%tsub_clock = zclock_raw + s_timer%parent_section%tsub_clock             
+         ENDIF
       ENDIF
             
@@ -186,4 +204,10 @@
       s_timer%l_tdone = .TRUE.
       !
+      !
+      ! we come back
+      IF ( ASSOCIATED(s_timer%parent_section ) ) s_timer => s_timer%parent_section
+     
+!      write(*,*) 'end of stop ', s_timer%cname
+
    END SUBROUTINE timing_stop
  
@@ -211,5 +235,5 @@
          WRITE(numtime,*) '                             NEMO team'
          WRITE(numtime,*) '                  Ocean General Circulation Model'
-         WRITE(numtime,*) '                        version 4.0  (2018) '
+         WRITE(numtime,*) '                        version 3.6  (2015) '
          WRITE(numtime,*)
          WRITE(numtime,*) '                        Timing Informations '
@@ -263,7 +287,11 @@
       TYPE(timer), POINTER :: s_temp
       INTEGER :: idum, iperiods, icode
+      INTEGER :: ji
       LOGICAL :: ll_ord, ll_averep
       CHARACTER(len=120) :: clfmt            
-      
+      REAL(wp), DIMENSION(:), ALLOCATABLE ::   timing_glob
+      REAL(wp) ::   zsypd   ! simulated years per day (Balaji 2017)
+      REAL(wp) ::   zperc, ztot
+
       ll_averep = .TRUE.
     
@@ -292,5 +320,5 @@
       END DO
       idum = nsize
-      IF(lk_mpp) CALL mpp_sum(idum)
+      CALL mpp_sum('timing', idum)
       IF( idum/jpnij /= nsize ) THEN
          IF( lwriter ) WRITE(numtime,*) '        ===> W A R N I N G: '
@@ -340,4 +368,31 @@
       &       ctime(2)(1:2), ctime(2)(3:4), ctime(2)(5:6),   &
       &       czone(1:3),    czone(4:5)
+
+#if defined key_mpp_mpi
+      ALLOCATE(timing_glob(4*jpnij), stat=icode)
+      CALL MPI_GATHER( (/compute_time, waiting_time(1), waiting_time(2), elapsed_time/),   &
+         &             4, MPI_DOUBLE_PRECISION, timing_glob, 4, MPI_DOUBLE_PRECISION, 0, MPI_COMM_OCE, icode)
+      IF( narea == 1 ) THEN
+         WRITE(numtime,*) ' '
+         WRITE(numtime,*) ' Report on time spent on waiting MPI messages '
+         WRITE(numtime,*) '    total timing measured between nit000+1 and nitend-1 '
+         WRITE(numtime,*) '    warning: includes restarts writing time if output before nitend... '
+         WRITE(numtime,*) ' '
+         DO ji = 1, jpnij
+            ztot = SUM( timing_glob(4*ji-3:4*ji-1) )
+            WRITE(numtime,'(A28,F11.6,            A34,I8)') 'Computing       time : ',timing_glob(4*ji-3), ' on MPI rank : ', ji
+            IF ( ztot /= 0. ) zperc = timing_glob(4*ji-2) / ztot * 100.
+            WRITE(numtime,'(A28,F11.6,A2, F4.1,A3,A25,I8)') 'Waiting lbc_lnk time : ',timing_glob(4*ji-2)   &
+               &                                                         , ' (',      zperc,' %)',   ' on MPI rank : ', ji
+            IF ( ztot /= 0. ) zperc = timing_glob(4*ji-1) / ztot * 100.
+            WRITE(numtime,'(A28,F11.6,A2, F4.1,A3,A25,I8)') 'Waiting  global time : ',timing_glob(4*ji-1)   &
+               &                                                         , ' (',      zperc,' %)',   ' on MPI rank : ', ji
+            zsypd = rn_rdt * REAL(nitend-nit000-1, wp) / (timing_glob(4*ji) * 365.)
+            WRITE(numtime,'(A28,F11.6,A7,F10.3,A2,A15,I8)') 'Total           time : ',timing_glob(4*ji  )   &
+               &                                                         , ' (SYPD: ', zsypd, ')',   ' on MPI rank : ', ji
+         END DO
+      ENDIF
+      DEALLOCATE(timing_glob)
+#endif      
 
       IF( lwriter ) CLOSE(numtime) 
@@ -459,4 +514,5 @@
          sl_timer_ave_root%next => NULL()
          sl_timer_ave_root%prev => NULL()
+         ALLOCATE(sl_timer_ave)
          sl_timer_ave => sl_timer_ave_root            
       ENDIF 
@@ -490,6 +546,4 @@
          s_timer => s_timer%next
       END DO      
-
-         WRITE(*,*) 'ARPDBG: timing: done gathers'
       
       IF( narea == 1 ) THEN    
@@ -514,6 +568,4 @@
             sl_timer_glob => sl_timer_glob%next                                
          END DO
-
-         WRITE(*,*) 'ARPDBG: timing: done computing stats'
       
          ! reorder the averaged list by CPU time      
@@ -567,9 +619,4 @@
       ENDIF
       !
-      DEALLOCATE(sl_timer_glob_root%cname     , &
-                 sl_timer_glob_root%tsum_cpu  , &
-                 sl_timer_glob_root%tsum_clock, &
-                 sl_timer_glob_root%niter)
-      !
       DEALLOCATE(sl_timer_glob_root)
       !                  
@@ -676,14 +723,39 @@
          s_timer => s_timer_root
          !
+         ALLOCATE(s_wrk)
          s_wrk => NULL()
-         
+         !
+         ALLOCATE(s_timer_old)
+         s_timer_old%cname       = cdinfo
+         s_timer_old%t_cpu      = 0._wp
+         s_timer_old%t_clock    = 0._wp
+         s_timer_old%tsum_cpu   = 0._wp
+         s_timer_old%tsum_clock = 0._wp
+         s_timer_old%tmax_cpu   = 0._wp
+         s_timer_old%tmax_clock = 0._wp
+         s_timer_old%tmin_cpu   = 0._wp
+         s_timer_old%tmin_clock = 0._wp
+         s_timer_old%tsub_cpu   = 0._wp
+         s_timer_old%tsub_clock = 0._wp
+         s_timer_old%ncount      = 0
+         s_timer_old%ncount_rate = 0
+         s_timer_old%ncount_max  = 0
+         s_timer_old%niter       = 0
+         s_timer_old%l_tdone  = .TRUE.
+         s_timer_old%next => NULL()
+         s_timer_old%prev => NULL()
+
       ELSE
          s_timer => s_timer_root
          ! case of already existing area (typically inside a loop)
+   !         write(*,*) 'in ini_var for routine : ', cdinfo
          DO WHILE( ASSOCIATED(s_timer) ) 
-            IF( TRIM(s_timer%cname) .EQ. TRIM(cdinfo) ) RETURN
+            IF( TRIM(s_timer%cname) .EQ. TRIM(cdinfo) ) THEN
+ !             write(*,*) 'in ini_var for routine : ', cdinfo,' we return'           
+               RETURN ! cdinfo is already in the chain
+            ENDIF
             s_timer => s_timer%next
          END DO
-         
+
          ! end of the chain
          s_timer => s_timer_root
@@ -691,6 +763,10 @@
             s_timer => s_timer%next
          END DO
-          
-         ALLOCATE(s_timer%next)      
+
+    !     write(*,*) 'after search', s_timer%cname
+         ! cdinfo is not part of the chain so we add it with initialisation          
+          ALLOCATE(s_timer%next)
+    !     write(*,*) 'after allocation of next'
+  
          s_timer%next%cname       = cdinfo
          s_timer%next%t_cpu      = 0._wp
@@ -713,17 +789,7 @@
          s_timer%next%next => NULL()
          s_timer => s_timer%next
-
-         ! are we inside a section
-         s_wrk => s_timer%prev
-         ll_section = .FALSE.
-         DO WHILE( ASSOCIATED(s_wrk) .AND. .NOT. ll_section )
-            IF( .NOT. s_wrk%l_tdone ) THEN
-               ll_section = .TRUE.
-               s_timer%parent_section => s_wrk 
-            ENDIF
-            s_wrk => s_wrk%prev
-         END DO 
-      ENDIF         
-      !
+      ENDIF 
+      !    write(*,*) 'after allocation'
+     !
    END SUBROUTINE timing_ini_var
 
@@ -738,5 +804,5 @@
 !      IF(lwp) WRITE(numout,*) 'timing_reset : instrumented routines for timing'
 !      IF(lwp) WRITE(numout,*) '~~~~~~~~~~~~'
-!      CALL timing_list(s_timer_root)
+      CALL timing_list(s_timer_root)
 !      WRITE(numout,*)
       !
