Derecho CSLAM performance issue.

[jedwards4b]

I am running PFS.ne30pg3_ne30pg3_mg17.FLTHIST_v0c.derecho_intel
and have run into a number of cases with the code hanging in bndry_mod.F90 looking at that code I see a couple of cases of neighborhood collectives when MPI_VERSION >= 3. I copied that file to SourceMods and disabled that check so that the older collective is used. That seems to be avoiding the hang.

[jedwards4b]

@PeterHjortLauritzen - any ideas?

[jedwards4b]

Actually not sure that this is the root cause - my second run with this mod hung as well.

[jedwards4b]

Adding environment variable MPICH_COLL_SYNC=1 seems to have solved this problem and does not seem to adversely affect performance.

       MPICH_COLL_SYNC
           If enabled, a Barrier is performed at the beginning of each specified MPI collective function. This forces all
           processes participating in that collective to sync up before the collective can begin.

           To disable this feature for all MPI collectives, set the value to 0. This is the default.

           To enable this feature for all MPI collectives, set the value to 1.

           To enable this feature for selected MPI collectives, set the value to a comma-separated list of the desired collective
           names. Names are not case-sensitive. Any unrecognizable name is flagged with a warning message and ignored. The
           following collective names are recognized: MPI_Allgather, MPI_Allgatherv, MPI_Allreduce, MPI_Alltoall, MPI_Alltoallv,
           MPI_Alltoallw, MPI_Bcast, MPI_Exscan, MPI_Gather, MPI_Gatherv, MPI_Reduce, MPI_Reduce_scatter, MPI_Scan, MPI_Scatter,
           and MPI_Scatterv.

           Default: Not enabled.

[jedwards4b]

Performance results are in the timing table. search for derecho.

[briandobbins]

At ne30, I wouldn't expect any speedup from 4096 -> 5120, really. Each rank will be 1 or 2 elements (5400 elements max), and you'll be rate-limited by the ones with 2, no?

I'd be more curious if we do have ~2x performance going from 2700 -> 5400 ranks. I expect some degradation from comms, but otherwise that's more well-mapped in terms of elements/rank, I'd think.

[adamrher]

Can you show the math for your 4k estimation?

CAM6 (ne30 L32) was ~2k. Increasing L32->L58 doubles this to ~4k. See timing files here showing a robust 4.5k number:

/glade/u/home/stepheba/cam112/cime/scripts/cam6_3_112_FLTHIST_v0c_ne30pg3_ne30pg3_mg17_L58_1800pes_230526_cntl/timing

[jedwards4b]

Thanks - that's helpful.

[jedwards4b]

I see several differences in the atm_in namelist between my run and the one you pointed out, would you expect any of these to affect performance?

< derecho
> cheyenne
12c12
<  seasalt_emis_scale		= 1.00D0
---
>  seasalt_emis_scale		= 1.5
146c157
<  clubb_c7		=  0.5     
---
>  clubb_c7		= 0.1
165c176
<  clubb_c_uu_shr		=  0.3     
---
>  clubb_c_uu_shr		= 0.1
194,195c205,206
<  clubb_l_mono_flux_lim_um		=  .false. 
<  clubb_l_mono_flux_lim_vm		=  .false. 
---
>  clubb_l_mono_flux_lim_um		= .true.
>  clubb_l_mono_flux_lim_vm		= .true.
197c208
<  clubb_l_predict_upwp_vpwp		=  .false. 
---
>  clubb_l_predict_upwp_vpwp		= .true.
238,239c249,250
<  dust_emis_fact		= 0.70D0
<  soil_erod_file		= '/glade/p/cesmdata/inputdata/atm/cam/dst/dst_source2x2tunedcam6-2x2-04062017.nc'
---
>  dust_emis_fact		= 0.80D0
>  soil_erod_file		= '/glade/p/cesmdata/cseg/inputdata/atm/cam/dst/dst_source2x2tunedcam6-2x2-04062017.nc'
326c337
<  micro_mg_dcs		=                                  500.D-6    
---
>  micro_mg_dcs		= 0.00025
338c349
<  micro_mg_vtrmi_factor		=   1.D0    
---
>  micro_mg_vtrmi_factor		= 0.5
346c357
<  microp_aero_wsubi_scale		=   1.D0    
---
>  microp_aero_wsubi_scale		= 2.5

