[petsc-users] MPI Communication times
Zhang, Junchao
jczhang at mcs.anl.gov
Sat Mar 23 12:19:49 CDT 2019
Before further looking into it, can you try these:
* It seems you used petsc 3.9.4. Could you update to petsc master branch? We have an optimization (after 3.9.4) that is very useful for VecScatter on DMDA vectors.
* To measure performance, you do not want that many printfs.
* Only measure the parallel part of your program, i.e., skip the init and I/O part. You can use petsc stages, see src/vec/vscat/examples/ex4.c for an example
* Since your grid is 3000 x 200 x 100, so can you measure with 60 and 240 processors? It is easy to do analysis with balanced partition.
Thanks.
--Junchao Zhang
On Fri, Mar 22, 2019 at 6:53 PM Manuel Valera <mvalera-w at sdsu.edu<mailto:mvalera-w at sdsu.edu>> wrote:
This is a 3D fluid dynamics code, it uses arakawa C type grids and curvilinear coordinates in nonhydrostatic navier stokes, we also add realistic stratification (Temperature / Density) and subgrid scale for turbulence. What we are solving here is just a seamount with a velocity forcing from one side and is just 5 pressure solvers or iterations.
PETSc is used via the DMDAs to set up the grids and arrays and do (almost) every calculation in a distributed manner, the pressure solver is implicit and carried out with the KSP module. I/O is still serial.
I am attaching the run outputs with the format 60mNP.txt with NP the number of processors used. These are large files you can read with tail -n 140 [filename] for the -log_view part
Thanks for your help,
On Fri, Mar 22, 2019 at 3:40 PM Zhang, Junchao <jczhang at mcs.anl.gov<mailto:jczhang at mcs.anl.gov>> wrote:
On Fri, Mar 22, 2019 at 4:55 PM Manuel Valera <mvalera-w at sdsu.edu<mailto:mvalera-w at sdsu.edu>> wrote:
No, is the same problem running with different number of processors, i have data from 1 to 20 processors in increments of 20 processors/1 node, and additionally for 1 processor.
That means you used strong scaling. If we combine VecScatterBegin/End, from 20 cores, to 100, 200 cores, it took 2%, 13%, 18% of the execution time respectively. It looks very unscalable. I do not know why.
VecScatterBegin took the same time with 100 and 200 cores. My explanation is VecScatterBegin just packs data and then calls non-blocking MPI_Isend. However, VecScatterEnd has to wait for data to come.
Could you tell us more about your problem, for example, is it 2D or 3D, what is the communication pattern, how many neighbors each rank has. Also attach the whole log files for -log_view so that we can know the problem better.
Thanks.
On Fri, Mar 22, 2019 at 2:48 PM Zhang, Junchao <jczhang at mcs.anl.gov<mailto:jczhang at mcs.anl.gov>> wrote:
Did you change problem size with different runs?
On Fri, Mar 22, 2019 at 4:09 PM Manuel Valera <mvalera-w at sdsu.edu<mailto:mvalera-w at sdsu.edu>> wrote:
Hello,
I repeated the timings with the -log_sync option and now i get for 200 processors / 20 nodes:
------------------------------------------------------------------------------------------------------------------------
Event Count Time (sec) Flop --- Global --- --- Stage --- Total
Max Ratio Max Ratio Max Ratio Mess Avg len Reduct %T %F %M %L %R %T %F %M %L %R Mflop/s
------------------------------------------------------------------------------------------------------------------------
VecScatterBarrie 3014 1.0 5.6771e+01 3.9 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 5 0 0 0 0 5 0 0 0 0 0
VecScatterBegin 3014 1.0 3.1684e+01 2.0 0.00e+00 0.0 4.2e+06 1.1e+06 2.8e+01 4 0 63 56 0 4 0 63 56 0 0
VecScatterEnd 2976 1.0 1.1383e+02 1.8 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 14 0 0 0 0 14 0 0 0 0 0
With 100 processors / 10 nodes:
VecScatterBarrie 3010 1.0 7.4430e+01 5.0 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 7 0 0 0 0 7 0 0 0 0 0
VecScatterBegin 3010 1.0 3.8504e+01 2.4 0.00e+00 0.0 1.6e+06 2.0e+06 2.8e+01 4 0 71 66 0 4 0 71 66 0 0
VecScatterEnd 2972 1.0 8.5158e+01 1.2 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 9 0 0 0 0 9 0 0 0 0 0
And with 20 processors / 1 node:
VecScatterBarrie 2596 1.0 4.0614e+01 7.3 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 4 0 0 0 0 4 0 0 0 0 0
VecScatterBegin 2596 1.0 1.4970e+01 1.3 0.00e+00 0.0 1.2e+05 4.0e+06 3.0e+01 1 0 81 61 0 1 0 81 61 0 0
VecScatterEnd 2558 1.0 1.4903e+01 1.3 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 1 0 0 0 0 1 0 0 0 0 0
Can you help me interpret this? what i see is the End portion taking more relative time and Begin staying the same beyond one node, also Barrier and Begin counts are the same every time, but how do i estimate communication times from here?
Thanks,
On Wed, Mar 20, 2019 at 3:24 PM Zhang, Junchao <jczhang at mcs.anl.gov<mailto:jczhang at mcs.anl.gov>> wrote:
Forgot to mention long VecScatter time might also due to local memory copies. If the communication pattern has large local to local (self to self) scatter, which often happens thanks to locality, then the memory copy time is counted in VecScatter. You can analyze your code's communication pattern to see if it is the case.
--Junchao Zhang
On Wed, Mar 20, 2019 at 4:44 PM Zhang, Junchao via petsc-users <petsc-users at mcs.anl.gov<mailto:petsc-users at mcs.anl.gov>> wrote:
On Wed, Mar 20, 2019 at 4:18 PM Manuel Valera <mvalera-w at sdsu.edu<mailto:mvalera-w at sdsu.edu>> wrote:
Thanks for your answer, so for example i have a log for 200 cores across 10 nodes that reads:
------------------------------------------------------------------------------------------------------------------------
Event Count Time (sec) Flop --- Global --- --- Stage --- Total
Max Ratio Max Ratio Max Ratio Mess Avg len Reduct %T %F %M %L %R %T %F %M %L %R Mflop/s
----------------------------------------------------------------------------------------------------------------------
VecScatterBegin 3014 1.0 4.5550e+01 2.6 0.00e+00 0.0 4.2e+06 1.1e+06 2.8e+01 4 0 63 56 0 4 0 63 56 0 0
VecScatterEnd 2976 1.0 1.2143e+02 1.7 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 14 0 0 0 0 14 0 0 0 0 0
While for 20 nodes at one node i have:
What does that mean?
VecScatterBegin 2596 1.0 2.9142e+01 2.1 0.00e+00 0.0 1.2e+05 4.0e+06 3.0e+01 2 0 81 61 0 2 0 81 61 0 0
VecScatterEnd 2558 1.0 8.0344e+01 7.9 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 3 0 0 0 0 3 0 0 0 0 0
Where do i see the max/min ratio in here? and why End step is all 0.0e00 in both but still grows from 3% to 14% of total time? It seems i would need to run again with the -log_sync option, is this correct?
e.g., 2.1, 7.9. MPI send/recv are in VecScatterBegin(). VecScatterEnd() only does MPI_Wait. That is why it has zero messages. Yes, run with -log_sync and see what happens.
Different question, can't i estimate the total communication time if i had a typical communication time per MPI message times the number of MPI messages reported in the log? or it doesn't work like that?
Probably not work because you have multiple processes doing send/recv at the same time. They might saturate the bandwidth. Petsc also does computation/communication overlapping.
Thanks.
On Wed, Mar 20, 2019 at 2:02 PM Zhang, Junchao <jczhang at mcs.anl.gov<mailto:jczhang at mcs.anl.gov>> wrote:
See the "Mess AvgLen Reduct" number in each log stage. Mess is the total number of messages sent in an event over all processes. AvgLen is average message len. Reduct is the number of global reduction.
Each event like VecScatterBegin/End has a maximal execution time over all processes, and a max/min ratio. %T is sum(execution time of the event on each process)/sum(execution time of the stage on each process). %T indicates how expensive the event is. It is a number you should pay attention to.
If your code is imbalanced (i.e., with a big max/min ratio), then the performance number is skewed and becomes misleading because some processes are just waiting for others. Then, besides -log_view, you can add -log_sync, which adds an extra MPI_Barrier for each event to let them start at the same time. With that, it is easier to interpret the number.
src/vec/vscat/examples/ex4.c is a tiny example for VecScatter logging.
--Junchao Zhang
On Wed, Mar 20, 2019 at 2:58 PM Manuel Valera via petsc-users <petsc-users at mcs.anl.gov<mailto:petsc-users at mcs.anl.gov>> wrote:
Hello,
I am working on timing my model, which we made MPI scalable using petsc DMDAs, i want to know more about the output log and how to calculate a total communication times for my runs, so far i see we have "MPI Messages" and "MPI Messages Lengths" in the log, along VecScatterEnd and VecScatterBegin reports.
My question is, how do i interpret these number to get a rough estimate on how much overhead we have just from MPI communications times in my model runs?
Thanks,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mcs.anl.gov/pipermail/petsc-users/attachments/20190323/d21c93c9/attachment-0001.html>
More information about the petsc-users
mailing list