Skip to content
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

Lazyflow logging and fix default operator naming #2850

Open
wants to merge 7 commits into
base: main
Choose a base branch
from

Conversation

btbest
Copy link
Contributor

@btbest btbest commented Apr 25, 2024

Now that debug logging actually works, this introduces a bunch of new debug statements that allow tracing what lazyflow is doing. Also:

  • Fix default naming of operators. This was only happening in _after_init, which is too late. We want the default name to already be set at the start of __init__ so that slots instantiated during __init__ can put it in their logger name.
  • Add utf-8 encoding to log config to override cp1252 on windows and make it possible to log slot.meta (which can contain σ, throws in cp1252)

At this point, the changes I make when I need to debug lazyflow are:

  1. Start ilastik with --debug
  2. Set write_logs=True in Slot.__init__ instead of False to set up slot-wise logging
  3. Change INFO to DEBUG in logging_config.json for lazyflow.signals, lazyflow.graph and lazyflow.op_debug
  4. Exchange module for name in the verbose format in default_config.py -- This is also the format for the log file in prod, otherwise I would commit this change.

Copy link

codecov bot commented Apr 25, 2024

Codecov Report

Attention: Patch coverage is 35.08772% with 37 lines in your changes are missing coverage. Please review.

Project coverage is 55.72%. Comparing base (723a458) to head (26fd121).
Report is 20 commits behind head on main.

Files Patch % Lines
lazyflow/slot.py 10.00% 20 Missing and 16 partials ⚠️
lazyflow/operator.py 88.88% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main    #2850      +/-   ##
==========================================
- Coverage   55.75%   55.72%   -0.04%     
==========================================
  Files         533      533              
  Lines       62207    62243      +36     
  Branches     8511     8526      +15     
==========================================
  Hits        34683    34683              
- Misses      25769    25789      +20     
- Partials     1755     1771      +16     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Copy link
Contributor

@k-dominik k-dominik left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

It does add quite some noise if one doesn't need to debug the whole graph with all ops, but I guess that will be a tooling question.

lazyflow/slot.py Outdated
@@ -826,6 +829,8 @@ def get(self, roi):
), "This inputSlot has no value and no upstream_slot. You can't ask for its data yet!"
# normal (outputslot) case
# --> construct heavy request object..
if self.logger:
self.logger.debug(f"Getting data for roi={roi}")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
self.logger.debug(f"Getting data for roi={roi}")
self.logger.debug(f"Getting data for {roi=}")

would be more concise and in line with other f-strings you introduced in this changeset.

@@ -108,6 +105,7 @@ def __init__(
allow_mask=False,
subindex=(),
top_level_slot=None,
write_logs=False,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is kinda neat, to enable per slot debug messages which would otherwise be overkill via a config. Seeing this I wonder if this would not also be nice to have selective per instance logging for only some operators.

Copy link
Contributor Author

@btbest btbest May 8, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I actually thought it was a bit ugly, adding a parameter and what feels like too much logic purely for debug logging. Plus, it's effectively logging config outside of the logging_config. But in a pixel classification example, this prevents bloating the already existing 469 loggers up to 901 loggers, so I figured it might be worth it...

btbest added 6 commits May 8, 2024 16:54
This avoids instantiating dozens of loggers outside of debugging, but allows fine-grained control during debugging.

* Move old debugs to the new per-slot loggers
* Move old errors to a new module-level logger that always exists
* Add more debugs for better tracing what slots are doing
This should give flexible control. Logs from operator.py for a specific op (e.g. `lazyflow.op_debug.OpPixelClassification`) can be separately controlled from the individual module's logging for the same op (e.g. `ilastik.applets.pixelClassification.opPixelClassification`).
Some slots put unicode characters in the slot's meta dict. E.g. `OpPixelFeaturesPresmoothed.Output.meta.channel_names` will contain the sigma character. On Windows, the log file is encoded with cp1252 by default, which cannot handle such characters and raises UnicodeEncodeError.

Logging f"{slot}" is therefore not possible by default, as the slot's repr will contain the full meta dict along with the unicode chars.
So that default name is available during subclass.__init__ and slots instantiated can use it in their logger name.
This was always defaulting to "Wrapped Operator (base class)"
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants