Streak detection may cause long measurement runtimes in characterize image

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)

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

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.