Debug code guarded with log.isEnabledFor(logging.DEBUG) is always run
#13541
Comments
mbargull
added
type::bug
|
N.B.: I have not looked into how the logging code is used with |
|
Wow, talk about a deep rabbit hole 🐰 |
Good thing is, that I was able to pin point this very quickly. |
Oooh, that's a nice tip! |
|
Addendum:
This is only happened because |
It's a convenient thing because one can just add it on top of everything. |
|
There a few places where we are calling 18 results - 7 files
conda • conda/resolve.py:
670
671: if log.isEnabledFor(DEBUG):
672 log.debug(
1055
1056: if log.isEnabledFor(DEBUG):
1057 log.debug(
1063 result = [(self.push_MatchSpec(C, ms),) for ms in specs]
1064: if log.isEnabledFor(DEBUG):
1065 log.debug(
1075 }
1076: if log.isEnabledFor(DEBUG):
1077 log.debug(
1429 specs = set(specs)
1430: if log.isEnabledFor(DEBUG):
1431 dlist = dashlist(
1525
1526: if log.isEnabledFor(DEBUG):
1527 log.debug("Requested specs: %s", dashlist(sorted(str(s) for s in specr)))
conda • conda/common/_logic.py:
611 def _run_sat(self, m, limit=0):
612: if log.isEnabledFor(DEBUG):
613 log.debug("Invoking SAT with clause count: %s", self.get_clause_count())
701 m_orig = self.m
702: if log.isEnabledFor(DEBUG):
703 # This is only used for the log message below.
723
724: if log.isEnabledFor(DEBUG):
725 log.trace(
conda • conda/core/solve.py:
649 _, inconsistent_precs = ssc.r.bad_installed(ssc.solution_precs, ())
650: if log.isEnabledFor(DEBUG):
651 log.debug(
994 specs_modified = False
995: if log.isEnabledFor(DEBUG):
996 log.debug(
1046 # Finally! We get to call SAT.
1047: if log.isEnabledFor(DEBUG):
1048 log.debug(
conda • conda/gateways/logging.py:
235 def trace(self, message, *args, **kwargs):
236: if self.isEnabledFor(TRACE):
237 self._log(TRACE, message, args, **kwargs)
conda • conda/gateways/subprocess.py:
109
110: if (raise_on_error and rc != 0) or log.isEnabledFor(TRACE):
111 formatted_output = _format_output(command_str, cwd, rc, stdout, stderr)
114 raise CalledProcessError(rc, command, output=formatted_output)
115: if log.isEnabledFor(TRACE):
116 log.trace(formatted_output)
conda • conda/gateways/connection/download.py:
97 )
98: if log.isEnabledFor(DEBUG):
99 log.debug(stringify(resp, content_max_len=256))
318 )
319: if log.isEnabledFor(DEBUG):
320 log.debug(stringify(response, content_max_len=256))
conda • conda/gateways/repodata/__init__.py:
158 )
159: if log.isEnabledFor(logging.DEBUG):
160 log.debug(stringify(response, content_max_len=256)) |
Probably; but that would be orthogonal to this issue (i.e., should go into a separate issue). |
kenodegard
added
the
backlog
|
I have been investigating this a bit. To sum up my understanding so far: Before #11193, the log level was set at the logger. This meant that no handler would get any log events with lower level. This makes it impossible to have some handlers that provide more detailed logs, for example in a log file. The log level is also used to prevent certain purely log related code to be run at all if the current log level is higher than This may be addressed in several ways:
I will start work on the first approach here, since it seems a relatively low hanging fruit, but feel free to chip in with thoughts on the larger structure. |
|
Thanks for working on this @zklaus!
Seems about right 👍.
Yes, this should be the step with the highest priority so that we can avoid the performance impact under normal operation.
Yes, even under debug conditions, we shouldn't do expensive computations if we don't actually use their output.
I'm not really following this train of thought.
Yes, the current logging setup is much more complicated as it should be and likely has quite a few deficiencies (depending on how
👍 |
|
/cc @kenodegard |
Hard no, at least based on the presented reasons above. Of course there are different libraries that are better suited, but any table flip scenarios need to take our deprecation policy into account and carry the risk of adding undue additional churn to user experience. IOW if you want to propose to move away from
I would strongly suggest to review how other complex logging based systems handle cases like this before jumping into "low hanging fruit". In my experience the layered setup of |
Oh, I don't think we want or should to do anything about that in connection to this issue.
Yes, our current code unfortunately carries such signs of this "easily leads to over-engineering the work-arounds." |
|
I've proposed gh-13628 as a fix for the excess resource usage due to this issue for now. @jezdez, do you want me to open a separate issue just for the acute increased resource use which that PR then closes? |
|
@mbargull Wow, what a horrible find! Yes please open a ticket for posterity and assign the March milestone. |
|
As an interesting aside, maybe as a way to roll back the changes we made for libmamba solver, we could maybe utilize logging adapters for the additonal context? https://docs.python.org/3/howto/logging-cookbook.html#adding-contextual-information-to-your-logging-output |
|
Moving to the next milestone, this is more involved than the time left for the March release. #13628 has addressed a symptom, but the question is whether we should still clean up the use of |
What happened?
In
conda>=4.12there is a seemingly innocuous change in the logging code:which changed the logger's level to
NOTSETwhich in turn renderslog.isEnabledFor(logging.DEBUG)as always true.Having those
isEnabledFor-guarded code always run increases the resource usage tremendously.Local tests with the
conda-forgechannel,libmambasolver and a cleaned index showed 5-6 times peak memory usage (we're talking a couple of GiB here...) and runtime nearly doubled.Interestingly, with the
classicsolver we seem to take slightly different code paths with much less impact.The peak memory is happening
Additional Context
Full reproducer showing the reduced resource usage when the logger level is not set to
NOTSET:output
The text was updated successfully, but these errors were encountered: