Percent time for MPI functions

[drmichaeltcvx]

Hello,

I am using Caliper from GEOS and I receive this output from "-t mpi-report"

MPI_Barrier                      3           3   0.019159 1318.964507 1182.399888 43.630951 
MPI_Comm_dup                     2           2   0.080361 1313.414572 1178.228226 43.477015 
MPI_Recv                      2705        8025   0.085642  525.549091  260.289181  9.604758 
MPI_Waitall                   4265        6714  17.182211   28.863937   24.043740  0.887222 
MPI_Allreduce                 2139        2139  20.650204   26.142581   22.332794  0.824088 
                           1449780     3734103  10.943946 2136.616929   17.240761  0.636190 
MPI_Gather                       7           7   0.000079  519.149465   12.091303  0.446173 
MPI_Waitany                    146         652   1.551483    7.465619    6.142051  0.226644 
MPI_Isend                    64239      255445   0.427579    6.268630    2.174159  0.080227 
MPI_Cart_create                  2           2   0.054504    1.135625    1.026053  0.037862 
MPI_Iprobe                  521724     1791210   0.463639    1.585946    0.832185  0.030708 
MPI_Wait                       156         908   0.138208    1.147570    0.808927  0.029850 
MPI_Bcast                       71          71   0.249041    1.121844    0.781155  0.028825 
MPI_Test                     29253      926183   0.028225    0.891557    0.464377  0.017131 
MPI_Testall                 141540     1346600   0.147656    1.279711    0.446740  0.016485 
MPI_Exscan                      16          16   0.000187    0.651155    0.270444  0.009979 
MPI_Irecv                    66046      255960   0.076047    0.974037    0.219408  0.008096 

Does it mean that MPI_Barrier and MPI_Comm_dup, etc. took %43.63 and %43.47, etc. percent of the total Wallclock time time or of the MPI time?

thanks !
Michael

[daboehme]

Hi @drmichaeltcvx ,

The percent total column would be for the total program time, including non-MPI time, across all processes. However it looks like non-MPI time (that's the row without a label) was only 0.63% of the total time, which is rather low.

Judging from the high average and max times and the low minimum time in MPI_Barrier() and MPI_Comm_dup() it looks like most processes were stuck in those collective calls waiting for just one or a just few processes to complete, so there seems to be some serious load imbalance in the program.

[drmichaeltcvx]

Thanks @daboehme !

I was also surprised to see such a high %-ntage of MPI time.

May I ask how you calculate the %-ntage of MPI_Functions()?

Suppose we have 10 ranks and the Wallclock time=120 seconds. If I can see, say, MPI_Recv taking 20% of the time, does it mean that all 10 ranks spent a total of 0.2 x 120 x 10 = 240 seconds aggregate in MPI_Recv (summing up the individual time lines of each rank)?

Thanks!

[daboehme]

Hi, @drmichaeltcvx ,

Yes, the %-ntage here is calculated from the aggregate time across all ranks. Your calculation is correct. You can also calculate the aggregate time in MPI_Recv (or any other function) by multiplying the Avg time/rank column with the number of ranks (however, that only works if all ranks call MPI_Recv).

[drmichaeltcvx]

Thanks @daboehme ! I just needed to make sure my assumption was correct.

[drmichaeltcvx]

Quick Q @daboehme : The mpi-report line w/o MPI_Fuction() in the first column should be interpreted to show the times the code spent outside any MPI call?

thanks ...

[daboehme]

Yes, the line without a function label is for everything outside of MPI. You can ignore the count columns but the times should be accurate.

[drmichaeltcvx]

thanks !