Streak detection may cause long measurement runtimes in characterize image

Support
#1

This is for weekly w_2024_09 and DECam images.

During some processing, I noticed that a single quanta for characterize image task took hours to complete instead of <1 minute. I investigated and found it coincided with maskStreaks masking 100% of the image as a streak:

INFO 2024-04-02T23:13:41.243-07:00 lsst.characterizeImage.maskStreaks (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995894, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(maskStreaks.py:785) - 1 streak(s) fit, with 8388608 pixels masked (100.00% of image)
INFO 2024-04-02T23:13:41.812-07:00 lsst.characterizeImage.measurement (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995894, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(sfm.py:293) - Measuring 624 sources (624 parents, 0 children) 
VERBOSE 2024-04-03T00:22:51.753-07:00 lsst.characterizeImage.measurement (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995894, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(sfm.py:329) - Measurement complete for 615 parents (and their children) out of 624
INFO 2024-04-03T00:22:52.147-07:00 lsst.characterizeImage.measureApCorr (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995894, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(measureApCorr.py:200) - Measuring aperture corrections for 31 flux fields

Looking at the timestamps, the subsequent measurement tasks takes an hour.

I looked at the processing logs for the next exposure in the sequence for the same detector (it was taken two minutes later of the same field) and saw that there was no issue with the runtime and no streaks were masked:

INFO 2024-04-02T20:46:48.497-07:00 lsst.characterizeImage.maskStreaks (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995895, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(maskStreaks.py:785) - 0 streak(s) fit, with 0 pixels masked (0.00% of image)
INFO 2024-04-02T20:46:49.028-07:00 lsst.characterizeImage.measurement (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995895, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(sfm.py:293) - Measuring 113 sources (113 parents, 0 children) 
INFO 2024-04-02T20:46:59.363-07:00 lsst.characterizeImage.measureApCorr (characterizeImage:{instrument: 'DECam', detector: 44, visit: 995895, band: 'VR', physical_filter: 'VR DECam c0007 6300.0 2600.0'})(measureApCorr.py:200) - Measuring aperture corrections for 31 flux fields

(Also I have no idea why a VERBOSE log prints on measurement completion for one vs the other.)

I re-ran the same task to see if this was some transient computing effect, but I reproduced the behavior for both exposures.

The streak detection fitting 100% of the pixels seems like an artifact of bad fitting. I looked at the exposures in ds9 and saw no obvious artifacts that would cause this in either image.

I’ll upload the logs here.
long_characterizeImage_995894_44.stderr (31.9 KB)
short_characterizeImage_995895_44.stderr (21.6 KB)

#2

It looks like SingleFrameMeasurement has a periodic logger, and the measurement took long enough for a log to be printed: meas_base/python/lsst/meas/base/sfm.py at w.2024.09 · lsst/meas_base · GitHub

#3

Yes, we have found similar issues with streak masking in single frame measurement. We are in the process of moving streak masking to run on the difference image instead, to avoid this problem.

#4

Hi,

I also noticed this issue when running the ci_hsc_gen3 pipeline: in some conditions, for some detectors, the characterizeImage task takes one hour to run instead of few minutes. In my case this does not seem to be correlated with the streak masking.

However I noticed that although the task was launched with pipetask -j 1, many threads were launched, which could cause some contention on the sqlite database. Is there some multithreading implemented somehow in the characterizeImage task?

#5

To be more precise it get “stuck” between these two lines:

DEBUG 2024-05-06T14:51:29.076+02:00 lsst.meas.extensions.shapeHSM._hsm_moments (characterizeImage:{instrument: 'HSC', detector: 100, visit: 903986, band: 'i', physical_filter: 'HSC-I'})(_hsm_moments.py:196) - Failed
 to measure shape for 388259245352550556 at (1897.999368, 3729.997096): Error: HSM collapsed to singular moment matrix. Object is too small.

DEBUG 2024-05-06T15:05:15.578+02:00 lsst.characterizeImage.measurement.ext_shapeHSM_HsmSourceMomentsRound (characterizeImage:{instrument: 'HSC', detector: 100, visit: 903986, band: 'i', physical_filter: 'HSC-I'})(ba
seMeasurement.py:391) - MeasurementError in ext_shapeHSM_HsmSourceMomentsRound.measure on record 388259245352550556: Warning: too many iterations in find_mom_2.