ratt-ru / CubiCal

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

Time / frequency interval weirdness with rebinning enabled #211

Open IanHeywood opened 6 years ago

IanHeywood commented 6 years ago

Processing a MS with 2347 unique timeslots, 1024 channels. The relevant parset options are:

--model-list = MODEL_DATA:DIR1:DIR2:DIR3:DIR4

--data-time-chunk = 720
--data-freq-chunk = 256

--data-rebin-time = 4
--data-rebin-freq = 16

--g-time-int = 40
--g-freq-int = 256

--de-time-int = 720
--de-freq-int = 256

So I would expect both G and dE tables to have :

1024 / 256 = 4 frequency intervals for both G and dE

and

2347/40 = 59 time intervals for G
2347/720 = 4 time intervals for dE

However the gain table shapes (dir x time x freq x ant x corr1 x corr2) are:

loading G:gain, shape 1x17x1x62x2x2
loading de:gain, shape 5x4x1x62x2x2

Scan number chunking is disabled, due to requiring a long dE solution interval.

Looking at the log, I never get beyond D0T3F0. The D and T make sense, but not the F. And why only 17 intervals in the G table?

A further question: why do I have solutions for five directions in the dE when I have --de-fix-dirs = 0?

Cheers.

o-smirnov commented 6 years ago

Could you point me to a full log please?

IanHeywood commented 6 years ago