[adamrher]

Those differences reflect our "F tunings" for the coupled eval, which don't come out of the box (yet). This shouldn't effect timings, other than the cheyenne run is solving for prognostic momentum fluxes (clubb_l_predict_upwp_vpwp=T) which would actually be more expensive.

It might be useful to print out timings for all CAM processes via ./xmlchange TIMER_LEVEL=10. Although it would be better to have these same timings from a cheyenne run to compare it against.

[jedwards4b]

In a comparison of cheyenne and derecho runs each using 1800 tasks I see a significant difference in time for the prim_advec_tracers_fvm

                                                            PETs   PEs    Count    Mean (s)    Min (s)     Min PET Max (s)     Max PET  
prim_advec_tracers_fvm                                       1800   1800   1922     841.1699    439.1891    1795    847.2990    73 
prim_advec_tracers_fvm                                       1800   1800   1922     102.2497    90.4665     1014    113.1982    198  

[jedwards4b]

These results are in /glade/work/jedwards/ESMF_Profile.summary.cheyenne1800 and /glade/work/jedwards/ESMF_Profile.summary.derecho1800

I am uncommenting timers found in fvm_consistent_se_cslam.F90 and rerunning. I am also going to try adding profile_barrier=.true.

[jedwards4b]

Cheyenne:

fvm:tracers_reconstruct                                    1800   1800   334428   41.2533     37.6388     1714    55.1831     198                                                                                                                                                          
  FVM:reconstruction:part#2                                1800   1800   334428   31.8428     29.3238     1714    38.9638     1556                                                                                                                                                         
  FVM:reconstruction:part#1                                1800   1800   334428   6.7204      5.4309      1234    19.2960     198                                                                                                                                                          
  FVM:reconstruction:part#3                                1800   1800   334428   2.1513      1.9933      770     2.5500      1746       

Derecho:

fvm:tracers_reconstruct                                    1800   1800   334428   748.8997    364.5543    1795    787.3841    76                                                                                                                                                           
  FVM:reconstruction:part#2                                1800   1800   334428   27.1220     24.7867     1702    33.4199     356                                                                                                                                                               
  FVM:reconstruction:part#1                                1800   1800   334428   18.6839     12.6640     353     35.6341     1098                                                                                                                                                         
  FVM:reconstruction:part#3                                1800   1800   334428   1.8947      1.7635      1432    2.3347      922                             

[jedwards4b]

I wrote a standalone program to test this /glade/work/jedwards/derecho_perf/fvmextend_standalone.F90

But it seems that the derecho run is faster than the cheyenne run - any ideas?

[adamrher]

What's the priority of this work? Can it wait for Peter? I heard the ASD simulations are to start on Monday; is that the driving factor here?

If this is about the ASD runs, and since the subroutine you've identified is specific to CSLAM, maybe we should be testing the var-res configuration, which doesn't use CSLAM. You could run ne0ARCTICne30x4_ne0ARCTICne30x4_mt12. Although it won't run FLTHIST, so I'd just run FHIST or F2000climo, which will invoke L32, and should cost about 20k.

[jedwards4b]

It can wait for Peter. Not aware of any ASD code using this compset.

[jedwards4b]

I am adding numbers for PFS.ne0ARCTICne30x4_ne0ARCTICne30x4_mt12.FHIST.derecho_intel to the timing table now. I think that it verifies that the performance issue we are seeing is limited to the CSLAM code.

[adamrher]

agreed, the ARCTIC grid numbers are about what I get on cheyenne.

[PeterHjortLauritzen]

Can you point me to your code base? I would like to add more timers. It does not look like

FVM:reconstruction:extend_panel1

increased timings explain the 10x ish slow down overall in fvm_resontruction.

[jedwards4b]

~jedwards/sandboxes/cesm2_x_alpha/components/cam

[jedwards4b]

Where are you getting 10x? I see 3x.

[jedwards4b]

Derecho:

FVM:reconstruction:part#2                                3120   3120   MULTIPLE 15.4309     7.9490      2833    22.2643     535    
FVM:reconstruction:part#1                                3120   3120   MULTIPLE 15.1461     7.4520      2752    32.1144     1647   
FVM:reconstruction:extend_panel_interpolate            3120   3120   MULTIPLE 7.2716      3.1201      2752    22.8356     1647   
FVM:reconstruction:get_gradients                       3120   3120   MULTIPLE 3.1109      1.4655      2966    4.7280      1799   
FVM:reconstruction:part#3                                3120   3120   MULTIPLE 1.0805      0.5141      2706    1.5149      748    

Cheyenne:

FVM:reconstruction:part#2                                3096   3096   MULTIPLE 18.5178     9.7713      2841    25.8639     534    
FVM:reconstruction:part#1                                3096   3096   MULTIPLE 11.3132     5.8533      2889    23.2706     1349   
FVM:reconstruction:get_gradients                       3096   3096   MULTIPLE 3.3177      1.8208      2454    4.7566      1349   
FVM:reconstruction:extend_panel_interpolate            3096   3096   MULTIPLE 2.3942      0.8411      2889    11.7490     1350   
FVM:reconstruction:part#3                                3096   3096   MULTIPLE 1.2640      0.6821      2499    1.7310      594    

[PeterHjortLauritzen]

In your table above (repeated here):

fvm:tracers_reconstruct 1800 1800 334428 41.2533 37.6388 1714 55.1831 198
FVM:reconstruction:part#2 1800 1800 334428 31.8428 29.3238 1714 38.9638 1556
FVM:reconstruction:part#1 1800 1800 334428 6.7204 5.4309 1234 19.2960 198
FVM:reconstruction:part#3 1800 1800 334428 2.1513 1.9933 770 2.5500 1746

Derecho:

fvm:tracers_reconstruct 1800 1800 334428 748.8997 364.5543 1795 787.3841 76
FVM:reconstruction:part#2 1800 1800 334428 27.1220 24.7867 1702 33.4199 356
FVM:reconstruction:part#1 1800 1800 334428 18.6839 12.6640 353 35.6341 1098
FVM:reconstruction:part#3 1800 1800 334428 1.8947 1.7635 1432 2.334

If I understand it correctly fvm:tracers_reconstruct is ~750 on Derecho and ~41 on Cheyenne which is ~18x. Also, part 1-3 timings on Cheyenne more or less add up to fvm:tracers_reconstruct (which they should) but on Derecho they don't.

[jedwards4b]

I've broken it down further, here the number following epi is the value of cubeboundary on the call.
I added an init that should cover all of the time not in part1, part2 or part3 - it still doesn't seem to add up.
These are for derecho, cheyenne is still queued.

FVM:tracers_reconstruct                                    3120   3120   MULTIPLE 107.2213    29.4057     3117    131.3613    1616   
FVM:reconstruction:part#1                                3120   3120   MULTIPLE 4.9117      2.4221      2992    9.4937      1799   
FVM:reconstruction:epi0                                2863   2863   MULTIPLE 1.6573      0.6881      2992    2.3325      111    
FVM:reconstruction:get_gradients                       3120   3120   MULTIPLE 0.7838      0.3811      2708    1.3772      1799   
FVM:reconstruction:epi3                                148    148    MULTIPLE 2.6669      1.8298      1192    4.8786      2223   
FVM:reconstruction:epi1                                125    125    MULTIPLE 2.3499      1.3631      1197    3.6619      1977   
FVM:reconstruction:epi2                                133    133    MULTIPLE 2.0050      1.2085      1552    3.3528      1059   
FVM:reconstruction:epi4                                133    133    MULTIPLE 1.7612      1.0602      2633    2.9276      1527   
FVM:reconstruction:epi6                                6      6      1146196  3.2476      2.7483      3119    3.4033      747    
FVM:reconstruction:epi5                                6      6      1146196  3.1816      2.8431      1197    3.3600      2250   
FVM:reconstruction:epi7                                6      6      1146196  2.4730      2.4077      2589    2.5362      1984   
FVM:reconstruction:epi8                                6      6      1146196  2.2442      2.1941      2814    2.3057      1534   
FVM:reconstruction:part#2                                3120   3120   MULTIPLE 3.7639      1.9009      2612    5.4892      534    
FVM:reconstruction:part#3                                3120   3120   MULTIPLE 0.2761      0.1319      2828    0.3919      135   
FVM:reconstruction:init                                  3120   3120   MULTIPLE 0.0213      0.0091      2465    0.0961      1799   

[jedwards4b]

I added a timer to the call and return and found all of the extra time:

                  FVM:tracers_reconstruct                                    3328   3328   MULTIPLE 100.3873    28.8841     3325    130.9224    1706  
                    FVM:tracers_reconstruct:call                             3328   3328   MULTIPLE 46.5454     11.9137     3325    63.5081     1596  
                    FVM:tracers_reconstruct:return                           3328   3328   MULTIPLE 45.2493     12.0831     3325    60.9730     810    
                    FVM:reconstruction:part#1                                3328   3328   MULTIPLE 4.6096      2.3498      2872    9.3350      1647  
                      FVM:reconstruction:epi0                                3026   3026   MULTIPLE 1.5436      0.6286      1193    2.2876      1006  
                      FVM:reconstruction:get_gradients                       3328   3328   MULTIPLE 0.7361      0.3736      2106    1.3547      1799  
                      FVM:reconstruction:epi3                                155    155    MULTIPLE 2.5064      1.7856      3322    4.8546      1727  
                      FVM:reconstruction:epi1                                126    126    MULTIPLE 2.3179      1.3015      2752    3.6686      135    
                      FVM:reconstruction:epi2                                142    142    MULTIPLE 1.8742      1.1475      1553    3.3275      1044  
                      FVM:reconstruction:epi4                                133    133    MULTIPLE 1.7848      1.3476      2946    2.9409      1486  
                      FVM:reconstruction:epi5                                6      6      1146196  3.1750      2.9258      1799    3.3458      184    
                      FVM:reconstruction:epi6                                6      6      1146196  3.1304      2.6433      3327    3.3439      297    
                      FVM:reconstruction:epi7                                6      6      1146196  2.4376      2.3803      1350    2.5249      1984  
                      FVM:reconstruction:epi8                                6      6      1146196  2.2511      2.1812      3022    2.3274      1534  
                    FVM:reconstruction:part#2                                3328   3328   MULTIPLE 3.5107      1.8793      2222    5.5592      1887  
                    FVM:reconstruction:part#3                                3328   3328   MULTIPLE 0.2494      0.1175      3309    0.3746      1781  
                    FVM:reconstruction:init                                  3328   3328   MULTIPLE 0.0087      0.0038      2970    0.0509      1197   

[PeterHjortLauritzen]

Interesting! Do you think the problem is that "call reconstruction" is in a loop over vertical levels and inside the reconstruction subroutine there are loops over tracers (hence the tracer data is not contiguous in memory/cache)?

[jedwards4b]

I'm not sure if it's that or if it is just creating copies of the data structures on the subroutine boundary.

[PeterHjortLauritzen]

In other words, would it help to change:

   call reconstruction(fvm(ie)%c(:,:,:,:),nlev,k,&
         ctracer(:,:,:,:),...

to

   call reconstruction(fvm(ie)%c(:,:,k,:),nlev,k,&
         ctracer(:,:,k,:),...

along with associated changes in the reconstruction subroutine (I can code that if you think that is worth pursuing - the reason for passing the entire %c and ctracer arrays it to avoid array copying but maybe that is not a performance issue or no longer the case with newer compilers ...)

[jedwards4b]

My instinct says that would make it worse instead of better, but it might be worth trying if you want to code it up.

[jedwards4b]

Holy cow I think I fixed it. I'd better call it a weekend.

                  FVM:tracers_reconstruct                                    3328   3328   MULTIPLE 6.7962      3.6937      2229    10.9411     1084   
                    FVM:reconstruction:part#2                                3328   3328   MULTIPLE 3.5708      1.8899      2869    6.3484      1589   
                    FVM:reconstruction:part#1                                3328   3328   MULTIPLE 2.8564      1.5595      3214    5.5777      1084   
                      FVM:reconstruction:get_gradients                       3328   3328   MULTIPLE 0.6038      0.3361      3306    0.9185      1350   
                      FVM:reconstruction:epi0                                3026   3026   MULTIPLE 0.3022      0.1564      2606    0.5072      853    
                      FVM:reconstruction:epi1                                126    126    MULTIPLE 0.8789      0.6069      2746    1.4139      135    
                      FVM:reconstruction:epi2                                142    142    MULTIPLE 0.7357      0.5501      3312    1.3712      760    
                      FVM:reconstruction:epi3                                155    155    MULTIPLE 0.6117      0.5006      3322    1.2103      1732   
                      FVM:reconstruction:epi4                                133    133    MULTIPLE 0.7011      0.5176      2838    1.1909      940    
                      FVM:reconstruction:epi7                                6      6      1146196  1.5441      1.4950      1984    1.5993      0      
                      FVM:reconstruction:epi6                                6      6      1146196  1.5379      1.3900      3327    1.6010      747    
                      FVM:reconstruction:epi5                                6      6      1146196  1.4420      1.3939      1799    1.4975      1800   
                      FVM:reconstruction:epi8                                6      6      1146196  1.4056      1.3566      2122    1.4562      899    
                    FVM:reconstruction:part#3                                3328   3328   MULTIPLE 0.2249      0.1107      3307    0.3447      135    
                    FVM:tracers_reconstruct:call                             3328   3328   MULTIPLE 0.0234      0.0120      3321    0.0360      1618   
                    FVM:tracers_reconstruct:return                           3328   3328   MULTIPLE 0.0214      0.0107      3305    0.0350      985    
                    FVM:reconstruction:init                                  3328   3328   MULTIPLE 0.0047      0.0026      3098    0.0131      1800   

Here is the change that I made in fvm_consistent_se_cslam.F90:

diff SourceMods/src.cam/fvm_consistent_se_cslam.F90 ~/sandboxes/cesm2_x_alpha/components/cam/src/dynamics/se/dycore/fvm_consistent_se_cslam.F90 
47c47
<     type (fvm_struct), target     , intent(inout) :: fvm(:)
---
>     type (fvm_struct)     , intent(inout) :: fvm(:)
74,77c74
< 
<     real(r8), pointer :: fcube(:,:,:,:)
<     real(r8), pointer :: spherecentroid(:,:,:)
< 
---
>   
158,159d154
<        fcube => fvm(ie)%c(:,:,:,:)
<        spherecentroid => fvm(ie)%spherecentroid(:,1-nhe:nc+nhe,1-nhe:nc+nhe)
161,163c156,157
<          call t_startf('FVM:tracers_reconstruct')
<          call t_startf('FVM:tracers_reconstruct:call')
<          call reconstruction(fcube,nlev,k,&
---
>         call t_startf('fvm:tracers_reconstruct')
>         call reconstruction(fvm(ie)%c(:,:,:,:),nlev,k,&
168c162
<              spherecentroid,&
---
>              fvm(ie)%spherecentroid(:,1-nhe:nc+nhe,1-nhe:nc+nhe),&
173,177c167,170
<          call t_stopf('FVM:tracers_reconstruct:return')
<          call t_stopf('FVM:tracers_reconstruct')
<          call t_startf('fvm:swept_flux')
<          call swept_flux(elem(ie),fvm(ie),k,ctracer,irecons_tracer_lev(k),gsweights,gspts)
<          call t_stopf('fvm:swept_flux')
---
>         call t_stopf('fvm:tracers_reconstruct')
>         call t_startf('fvm:swept_flux')
>         call swept_flux(elem(ie),fvm(ie),k,ctracer,irecons_tracer_lev(k),gsweights,gspts)
>         call t_stopf('fvm:swept_flux')

[PeterHjortLauritzen]

Great! Thanks! (I was about to start coding ...)

Do you know what is happening? As far as I understand you switched to using a pointer ...

[jedwards4b]

The pointer is outside the k loop, I think it's avoiding a copy. Still need to test for correctness.