New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
DM-31528: Add more log messages #43
Conversation
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks great. One minor comment about when the 600 seconds is added onto the time.
@@ -674,7 +679,8 @@ def deblend(self, mExposure, catalog): | |||
idFactory.notify(maxId) | |||
|
|||
filters = mExposure.filters | |||
self.log.info(f"Deblending {len(catalog)} sources in {len(mExposure)} exposure bands") | |||
self.log.info("Deblending %d sources in %d exposure bands", len(catalog), len(mExposure)) | |||
logTime = time.time() |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
maybe call this lastLoggedTime
? (or see later comment about changing it to next time a log message is needed)
@@ -827,6 +833,10 @@ def deblend(self, mExposure, catalog): | |||
catalog=catalog, | |||
scarletSource=scarletSource, | |||
) | |||
# Log a message if it has been a while since the last log. | |||
if (currentTime := time.time()) > logTime + self.config.loggingInterval: |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Rather than always comparing against logTime + loggingInterval
every time, instead use nextLogTime
instead of lastLoggedTime
and calculate the next time at which you want to log and then simplify the if statement and only calculate the time with offset once you do log.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
That's an excellent suggestion! Adopted this now.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This looks good to me. I never thought I would see the day when people thought that scarlet didn't have enough logs. :)
I do wonder if this will completely fix the problem. Sometimes there can be very large blends, for example there are some HSC patches where a single blend takes up almost the entire patch due to satellite trails (unless that has been fixed recently), so it is possible that those will still time out with this fix and we might need to put a similar heartbeat into scarlet itself.
b3d2c51
to
b3cea2e
Compare
Thanks Fred! Yes, it would be good to have a similar heartbeat log message in scarlet itself. This fix implicitly assumes that any single parent can be deblended on timescales that are much smaller than |
Scarlet can be silent for too long when deblending sources, making it look like the job is hung. This PR allows a user to request more frequent logging (at VERBOSE level) to monitor the progress.