Here's the log. I've been assuming the reported noise statistics are being skewed by the averaging.

 - 08:16:27 - cc                 [0.1/0.1 2.8/2.8 0.7Gb] set global console verbosity level 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] started /users/ianh/.local/bin/gocubical dE-modcols-new.parset --data-ms=1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms --out-name cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  Selected Options:
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [data] Visibility data options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ms ................................................ = 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - column ............................................ = DATA
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - time-chunk ........................................ = 720
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - freq-chunk ........................................ = 256
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - rebin-time ........................................ = 4
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - rebin-freq ........................................ = 16
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - chunk-by .......................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - chunk-by-jump ..................................... = 1.0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - single-chunk ...................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [sel] Data selection options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - field ............................................. = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ddid .............................................. = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - taql .............................................. =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - chan .............................................. =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [model] Calibration model options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - list .............................................. = MODEL_DATA:DIR1:DIR2:DIR3:DIR4
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ddes .............................................. = auto
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - beam-pattern ...................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - beam-l-axis ....................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - beam-m-axis ....................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [montblanc] Montblanc simulation options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - device-type ....................................... = CPU
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - dtype ............................................. = float
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - feed-type ......................................... = linear
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - mem-budget ........................................ = 1024
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - verbosity ......................................... = WARNING
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - threads ........................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [weight] Weighting options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - column ............................................ = WEIGHT_SPECTRUM
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [flags] General flagging options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - apply ............................................. = -cubical
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - auto-init ......................................... = legacy
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - save .............................................. = cubical
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - save-legacy ....................................... = auto
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - reinit-bitflags ................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - warn-thr .......................................... = 0.3
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - see-no-evil ....................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [postmortem] Options for "postmortem" flagging based on solution statistics
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - enable ............................................ = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - tf-chisq-median ................................... = 1.2
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - tf-np-median ...................................... = 0.5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - time-density ...................................... = 0.5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - chan-density ...................................... = 0.5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ddid-density ...................................... = 0.5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [madmax] Options for the "Mad Max" flagger
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - enable ............................................ = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - estimate .......................................... = corr
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - diag .............................................. = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - offdiag ........................................... = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - threshold ......................................... = [0, 10]
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - global-threshold .................................. = [0]
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - plot .............................................. = 1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - plot-frac-above ................................... = 0.01
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [sol] Solution options which apply at the solver level
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - jones ............................................. = ['G', 'dE']
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - precision ......................................... = 32
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - delta-g ........................................... = 1e-06
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - delta-chi ......................................... = 1e-06
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - chi-int ........................................... = 5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - last-rites ........................................ = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - stall-quorum ...................................... = 0.99
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - diag-diag ......................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - term-iters ........................................ =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - min-bl ............................................ = 150.0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-bl ............................................ = 100000000.0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - subset ............................................ =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [bbc] Options for baseline-based corrections (a.k.a. BBCs, a.k.a. interferometer gains).
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - load-from ......................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - compute-2x2 ....................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - apply-2x2 ......................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - save-to ........................................... = {data[ms]}/BBC-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - per-chan .......................................... = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - plot .............................................. = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [dist] Parallelization and distribution options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ncpu .............................................. = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - nworker ........................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - nthread ........................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-chunks ........................................ = 1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - min-chunks ........................................ = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - pin ............................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - pin-io ............................................ = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - pin-main .......................................... = io
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [out] Options for output products
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - name .............................................. = cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - mode .............................................. = so
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - column ............................................ = CORRECTED_DATA
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - model-column ...................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - reinit-column ..................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - subtract-model .................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - subtract-dirs ..................................... = :
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - plots ............................................. = 1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - casa-gaintables ................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [log] Options related to logging
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - memory ............................................ = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - boring ............................................ = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - append ............................................ = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - verbose ........................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - file-verbose ...................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [debug] Debugging options for the discerning masochist
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - pdb ............................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - panic-amplitude ................................... = 0.0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - stop-before-solver ................................ = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [misc] Miscellaneous options
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - random-seed ....................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - parset-version .................................... = 0.1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [g] Options for G-Jones term
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - solvable .......................................... = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - type .............................................. = complex-2x2
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - load-from ......................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - xfer-from ......................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - save-to ........................................... = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - dd-term ........................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - fix-dirs .......................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - diag-diag ......................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - update-type ....................................... = full
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - time-int .......................................... = 40
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - freq-int .......................................... = 256
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-prior-error ................................... = 0.1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-post-error .................................... = 0.1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - clip-low .......................................... = 0.8
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - clip-high ......................................... = 1.2
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - clip-after ........................................ = 5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-iter .......................................... = 20
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - conv-quorum ....................................... = 0.99
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ref-ant ........................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - prop-flags ........................................ = default
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] [de] Options for G-Jones term
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - solvable .......................................... = True
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - type .............................................. = complex-2x2
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - load-from ......................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - xfer-from ......................................... =
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - save-to ........................................... = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - dd-term ........................................... = 1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - fix-dirs .......................................... = 0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - diag-diag ......................................... = False
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - update-type ....................................... = full
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - time-int .......................................... = 720
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - freq-int .......................................... = 256
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-prior-error ................................... = 0.1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-post-error .................................... = 0.1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - clip-low .......................................... = 0.1
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - clip-high ......................................... = 10.0
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - clip-after ........................................ = 5
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - max-iter .......................................... = 20
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - conv-quorum ....................................... = 0.99
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - ref-ant ........................................... = None
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb]  - prop-flags ........................................ = default
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] Enabling G,dE-Jones
 - 08:16:27 - main               [0.1/0.1 2.8/2.8 0.7Gb] mode: solve only
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb] reading MS 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   detected linear (xy) feeds
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   fields are *0: 47Tuc
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   MS contains 1 spectral windows
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   max freq chunk size is 256 channels and/or -- MHz
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   rebinning by 16 channels
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   DDID 0: 256/256 selected channels will be rebinned into 16 channels
 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]     found 1 frequency chunks: 0 16
 - 08:16:28 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   applying TAQL query 'FIELD_ID == 0 && DATA_DESC_ID IN [0]' (4583691/4583691 rows selected)
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]   62 antennas, 4583691 rows, 1/1 DDIDs, 2347 timeslots, 4 corrs
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]   DDID central frequencies are at 1.31 GHz
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb] WARNING: output columns will be upsampled from frequency-binned data!
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb] WARNING: the BITFLAG column does not appear to be properly initialized. This is perhaps due to a previous CubiCal run being interrupted while it was filling the column. This is not fatal, and we'll attempt to refill it.
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]   BITFLAG column found. Will auto-fill with 'legacy' (1) from FLAG/FLAG_ROW if not filled
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     BITFLAG column defines the following flagsets: legacy:1 cubical:2
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     Excluding flagset cubical
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]   Applying BITFLAG mask 1 to input data
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]   Will save output flags into BITFLAG 'cubical' (2), and into FLAG/FLAG_ROW
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb] Using 1 model(s) for 5 directions(s)
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]   model 0 (weight WEIGHT_SPECTRUM):
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     direction 0: MODEL_DATA
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     direction 1: DIR1
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     direction 2: DIR2
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     direction 3: DIR3
 - 08:16:28 - data_handler       [0.1/0.2 2.8/2.8 0.7Gb]     direction 4: DIR4
 - 08:16:28 - main               [0.1/0.2 2.8/2.8 0.7Gb] subtraction directions set to slice(None, None, None)
 - 08:16:28 - param_db           [0.1/0.2 2.8/2.8 0.7Gb] creating 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/G-field_0-ddid_None.parmdb in fragmented mode
 - 08:16:28 - gain_machine       [0.1/0.2 2.8/2.8 0.7Gb] G solutions will be saved to 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/G-field_0-ddid_None.parmdb
 - 08:16:28 - param_db           [0.1/0.2 2.8/2.8 0.7Gb] creating 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/de-field_0-ddid_None.parmdb in fragmented mode
 - 08:16:28 - gain_machine       [0.1/0.2 2.8/2.8 0.7Gb] de solutions will be saved to 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/de-field_0-ddid_None.parmdb
 - 08:16:28 - param_db           [0.1/0.2 2.8/2.8 0.7Gb] creating 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/BBC-field_0-ddid_None.parmdb in fragmented mode
 - 08:16:28 - gain_machine       [0.1/0.2 2.8/2.8 0.7Gb] will compute & save suggested baseline-based corrections (BBCs) to 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/BBC-field_0-ddid_None.parmdb
 - 08:16:28 - gain_machine       [0.1/0.2 2.8/2.8 0.7Gb]   (these can optionally be applied in a subsequent CubiCal run)
 - 08:16:28 - main               [0.1/0.2 2.8/2.8 0.7Gb] single-process, single-thread mode
 - 08:16:28 - main               [0.1/0.2 2.8/2.8 0.7Gb] defining chunks (time 720, freq 256)
 - 08:16:29 - data_handler       [0.3/0.3 2.9/2.9 0.7Gb]   read indexing columns (4583691 total rows)
 - 08:16:30 - data_handler       [0.3/0.3 3.0/3.0 0.7Gb]   built timeslot index (2347 unique timestamps)
 - 08:16:30 - data_handler       [0.3/0.3 3.0/3.0 0.7Gb]   max chunk size is 720 timeslots and/or -- seconds
 - 08:16:30 - data_handler       [0.3/0.3 3.0/3.0 0.7Gb]   computing time rebinning by 4 timeslots
 - 08:16:40 - data_handler       [0.4/1.4 3.1/4.1 0.7Gb]   found 4 time chunks: 0 720 1440 2160 2347
 - 08:16:40 - data_handler       [0.4/1.4 3.1/4.1 0.7Gb]   will rebin into 1146411 rows (587 rebinned timeslots)
 - 08:16:40 - data_handler       [0.4/1.4 3.1/4.1 0.7Gb] WARNING: output columns will be upsampled from time-binned data!
 - 08:16:40 - data_handler       [0.5/1.4 3.2/4.1 0.7Gb]   generated 4 row chunks based on time and DDID
 - 08:16:40 - data_handler       [0.5/1.4 3.2/4.1 0.7Gb]   row chunks yield 4 potential tiles
 - 08:16:41 - data_handler       [0.6/1.4 3.3/4.1 0.7Gb]   coarsening this to 4 tiles (max 1 chunks per tile, based on 1/1 requested)
 - 08:16:41 - data_handler       [0.4/1.4 3.1/4.1 0.7Gb] tile #1/4: reading MS rows 0~1406159
 - 08:17:41 - data_handler       [23.3/24.6 28.6/29.9 0.7Gb]   applying solvable baseline cutoff deselects 122649 rows
 - 08:17:41 - data_handler       [23.3/24.6 28.6/29.9 0.7Gb]   8.72% visibilities deselected via specificed subset and/or baseline cutoffs
 - 08:18:23 - data_handler       [32.6/37.0 35.3/42.0 0.7Gb]   19.79% input visibilities flagged and/or deselected
 - 08:18:23 - data_handler       [32.6/37.0 35.3/42.0 0.7Gb]   rebinning into 351540 rows and 16 channels
 - 08:18:34 - data_handler       [22.2/37.0 25.7/42.0 1.0Gb]   reading MODEL_DATA for model 0 direction 0
 - 08:19:17 - data_handler       [22.5/43.6 25.9/47.2 1.2Gb]   reading DIR1 for model 0 direction 1
 - 08:20:03 - data_handler       [22.8/44.0 26.0/47.3 1.4Gb]   reading DIR2 for model 0 direction 2
 - 08:20:48 - data_handler       [23.2/44.3 26.2/47.5 1.5Gb]   reading DIR3 for model 0 direction 3
 - 08:21:34 - data_handler       [23.5/44.6 26.4/47.7 1.7Gb]   reading DIR4 for model 0 direction 4
 - 08:25:31 - solver             [13.8/44.9 16.5/47.8 1.9Gb] D0T0F0 G: 13 iters, conv 100.00%, g/fl 46.13%, PGE 0.0243; de: 20 iters, conv 0.00%, g/fl 3.23%, PGE 0.0208 0.104 0.0835 0.118 0.0842, NFPGE 0 1 0 1 0, stall 22.15%, chi^2 0.3835 -> 0.1234 (0.4891), noise 0.695 -> 0.241
 - 08:25:31 - solver             [13.8/44.9 16.5/47.8 1.9Gb] WARNING: D0T0F0 solver flags GOOB:3(0.97%) GVAR:2(0.65%) ILLCOND:5(1.61%) : 5575882 (50.37%) new data flags
 - 08:25:41 - data_handler       [5.7/44.9 8.4/47.8 1.9Gb] tile #1/4: saving MS rows 0~1406159
 - 08:25:57 - data_handler       [7.1/44.9 9.8/47.8 1.9Gb]   54.88% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 08:26:18 - data_handler       [8.5/44.9 11.2/47.8 1.9Gb]   updated BITFLAG column (61.57% visibilities flagged)
 - 08:26:19 - data_handler       [8.5/44.9 11.2/47.8 1.9Gb]   updated BITFLAG_ROW column (54.75% rows flagged)
 - 08:26:22 - data_handler       [8.5/44.9 11.2/47.8 1.9Gb]   updated FLAG column (61.57% visibilities flagged)
 - 08:26:22 - data_handler       [8.5/44.9 11.2/47.8 1.9Gb]   updated FLAG_ROW column (54.75% rows flagged)
 - 08:26:23 - data_handler       [5.8/44.9 8.4/47.8 0.7Gb] tile #2/4: reading MS rows 1406160~2812319
 - 08:27:23 - data_handler       [28.6/44.9 34.0/47.8 0.7Gb]   applying solvable baseline cutoff deselects 130953 rows
 - 08:27:23 - data_handler       [28.6/44.9 34.0/47.8 0.7Gb]   9.31% visibilities deselected via specificed subset and/or baseline cutoffs
 - 08:28:05 - data_handler       [38.0/44.9 40.7/47.8 0.7Gb]   21.32% input visibilities flagged and/or deselected
 - 08:28:05 - data_handler       [38.0/44.9 40.7/47.8 0.7Gb]   rebinning into 351540 rows and 16 channels
 - 08:28:16 - data_handler       [27.5/44.9 31.1/47.8 1.0Gb]   reading MODEL_DATA for model 0 direction 0
 - 08:29:00 - data_handler       [27.9/49.0 31.2/52.5 1.2Gb]   reading DIR1 for model 0 direction 1
 - 08:29:45 - data_handler       [28.2/49.3 31.4/52.7 1.4Gb]   reading DIR2 for model 0 direction 2
 - 08:30:31 - data_handler       [28.5/49.6 31.6/52.9 1.5Gb]   reading DIR3 for model 0 direction 3
 - 08:31:18 - data_handler       [28.8/50.0 31.7/53.0 1.7Gb]   reading DIR4 for model 0 direction 4
 - 08:35:11 - solver             [19.2/50.3 21.9/53.2 1.9Gb] D0T1F0 G: 12 iters, conv 100.00%, g/fl 26.45%, d/fl 0.32%, PGE 0.0305; de: 20 iters, conv 0.00%, g/fl 3.23%, PGE 0.0153 0.0895 0.0387 0.0963 0.0505, stall 34.58%, chi^2 0.398 -> 0.1815 (0.6745), noise 0.663 -> 0.234
 - 08:35:11 - solver             [19.2/50.3 21.9/53.2 1.9Gb] WARNING: D0T1F0 solver flags GOOB:5(1.61%) ILLCOND:5(1.61%) : 3731872 (33.71%) new data flags
 - 08:35:21 - data_handler       [11.1/50.3 13.8/53.2 1.9Gb] tile #2/4: saving MS rows 1406160~2812319
 - 08:35:35 - data_handler       [12.5/50.3 15.2/53.2 1.9Gb]   38.33% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 08:35:56 - data_handler       [13.9/50.3 16.6/53.2 1.9Gb]   updated BITFLAG column (47.82% visibilities flagged)
 - 08:35:58 - data_handler       [13.9/50.3 16.6/53.2 1.9Gb]   updated BITFLAG_ROW column (38.91% rows flagged)
 - 08:36:01 - data_handler       [13.9/50.3 16.6/53.2 1.9Gb]   updated FLAG column (47.82% visibilities flagged)
 - 08:36:01 - data_handler       [13.9/50.3 16.6/53.2 1.9Gb]   updated FLAG_ROW column (38.91% rows flagged)
 - 08:36:01 - data_handler       [11.1/50.3 13.8/53.2 0.7Gb] tile #3/4: reading MS rows 2812320~4218479
 - 08:37:03 - data_handler       [34.0/50.3 39.3/53.2 0.7Gb]   applying solvable baseline cutoff deselects 151856 rows
 - 08:37:03 - data_handler       [34.0/50.3 39.3/53.2 0.7Gb]   10.80% visibilities deselected via specificed subset and/or baseline cutoffs
 - 08:37:44 - data_handler       [43.4/50.3 46.1/53.2 0.7Gb]   21.03% input visibilities flagged and/or deselected
 - 08:37:44 - data_handler       [43.4/50.3 46.1/53.2 0.7Gb]   rebinning into 351540 rows and 16 channels
 - 08:37:56 - data_handler       [32.9/50.3 36.4/53.2 1.0Gb]   reading MODEL_DATA for model 0 direction 0
 - 08:38:39 - data_handler       [33.2/54.4 36.6/57.9 1.2Gb]   reading DIR1 for model 0 direction 1
 - 08:39:25 - data_handler       [33.6/54.7 36.8/58.1 1.4Gb]   reading DIR2 for model 0 direction 2
 - 08:40:11 - data_handler       [33.9/55.0 36.9/58.2 1.5Gb]   reading DIR3 for model 0 direction 3
 - 08:40:56 - data_handler       [34.2/55.3 37.1/58.4 1.7Gb]   reading DIR4 for model 0 direction 4
 - 08:44:37 - solver             [24.5/55.7 27.2/58.6 1.9Gb] D0T2F0 G: 12 iters, conv 100.00%, g/fl 1.94%, PGE 0.0236; de: 20 iters, conv 0.00%, g/fl 1.29%, PGE 0.0123 0.0553 0.0214 0.0777 0.0278, stall 47.78%, chi^2 0.353 -> 0.2414 (1.018), noise 0.667 -> 0.218
 - 08:44:37 - solver             [24.5/55.7 27.2/58.6 1.9Gb] D0T2F0 solver flags GOOB:4(1.29%) : 365388 (3.30%) new data flags
 - 08:44:47 - data_handler       [16.5/55.7 19.2/58.6 1.9Gb] tile #3/4: saving MS rows 2812320~4218479
 - 08:44:59 - data_handler       [17.9/55.7 20.6/58.6 1.9Gb]   7.84% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 08:45:20 - data_handler       [19.2/55.7 21.9/58.6 1.9Gb]   updated BITFLAG column (20.62% visibilities flagged)
 - 08:45:21 - data_handler       [19.2/55.7 21.9/58.6 1.9Gb]   updated BITFLAG_ROW column (7.12% rows flagged)
 - 08:45:24 - data_handler       [19.2/55.7 21.9/58.6 1.9Gb]   updated FLAG column (20.62% visibilities flagged)
 - 08:45:24 - data_handler       [19.2/55.7 21.9/58.6 1.9Gb]   updated FLAG_ROW column (7.12% rows flagged)
 - 08:45:25 - data_handler       [16.5/55.7 19.2/58.6 0.7Gb] tile #4/4: reading MS rows 4218480~4583690
 - 08:45:41 - data_handler       [22.4/55.7 25.8/58.6 0.7Gb]   applying solvable baseline cutoff deselects 46241 rows
 - 08:45:41 - data_handler       [22.4/55.7 25.8/58.6 0.7Gb]   12.66% visibilities deselected via specificed subset and/or baseline cutoffs
 - 08:45:52 - data_handler       [24.9/55.7 27.6/58.6 0.7Gb]   23.91% input visibilities flagged and/or deselected
 - 08:45:52 - data_handler       [24.9/55.7 27.6/58.6 0.7Gb]   rebinning into 91791 rows and 16 channels
 - 08:45:55 - data_handler       [22.2/55.7 25.1/58.6 0.8Gb]   reading MODEL_DATA for model 0 direction 0
 - 08:46:06 - data_handler       [22.2/55.7 25.1/58.6 0.9Gb]   reading DIR1 for model 0 direction 1
 - 08:46:18 - data_handler       [22.3/55.7 25.2/58.6 0.9Gb]   reading DIR2 for model 0 direction 2
 - 08:46:30 - data_handler       [22.4/55.7 25.2/58.6 0.9Gb]   reading DIR3 for model 0 direction 3
 - 08:46:42 - data_handler       [22.5/55.7 25.2/58.6 1.0Gb]   reading DIR4 for model 0 direction 4
 - 08:47:40 - solver             [20.0/55.7 22.7/58.6 1.0Gb] D0T3F0 G: 12 iters, conv 100.00%, g/fl 3.23%, PGE 0.0298; de: 20 iters, conv 0.00%, g/fl 4.19%, PGE 0.02 0.0981 0.0526 0.164 0.0612, NFPGE 0 0 0 7 0, stall 39.36%, chi^2 0.3354 -> 0.2204 (0.9461), noise 0.687 -> 0.231
 - 08:47:40 - solver             [20.0/55.7 22.7/58.6 1.0Gb] D0T3F0 solver flags GOOB:6(1.94%) GVAR:7(2.26%) : 269536 (9.32%) new data flags
 - 08:47:42 - data_handler       [17.9/55.7 20.6/58.6 1.0Gb] tile #4/4: saving MS rows 4218480~4583690
 - 08:47:46 - data_handler       [18.2/55.7 20.9/58.6 1.0Gb]   15.61% visibilities flagged by solver: saving to BITFLAG and FLAG columns
 - 08:47:51 - data_handler       [18.6/55.7 21.3/58.6 1.0Gb]   updated BITFLAG column (28.51% visibilities flagged)
 - 08:47:52 - data_handler       [18.6/55.7 21.3/58.6 1.0Gb]   updated BITFLAG_ROW column (13.60% rows flagged)
 - 08:47:53 - data_handler       [18.6/55.7 21.3/58.6 1.0Gb]   updated FLAG column (28.51% visibilities flagged)
 - 08:47:53 - data_handler       [18.6/55.7 21.3/58.6 1.0Gb]   updated FLAG_ROW column (13.60% rows flagged)
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] dimensions of G:gain are 1,17,1,62,2,2
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] dimensions of G:gain.err are 1,17,1,62,2,2
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] saved updated parameter skeletons to 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/G-field_0-ddid_None.parmdb.skel
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] previous DB will be backed up as 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/~G-field_0-ddid_None.parmdb
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   removing old backup 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/~G-field_0-ddid_None.parmdb
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] wrote 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/G-field_0-ddid_None.parmdb in fragmented mode
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] reading 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/G-field_0-ddid_None.parmdb in fragmented mode
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   loading G:gain, shape 1x17x1x62x2x2
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   loading G:gain.err, shape 1x17x1x62x2x2
 - 08:47:53 - casa_db_adaptor    [17.9/55.7 20.6/58.6 0.7Gb] Measurement metadata not set. Cannot write CASA-style gaintable.
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] dimensions of BBC are 16,62,62,2,2
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] saved updated parameter skeletons to 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/BBC-field_0-ddid_None.parmdb.skel
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] previous DB will be backed up as 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/~BBC-field_0-ddid_None.parmdb
 - 08:47:53 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   removing old backup 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/~BBC-field_0-ddid_None.parmdb
 - 08:47:54 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] wrote 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/BBC-field_0-ddid_None.parmdb in fragmented mode
 - 08:47:54 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] reading 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/BBC-field_0-ddid_None.parmdb in fragmented mode
 - 08:47:54 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   loading BBC, shape 16x62x62x2x2
 - 08:47:55 - casa_db_adaptor    [17.9/55.7 20.6/58.6 0.7Gb] Measurement metadata not set. Cannot write CASA-style gaintable.
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] dimensions of de:gain.err are 5,4,1,62,2,2
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] dimensions of de:gain are 5,4,1,62,2,2
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] saved updated parameter skeletons to 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/de-field_0-ddid_None.parmdb.skel
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] previous DB will be backed up as 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/~de-field_0-ddid_None.parmdb
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   removing old backup 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/~de-field_0-ddid_None.parmdb
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] wrote 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/de-field_0-ddid_None.parmdb in fragmented mode
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb] reading 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/de-field_0-ddid_None.parmdb in fragmented mode
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   loading de:gain.err, shape 5x4x1x62x2x2
 - 08:47:55 - param_db           [17.9/55.7 20.6/58.6 0.7Gb]   loading de:gain, shape 5x4x1x62x2x2
 - 08:47:55 - casa_db_adaptor    [17.9/55.7 20.6/58.6 0.7Gb] Measurement metadata not set. Cannot write CASA-style gaintable.
 - 08:47:55 - main               [17.9/55.7 20.6/58.6 0.7Gb] Time taken for solve only: 1874.31392884 seconds
 - 08:47:55 - main               [17.9/55.7 20.6/58.6 0.7Gb] Flagging stats: FLAG:25.56% legacy:15.84% cubical:3.95% IN:20.97% NEW:32.24% OUT:42.15%
 - 08:47:55 - main               [17.9/55.7 20.6/58.6 0.7Gb] computing summary statistics
 - 08:47:55 - main               [17.9/55.7 20.6/58.6 0.7Gb] saved summary statistics to cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.stats.pickle
 - 08:47:59 - plots              [17.9/55.7 20.7/58.6 0.7Gb] saved plot cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.noise.tf.png
 - 08:48:01 - plots              [18.0/55.7 20.7/58.6 0.7Gb] saved plot cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.chi2.tf.png
 - 08:48:03 - plots              [18.0/55.7 20.7/58.6 0.7Gb] saved plot cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.noise.antchan.png
 - 08:48:04 - plots              [18.0/55.7 20.7/58.6 0.7Gb] saved plot cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.chi2.antchan.png
 - 08:48:04 - param_db           [18.0/55.7 20.7/58.6 0.7Gb] reading 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms/BBC-field_0-ddid_None.parmdb in fragmented mode
 - 08:48:04 - param_db           [18.0/55.7 20.7/58.6 0.7Gb]   loading BBC, shape 16x62x62x2x2
 - 08:48:13 - plots              [18.0/55.7 20.7/58.6 0.7Gb] generating plots for suggested baseline-based corrections (BBCs)
 - 09:01:01 - plots              [18.4/55.7 21.1/58.6 0.7Gb] saved plot cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.bbc-diag.png
 - 09:05:50 - plots              [18.8/55.7 21.5/58.6 0.7Gb] saved plot cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24.bbc-diag-ant.png
 - 09:05:50 - main               [18.8/55.7 21.5/58.6 0.7Gb] completed successfully
