Fix Nalu timers

[sayerhs]

• Fix timerMisc_ for LowMach and Momentum EQS that were counting certain
  execution regions twice. timerMisc_ was accumulating time when
  computing projected_nodal_gradient which in turn was either
  incrementing timerMisc_ or accumulating time in PNGEQS. Current fix is
  to keep calls to compute_projected_nodal_gradient out of timed blocks.

• Low Mach timerMisc_ accumulates time with project_nodal_velocity which
  calls ContinuityEQS projected_nodal_gradient where there is additional
  time accumulation in continuityEQS->timerMisc_.

• "No output time" was reporting CPU Time instead of WallClock time.
  This commit changes that to WallClock time so that it is consistent
  with what is being reported for STKPERF: Total time

• "Timing for connectivity" summary was removed because this is already
  reported as "init" for each equation system

With these changes the sum of all the timers in the timing table should
be less than the total time reported for "main()" as well as "STKPERF:
Total Time" in the summary.

[sayerhs]

This was previously discussed here: NaluCFD/Nalu#189 and was pointed out by the solvers team during the ECP FY18-Q3 milestone work. I noticed that the sum of individual timers did not add up to the total time even on non-OpenMP runs, and found several places where the timers were double counted.

Cc: @sthomas61 @aprokop @jhux2

[aprokop]

This is great! But is there a way if that's all of them? Or is the possible that some problems still exist? How does one check (now, or in the future)?

[sayerhs]

@aprokop I assume your question is "is there a way to be sure if this commit fixes all the timer issues?" Short of a thorough code audit by several people, I don't know of a good way to prove that there are no more timer issues.

What we can be fairly certain after this commit, the discussion/fixes in issues NaluCFD/Nalu#238 and NaluCFD/Nalu#189:

• All times reported in Nalu timer summary is WallClock time and there are no more CPUTime reported. So multi-threaded runs can be compared with non-threaded runs.

• The timers for linear solver (init, assemble, load_complete, precond, and solve) are reliable for all runs with code base after this merge Fix error in preconditioner timer calculations with system reinitialization NaluCFD/Nalu#241. They are updated only at one location in the codebase, i.e., not nested.

• The main() and STKPERF: Total time timers have been correct since Timing mis-match when threading NaluCFD/Nalu#189 was fixed by @spdomin.

• The main() timer should be the same as or very close to STKPERF: Total time. The difference between main() and STKPERF: Total time is that main() is the average, min, and max across all processors. STKPERF: Total time is the time on MPI rank 0. The "No output time" will always be less than STKPERF: Total time even when threading is active.

The place where a second look would be useful is the misc timers. I have gone through LowMach, Enthalpy, and Turbulence EQS and have fixed all the issues I could see. While I feel that I've caught everything in those equation systems, I can't guarantee it. So I would be cautious of any conclusions that depend solely on misc timers. However, this doesn't corrupt other timers because the total time is arrived at independently and not by summing up the timers reported in the table.

We would definitely know that there are more issues if the sum of all timers in the reported table adds up to more than main(). However, the opposite doesn't mean there are no further issues.

[sayerhs]

I would also recommend that we add another timer that tracks the total time spent in each EQS and use that as a metric instead of summing up individual pieces. That will quickly show us any issues if there is still double counting in any of the misc timers, and also be a better estimate of total time spent in any equation system than summing up these pieces as there are several portions of code that are not covered by the timers in Nalu currently.

Further, we can also check that the sum of Continuity and Momentum total time is less than or equal to timing reported for LowMachEQS and so on.

[aprokop]

I think there may still be a problem somewhere. If I go back to my June runs, I had for example the following reporte max timers (different columns for different MPI/thread combinations):

-  \multicolumn{6}{l}{Momentum equation} \\
-  \midrule
-  init               & 61.1     & 80.2      & 130.8     & 255.0     & 426.1 \\
-  assemble           & 202.7    & 369.1     & 650.1     & 1238.3    & 2137.3 \\
-  load complete      & 154.3    & 266.5     & 461.7     & 862.0     & 1229.1 \\
-  solve              & 252.3    & 271.5     & 306.5     & 387.5     & 444.4 \\
-  precond setup      & 42.0     & 49.4      & 56.8      & 75.4      & 88.8 \\
-  misc               & 19.1     & 36.6      & 66.2      & 133.8     & 228.3 \\
-  \midrule
...
-  \multicolumn{6}{l}{Continuity equation} \\
-  \midrule
-  init               & 35.4     & 50.8      & 88.5      & 180.5     & 311.8 \\
-  assemble           & 28.5     & 54.2      & 98.2      & 196.2     & 351.8 \\
-  load complete      & 22.4     & 38.3      & 68.8      & 135.7     & 207.9 \\
-  solve              & 203.4    & 188.4     & 211.8     & 260.7     & 304.5 \\
-  precond setup      & 73.5     & 66.1      & 87.1      & 122.8     & 148.6 \\
-  misc               & 21.7     & 39.9      & 72.7      & 142.9     & 248.0 \\
...
-  total time         & 1081.3   & 1370.2    & 1952.3    & 3246.4    & 5091.3 \\

