DDFacet Memory issue

[mangla-sarvesh]

This is the Problem we are facing at MeerKLASS OTF imaging run.
For this current DDFacet run, I had ~4500 MS's (32 MB each).

When the number of snapshots visibilities are greater than ~2500; the jobs fail.
My DDF job fails at this point

log.err

 - 10:02:08 - CacheManager                 [260.0/283.7 296.4/320.0 50.0Gb] writing cache hash mslist.txt.ddfcache/Dirty.hash
 - 10:02:13 - AsyncProcessPool             [260.0/283.7 296.3/320.0 61.1Gb] FFT PSF: 2304 jobs complete, average single-core time 0.06s per job
 - 10:02:14 - ClassFacetMachine            [260.0/283.7 296.3/320.0 61.1Gb] Reading mslist.txt.ddfcache/DicoSumJonesNorm_FacetLabel.pickle from cache
 - 10:02:24 - AsyncProcessPool             [262.8/283.7 300.8/320.0 75.4Gb] Build PSF facet slices: 2304 jobs complete, average single-core time 0.03s per job
 - 10:02:25 - ClassFacetMachine            [262.9/283.7 317.5/320.0 75.4Gb] cutting PSF facet-slices of shape 309x309
 - 10:02:26 - AsyncProcessPool             [262.9/283.7 317.5/320.0 80.3Gb] Cut PSF facet slices: 2304 jobs complete, average single-core time 0.02s per job
 - 10:02:26 - ClassFacetMachine            [262.9/283.7 317.5/320.0 80.3Gb]   Building Facets-PSF normalised by their maximum
 - 10:05:19 - ClassFacetMachine            [380.4/380.4 435.3/435.3 196.6Gb] Combining facets to stitched PSF image

log.out

Glue facets....................2304/2304 [==================================================] 100% - 0'34"

/dev/shm

Filesystem      Size  Used Avail Use% Mounted on
tmpfs           454G  163G  292G  36% /dev/shm

free -h

              total        used        free      shared  buff/cache   available
Mem:          503Gi       338Gi       1.1Gi       162Gi       163Gi        50Mi
Swap:          14Gi        14Gi          0B

Any suggestions for how can I solve this problem ?

[o-smirnov]

Just discussing this in the telecon now -- @cyriltasse I find this a strange problem. @mangla-sarvesh tells me he runs out of memory as per above when he runs through all the MSs in a block, but he doesn't run out of memory if he processes half the MSs. But the image size and number of facets should be the same in both cases -- and as far as I know, that's what should be driving the memory requirements of this particular step. The MSs are gridded one by one and thrown away, right?

@mangla-sarvesh could you please post links to full logs for the failing case above, and for the successful case when you use half the MSs?

[cyriltasse]

Yes - this is weird, and this is with the master branch, not yet with the fancy stuff I'm trying to merge...

@mangla-sarvesh I don't see where it crashes in your log...

[mangla-sarvesh]

This is log file. for L-band . I will add UHF too

Failed Job

Completed Job

Sometimes the slurm job get requeued and starts again. Because of that the log file gets rewritten.

[cyriltasse]

Ok thanks! 4000 pointings is something, we've never done it before! ;)

You have a first jump here, before it starts gridding - I think it's the grid allocation in RAM

 - 08:28:55 - CacheManager                 [1.4/1.6 2.1/2.3 12.6Gb] writing cache hash /archive/ls-mohr/MeerKLASS/IMAGING_data/TESTs/DR2_Lband/tile_19_41_check/ms_dir/otf_pointing_no_1183-OTFaspJ225006_29-293744_84-corr_ch4x.ms.N0.F0.D0.ddfcache/R0:1770/BDA.Degrid.hash
 - 08:29:36 - AsyncProcessPool             [128.7/128.7 158.3/158.3 12.6Gb] Reading 1.1: 1 jobs complete, average single-core time 13.52s per job

Then it starts gridding:

In the log, the RAM is [virtual/virtual_peak resident/resident_peak shared]

 - 08:30:38 - AsyncProcessPool             [141.1/141.1 170.8/170.8 18.3Gb] Grid 1.1: 1024 jobs complete, average single-core time 0.09s per job
 - 08:30:38 - AsyncProcessPool             [141.1/141.1 170.8/170.8 18.3Gb] Stack Beam 1.1: 121 jobs complete, average single-core time 0.04s per job

Then stops gridding:

 - 23:03:54 - ClassImagerDeconv            [151.3/151.6 174.2/174.6 23.0Gb] sparsify 0.000000
 - 23:04:00 - AsyncProcessPool             [151.3/151.6 174.2/174.6 23.0Gb] Grid 4252.1: 1024 jobs complete, average single-core time 0.09s per job
 - 23:04:00 - AsyncProcessPool             [151.3/151.6 174.2/174.6 23.0Gb] Stack Beam 4252.1: 121 jobs complete, average single-core time 0.04s per job
 - 23:04:00 - AsyncProcessPool             [151.3/151.6 174.2/174.6 23.0Gb] Grid PSF 4252.1: 1024 jobs complete, average single-core time 0.08s per job

Then builds the PSF cube

 - 23:07:37 - AsyncProcessPool             [165.2/174.6 189.1/189.1 42.1Gb] Cut PSF facet slices: 1024 jobs complete, average single-core time 0.01s per job
 - 23:07:37 - ClassFacetMachine            [165.2/174.6 189.1/189.1 42.1Gb]   Building Facets-PSF normalised by their maximum
 - 23:09:02 - ClassFacetMachine            [236.3/236.3 259.9/259.9 110.9Gb] Combining facets to stitched PSF image
 - 23:17:10 - ClassImagerDeconv            [309.9/310.2 312.7/313.1 179.9Gb] Fitting mean PSF in a [200,200] box ...

So between starts and stop gridding the RAM only increases by 20Gb. Is there anything else that change between your 2 runs aprat from mslist?

I'm sorry I won't have very much time in the next two weeks to look into this. You should look into your logs as I did and try to identify differences... How big is your node in terms of RAM?

[mangla-sarvesh]

Only the mslist changed in the two jobs.

each node are of 512 GB each.
We have only one node of 1TB of memory and when I submit the job into that node, the jobs completes.

[cyriltasse]

Can you check at the two logs and try to identify differences? You can also extract RAM against time from the logs for the two runs and plot one against the other