IanHeywood commented 6 years ago

And the parset:

[data]
_Help = Visibility data options
ms = 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms
column = DATA
time-chunk = 720
freq-chunk = 256
rebin-time = 4
rebin-freq = 16
chunk-by = None
chunk-by-jump = 1.0
single-chunk = 

[sel]
_Help = Data selection options
field = 0
ddid = None
taql = 
chan = 

[model]
_Help = Calibration model options
list = MODEL_DATA:DIR1:DIR2:DIR3:DIR4
ddes = auto
beam-pattern = None
beam-l-axis = None
beam-m-axis = None

[montblanc]
_Help = Montblanc simulation options
device-type = CPU
dtype = float
feed-type = linear
mem-budget = 1024
verbosity = WARNING
threads = 0

[weight]
_Help = Weighting options
column = WEIGHT_SPECTRUM

[flags]
_Help = General flagging options
apply = -cubical
auto-init = legacy
save = cubical
save-legacy = auto
reinit-bitflags = False
warn-thr = 0.3
see-no-evil = False

[postmortem]
_Help = Options for "postmortem" flagging based on solution statistics
enable = False
tf-chisq-median = 1.2
tf-np-median = 0.5
time-density = 0.5
chan-density = 0.5
ddid-density = 0.5

[madmax]
_Help = Options for the "Mad Max" flagger
enable = False
estimate = corr
diag = True
offdiag = True
threshold = [0, 10]
global-threshold = [0]
plot = 1
plot-frac-above = 0.01

[sol]
_Help = Solution options which apply at the solver level
jones = ['G', 'dE']
precision = 32
delta-g = 1e-06
delta-chi = 1e-06
chi-int = 5
last-rites = True
stall-quorum = 0.99
diag-diag = False
term-iters = 
min-bl = 150.0
max-bl = 100000000.0
subset = 

[bbc]
_Help = Options for baseline-based corrections (a.k.a. BBCs, a.k.a. interferometer gains).
load-from = 
compute-2x2 = False
apply-2x2 = False
save-to = {data[ms]}/BBC-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
per-chan = True
plot = True

[dist]
_Help = Parallelization and distribution options
ncpu = 0
nworker = 0
nthread = 0
max-chunks = 1
min-chunks = 0
pin = 0
pin-io = False
pin-main = io

[out]
_Help = Options for output products
name = cube_dEcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc_1k.ms_2018-08-20-08-16-24
mode = so
column = CORRECTED_DATA
model-column = 
reinit-column = False
subtract-model = 0
subtract-dirs = :
plots = 1
casa-gaintables = False

[log]
_Help = Options related to logging
memory = True
boring = False
append = False
verbose = 0
file-verbose = None

[debug]
_Help = Debugging options for the discerning masochist
pdb = False
panic-amplitude = 0.0
stop-before-solver = False

[misc]
_Help = Miscellaneous options
random-seed = None
parset-version = 0.1

[JONES-TEMPLATE]
_Help = Options for {LABEL}-Jones term
_NameTemplate = {LABEL}
_ExpandedFrom = --sol-jones
_OtherTemplates = _Help:label
label = {LABEL}
solvable = True
type = complex-2x2
load-from = 
xfer-from = 
save-to = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
dd-term = False
fix-dirs = 
diag-diag = False
update-type = full
time-int = 1
freq-int = 1
max-prior-error = 0.1
max-post-error = 0.1
clip-low = 0.1
clip-high = 10.0
clip-after = 5
max-iter = 20
conv-quorum = 0.99
ref-ant = None
prop-flags = default

[g]
_Help = Options for G-Jones term
label = G
solvable = True
type = complex-2x2
load-from = 
xfer-from = 
save-to = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
dd-term = 0
fix-dirs = 
diag-diag = False
update-type = full
time-int = 40
freq-int = 256
max-prior-error = 0.1
max-post-error = 0.1
clip-low = 0.8
clip-high = 1.2
clip-after = 5
max-iter = 20
conv-quorum = 0.99
ref-ant = None
prop-flags = default
_Templated = True

