ratt-ru / CubiCal

A fast radio interferometric calibration suite.
GNU General Public License v2.0
18 stars 13 forks source link

Accessing missing file in /dev/shm #292

Open IanHeywood opened 5 years ago

IanHeywood commented 5 years ago
 08:56:44 - solver             [26.9/34.0 28.6/35.8 0.2Gb] D0T23F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0253, stall 86.86%, chi^2 3.044 -> 3.018 (2.55), noise 0.221 -> 0.216
 - 08:57:01 - NpShared           [26.9/34.0 28.6/35.8 0.2Gb] File file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a exists, deleting
 - 08:57:01 - solver             [26.9/34.0 28.6/35.8 0.2Gb] Solver for tile 11 chunk D0T23F0 failed with exception: [Errno 2] No such file or directory: 'file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a'

The other curious thing about this run is that every tile had exactly 50% convergence.

I'm using the containerised version from @SpheMakh's stimela dockerhub.

Full log below.

 - 02:14:56 - cc                 [0.1/0.1 1.5/1.5 0.0Gb] set global console verbosity level 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] started /usr/local/bin/gocubical /ceph/pipelines/ianh/MIGHTEE/CDFS/CDFS_4_3/parsets/phasecal.parset --data-ms=1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms --out-name=cube_pcal_1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms_2019-07-15-11-19-22
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  Selected Options:
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [data] Visibility data options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - ms ................................................ = 1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - column ............................................ = DATA
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - time-chunk ........................................ = 32
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - freq-chunk ........................................ = 1024
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - rebin-time ........................................ = 1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - rebin-freq ........................................ = 1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - chunk-by .......................................... = SCAN_NUMBER
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - chunk-by-jump ..................................... = 1.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - single-chunk ...................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - single-tile ....................................... = -1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [sel] Data selection options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - field ............................................. = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - ddid .............................................. = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - taql .............................................. =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - chan .............................................. =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - diag .............................................. = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [out] Options for output products
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - name .............................................. = cube_pcal_1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms_2019-07-15-11-19-22
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - overwrite ......................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - mode .............................................. = sc
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - column ............................................ = CORRECTED_DATA
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - derotate .......................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - model-column ...................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - weight-column ..................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - reinit-column ..................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - subtract-model .................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - subtract-dirs ..................................... = :
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - plots ............................................. = 1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - casa-gaintables ................................... = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [model] Calibration model options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - list .............................................. = MODEL_DATA
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - ddes .............................................. = auto
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - beam-pattern ...................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - beam-l-axis ....................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - beam-m-axis ....................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - feed-rotate ....................................... = auto
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - pa-rotate ......................................... = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [montblanc] Montblanc simulation options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - device-type ....................................... = CPU
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - dtype ............................................. = float
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - mem-budget ........................................ = 1024
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - verbosity ......................................... = WARNING
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - threads ........................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - pa-rotate ......................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - feed-type ......................................... = linear
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [weight] Weighting options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - column ............................................ = WEIGHT_SPECTRUM
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - fill-offdiag ...................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - legacy-v1-2 ....................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [flags] General flagging options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - apply ............................................. = -cubical
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - auto-init ......................................... = legacy
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - save .............................................. = cubical
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - save-legacy ....................................... = auto
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - reinit-bitflags ................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - warn-thr .......................................... = 0.3
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - see-no-evil ....................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [postmortem] Options for "postmortem" flagging based on solution statistics
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - enable ............................................ = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - tf-chisq-median ................................... = 1.2
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - tf-np-median ...................................... = 0.5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - time-density ...................................... = 0.5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - chan-density ...................................... = 0.5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - ddid-density ...................................... = 0.5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [madmax] Options for the "Mad Max" flagger
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - enable ............................................ = pretend
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - residuals ......................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - estimate .......................................... = corr
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - diag .............................................. = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - offdiag ........................................... = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - threshold ......................................... = [0, 20]
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - global-threshold .................................. = [0]
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - plot .............................................. = 1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - plot-frac-above ................................... = 0.01
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - plot-bl ........................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - flag-ant .......................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - flag-ant-thr ...................................... = 5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [sol] Solution options which apply at the solver level
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - jones ............................................. = G
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - precision ......................................... = 32
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - delta-g ........................................... = 1e-06
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - delta-chi ......................................... = 1e-06
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - chi-int ........................................... = 5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - last-rites ........................................ = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - stall-quorum ...................................... = 0.99
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - term-iters ........................................ =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - min-bl ............................................ = 150.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - max-bl ............................................ = 100000000.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - subset ............................................ =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - diag-diag ......................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [bbc] Options for baseline-based corrections (a.k.a. BBCs, a.k.a. interferometer gains).
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - load-from ......................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - compute-2x2 ....................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - apply-2x2 ......................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - save-to ........................................... = {data[ms]}/BBC-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - per-chan .......................................... = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - plot .............................................. = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [dist] Parallelization and distribution options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - ncpu .............................................. = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - nworker ........................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - nthread ........................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - max-chunks ........................................ = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - min-chunks ........................................ = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - pin ............................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - pin-io ............................................ = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - pin-main .......................................... = io
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [log] Options related to logging
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - memory ............................................ = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - stats ............................................. = chi2:.3f
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - stats-warn ........................................ = chi2:10
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - boring ............................................ = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - append ............................................ = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - verbose ........................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - file-verbose ...................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [debug] Debugging options for the discerning masochist
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - pdb ............................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - panic-amplitude ................................... = 0.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - stop-before-solver ................................ = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - escalate-warnings ................................. = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [misc] Miscellaneous options
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - random-seed ....................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - parset-version .................................... = 0.1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [g] Options for G-Jones term
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - solvable .......................................... = True
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - type .............................................. = phase-diag
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - load-from ......................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - xfer-from ......................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - save-to ........................................... = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - dd-term ........................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - fix-dirs .......................................... =
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - update-type ....................................... = full
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - time-int .......................................... = 4
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - freq-int .......................................... = 256
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - max-prior-error ................................... = 1000000
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - max-post-error .................................... = 1000000
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - clip-low .......................................... = 0.1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - clip-high ......................................... = 10.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - clip-after ........................................ = 5
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - max-iter .......................................... = 20
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - epsilon ........................................... = 1e-06
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - delta-chi ......................................... = 1e-06
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - conv-quorum ....................................... = 0.99
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - ref-ant ........................................... = None
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - prop-flags ........................................ = default
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - estimate-pzd ...................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - diag-only ......................................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - offdiag-only ...................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - robust-cov ........................................ = compute
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - robust-npol ....................................... = 2
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - robust-int ........................................ = 1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - robust-save-weights ............................... = 0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - diag-diag ......................................... = False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] [de] de
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - dd-term ........................................... = 1
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - clip-low .......................................... = 0.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - clip-high ......................................... = 0.0
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb]  - delta-chi ......................................... = 1e-05
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] Enabling G-Jones
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] mode: SolveAndCorrect
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] solver is apply-only type: False
 - 02:14:56 - main               [0.1/0.1 1.5/1.5 0.0Gb] solver requires model: True
 - 02:14:56 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb] reading MS 1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms
 - 02:14:58 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb]   detected linear (xy) feeds
 - 02:14:58 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb]   fields are *0: CDFS_4_3
 - 02:14:58 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb]   MS contains 1 spectral windows
 - 02:14:58 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb]   max freq chunk size is 1024 channels and/or -- MHz
 - 02:14:58 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb]   DDID 0: 1024/1024 channels selected
 - 02:14:58 - data_handler       [0.1/0.1 1.5/1.5 0.0Gb]     found 1 frequency chunks: 0 1024
 - 02:14:59 - data_handler       [0.1/0.2 1.5/1.6 0.0Gb]   applying TAQL query 'FIELD_ID == 0 && DATA_DESC_ID IN [0]' (5759010/5759010 rows selected)
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb]   60 antennas, 5759010 rows, 1/1 DDIDs, 3147 timeslots, 4 corrs
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb]   DDID central frequencies are at 1.28 GHz
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb] Input model feed rotation enabled, PA rotation enabled
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb] Output visibilities derotation enabled
 - 02:14:59 - parallactic_machin [0.1/0.2 1.6/1.6 0.0Gb] Initializing new parallactic angle machine for 60 ECEF positions
 - 02:14:59 - parallactic_machin [0.1/0.2 1.6/1.6 0.0Gb] Conversion epoch is J2000
 - 02:14:59 - parallactic_machin [0.1/0.2 1.6/1.6 0.0Gb] Selecting 'linear' feed bases
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb] Using 1 model(s) for 1 directions(s) (DDEs explicitly disabled)
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb]   model 0 (weight WEIGHT_SPECTRUM):
 - 02:14:59 - data_handler       [0.1/0.2 1.6/1.6 0.0Gb]     direction 0: MODEL_DATA
 - 02:14:59 - main               [0.1/0.2 1.6/1.6 0.0Gb] subtraction directions set to slice(None, None, None)
 - 02:14:59 - param_db           [0.1/0.2 1.6/1.6 0.0Gb] creating 1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms/G-field_0-ddid_None.parmdb in fragmented mode
 - 02:14:59 - gain_machine       [0.1/0.2 1.6/1.6 0.0Gb] G solutions will be saved to 1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms/G-field_0-ddid_None.parmdb
 - 02:14:59 - param_db           [0.1/0.2 1.6/1.6 0.0Gb] creating 1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms/BBC-field_0-ddid_None.parmdb in fragmented mode
 - 02:14:59 - gain_machine       [0.1/0.2 1.8/1.8 0.0Gb] will compute & save suggested baseline-based corrections (BBCs) to 1562295660_sdp_l0.full_1284.full_pol_wtspec_CDFS_4_3.ms/BBC-field_0-ddid_None.parmdb
 - 02:14:59 - gain_machine       [0.1/0.2 1.8/1.8 0.0Gb]   (these can optionally be applied in a subsequent CubiCal run)
 - 02:14:59 - main               [0.1/0.2 1.8/1.8 0.0Gb] single-process, single-thread mode
 - 02:14:59 - main               [0.1/0.2 1.8/1.8 0.0Gb] defining chunks (time 32, freq 1024, also when SCAN_NUMBER jumps > 1.0)
 - 02:15:01 - data_handler       [0.5/0.5 2.2/2.2 0.0Gb]   read indexing columns (5759010 total rows)
 - 02:15:02 - data_handler       [0.5/0.6 2.2/2.3 0.0Gb]   built timeslot index (3147 unique timestamps)
 - 02:15:02 - data_handler       [0.5/0.6 2.2/2.3 0.0Gb]   max chunk size is 32 timeslots and/or -- seconds
 - 02:15:13 - data_handler       [0.6/1.9 2.3/3.5 0.0Gb]   found 105 time chunks: 0:0:0 1:58560:32 2:117120:64 3:175680:96 4:234240:128 5:292800:160 6:351360:192 7:409920:224 8:468480:256 9:527040:288 10:585600:320 11:644160:352 12:702720:384 13:761280:416 14:819840:448 15:821670:449 16:880230:481 17:938790:513 18:997350:545 19:1055910:577 20:1114470:609 21:1173030:641 22:1231590:673 23:1290150:705 24:1348710:737 25:1407270:769 26:1465830:801 27:1524390:833 28:1582950:865 29:1641510:897 30:1645170:899 31:1703730:931 32:1762290:963 33:1820850:995 34:1879410:1027 35:1937970:1059 36:1996530:1091 37:2055090:1123 38:2113650:1155 39:2172210:1187 40:2230770:1219 41:2289330:1251 42:2347890:1283 43:2406450:1315 44:2465010:1347 45:2468670:1349 46:2527230:1381 47:2585790:1413 48:2644350:1445 49:2702910:1477 50:2761470:1509 51:2820030:1541 52:2878590:1573 53:2937150:1605 54:2995710:1637 55:3054270:1669 56:3112830:1701 57:3171390:1733 58:3229950:1765 59:3288510:1797 60:3290340:1798 61:3348900:1830 62:3407460:1862 63:3466020:1894 64:3524580:1926 65:3583140:1958 66:3641700:1990 67:3700260:2022 68:3758820:2054 69:3817380:2086 70:3875940:2118 71:3934500:2150 72:3993060:2182 73:4051620:2214 74:4110180:2246 75:4113840:2248 76:4172400:2280 77:4230960:2312 78:4289520:2344 79:4348080:2376 80:4406640:2408 81:4465200:2440 82:4523760:2472 83:4582320:2504 84:4640880:2536 85:4699440:2568 86:4758000:2600 87:4816560:2632 88:4875120:2664 89:4933680:2696 90:4937340:2698 91:4995900:2730 92:5054460:2762 93:5113020:2794 94:5171580:2826 95:5230140:2858 96:5288700:2890 97:5347260:2922 98:5405820:2954 99:5464380:2986 100:5522940:3018 101:5581500:3050 102:5640060:3082 103:5698620:3114 104:5757180:3146 3147
 - 02:15:13 - data_handler       [0.8/1.9 3.5/3.5 0.0Gb]   generated 105 row chunks based on time and DDID
 - 02:15:13 - data_handler       [0.8/1.9 3.5/3.5 0.0Gb]   row chunks yield 105 potential tiles
 - 02:15:14 - data_handler       [0.9/1.9 3.6/3.6 0.0Gb]   coarsening this to 53 tiles (max 2 chunks per tile, based on 1/0 requested)
 - 02:15:14 - data_handler       [0.9/1.9 3.6/3.6 0.0Gb]   inserting new column BITFLAG
 - 02:15:14 - data_handler       [0.9/1.9 3.6/3.6 0.0Gb]   inserting new column BITFLAG_ROW
 - 02:15:16 - data_handler       [0.9/1.9 3.6/3.6 0.0Gb]   auto-filling bitflag 'legacy' from FLAG/FLAG_ROW column. Please do not interrupt this process!
 - 02:15:16 - data_handler       [0.9/1.9 3.6/3.6 0.0Gb]     note that all other bitflags will be cleared by this
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb]   auto-fill complete
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb]   BITFLAG column defines the following flagsets: legacy:1
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb]   will exclude flagset cubical
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb]     flagset 'cubical' not found -- ignoring
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb]   applying BITFLAG mask 1 to input data
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb]   will save output flags into BITFLAG 'cubical' (2), and into FLAG/FLAG_ROW
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb] tile 0/53: reading MS rows 0~117119
 - 02:20:06 - data_handler       [1.7/3.5 3.6/5.3 0.0Gb] reading DATA
 - 02:20:43 - data_handler       [5.3/8.9 8.9/10.7 0.0Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 02:20:57 - data_handler       [8.9/8.9 10.7/12.5 0.0Gb]   applying solvable baseline cutoff deselects 10613 rows
 - 02:20:57 - data_handler       [8.9/8.9 10.7/12.5 0.0Gb]   9.06% visibilities deselected via specificed subset and/or baseline cutoffs
 - 02:20:57 - data_handler       [9.0/9.0 10.7/12.5 0.0Gb] reading BITFLAG
 - 02:21:19 - data_handler       [12.1/13.9 13.8/15.6 0.0Gb]   76.19% input visibilities flagged and/or deselected
 - 02:21:25 - data_handler       [16.6/18.3 21.9/21.9 6.3Gb]   reading MODEL_DATA for model 0 direction 0
 - 02:21:25 - data_handler       [16.6/18.3 21.9/21.9 6.3Gb] reading MODEL_DATA
 - 02:22:20 - parallactic_machin [13.2/26.4 19.0/29.0 9.9Gb] Applying P Jones to sky (precomputed)
 - 02:25:09 - madmax             [28.5/28.7 30.3/30.5 9.9Gb] D0T0F0 iter 1 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:25:12 - madmax             [28.5/28.7 30.3/30.5 9.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:27:13 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] D0T0F0 iter 5 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:27:17 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:29:21 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] D0T0F0 iter 10 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:29:24 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:31:29 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] D0T0F0 iter 15 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:31:32 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:33:37 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] D0T0F0 iter 20 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:33:40 - madmax             [28.5/28.8 30.3/30.6 9.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:35:02 - solver             [26.8/32.0 28.6/33.8 9.9Gb] D0T0F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0365, stall 93.23%, chi^2 2.902 -> 2.882 (2.346), noise 0.217 -> 0.216
 - 02:35:32 - solver             [27.0/33.9 28.8/35.8 10.2Gb] D0T0F0 has 0 (0.00%) new data flags: MadMax took out 779990 visibilities
 - 02:35:36 - parallactic_machin [30.6/33.9 34.2/35.8 11.9Gb] Applying P Jones to corrected data (precomputed)
 - 02:36:28 - parallactic_machin [17.5/33.9 23.3/35.8 11.9Gb] Applying P Jones to sky (precomputed)
 - 02:38:51 - madmax             [24.8/33.9 26.5/35.8 11.9Gb] D0T1F0 initial: antennas m032 have mad residuals, refer to Mad Max plots
 - 02:38:55 - madmax             [24.8/33.9 26.6/35.8 11.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:40:46 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] D0T1F0 iter 1 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:40:50 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:42:52 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] D0T1F0 iter 5 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:42:56 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:45:01 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] D0T1F0 iter 10 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:45:05 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:47:11 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] D0T1F0 iter 15 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:47:14 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:49:20 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] D0T1F0 iter 20 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:49:24 - madmax             [28.3/33.9 30.1/35.8 11.9Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:50:46 - solver             [26.5/33.9 28.3/35.8 11.9Gb] D0T1F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0256, stall 93.52%, chi^2 2.911 -> 2.888 (2.353), noise 0.216 -> 0.215
 - 02:51:16 - solver             [26.8/33.9 28.6/35.8 12.2Gb] D0T1F0 has 0 (0.00%) new data flags: MadMax took out 980074 visibilities
 - 02:51:20 - parallactic_machin [30.4/33.9 34.0/35.8 14.0Gb] Applying P Jones to corrected data (precomputed)
 - 02:52:00 - data_handler       [7.2/33.9 9.0/35.8 14.0Gb] tile 0/53: saving MS rows 0~117119
 - 02:52:00 - data_handler       [7.2/33.9 9.0/35.8 14.0Gb]   inserting new column CORRECTED_DATA
 - 02:52:01 - data_handler       [7.2/33.9 12.6/35.8 14.0Gb]   writing CORRECTED_DATA column
 - 02:52:08 - data_handler       [11.7/33.9 13.5/35.8 14.0Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 02:52:13 - data_handler       [12.1/33.9 13.9/35.8 14.0Gb]   updated BITFLAG column (75.56% visibilities flagged)
 - 02:52:13 - data_handler       [12.1/33.9 13.9/35.8 14.0Gb]   updated BITFLAG_ROW column (40.29% rows flagged)
 - 02:52:14 - data_handler       [10.3/33.9 12.1/35.8 14.0Gb]   updated FLAG column (75.56% visibilities flagged)
 - 02:52:14 - data_handler       [10.3/33.9 12.1/35.8 14.0Gb]   updated FLAG_ROW column (40.29% rows flagged)
 - 02:52:16 - data_handler       [5.8/33.9 7.4/35.8 0.2Gb] tile 1/53: reading MS rows 117120~234239
 - 02:52:17 - data_handler       [5.8/33.9 7.4/35.8 0.2Gb] reading DATA
 - 02:52:52 - data_handler       [9.3/33.9 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 02:53:05 - data_handler       [12.9/33.9 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 10377 rows
 - 02:53:05 - data_handler       [12.9/33.9 15.5/35.8 0.2Gb]   8.86% visibilities deselected via specificed subset and/or baseline cutoffs
 - 02:53:05 - data_handler       [13.0/33.9 15.5/35.8 0.2Gb] reading BITFLAG
 - 02:53:29 - data_handler       [16.5/33.9 18.2/35.8 0.2Gb]   75.40% input visibilities flagged and/or deselected
 - 02:53:35 - data_handler       [20.9/33.9 26.2/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 02:53:35 - data_handler       [20.9/33.9 26.2/35.8 6.5Gb] reading MODEL_DATA
 - 02:54:27 - parallactic_machin [14.3/33.9 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 02:56:50 - madmax             [25.1/33.9 26.8/35.8 10.2Gb] D0T2F0 initial: antennas m032 have mad residuals, refer to Mad Max plots
 - 02:56:54 - madmax             [25.2/33.9 26.8/35.8 10.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 02:58:44 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] D0T2F0 iter 1 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 02:58:48 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:00:49 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] D0T2F0 iter 5 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:00:52 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:02:58 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] D0T2F0 iter 10 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:03:02 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:05:07 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] D0T2F0 iter 15 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:05:11 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:07:16 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] D0T2F0 iter 20 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:07:19 - madmax             [28.6/33.9 30.3/35.8 10.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:08:42 - solver             [26.9/33.9 28.6/35.8 10.2Gb] D0T2F0 (end solve) G: 20 iters, conv 53.12%, d/fl 20.00%, PGE 0.0257, stall 94.18%, chi^2 2.915 -> 2.888 (2.357), noise 0.216 -> 0.215
 - 03:09:12 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T2F0 has 0 (0.00%) new data flags: MadMax took out 976544 visibilities
 - 03:09:16 - parallactic_machin [30.7/34.0 34.2/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 03:10:09 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 03:12:32 - madmax             [25.1/34.0 26.8/35.8 12.2Gb] D0T3F0 initial: antennas m032 have mad residuals, refer to Mad Max plots
 - 03:12:35 - madmax             [25.2/34.0 26.8/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:14:24 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] D0T3F0 iter 1 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:14:28 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:16:28 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] D0T3F0 iter 5 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:16:32 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:18:37 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] D0T3F0 iter 10 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:18:40 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:20:45 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] D0T3F0 iter 15 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:20:49 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:22:53 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] D0T3F0 iter 20 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 03:22:57 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 03:24:18 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T3F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0261, stall 90.49%, chi^2 2.919 -> 2.89 (2.364), noise 0.216 -> 0.214
 - 03:24:49 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T3F0 has 0 (0.00%) new data flags: MadMax took out 975332 visibilities
 - 03:24:53 - parallactic_machin [30.7/34.0 34.2/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 03:25:32 - data_handler       [7.5/34.0 9.2/35.8 14.2Gb] tile 1/53: saving MS rows 117120~234239
 - 03:25:32 - data_handler       [7.5/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 03:25:40 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 03:25:54 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (74.75% visibilities flagged)
 - 03:25:55 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 03:25:56 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (74.75% visibilities flagged)
 - 03:25:56 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 03:25:58 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 2/53: reading MS rows 234240~351359
 - 03:25:58 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 03:26:29 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 03:26:41 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 10287 rows
 - 03:26:41 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   8.78% visibilities deselected via specificed subset and/or baseline cutoffs
 - 03:26:42 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 03:27:13 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   75.38% input visibilities flagged and/or deselected
 - 03:27:18 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 03:27:18 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 03:28:12 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 03:42:32 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T4F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0259, stall 90.10%, chi^2 2.916 -> 2.886 (2.368), noise 0.216 -> 0.214
 - 03:43:02 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T4F0 has 0 (0.00%) new data flags: MadMax took out 962036 visibilities
 - 03:43:06 - parallactic_machin [30.7/34.0 34.2/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 03:43:58 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 03:58:22 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T5F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0258, stall 90.14%, chi^2 2.911 -> 2.879 (2.374), noise 0.217 -> 0.215
 - 03:58:53 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T5F0 has 0 (0.00%) new data flags: MadMax took out 961084 visibilities
 - 03:58:57 - parallactic_machin [30.7/34.0 34.2/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 03:59:37 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 2/53: saving MS rows 234240~351359
 - 03:59:37 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 03:59:44 - data_handler       [12.0/34.0 13.7/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 03:59:49 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   updated BITFLAG column (74.73% visibilities flagged)
 - 03:59:50 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 03:59:51 - data_handler       [10.7/34.0 12.4/35.8 14.2Gb]   updated FLAG column (74.73% visibilities flagged)
 - 03:59:51 - data_handler       [10.7/34.0 12.4/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 03:59:53 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 3/53: reading MS rows 351360~468479
 - 03:59:53 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 04:00:22 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 04:00:37 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 9990 rows
 - 04:00:37 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   8.53% visibilities deselected via specificed subset and/or baseline cutoffs
 - 04:00:37 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 04:01:14 - data_handler       [16.5/34.0 18.2/35.8 0.2Gb]   75.30% input visibilities flagged and/or deselected
 - 04:01:19 - data_handler       [21.0/34.0 26.2/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 04:01:19 - data_handler       [21.0/34.0 26.2/35.8 6.5Gb] reading MODEL_DATA
 - 04:02:20 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 04:16:42 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T6F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0257, stall 89.00%, chi^2 2.915 -> 2.882 (2.378), noise 0.217 -> 0.214
 - 04:17:13 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T6F0 has 0 (0.00%) new data flags: MadMax took out 973740 visibilities
 - 04:17:17 - parallactic_machin [30.7/34.0 34.2/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 04:18:09 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 04:22:29 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] D0T7F0 iter 1 (G): antennas m032 have mad residuals, refer to Mad Max plots
 - 04:22:32 - madmax             [28.6/34.0 30.3/35.8 12.2Gb] 59 baselines would have been flagged due to mad residuals (use --madmax-flag-ant to enable this)
 - 04:32:41 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T7F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0259, stall 88.58%, chi^2 2.965 -> 2.928 (2.404), noise 0.214 -> 0.212
 - 04:33:11 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T7F0 has 0 (0.00%) new data flags: MadMax took out 993804 visibilities
 - 04:33:16 - parallactic_machin [30.7/34.0 34.2/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 04:33:55 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 3/53: saving MS rows 351360~468479
 - 04:33:55 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 04:34:03 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 04:34:08 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (74.67% visibilities flagged)
 - 04:34:08 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 04:34:10 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (74.67% visibilities flagged)
 - 04:34:10 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 04:34:11 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 4/53: reading MS rows 468480~585599
 - 04:34:12 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 04:34:42 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 04:34:56 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 9708 rows
 - 04:34:56 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   8.29% visibilities deselected via specificed subset and/or baseline cutoffs
 - 04:34:56 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 04:35:28 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   75.25% input visibilities flagged and/or deselected
 - 04:35:34 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 04:35:34 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 04:36:27 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 04:50:47 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T8F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.026, stall 88.10%, chi^2 2.974 -> 2.933 (2.411), noise 0.214 -> 0.211
 - 04:51:17 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T8F0 has 0 (0.00%) new data flags: MadMax took out 993914 visibilities
 - 04:51:21 - parallactic_machin [30.7/34.0 34.2/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 04:52:13 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 05:06:27 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T9F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0259, stall 87.48%, chi^2 2.956 -> 2.921 (2.414), noise 0.215 -> 0.212
 - 05:06:58 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T9F0 has 0 (0.00%) new data flags: MadMax took out 992160 visibilities
 - 05:07:02 - parallactic_machin [30.7/34.0 34.2/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 05:07:41 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 4/53: saving MS rows 468480~585599
 - 05:07:41 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 05:07:48 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 05:07:53 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (74.66% visibilities flagged)
 - 05:07:54 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 05:07:55 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (74.66% visibilities flagged)
 - 05:07:55 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 05:07:56 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 5/53: reading MS rows 585600~702719
 - 05:07:57 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 05:08:26 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 05:08:42 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 9504 rows
 - 05:08:42 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   8.11% visibilities deselected via specificed subset and/or baseline cutoffs
 - 05:08:42 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 05:09:13 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   75.25% input visibilities flagged and/or deselected
 - 05:09:19 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 05:09:19 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 05:10:14 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 05:24:32 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T10F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0258, stall 87.67%, chi^2 2.949 -> 2.912 (2.417), noise 0.216 -> 0.213
 - 05:25:03 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T10F0 has 0 (0.00%) new data flags: MadMax took out 985488 visibilities
 - 05:25:07 - parallactic_machin [30.7/34.0 34.2/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 05:25:59 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 05:40:16 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T11F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.026, stall 87.35%, chi^2 2.949 -> 2.911 (2.424), noise 0.217 -> 0.213
 - 05:40:47 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T11F0 has 0 (0.00%) new data flags: MadMax took out 993636 visibilities
 - 05:40:52 - parallactic_machin [30.7/34.0 34.2/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 05:41:31 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 5/53: saving MS rows 585600~702719
 - 05:41:31 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 05:41:38 - data_handler       [12.0/34.0 13.7/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 05:41:43 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   updated BITFLAG column (74.71% visibilities flagged)
 - 05:41:43 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 05:41:45 - data_handler       [10.7/34.0 12.4/35.8 14.2Gb]   updated FLAG column (74.71% visibilities flagged)
 - 05:41:45 - data_handler       [10.7/34.0 12.4/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 05:41:47 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 6/53: reading MS rows 702720~819839
 - 05:41:47 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 05:42:16 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 05:42:32 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 9333 rows
 - 05:42:32 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   7.97% visibilities deselected via specificed subset and/or baseline cutoffs
 - 05:42:32 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 05:43:03 - data_handler       [16.5/34.0 18.2/35.8 0.2Gb]   75.38% input visibilities flagged and/or deselected
 - 05:43:08 - data_handler       [21.0/34.0 26.2/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 05:43:08 - data_handler       [21.0/34.0 26.2/35.8 6.5Gb] reading MODEL_DATA
 - 05:44:05 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 05:58:31 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T12F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0256, stall 87.57%, chi^2 2.961 -> 2.923 (2.437), noise 0.217 -> 0.213
 - 05:59:02 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T12F0 has 0 (0.00%) new data flags: MadMax took out 988632 visibilities
 - 05:59:06 - parallactic_machin [30.7/34.0 34.3/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 05:59:58 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 06:14:31 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T13F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0255, stall 87.16%, chi^2 2.98 -> 2.937 (2.448), noise 0.217 -> 0.213
 - 06:15:01 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T13F0 has 0 (0.00%) new data flags: MadMax took out 981044 visibilities
 - 06:15:05 - parallactic_machin [30.7/34.0 34.2/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 06:15:44 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 6/53: saving MS rows 702720~819839
 - 06:15:44 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 06:15:51 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 06:15:56 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (74.86% visibilities flagged)
 - 06:15:57 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 06:15:58 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (74.86% visibilities flagged)
 - 06:15:58 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 06:16:00 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 7/53: reading MS rows 819840~880229
 - 06:16:00 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 06:16:17 - data_handler       [7.6/34.0 10.2/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 06:16:27 - data_handler       [9.5/34.0 11.6/35.8 0.2Gb]   applying solvable baseline cutoff deselects 4667 rows
 - 06:16:27 - data_handler       [9.5/34.0 11.6/35.8 0.2Gb]   7.73% visibilities deselected via specificed subset and/or baseline cutoffs
 - 06:16:27 - data_handler       [9.5/34.0 11.6/35.8 0.2Gb] reading BITFLAG
 - 06:16:47 - data_handler       [11.3/34.0 13.0/35.8 0.2Gb]   77.65% input visibilities flagged and/or deselected
 - 06:16:50 - data_handler       [13.6/34.0 17.1/35.8 3.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 06:16:50 - data_handler       [13.6/34.0 17.1/35.8 3.5Gb] reading MODEL_DATA
 - 06:17:14 - parallactic_machin [3.3/34.0 9.0/35.8 5.3Gb] Applying P Jones to sky (precomputed)
 - 06:25:21 - solver             [3.3/34.0 5.0/35.8 5.3Gb] D0T14F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0498, stall 87.89%, chi^2 2.796 -> 2.755 (2.347), noise 0.227 -> 0.224
 - 06:25:22 - solver             [3.6/34.0 5.2/35.8 5.6Gb] D0T14F0 has 0 (0.00%) new data flags: MadMax took out 28100 visibilities
 - 06:25:22 - parallactic_machin [3.6/34.0 7.1/35.8 5.6Gb] Applying P Jones to corrected data (precomputed)
 - 06:25:36 - parallactic_machin [13.6/34.0 15.3/35.8 5.6Gb] Applying P Jones to sky (precomputed)
 - 06:39:59 - solver             [26.0/34.0 27.7/35.8 5.6Gb] D0T15F0 (end solve) G: 20 iters, conv 56.25%, d/fl 20.00%, PGE 0.0371, stall 91.89%, chi^2 2.964 -> 2.942 (2.47), noise 0.22 -> 0.215
 - 06:40:29 - solver             [26.2/34.0 27.9/35.8 5.9Gb] D0T15F0 has 0 (0.00%) new data flags: MadMax took out 897392 visibilities
 - 06:40:33 - parallactic_machin [29.9/34.0 31.6/35.8 7.6Gb] Applying P Jones to corrected data (precomputed)
 - 06:41:13 - data_handler       [6.7/34.0 8.4/35.8 7.6Gb] tile 7/53: saving MS rows 819840~880229
 - 06:41:13 - data_handler       [6.7/34.0 10.2/35.8 7.6Gb]   writing CORRECTED_DATA column
 - 06:41:16 - data_handler       [9.0/34.0 10.7/35.8 7.6Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 06:41:19 - data_handler       [9.0/34.0 10.7/35.8 7.6Gb]   updated BITFLAG column (77.21% visibilities flagged)
 - 06:41:19 - data_handler       [9.0/34.0 10.7/35.8 7.6Gb]   updated BITFLAG_ROW column (42.10% rows flagged)
 - 06:41:20 - data_handler       [8.1/34.0 9.7/35.8 7.6Gb]   updated FLAG column (77.21% visibilities flagged)
 - 06:41:20 - data_handler       [8.1/34.0 9.7/35.8 7.6Gb]   updated FLAG_ROW column (42.10% rows flagged)
 - 06:41:21 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 8/53: reading MS rows 880230~997349
 - 06:41:21 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 06:41:53 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 06:42:09 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 8962 rows
 - 06:42:09 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   7.65% visibilities deselected via specificed subset and/or baseline cutoffs
 - 06:42:09 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 06:42:41 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   77.38% input visibilities flagged and/or deselected
 - 06:42:47 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 06:42:47 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 06:43:42 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 06:58:01 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T16F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0273, stall 88.62%, chi^2 2.951 -> 2.93 (2.47), noise 0.221 -> 0.216
 - 06:58:31 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T16F0 has 0 (0.00%) new data flags: MadMax took out 959810 visibilities
 - 06:58:35 - parallactic_machin [30.7/34.0 34.3/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 06:59:27 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 07:13:54 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T17F0 (end solve) G: 20 iters, conv 59.38%, d/fl 20.00%, PGE 0.0537, stall 93.59%, chi^2 2.976 -> 2.954 (2.486), noise 0.221 -> 0.217
 - 07:14:25 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T17F0 has 0 (0.00%) new data flags: MadMax took out 869196 visibilities
 - 07:14:29 - parallactic_machin [30.7/34.0 34.3/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 07:15:08 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 8/53: saving MS rows 880230~997349
 - 07:15:08 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 07:15:16 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 07:15:21 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (76.93% visibilities flagged)
 - 07:15:21 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (41.25% rows flagged)
 - 07:15:23 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (76.93% visibilities flagged)
 - 07:15:23 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (41.25% rows flagged)
 - 07:15:24 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 9/53: reading MS rows 997350~1114469
 - 07:15:25 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 07:16:08 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 07:16:25 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 8704 rows
 - 07:16:25 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   7.43% visibilities deselected via specificed subset and/or baseline cutoffs
 - 07:16:25 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 07:17:02 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   76.17% input visibilities flagged and/or deselected
 - 07:17:08 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 07:17:08 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 07:18:08 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 07:32:29 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T18F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0259, stall 88.12%, chi^2 2.978 -> 2.953 (2.493), noise 0.222 -> 0.217
 - 07:32:59 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T18F0 has 0 (0.00%) new data flags: MadMax took out 955626 visibilities
 - 07:33:04 - parallactic_machin [30.7/34.0 34.3/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 07:33:56 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 07:48:19 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T19F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0251, stall 87.07%, chi^2 2.99 -> 2.964 (2.511), noise 0.222 -> 0.217
 - 07:48:49 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T19F0 has 0 (0.00%) new data flags: MadMax took out 963904 visibilities
 - 07:48:54 - parallactic_machin [30.7/34.0 34.3/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 07:49:33 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 9/53: saving MS rows 997350~1114469
 - 07:49:33 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 07:49:40 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 07:49:45 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (75.73% visibilities flagged)
 - 07:49:46 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 07:49:47 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (75.73% visibilities flagged)
 - 07:49:47 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 07:49:48 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 10/53: reading MS rows 1114470~1231589
 - 07:49:49 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 07:50:22 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 07:50:38 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 8558 rows
 - 07:50:38 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   7.31% visibilities deselected via specificed subset and/or baseline cutoffs
 - 07:50:38 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 07:51:10 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   76.02% input visibilities flagged and/or deselected
 - 07:51:15 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 07:51:15 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 07:52:15 - parallactic_machin [14.3/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 08:06:40 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T20F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0257, stall 87.02%, chi^2 3.017 -> 2.989 (2.525), noise 0.22 -> 0.215
 - 08:07:10 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T20F0 has 0 (0.00%) new data flags: MadMax took out 987338 visibilities
 - 08:07:15 - parallactic_machin [30.7/34.0 34.3/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 08:08:07 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 08:22:31 - solver             [26.9/34.0 28.6/35.8 12.2Gb] D0T21F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0259, stall 86.87%, chi^2 3.021 -> 2.993 (2.526), noise 0.22 -> 0.215
 - 08:23:02 - solver             [27.1/34.0 28.8/35.8 12.4Gb] D0T21F0 has 0 (0.00%) new data flags: MadMax took out 1001226 visibilities
 - 08:23:07 - parallactic_machin [30.7/34.0 34.3/35.8 14.2Gb] Applying P Jones to corrected data (precomputed)
 - 08:23:46 - data_handler       [7.6/34.0 9.2/35.8 14.2Gb] tile 10/53: saving MS rows 1114470~1231589
 - 08:23:46 - data_handler       [7.6/34.0 12.8/35.8 14.2Gb]   writing CORRECTED_DATA column
 - 08:23:53 - data_handler       [12.5/34.0 14.1/35.8 14.2Gb]   3.28% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 08:23:58 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG column (75.59% visibilities flagged)
 - 08:23:59 - data_handler       [12.9/34.0 14.6/35.8 14.2Gb]   updated BITFLAG_ROW column (38.36% rows flagged)
 - 08:24:00 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG column (75.59% visibilities flagged)
 - 08:24:00 - data_handler       [11.1/34.0 12.8/35.8 14.2Gb]   updated FLAG_ROW column (38.36% rows flagged)
 - 08:24:02 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] tile 11/53: reading MS rows 1231590~1348709
 - 08:24:02 - data_handler       [5.8/34.0 7.4/35.8 0.2Gb] reading DATA
 - 08:24:37 - data_handler       [9.3/34.0 12.8/35.8 0.2Gb] model 0 weights 0: reading from WEIGHT_SPECTRUM
 - 08:24:53 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   applying solvable baseline cutoff deselects 8369 rows
 - 08:24:53 - data_handler       [12.9/34.0 15.5/35.8 0.2Gb]   7.15% visibilities deselected via specificed subset and/or baseline cutoffs
 - 08:24:53 - data_handler       [13.0/34.0 15.5/35.8 0.2Gb] reading BITFLAG
 - 08:25:28 - data_handler       [16.9/34.0 18.6/35.8 0.2Gb]   76.05% input visibilities flagged and/or deselected
 - 08:25:33 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 08:25:33 - data_handler       [21.4/34.0 26.7/35.8 6.5Gb] reading MODEL_DATA
 - 08:26:37 - parallactic_machin [14.4/34.0 20.0/35.8 10.2Gb] Applying P Jones to sky (precomputed)
 - 08:40:54 - solver             [26.9/34.0 28.6/35.8 10.2Gb] D0T22F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0258, stall 86.82%, chi^2 3.034 -> 3.006 (2.537), noise 0.22 -> 0.215
 - 08:41:25 - solver             [27.1/34.0 28.8/35.8 10.4Gb] D0T22F0 has 0 (0.00%) new data flags: MadMax took out 1017478 visibilities
 - 08:41:29 - parallactic_machin [30.7/34.0 34.3/35.8 12.2Gb] Applying P Jones to corrected data (precomputed)
 - 08:42:21 - parallactic_machin [17.8/34.0 23.6/35.8 12.2Gb] Applying P Jones to sky (precomputed)
 - 08:56:44 - solver             [26.9/34.0 28.6/35.8 0.2Gb] D0T23F0 (end solve) G: 20 iters, conv 50.00%, d/fl 20.00%, PGE 0.0253, stall 86.86%, chi^2 3.044 -> 3.018 (2.55), noise 0.221 -> 0.216
 - 08:57:01 - NpShared           [26.9/34.0 28.6/35.8 0.2Gb] File file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a exists, deleting
 - 08:57:01 - solver             [26.9/34.0 28.6/35.8 0.2Gb] Solver for tile 11 chunk D0T23F0 failed with exception: [Errno 2] No such file or directory: 'file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a'
 - 08:57:01 - solver             [26.9/34.0 28.6/35.8 0.2Gb] Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 833, in run_solver
    corr_vis = solver_machine.run()
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 656, in run
    SolveOnly.run(self)
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 644, in run
    self.vdm.freq_slice, self.soldict)
  File "/usr/local/lib/python2.7/dist-packages/cubical/machines/ifr_gain_machine.py", line 123, in update
    DDH = soldict.addSharedArray('ifrgains:DDH__', bbshape, dtype=obser_arr.dtype)
  File "/usr/local/lib/python2.7/dist-packages/cubical/tools/shared_dict.py", line 285, in addSharedArray
    array = NpShared.CreateShared(_to_shm(filepath), shape, dtype)
  File "/usr/local/lib/python2.7/dist-packages/cubical/tools/NpShared.py", line 45, in CreateShared
    a = SharedArray.create(Name, shape, dtype=dtype)
OSError: [Errno 2] No such file or directory: 'file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a'
 - 08:57:01 - main               [26.9/34.0 28.6/35.8 0.2Gb] Exiting with exception: OSError([Errno 2] No such file or directory: 'file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a')
 Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/cubical/main.py", line 480, in main
    stats_dict = workers.run_process_loop(ms, tile_list, load_model, single_chunk, solver_type, solver_opts, debug_opts)
  File "/usr/local/lib/python2.7/dist-packages/cubical/workers.py", line 212, in run_process_loop
    return _run_single_process_loop(ms, load_model, single_chunk, solver_type, solver_opts, debug_opts)
  File "/usr/local/lib/python2.7/dist-packages/cubical/workers.py", line 349, in _run_single_process_loop
    solver.run_solver(solver_type, itile, key, solver_opts, debug_opts)
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 833, in run_solver
    corr_vis = solver_machine.run()
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 656, in run
    SolveOnly.run(self)
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 644, in run
    self.vdm.freq_slice, self.soldict)
  File "/usr/local/lib/python2.7/dist-packages/cubical/machines/ifr_gain_machine.py", line 123, in update
    DDH = soldict.addSharedArray('ifrgains:DDH__', bbshape, dtype=obser_arr.dtype)
  File "/usr/local/lib/python2.7/dist-packages/cubical/tools/shared_dict.py", line 285, in addSharedArray
    array = NpShared.CreateShared(_to_shm(filepath), shape, dtype)
  File "/usr/local/lib/python2.7/dist-packages/cubical/tools/NpShared.py", line 45, in CreateShared
    a = SharedArray.create(Name, shape, dtype=dtype)
OSError: [Errno 2] No such file or directory: 'file:///dev/shm/cubical.17274/DATA:1231590:1348709/str:solutions:d/str:D0T23F0:d/str:ifrgains:DDH__:a'
IanHeywood commented 5 years ago

Log seems difficult to read there so there's a text file uploaded here.

o-smirnov commented 5 years ago

OK pretty sure it's this problem biting us: https://github.com/mhardcastle/ddf-pipeline/issues/150

293 smells related too. It ends up with a None instead of a shared array when looking for weights, so a similar failure regime.

@IanHeywood could you do /sbin/sysctl vm.max_map_count on the node and let me know what it says?

Might also be some unholy interaction with Singularity. @SpheMakh did we have some discussion of how shared memoery is handled/restricted within Singularity containers, or was I hallucinating?

o-smirnov commented 5 years ago

Also, df -h /dev/shm please....

o-smirnov commented 5 years ago

@SpheMakh could you please make a "debugging" container that runs

/sbin/sysctl vm.max_map_count
df -h /dev/shm

before invoking gocubical. That way we can see what the system limits are on the node. Actually might be a good idea to do this routinely, not just for debugging.

o-smirnov commented 5 years ago

Actually @IanHeywood, @SpheMakh tells me you're explicitly launching CubiCal within the container with your own command -- maybe you could run those two commands inside the container yourself?

IanHeywood commented 5 years ago

I've added those commands to each cubical run by default. It now starts logging like this:

vm.max_map_count = 65530
Filesystem      Size  Used Avail Use% Mounted on
tmpfs           119G     0  119G   0% /dev/shm
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 868, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 741, in format
    return fmt.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 469, in format
    s = self._fmt % record.__dict__
KeyError: 'shortname'
Logged from file driver.py, line 124
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 868, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 741, in format
    return fmt.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 469, in format
    s = self._fmt % record.__dict__
KeyError: 'shortname'
Logged from file driver.py, line 124
 - 07:49:50 - main               | reading defaults from /ceph/pipelines/ianh/MIGHTEE/CDFS/CDFS_2_4/parsets/phas
ecal.parset
 - 07:49:50 - main               | using cube_pcal_1561266559_sdp_l0.full_1284.full_pol_wtspec_CDFS_2_4.m
s_2019-07-16-23-46-02 as base for output files

Looks to be the same setup for the four nodes I've run jobs on since:

CDFS_2_3/logs/slurm_cubical1_2_3.log:tmpfs           119G     0  119G   0% /dev/shm
CDFS_2_4/logs/slurm_cubical1_2_4.log:tmpfs           119G     0  119G   0% /dev/shm
CDFS_4_3/logs/slurm_cubical1_4_3.log:tmpfs           119G     0  119G   0% /dev/shm
CDFS_4_4/logs/slurm_cubical1_4_4.log:tmpfs           119G  4.0K  119G   1% /dev/shm
ianh@slurm-login:/ceph/pipelines/ianh/MIGHTEE/CDFS$ grep count */logs/*cub*
CDFS_2_3/logs/slurm_cubical1_2_3.log:vm.max_map_count = 65530
CDFS_2_4/logs/slurm_cubical1_2_4.log:vm.max_map_count = 65530
CDFS_4_3/logs/slurm_cubical1_4_3.log:vm.max_map_count = 65530
CDFS_4_4/logs/slurm_cubical1_4_4.log:vm.max_map_count = 65530

although three of the four of them dropped dead overnight with no error message, and one ended with the following:

 - 07:12:33 - solver             [x27] [7.8/8.7 9.7/29.2 52.6Gb] Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 833, in run_solver
    corr_vis = solver_machine.run()
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 656, in run
    SolveOnly.run(self)
  File "/usr/local/lib/python2.7/dist-packages/cubical/solver.py", line 644, in run
    self.vdm.freq_slice, self.soldict)
  File "/usr/local/lib/python2.7/dist-packages/cubical/machines/ifr_gain_machine.py", line 130, in update
    DDH[:] = (D * DH).sum(axis=(0,1))
MemoryError
IanHeywood commented 5 years ago

I'm going to dial down the parallelism and resubmit.

o-smirnov commented 5 years ago
vm.max_map_count = 65530
Filesystem      Size  Used Avail Use% Mounted on
tmpfs           119G     0  119G   0% /dev/shm

Yeah thart's looking rather tight on both counts. Any chance to get the admins to (a) increase vm.max_map_count to 1000000, and (b) increase max shm size to 80 or 90% of RAM?

IanHeywood commented 5 years ago

(b) I am working on as part of my efforts to get the IDIA slurm cluster to be DDFacet-friendly.

I will ask about (a).

Is it noteworthy that the original problem in this issue occurred with parallelism disabled? For the tile sizes I had it was using maybe 40 GB of the 230 GB of available RAM.

o-smirnov commented 5 years ago

DDFacet needs a+b really...

Is it noteworthy that the original problem in this issue occurred with parallelism disabled?

I'm not sure.... shared memory use goes up by a factor of 2 in parallel mode (because of the tile read-ahead thingy), so it would probably have been even worse.

IanHeywood commented 5 years ago

OK thanks to Mike Currin and others I have a test worker node that has 192 GB of /dev/shm space and vm.max_map_count = 1000000.

DDF tests are ahead of CubiCal in the queue but I'll let you know.

I've also reduced the max tiles in the above runs and will see how those go on the general worker nodes.

Cheers.