So the total time (STKPERF) was smaller than just the sum of init+assemble+load complete+solve+precond setup for momentum+continuity. So even with fixed misc (or simply ignoring it) it still does not explain why the max timers would add up to more. The only possible explanation for that would have been if max for different timers was achieved on different ranks, but my understanding that each of these timers is a global barrier.

[sayerhs]

@aprokop In Nalu is just using stk::wall_time(). So there is a high probability that the max time does occur on different ranks. Further, the max for solve might be very likely occurring on a different rank than for say init. Now when Nalu reports timers, it is doing an MPI_Reduce with MPI_SUM, MPI_MIN and MPI_MAX for the avg, min, and max respectively.

Furthermore, STKPERF Total time is not global (across all MPI ranks), it is the time reported by MPI rank=0 – see nalu.C. Also there are no explicit MPI_Barrier in any of these section just before time is accumulated, so I am not sure we can expect STKPERF total time to be always greater than the sum of all the max times.

The situation might be different if we are using Techos::Time because that appears to use MPI_Wtime which might be synchronizing across all procs for MPICH. Although the OpenMPI docs for MPI_Wtime says that the times are local.

[sayerhs]

@aprokop Can you explain the columns in your timers?

In [1]: 61.1+202.7+154.3+252.3+42.0+19.1+35.4+28.5+22.4+203.4+73.4+21.7 # Including misc
Out[1]: 1116.3000000000002

In [2]: 61.1+202.7+154.3+252.3+42.0+35.4+28.5+22.4+203.4+73.4 # Excluding misc
Out[2]: 1075.5

In [3]: 80.2+369.1+366.5+271.5+49.4+36.6+50.8+54.2+38.3+188.4+66.1+39.9
Out[3]: 1611.0

In [4]: 80.2+369.1+366.5+271.5+49.4+50.8+54.2+38.3+188.4+66.1
Out[4]: 1534.5

For the second column, the difference is quite large. So I agree with you that there is still something that is unexplained.

[sayerhs]

@aprokop Here are the locations in Nalu source code where the time is accumulated for the equation systems. May be you'll notice something that I overlooked.

• init: https://github.com/Exawind/nalu-wind/blob/master/src/EquationSystems.C#L643
• assemble, load complete, precond setup, solve: https://github.com/Exawind/nalu-wind/blob/master/src/EquationSystem.C#L264

Looking at the source code, you'll notice that precond setup time is nested within timerSolve_, but we subtract it out before reporting (dump_eq_time).

As far as I can tell, there is no barrier within assemble portion, so that section could be overlapping on certain procs with init and/or load_complete until Tpetra would enforce a barrier. We could test this hypothesis by rerunning one of your cases with an MPI Barrier in nalu_time like so

double
NaluEnv::nalu_time()
{
  MPI_Barrier(parallelCommunicator_);
  return stk::wall_time();
}

[aprokop]

@aprokop In Nalu is just using stk::wall_time(). So there is a high probability that the max time does occur on different ranks. Further, the max for solve might be very likely occurring on a different rank than for say init.

Well, any solve would synchronize due to reductions. Any assemble too due to calling Tpetra's fillComplete (if that's the stage it happens in). At least, I think there are a bunch of barriers (implicit or explicit) that it is very likely that each stage is barrier'd.

@aprokop Can you explain the columns in your timers?

The first column is 32 MPI ranks with a single thread per ranks, so 2048 MPI with a single thread. The second column, same V27 41 R1 problem, but in 16x2, so 1048 MPI ranks with 2 threads each. And so on, column 3 is 8x4, ... It is certainly an interesting observation that the timings seem off when running with multiple threads. No clue of why that would be, though.

Looking at the source code, you'll notice that precond setup time is nested within timerSolve_, but we subtract it out before reporting (dump_eq_time).

Yeah, I saw that.

We could test this hypothesis by rerunning one of your cases with an MPI Barrier in nalu_time like so

Certainly, this could be an interesting experiment.

Could also try replacing gettimeofday in stk::wall_time() with something like omp_get_wtime or clock_gettime(CLOCK_MONOTONIC, ...).

[aprokop]

Ran on Cori in 4x8 configuration with this PR and MPI_Barrier in nalu_time:

Timing for Eq: myLowMach                                                                                                                                       
             init --    avg: 0.00356548     min: 0.00195289     max: 0.00453711                                                                                
         assemble --    avg: 0  min: 0  max: 0                                                                                                                 
    load_complete --    avg: 0  min: 0  max: 0                                                                                                                 
            solve --    avg: 0  min: 0  max: 0                                                                                                                 
    precond setup --    avg: 0  min: 0  max: 0                                                                                                                 
             misc --    avg: 0  min: 0  max: 0                                                                                                                 
Timing for Eq: MomentumEQS                                                                                                                                                                             
             init --    avg: 136.387    min: 136.387    max: 136.388  
         assemble --    avg: 655.823    min: 655.803    max: 655.847                                                                                           
    load_complete --    avg: 8.26235    min: 8.25896    max: 8.26611                                                                                           
            solve --    avg: 310.468    min: 310.461    max: 310.479                                                                                           
    precond setup --    avg: 57.8206    min: 57.8196    max: 57.8226                                                                                           
             misc --    avg: 33.5131    min: 33.4873    max: 33.5183                                                                                           
linear iterations --    avg: 10.15  min: 1  max: 20                                                                                                            
Timing for Eq: ContinuityEQS                                                                                                                                   
             init --    avg: 89.2507    min: 89.2497    max: 89.2537                                                                                           
         assemble --    avg: 99.432     min: 99.4036    max: 99.4564                                                                                           
    load_complete --    avg: 1.1394     min: 1.13707    max: 1.13988                                                                                           
            solve --    avg: 228.954    min: 228.951    max: 228.968                                                                                           
    precond setup --    avg: 91.5628    min: 91.5611    max: 91.5643                                                                                           
             misc --    avg: 71.4769    min: 71.4664    max: 71.4922                                                                                           
linear iterations --    avg: 29.9   min: 26     max: 33                                                                                                        
Timing for IO:                                                                                                                                                 
   io create mesh --    avg: 0.0702459  min: 0.070142   max: 0.0703211                                                                                         
 io output fields --    avg: 0.0139458  min: 0.00397229     max: 0.027122                                                                                      
 io populate mesh --    avg: 37.9507    min: 37.9506    max: 37.9507                                                                                           
 io populate fd   --    avg: 1.47922    min: 1.47919    max: 1.47925                                                                                           
Timing for property evaluation:                                                                                                                                
            props --    avg: 0.219486   min: 0.204501   max: 0.226283
Timing for Nonconformal:                                                                                                                                       
  nonconformal bc --    avg: 113.954    min: 113.95     max: 113.955                                                                                           
Timing for skin_mesh :                                                                                                                                         
        skin_mesh --    avg: 0.747587   min: 0.747544   max: 0.74768
...
STKPERF: Total Time: 2005.5482  

Hmm, now the sum of max timers seems less than total time, as expected.

There is trove of interesting info here. First, myLowMach misc timers is 0, that was never the case for us. Second, comparing it with the previous 4x8 run, we see there is/was something fishy with load complete times. Here, they are almost negligible, while above they are huge.

[sayerhs]

@aprokop LowMachEqs - misc timer is zero now because I removed the timer count around project_nodal_velocity in the LowMachEquationSystem::solve_and_update method.

The timer info for load_complete is definitely interesting. Could it be because there was no explicit barrier previously around assemble, so some MPI rank is starting the load_complete timer and then waiting on a Barrier imposed by Tpetra, while another rank is still processing elements for assemble?

The MomentumEQS is missing init line, can you add that back in please?

[sayerhs]

I am attaching a schematic of what I think is going on here with the assemble and load_complete max timers. Since there is no explicit barrier, the idle time between two MPI synchronizations is bookkept in different sections across different MPI ranks. So when we do a MPI_MAX operation, the same time gets reported in different sections assemble and load_complete. I also suspect that if we compare max - min times for assemble and load_complete we will see that there was a much bigger difference in the previous run than in the current run with MPI_Barriers.

So why does this situation get worse with multiple threads? Could it be that based on scheduling and load imbalance, the thread synchronizations imposed by atomic_add is different across MPI ranks and that could play a role?

[aprokop]

The MomentumEQS is missing init line, can you add that back in please?

Done. It's interesting that it was there, but not shown for some reason.

[alanw0]

@sayerhs I think these changes look good. It is hard to in-tangle the times but this looks like a step in the right direction. I believe the assemble phase is bracketed by synchronizations. finalizeLinearSystem() happens before assembly starts, and it calls graph->fillComplete() and other methods which include synchronization. load_complete() is called at the end of assembly, and I'm pretty sure that is also a synchronization.