[de]
_Help = Options for G-Jones term
label = de
solvable = True
type = complex-2x2
load-from = 
xfer-from = 
save-to = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
dd-term = 1
fix-dirs = 0
diag-diag = False
update-type = full
time-int = 720
freq-int = 256
max-prior-error = 0.1
max-post-error = 0.1
clip-low = 0.1
clip-high = 10.0
clip-after = 5
max-iter = 20
conv-quorum = 0.99
ref-ant = None
prop-flags = default
_Templated = True
IanHeywood commented 6 years ago
Processing a MS with 2347 unique timeslots, 1024 channels.

I am an idiot, Part 12,258. I've averaged this twice somehow, 256 channels is correct.

o-smirnov commented 6 years ago

OK, this line suggests it's thinking there's only 256 channels in the MS to begin with:

 - 08:16:27 - data_handler       [0.1/0.1 2.8/2.8 0.7Gb]   DDID 0: 256/256 selected channels will be rebinned into 16 channels

Then: looking at the code, I can see that time-int and freq-int is interpreted in terms of rebinned timeslots and channels rather than original ones. I don't remember the rationale for this or whether there even was one, but if this is tripping you up, we should consider changing this behaviour. What do you reckon? (Note that it can also be specified with physical units of seconds/minutes and k/MHz).

So, 256 channels rebinned by 16 gives you 16 channels, so only a single interval.

720 timeslots rebinned by 4 gives you 180 timeslots. With time-int 40 this is 5 intervals per full chunk (4.5 actually, but intervals are always terminated at a chunk boundary, so it ends up with 5). Thus the first three time chunks yield 5 intervals each, while the last chunk only has 184 original timeslots, thus 46 rebinned timeslots, thus 2 intervals. So 17 G intervals in total.

Your dE time interval is >= chunk size, so 1 dE per time chunk, so 4 in total.

So the numbers make sense using CubiCal's current interval interpretation. Question stands whether this is the right one from a user's point of view.

A further question: why do I have solutions for five directions in the dE when I have --de-fix-dirs = 0?

The solution saving code doesn't know about fix-dirs, so it writes a unity for direction 0. This can be easily fixed though.

o-smirnov commented 6 years ago

The solution saving code doesn't know about fix-dirs, so it writes a unity for direction 0. This can be easily fixed though.

Not sure it should be fixed though... would it be better to have as many dEs as directions in the database, nominally, even if some are non-solvable?

IanHeywood commented 6 years ago

Then: looking at the code, I can see that time-int and freq-int is interpreted in terms of rebinned timeslots and channels rather than original ones.

OK, this makes sense. Personally I'd prefer it if the rebinning was as 'hidden' as possible, and everything was considered in terms of the native time / freq resolution of the MS, but since I don't even know how many channels my MS has I'm not sure I'm the best person to listen to. As long as I know what the behaviour is then it's fine to leave it as far as I'm concerned.

Note that it can also be specified with physical units of seconds/minutes and k/MHz

This is great though. I should try to move to that. It's MeqTrees that has conditioned me otherwise! :)

IanHeywood commented 6 years ago

Not sure it should be fixed though... would it be better to have as many dEs as directions in the database, nominally, even if some are non-solvable?

I agree, and I wasn't thrown by the direction being there, but that is actually seems to contain solutions that aren't unity.

diffgains

Anyway, I'll tear this down and start again now that I'm enlightened.

Cheers. 👍

EDIT: Typo

o-smirnov commented 6 years ago

I agree, and I wasn't thrown by the direction being there, but that is actually seems to contain solutions that aren't unity.

Now that would indicate a bug! Please post if you keep seeing this on your restart.

IanHeywood commented 6 years ago

Urgh, am now in segfault town every time it starts on tile 2. Doesn't seem to be doing anything close to the edge in terms of memory consumption.

[71.9/120.8 94.3/148.9 76.1Gb]
o-smirnov commented 6 years ago

Can has MS?

IanHeywood commented 6 years ago

It's completed on a different IDIA node. Go figure. Will report back on this later today.

IanHeywood commented 6 years ago

Think am done with radio astronomy.

 - 08:22:30 - data_handler       [14.8/17.5 36.0/36.0 8.5Gb]   reading MODEL_DATA for model 0 direction 0
 - 08:22:48 - data_handler       [22.0/22.0 39.5/43.1 12.1Gb]   reading DIR1 for model 0 direction 1
 - 08:23:08 - data_handler       [29.2/29.2 43.1/46.7 15.7Gb]   reading DIR2 for model 0 direction 2
 - 08:23:26 - data_handler       [36.3/36.3 46.7/50.3 19.3Gb]   reading DIR3 for model 0 direction 3
 - 08:23:43 - data_handler       [43.5/43.5 50.3/53.8 22.8Gb]   reading DIR4 for model 0 direction 4
 - 08:26:58 - gain_machine       [54.2/79.8 57.3/83.1 26.4Gb] D0T0F0: interpolating G:gain from 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc.ms/G-field_0-ddid_None.parmdb
 - 08:27:00 - gain_machine       [54.4/79.8 57.4/83.1 26.4Gb] D0T0F0: 39.38% valid G:gain slots populated
 - 08:27:00 - gain_machine       [54.3/79.8 57.3/83.1 26.4Gb] D0T0F0: interpolating de:gain from 1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc.ms/de-field_0-ddid_None.parmdb
 - 08:27:02 - solver             [54.8/79.8 57.9/83.1 26.4Gb] Solver for tile 0 chunk D0T0F0 failed with exception: QH6229 qhull precision error: 101 attempts to construct a convex hull
        with joggled input.  Increase joggle above 'QJ3.3e-11'
        or modify qh_JOGGLE... parameters in user.h

While executing:  | qhull d Qbb Qz QJ Qc Q12
Options selected for Qhull 2015.2.r 2016/01/18:
  run-id 605496202  delaunay  Qbbound-last  Qz-infinity-point  Qcoplanar-keep
  Q12-no-wide-dup  Qinterior-keep  Pgood
  _run 101  QJoggle 3.3e-11  _joggle-seed 1034823503  _max-width 4.9e-11
  Error-roundoff 1.1e-15  _near-inside 1.1e-10  Width-outside 2.2e-15
  _wide-facet 6.6e-15

At error exit:

At a premature exit due to 'TVn', 'TCn', 'TRn', or precision error with 'QJn'.
Delaunay triangulation by the convex hull of 5 points in 3-d:

  Number of input sites and at-infinity: 4
  Total number of nearly incident points: 1
  Number of Delaunay regions: 0

Statistics for:  | qhull d Qbb Qz QJ Qc Q12

  Number of points processed: 0
  Number of hyperplanes created: 505
  Number of facets in hull: 4
  Number of distance tests for qhull: 101
  After 101 retries, input joggled by: 3.3e-11

precision problems (corrected unless 'Q0' or an error)
    101 flipped facets

 - 08:27:02 - solver             [54.8/79.8 57.9/83.1 26.4Gb] Traceback (most recent call last):
  File "/users/ianh/Software/CubiCal/cubical/solver.py", line 774, in run_solver
    vdm.gm = gm_factory.create_machine(vdm.weighted_obser, n_dir, n_mod, chunk_ts, chunk_fs, label)
  File "/users/ianh/Software/CubiCal/cubical/machines/abstract_machine.py", line 816, in create_machine
    gm._load_solutions(self._init_sols)
  File "/users/ianh/Software/CubiCal/cubical/machines/jones_chain_machine.py", line 147, in _load_solutions
    term._load_solutions(init_sols)
  File "/users/ianh/Software/CubiCal/cubical/machines/abstract_machine.py", line 544, in _load_solutions
    sols[label] = sol = db[name].reinterpolate(**grids)
  File "/users/ianh/Software/CubiCal/cubical/database/parameter.py", line 591, in reinterpolate
    triang = scipy.spatial.Delaunay(meshgrids, qhull_options=qhull_options)
  File "qhull.pyx", line 1826, in scipy.spatial.qhull.Delaunay.__init__
  File "qhull.pyx", line 354, in scipy.spatial.qhull._Qhull.__init__
QhullError: QH6229 qhull precision error: 101 attempts to construct a convex hull
        with joggled input.  Increase joggle above 'QJ3.3e-11'
        or modify qh_JOGGLE... parameters in user.h

While executing:  | qhull d Qbb Qz QJ Qc Q12
Options selected for Qhull 2015.2.r 2016/01/18:
  run-id 605496202  delaunay  Qbbound-last  Qz-infinity-point  Qcoplanar-keep
  Q12-no-wide-dup  Qinterior-keep  Pgood
  _run 101  QJoggle 3.3e-11  _joggle-seed 1034823503  _max-width 4.9e-11
  Error-roundoff 1.1e-15  _near-inside 1.1e-10  Width-outside 2.2e-15
  _wide-facet 6.6e-15

At error exit:

At a premature exit due to 'TVn', 'TCn', 'TRn', or precision error with 'QJn'.
Delaunay triangulation by the convex hull of 5 points in 3-d:

  Number of input sites and at-infinity: 4
  Total number of nearly incident points: 1
  Number of Delaunay regions: 0

Statistics for:  | qhull d Qbb Qz QJ Qc Q12

  Number of points processed: 0
  Number of hyperplanes created: 505
  Number of facets in hull: 4
  Number of distance tests for qhull: 101
  After 101 retries, input joggled by: 3.3e-11

precision problems (corrected unless 'Q0' or an error)
    101 flipped facets
 - 08:27:02 - main               [54.8/79.8 57.9/83.1 26.4Gb] Exiting with exception: QhullError(QH6229 qhull precision error: 101 attempts to construct a convex hull
        with joggled input.  Increase joggle above 'QJ3.3e-11'
        or modify qh_JOGGLE... parameters in user.h

While executing:  | qhull d Qbb Qz QJ Qc Q12
Options selected for Qhull 2015.2.r 2016/01/18:
  run-id 605496202  delaunay  Qbbound-last  Qz-infinity-point  Qcoplanar-keep
  Q12-no-wide-dup  Qinterior-keep  Pgood
  _run 101  QJoggle 3.3e-11  _joggle-seed 1034823503  _max-width 4.9e-11
  Error-roundoff 1.1e-15  _near-inside 1.1e-10  Width-outside 2.2e-15
  _wide-facet 6.6e-15

At error exit:

At a premature exit due to 'TVn', 'TCn', 'TRn', or precision error with 'QJn'.
Delaunay triangulation by the convex hull of 5 points in 3-d:

  Number of input sites and at-infinity: 4
  Total number of nearly incident points: 1
  Number of Delaunay regions: 0

Statistics for:  | qhull d Qbb Qz QJ Qc Q12

  Number of points processed: 0
  Number of hyperplanes created: 505
  Number of facets in hull: 4
  Number of distance tests for qhull: 101
  After 101 retries, input joggled by: 3.3e-11

precision problems (corrected unless 'Q0' or an error)
    101 flipped facets
)
 Traceback (most recent call last):
  File "/users/ianh/Software/CubiCal/cubical/main.py", line 360, in main
    stats_dict = workers.run_process_loop(ms, tile_list, load_model, single_chunk, solver_type, solver_opts, debug_opts)
  File "/users/ianh/Software/CubiCal/cubical/workers.py", line 207, in run_process_loop
    return _run_single_process_loop(ms, load_model, single_chunk, solver_type, solver_opts, debug_opts)
  File "/users/ianh/Software/CubiCal/cubical/workers.py", line 322, in _run_single_process_loop
    solver.run_solver(solver_type, itile, key, solver_opts, debug_opts)
  File "/users/ianh/Software/CubiCal/cubical/solver.py", line 774, in run_solver
    vdm.gm = gm_factory.create_machine(vdm.weighted_obser, n_dir, n_mod, chunk_ts, chunk_fs, label)
  File "/users/ianh/Software/CubiCal/cubical/machines/abstract_machine.py", line 816, in create_machine
    gm._load_solutions(self._init_sols)
  File "/users/ianh/Software/CubiCal/cubical/machines/jones_chain_machine.py", line 147, in _load_solutions
    term._load_solutions(init_sols)
  File "/users/ianh/Software/CubiCal/cubical/machines/abstract_machine.py", line 544, in _load_solutions
    sols[label] = sol = db[name].reinterpolate(**grids)
  File "/users/ianh/Software/CubiCal/cubical/database/parameter.py", line 591, in reinterpolate
    triang = scipy.spatial.Delaunay(meshgrids, qhull_options=qhull_options)
  File "qhull.pyx", line 1826, in scipy.spatial.qhull.Delaunay.__init__
  File "qhull.pyx", line 354, in scipy.spatial.qhull._Qhull.__init__
QhullError: QH6229 qhull precision error: 101 attempts to construct a convex hull
        with joggled input.  Increase joggle above 'QJ3.3e-11'
        or modify qh_JOGGLE... parameters in user.h

While executing:  | qhull d Qbb Qz QJ Qc Q12
Options selected for Qhull 2015.2.r 2016/01/18:
  run-id 605496202  delaunay  Qbbound-last  Qz-infinity-point  Qcoplanar-keep
  Q12-no-wide-dup  Qinterior-keep  Pgood
  _run 101  QJoggle 3.3e-11  _joggle-seed 1034823503  _max-width 4.9e-11
  Error-roundoff 1.1e-15  _near-inside 1.1e-10  Width-outside 2.2e-15
  _wide-facet 6.6e-15

At error exit:

At a premature exit due to 'TVn', 'TCn', 'TRn', or precision error with 'QJn'.
Delaunay triangulation by the convex hull of 5 points in 3-d:

  Number of input sites and at-infinity: 4
  Total number of nearly incident points: 1
  Number of Delaunay regions: 0

Statistics for:  | qhull d Qbb Qz QJ Qc Q12

  Number of points processed: 0
  Number of hyperplanes created: 505
  Number of facets in hull: 4
  Number of distance tests for qhull: 101
  After 101 retries, input joggled by: 3.3e-11

precision problems (corrected unless 'Q0' or an error)
    101 flipped facets
IanHeywood commented 6 years ago

Does the interpolation rely on there being valid solutions within the time/freq interval of the currently loaded tile?

o-smirnov commented 6 years ago

No, it reads the whole database, not just per tile. But you're on the right track: that error is surely due to some unusual configuration of missing solutions. I haven't seen it before... Can you copy the ms and solutions DB somewhere?

On Mon, 27 Aug 2018, 10:33 Ian Heywood, notifications@github.com wrote:

Does the interpolation rely on there being valid solutions within the time/freq interval of the currently loaded tile?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/ratt-ru/CubiCal/issues/211#issuecomment-416155597, or mute the thread https://github.com/notifications/unsubscribe-auth/AGK5vwboa3Lot0rrStHfeAqKnTm4fYMTks5uU67ggaJpZM4WIcWZ .

IanHeywood commented 6 years ago

Will do. Need to diagnose and undo the current state of the flags first though, perhaps it's related to this:

Feel like I've just come full circle somehow.

o-smirnov commented 6 years ago

Bet you a bottle it's related. Two things then:

IanHeywood commented 6 years ago
 - 02:39:21 - main               [70.3/155.0 73.1/200.6 2.3Gb] Flagging stats: FLAG:94.35% legacy:94.35% cubical:0.00% DESEL:9.85% IN:95.01% NEW:6.22% OUT:96.83%

The run of CASA's flagdata task (rflag on defaults) certainly doesn't do that much damage, and the flagging chunks are the same size in time/freq as my cubical intervals, so I'm assuming this is all down to a butchered BITFLAG column.

I tried this snippet to revert the flags to legacy only, but the end result was the removal of all flags.

bf = tab.getcol("BITFLAG")
tab.putcol("FLAG", (bf&1)!=0)
bf = tab.getcol("BITFLAG_ROW")
tab.putcol("FLAG_ROW", (bf&1)!=0)

I've run rflag again and am now running CubiCal with --flags-reinit-bitflags set to True.

IanHeywood commented 6 years ago
That overflagging nonsense better not be coming from CubiCal -- I've tried to eradicate such cases. Could you check the flag statistics of your cubical runs?

OK, let me know what you make of this lot.

I tore all this down and started again. I re-split the target MS, no fancy dE stuff, no on-the-fly averaging, just predicting a model and solving for phases.

Note that I haven't put the FLAG_ROW logic into this plotting script yet (as we discussed elsewhere), but here's a time-frequency plot of a baseline showing the DATA column of a particular baseline at the starting point:

1529209968_sdp_l0_1284 full_pol_fg_wtspec_47tuc ms_baseline_0_36_field0_amp

Here's the corresponding plot showing the MODEL_DATA column which, differences in pixel scales aside, looks pretty good to me:

1529209968_sdp_l0_1284 full_pol_fg_wtspec_47tuc ms_baseline_0_36_field0_amp

I proceed to solve for phases, with the default flagging settings:

[flags]
_Help = General flagging options
apply = -cubical
auto-init = legacy
save = cubical
save-legacy = auto
reinit-bitflags = False
warn-thr = 0.3
see-no-evil = False

and madmax enabled but just pretending:

[madmax]
_Help = Options for the "Mad Max" flagger
enable = pretend
estimate = corr
diag = True
offdiag = True
threshold = [0, 10]
global-threshold = [0]
plot = 1
plot-frac-above = 0.01

My G-term setup is normal, apart from being phase-only. The clip levels are defaults but I believe shouldn't affect anything anyway since this is a phase-only solve:

[g]
_Help = Options for G-Jones term
label = G
solvable = True
type = phase-diag
load-from =
xfer-from =
save-to = {data[ms]}/{JONES}-field_{sel[field]}-ddid_{sel[ddid]}.parmdb
dd-term = 0
fix-dirs =
diag-diag = False
update-type = full
time-int = 16
freq-int = 1024
max-prior-error = 0.1
max-post-error = 0.1
clip-low = 0.1
clip-high = 10.0
clip-after = 5
max-iter = 20
conv-quorum = 0.99
ref-ant = None
prop-flags = default
_Templated = True

And here's the CORRECTED_DATA column of the baseline plotted above, following calibration:

1529209968_sdp_l0_1284 full_pol_fg_wtspec_47tuc ms_baseline_0_36_field0_amp

So something has butchered the flags here, and I don't know what. It's actually worse than these plots show, the observation has 62 antennas and following phase calibration all baselines to 30 of them are flagged completely.

$ grep Flagging cube_pcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc.ms_2018-08-30-19-03-05.log
 - 11:20:32 - main               [72.2/140.5 74.5/143.7 2.3Gb] Flagging stats: FLAG:24.48% legacy:24.48% cubical:0.00% DESEL:9.85% IN:28.93% NEW:87.11% OUT:90.65%
> grep Pretend cube_pcal_1529209968_sdp_l0_1284.full_pol_fg_wtspec_47Tuc.ms_2018-08-30-19-03-05.log
 - 19:24:01 - solver             [50.5/61.8 53.8/66.0 20.6Gb] WARNING: D0T0F0 solver flags GVAR:134(54.03%), Pretend-Mad Max took out 2562706 visibilities: 191187768 (75.89%) new data flags
 - 19:46:55 - solver             [38.9/73.1 42.1/76.6 24.7Gb] WARNING: D0T1F0 solver flags GVAR:98(52.69%), Pretend-Mad Max took out 2770356 visibilities: 141484516 (74.88%) new data flags
 - 20:13:54 - solver             [54.2/73.1 57.3/76.6 20.9Gb] WARNING: D0T2F0 solver flags GVAR:133(53.63%), Pretend-Mad Max took out 3898304 visibilities: 190727570 (75.71%) new data flags
 - 20:36:31 - solver             [42.7/77.0 45.7/80.2 24.9Gb] WARNING: D0T3F0 solver flags GVAR:105(56.45%), Pretend-Mad Max took out 3205970 visibilities: 147576030 (78.11%) new data flags
 - 21:03:28 - solver             [57.6/77.0 60.7/80.2 20.9Gb] WARNING: D0T4F0 solver flags GVAR:138(55.65%), Pretend-Mad Max took out 4075448 visibilities: 195211428 (77.49%) new data flags
 - 21:26:36 - solver             [46.0/80.3 49.1/83.6 24.9Gb] WARNING: D0T5F0 solver flags GVAR:103(55.38%), Pretend-Mad Max took out 2990788 visibilities: 146001462 (77.27%) new data flags
 - 21:48:07 - solver             [60.9/80.3 64.0/83.6 20.7Gb] WARNING: D0T6F0 solver flags GVAR:138(55.65%), Pretend-Mad Max took out 2943942 visibilities: 196429592 (77.97%) new data flags
 - 22:05:17 - solver             [48.5/83.6 51.6/86.9 24.8Gb] WARNING: D0T7F0 solver flags GVAR:106(56.99%), Pretend-Mad Max took out 2385722 visibilities: 146231694 (79.04%) new data flags
 - 22:32:48 - solver             [64.3/83.6 67.3/86.9 20.9Gb] WARNING: D0T8F0 solver flags GVAR:140(56.45%), Pretend-Mad Max took out 5464150 visibilities: 197496360 (78.40%) new data flags
 - 22:50:21 - solver             [52.7/87.0 55.7/90.2 24.9Gb] WARNING: D0T9F0 solver flags GVAR:103(55.38%), Pretend-Mad Max took out 2548536 visibilities: 146443186 (77.51%) new data flags
 - 23:17:47 - solver             [67.6/87.0 70.7/90.2 20.9Gb] WARNING: D0T10F0 solver flags GVAR:142(57.26%), Pretend-Mad Max took out 5258952 visibilities: 198517038 (78.80%) new data flags
 - 23:40:51 - solver             [56.1/90.4 59.1/93.6 24.9Gb] WARNING: D0T11F0 solver flags GVAR:105(56.45%), Pretend-Mad Max took out 3970028 visibilities: 147645974 (78.14%) new data flags
 - 00:08:14 - solver             [71.0/90.4 74.1/93.6 20.9Gb] WARNING: D0T12F0 solver flags GVAR:140(56.45%), Pretend-Mad Max took out 4055286 visibilities: 196483888 (77.99%) new data flags
 - 00:31:13 - solver             [59.4/93.7 62.5/96.9 24.9Gb] WARNING: D0T13F0 solver flags GVAR:107(57.53%), Pretend-Mad Max took out 2859174 visibilities: 148977428 (78.85%) new data flags
 - 00:58:22 - solver             [74.4/93.7 77.4/96.9 20.9Gb] WARNING: D0T14F0 solver flags GVAR:148(59.68%), Pretend-Mad Max took out 3928898 visibilities: 202692300 (80.46%) new data flags
 - 01:21:02 - solver             [62.8/97.1 65.8/100.3 24.9Gb] WARNING: D0T15F0 solver flags GVAR:109(58.60%), Pretend-Mad Max took out 3226412 visibilities: 150686284 (79.75%) new data flags
 - 01:48:11 - solver             [77.7/97.1 80.8/100.3 20.9Gb] WARNING: D0T16F0 solver flags GVAR:151(60.89%), Pretend-Mad Max took out 4333698 visibilities: 204630606 (81.23%) new data flags
 - 02:09:50 - solver             [66.1/100.4 69.2/103.6 24.9Gb] WARNING: D0T17F0 solver flags GVAR:114(61.29%), Pretend-Mad Max took out 3490666 visibilities: 153986426 (81.50%) new data flags
 - 02:35:28 - solver             [81.1/100.4 84.1/103.6 20.7Gb] WARNING: D0T18F0 solver flags GVAR:148(59.68%), Pretend-Mad Max took out 4443228 visibilities: 201686426 (80.06%) new data flags
 - 02:56:22 - solver             [68.8/103.9 71.8/107.0 24.8Gb] WARNING: D0T19F0 solver flags GVAR:123(66.13%), Pretend-Mad Max took out 3228054 visibilities: 156200988 (84.43%) new data flags
 - 03:21:52 - solver             [84.4/103.9 87.4/107.0 20.7Gb] WARNING: D0T20F0 solver flags GVAR:161(64.92%), Pretend-Mad Max took out 4248368 visibilities: 211144116 (83.81%) new data flags
 - 03:42:56 - solver             [72.1/107.1 75.0/110.3 24.8Gb] WARNING: D0T21F0 solver flags GVAR:123(66.13%), Pretend-Mad Max took out 3214536 visibilities: 156106176 (84.38%) new data flags
 - 04:08:32 - solver             [87.6/107.1 90.7/110.3 20.9Gb] WARNING: D0T22F0 solver flags GVAR:159(64.11%), Pretend-Mad Max took out 4196344 visibilities: 209334956 (83.10%) new data flags
 - 04:30:05 - solver             [76.0/110.4 79.1/113.6 24.9Gb] WARNING: D0T23F0 solver flags GVAR:120(64.52%), Pretend-Mad Max took out 3169238 visibilities: 157541474 (83.38%) new data flags
 - 04:56:12 - solver             [91.0/110.4 94.1/113.6 20.9Gb] WARNING: D0T24F0 solver flags GVAR:166(66.94%), Pretend-Mad Max took out 4043942 visibilities: 213792590 (84.87%) new data flags
 - 05:18:01 - solver             [79.4/113.7 82.5/117.0 24.9Gb] WARNING: D0T25F0 solver flags GVAR:126(67.74%), Pretend-Mad Max took out 3005144 visibilities: 161353710 (85.40%) new data flags
 - 05:44:44 - solver             [94.3/113.7 97.4/117.0 20.7Gb] WARNING: D0T26F0 solver flags GVAR:167(67.34%), Pretend-Mad Max took out 4502612 visibilities: 214223124 (85.04%) new data flags
 - 06:05:55 - solver             [82.0/117.0 85.1/120.3 24.8Gb] WARNING: D0T27F0 solver flags GVAR:133(71.51%), Pretend-Mad Max took out 3279778 visibilities: 161517290 (87.30%) new data flags
 - 06:26:00 - solver             [97.6/117.0 100.8/120.3 20.9Gb] WARNING: D0T28F0 solver flags GVAR:176(70.97%), Pretend-Mad Max took out 3112818 visibilities: 218627626 (86.78%) new data flags
 - 06:47:28 - solver             [86.0/120.4 89.1/123.6 24.9Gb] WARNING: D0T29F0 solver flags GVAR:133(71.51%), Pretend-Mad Max took out 3485768 visibilities: 164514716 (87.07%) new data flags
 - 07:12:53 - solver             [100.9/120.4 104.1/123.6 20.9Gb] WARNING: D0T30F0 solver flags GVAR:180(72.58%), Pretend-Mad Max took out 4268740 visibilities: 220822446 (87.66%) new data flags
 - 07:34:02 - solver             [89.4/123.7 92.5/127.0 25.0Gb] WARNING: D0T31F0 solver flags GVAR:131(70.43%), Pretend-Mad Max took out 3055834 visibilities: 163221174 (86.39%) new data flags
 - 07:54:17 - solver             [104.2/123.7 107.4/127.0 20.9Gb] WARNING: D0T32F0 solver flags GVAR:179(72.18%), Pretend-Mad Max took out 2688338 visibilities: 218902144 (86.89%) new data flags
 - 08:15:49 - solver             [92.7/127.0 95.8/130.3 25.0Gb] WARNING: D0T33F0 solver flags GVAR:126(67.74%), Pretend-Mad Max took out 2997030 visibilities: 159645892 (84.50%) new data flags
 - 08:41:39 - solver             [107.6/127.0 110.8/130.3 20.9Gb] WARNING: D0T34F0 solver flags GVAR:179(72.18%), Pretend-Mad Max took out 4083088 visibilities: 218805496 (86.86%) new data flags
 - 09:03:01 - solver             [96.0/130.4 99.2/133.7 25.0Gb] WARNING: D0T35F0 solver flags GVAR:131(70.43%), Pretend-Mad Max took out 2902468 visibilities: 162297142 (85.90%) new data flags
 - 09:22:49 - solver             [111.0/130.4 114.1/133.7 20.9Gb] WARNING: D0T36F0 solver flags GVAR:170(68.55%), Pretend-Mad Max took out 2337988 visibilities: 213327252 (84.68%) new data flags
 - 09:44:15 - solver             [99.5/133.8 102.5/137.0 25.0Gb] WARNING: D0T37F0 solver flags GVAR:128(68.82%), Pretend-Mad Max took out 2597126 visibilities: 160182084 (84.78%) new data flags
 - 10:09:55 - solver             [114.4/133.8 117.5/137.0 20.9Gb] WARNING: D0T38F0 solver flags GVAR:169(68.15%), Pretend-Mad Max took out 5244220 visibilities: 211206374 (83.84%) new data flags
 - 10:31:50 - solver             [102.8/137.1 105.9/140.4 25.0Gb] WARNING: D0T39F0 solver flags GVAR:138(74.19%), Pretend-Mad Max took out 4340450 visibilities: 164609260 (87.12%) new data flags
 - 10:57:31 - solver             [117.7/137.1 120.8/140.4 20.8Gb] WARNING: D0T40F0 solver flags GVAR:185(74.60%), Pretend-Mad Max took out 3793008 visibilities: 219258000 (87.03%) new data flags
 - 11:18:41 - solver             [105.4/140.5 108.5/143.7 24.8Gb] WARNING: D0T41F0 solver flags GVAR:141(75.81%), Pretend-Mad Max took out 2203874 visibilities: 161628342 (87.36%) new data flags

It looks like madmax has tried to do this level of flagging from these warnings, but I thought the pretend mode did just that.

o-smirnov commented 6 years ago

Hmmm, reviewing the code, pretend-mad really should be pretend-mad and not really flagging, even if the message itself looks misleadingly fearsome (which is something I need to fix...) Also if you look at the numbers, "Pretend-Mad Max took out 2203874 visibilities" ... "161628342 new data flags"... suggests the flags it pretend-raised are still a relatively small fraction of the total...

I see you had --madmax-plot 1, great, could you post up some of the madmax plots? I'd like to see if it's pretending to do anything sensible.

I'll bet this is the real culprit: GVAR:141(75.81%). That's the solver flagging solutions on excessive variance. Set --g-max-posterior-error and --g-max-prior-error to something stupidly high to disable this. But, why is it so high in the first place? Is your amplitude significantly off?

o-smirnov commented 6 years ago

Also, at least your BITFLAG column should be OK now -- just don't reinit it!

IanHeywood commented 6 years ago
Set --g-max-posterior-error and --g-max-prior-error to something stupidly high to disable this.

Re-running now.

Is your amplitude significantly off?

In the model? I'd be surprised, it's just a clean component model derived from a wsclean run with masking. Not sure why this approach would suddenly start causing trouble when it's worked fine in the past (even on this very data set).

I'm on the latest master branch here, for the record.

o-smirnov commented 6 years ago

Can I see the MS?

IanHeywood commented 6 years ago

I made the following changes:

max-prior-error = 1000000
max-post-error = 1000000

and re-ran the phase calibration. Here's the corresponding baseline plot:

1529209968_sdp_l0_1284 full_pol_fg_wtspec_47tuc ms_baseline_0_36_field0_amp

o-smirnov commented 6 years ago

That looks... dark? OK, I'm stumped, can you copy the MS somewhere?

IanHeywood commented 6 years ago

Should I hardwrite the current flags? I think it would compress nicely for a quick transfer.

Only kidding, it's on its way.

Here's the final flag summary:

 - 14:50:22 - main               [72.1/132.6 74.3/135.8 2.4Gb] Flagging stats: FLAG:20.27% legacy:20.27% cubical:0.00% DESEL:9.85% IN:25.04% NEW:99.84% OUT:100.00%
o-smirnov commented 6 years ago

legacy:20% well at least the bitflag column is all right now, we've got something to fall back to.

o-smirnov commented 6 years ago

P.S. Pull over a copy of the logs as well please.

IanHeywood commented 6 years ago

You've got mail.

Here are a few plots from madmax, as requested. These are from the first run on 30 August. None of this looks particularly wild to me.

d0t0f0 0

d0t2f0 9

d0t4f0 0

d0t0f0 2 mads

d0t0f0 5 mads

d0t5f0 2 mads

Note that the second run that seemed to flag everything didn't produce any madmax output, despite being enabled in pretend mode.

I can provide the entire output from the above if you're interested.

Cheers.