conda / conda

A system-level, binary package and environment manager running on all major operating systems and platforms.
https://docs.conda.io/projects/conda/
Other
6.44k stars 1.67k forks source link

Debug code guarded with `log.isEnabledFor(logging.DEBUG)` is always run #13541

Closed mbargull closed 4 months ago

mbargull commented 9 months ago

What happened?

In conda>=4.12 there is a seemingly innocuous change in the logging code:

which changed the logger's level to NOTSET which in turn renders log.isEnabledFor(logging.DEBUG) as always true.

Having those isEnabledFor-guarded code always run increases the resource usage tremendously. Local tests with the conda-forge channel, libmamba solver 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 classic solver 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 ```sh podman run --rm -it quay.io/condaforge/linux-anvil-cos7-x86_64 sh -ileuc "$( cat << 'end-of-script' conda create --quiet --yes --prefix=./conda-23.11 conda=23.11 python=3.11 patch time mamba conda deactivate && unset CONDA_SHLVL && . ./conda-23.11/etc/profile.d/conda.sh && conda activate test() { case ${1} in (clean) "${2}" clean --quiet --yes --index ;; esac printf '%80s\n' | tr ' ' '=' printf 'TEST: %s\n' "${2} (${1})${3+ ${3}}" command time \ --format='time: %es | peak memory: %MKB' \ "${2}" create \ --solver="${3-libmamba}" \ --yes --dry-run --name=test \ python_abi 2>&1 \ | grep '[ 0-9][kKMG]i\?B\>' printf '%80s\n' | tr ' ' '=' } test clean conda test cache conda test clean conda classic test cache conda classic test clean mamba test cache mamba { cat << 'end-of-patch' --- ./conda-23.11/lib/python3.11/site-packages/conda/common/io.py +++ ./conda-23.11/lib/python3.11/site-packages/conda/common/io.py @@ -329,17 +329,17 @@ # create new stderr logger new_stderr_handler = StreamHandler(sys.stderr) new_stderr_handler.name = "stderr" - new_stderr_handler.setLevel(level) + new_stderr_handler.setLevel(NOTSET) new_stderr_handler.setFormatter(formatter or _FORMATTER) # do the switch with _logger_lock(): if old_stderr_handler: logr.removeHandler(old_stderr_handler) logr.addHandler(new_stderr_handler) - logr.setLevel(NOTSET) + logr.setLevel(level) logr.propagate = propagate def timeout(timeout_secs, func, *args, default_return=None, **kwargs): --- ./conda-23.11/lib/python3.11/site-packages/conda/gateways/logging.py +++ ./conda-23.11/lib/python3.11/site-packages/conda/gateways/logging.py @@ -186,9 +186,9 @@ def set_conda_log_level(level=WARN): conda_logger = getLogger("conda") - conda_logger.setLevel(logging.NOTSET) + conda_logger.setLevel(level) attach_stderr_handler(level=level, logger_name="conda") conda_logger.propagate = False end-of-patch } | patch -p1 test clean conda test cache conda test clean conda classic test cache conda classic test clean mamba test cache mamba end-of-script )" ``` ``` sh: USER_LS_COLORS: unbound variable Channels: - conda-forge Platform: linux-64 Collecting package metadata (repodata.json): ...working... done Solving environment: ...working... done ## Package Plan ## environment location: /home/conda/conda-23.11 added / updated specs: - conda=23.11 - mamba - patch - python=3.11 - time The following packages will be downloaded: package | build ---------------------------|----------------- _libgcc_mutex-0.1 | conda_forge 3 KB conda-forge _openmp_mutex-4.5 | 2_gnu 23 KB conda-forge brotli-python-1.1.0 | py311hb755f60_1 343 KB conda-forge cffi-1.16.0 | py311hb3a22ac_0 293 KB conda-forge conda-23.11.0 | py311h38be061_1 1.2 MB conda-forge jsonpointer-2.4 | py311h38be061_3 18 KB conda-forge libmambapy-1.5.6 | py311hf2555c7_0 297 KB conda-forge mamba-1.5.6 | py311h3072747_0 65 KB conda-forge menuinst-2.0.2 | py311h38be061_0 159 KB conda-forge pybind11-abi-4 | hd8ed1ab_3 10 KB conda-forge pycosat-0.6.6 | py311h459d7ec_0 86 KB conda-forge python-3.11.7 |hab00c5b_1_cpython 29.4 MB conda-forge python_abi-3.11 | 4_cp311 6 KB conda-forge ruamel.yaml-0.18.5 | py311h459d7ec_0 271 KB conda-forge ruamel.yaml.clib-0.2.7 | py311h459d7ec_2 131 KB conda-forge time-1.8 | h516909a_0 38 KB conda-forge zstandard-0.22.0 | py311haa97af0_0 406 KB conda-forge ------------------------------------------------------------ Total: 32.7 MB The following NEW packages will be INSTALLED: _libgcc_mutex conda-forge/linux-64::_libgcc_mutex-0.1-conda_forge _openmp_mutex conda-forge/linux-64::_openmp_mutex-4.5-2_gnu archspec conda-forge/noarch::archspec-0.2.2-pyhd8ed1ab_0 boltons conda-forge/noarch::boltons-23.1.1-pyhd8ed1ab_0 brotli-python conda-forge/linux-64::brotli-python-1.1.0-py311hb755f60_1 bzip2 conda-forge/linux-64::bzip2-1.0.8-hd590300_5 c-ares conda-forge/linux-64::c-ares-1.26.0-hd590300_0 ca-certificates conda-forge/linux-64::ca-certificates-2023.11.17-hbcca054_0 certifi conda-forge/noarch::certifi-2023.11.17-pyhd8ed1ab_0 cffi conda-forge/linux-64::cffi-1.16.0-py311hb3a22ac_0 charset-normalizer conda-forge/noarch::charset-normalizer-3.3.2-pyhd8ed1ab_0 colorama conda-forge/noarch::colorama-0.4.6-pyhd8ed1ab_0 conda conda-forge/linux-64::conda-23.11.0-py311h38be061_1 conda-libmamba-so~ conda-forge/noarch::conda-libmamba-solver-23.12.0-pyhd8ed1ab_0 conda-package-han~ conda-forge/noarch::conda-package-handling-2.2.0-pyh38be061_0 conda-package-str~ conda-forge/noarch::conda-package-streaming-0.9.0-pyhd8ed1ab_0 distro conda-forge/noarch::distro-1.9.0-pyhd8ed1ab_0 fmt conda-forge/linux-64::fmt-10.2.1-h00ab1b0_0 icu conda-forge/linux-64::icu-73.2-h59595ed_0 idna conda-forge/noarch::idna-3.6-pyhd8ed1ab_0 jsonpatch conda-forge/noarch::jsonpatch-1.33-pyhd8ed1ab_0 jsonpointer conda-forge/linux-64::jsonpointer-2.4-py311h38be061_3 keyutils conda-forge/linux-64::keyutils-1.6.1-h166bdaf_0 krb5 conda-forge/linux-64::krb5-1.21.2-h659d440_0 ld_impl_linux-64 conda-forge/linux-64::ld_impl_linux-64-2.40-h41732ed_0 libarchive conda-forge/linux-64::libarchive-3.7.2-h2aa1ff5_1 libcurl conda-forge/linux-64::libcurl-8.5.0-hca28451_0 libedit conda-forge/linux-64::libedit-3.1.20191231-he28a2e2_2 libev conda-forge/linux-64::libev-4.33-hd590300_2 libexpat conda-forge/linux-64::libexpat-2.5.0-hcb278e6_1 libffi conda-forge/linux-64::libffi-3.4.2-h7f98852_5 libgcc-ng conda-forge/linux-64::libgcc-ng-13.2.0-h807b86a_4 libgomp conda-forge/linux-64::libgomp-13.2.0-h807b86a_4 libiconv conda-forge/linux-64::libiconv-1.17-hd590300_2 libmamba conda-forge/linux-64::libmamba-1.5.6-had39da4_0 libmambapy conda-forge/linux-64::libmambapy-1.5.6-py311hf2555c7_0 libnghttp2 conda-forge/linux-64::libnghttp2-1.58.0-h47da74e_1 libnsl conda-forge/linux-64::libnsl-2.0.1-hd590300_0 libsolv conda-forge/linux-64::libsolv-0.7.27-hfc55251_0 libsqlite conda-forge/linux-64::libsqlite-3.44.2-h2797004_0 libssh2 conda-forge/linux-64::libssh2-1.11.0-h0841786_0 libstdcxx-ng conda-forge/linux-64::libstdcxx-ng-13.2.0-h7e041cc_4 libuuid conda-forge/linux-64::libuuid-2.38.1-h0b41bf4_0 libxcrypt conda-forge/linux-64::libxcrypt-4.4.36-hd590300_1 libxml2 conda-forge/linux-64::libxml2-2.12.4-h232c23b_1 libzlib conda-forge/linux-64::libzlib-1.2.13-hd590300_5 lz4-c conda-forge/linux-64::lz4-c-1.9.4-hcb278e6_0 lzo conda-forge/linux-64::lzo-2.10-h516909a_1000 mamba conda-forge/linux-64::mamba-1.5.6-py311h3072747_0 menuinst conda-forge/linux-64::menuinst-2.0.2-py311h38be061_0 ncurses conda-forge/linux-64::ncurses-6.4-h59595ed_2 openssl conda-forge/linux-64::openssl-3.2.0-hd590300_1 packaging conda-forge/noarch::packaging-23.2-pyhd8ed1ab_0 patch conda-forge/linux-64::patch-2.7.6-h7f98852_1002 pip conda-forge/noarch::pip-23.3.2-pyhd8ed1ab_0 platformdirs conda-forge/noarch::platformdirs-4.1.0-pyhd8ed1ab_0 pluggy conda-forge/noarch::pluggy-1.4.0-pyhd8ed1ab_0 pybind11-abi conda-forge/noarch::pybind11-abi-4-hd8ed1ab_3 pycosat conda-forge/linux-64::pycosat-0.6.6-py311h459d7ec_0 pycparser conda-forge/noarch::pycparser-2.21-pyhd8ed1ab_0 pysocks conda-forge/noarch::pysocks-1.7.1-pyha2e5f31_6 python conda-forge/linux-64::python-3.11.7-hab00c5b_1_cpython python_abi conda-forge/linux-64::python_abi-3.11-4_cp311 readline conda-forge/linux-64::readline-8.2-h8228510_1 reproc conda-forge/linux-64::reproc-14.2.4.post0-hd590300_1 reproc-cpp conda-forge/linux-64::reproc-cpp-14.2.4.post0-h59595ed_1 requests conda-forge/noarch::requests-2.31.0-pyhd8ed1ab_0 ruamel.yaml conda-forge/linux-64::ruamel.yaml-0.18.5-py311h459d7ec_0 ruamel.yaml.clib conda-forge/linux-64::ruamel.yaml.clib-0.2.7-py311h459d7ec_2 setuptools conda-forge/noarch::setuptools-69.0.3-pyhd8ed1ab_0 time conda-forge/linux-64::time-1.8-h516909a_0 tk conda-forge/linux-64::tk-8.6.13-noxft_h4845f30_101 tqdm conda-forge/noarch::tqdm-4.66.1-pyhd8ed1ab_0 truststore conda-forge/noarch::truststore-0.8.0-pyhd8ed1ab_0 tzdata conda-forge/noarch::tzdata-2023d-h0c530f3_0 urllib3 conda-forge/noarch::urllib3-2.1.0-pyhd8ed1ab_0 wheel conda-forge/noarch::wheel-0.42.0-pyhd8ed1ab_0 xz conda-forge/linux-64::xz-5.2.6-h166bdaf_0 yaml-cpp conda-forge/linux-64::yaml-cpp-0.8.0-h59595ed_0 zstandard conda-forge/linux-64::zstandard-0.22.0-py311haa97af0_0 zstd conda-forge/linux-64::zstd-1.5.5-hfc55251_0 Preparing transaction: ...working... done Verifying transaction: ...working... done Executing transaction: ...working... done ================================================================================ TEST: conda (clean) python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 27.71s | peak memory: 2936256KB ================================================================================ ================================================================================ TEST: conda (cache) python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 10.26s | peak memory: 602272KB ================================================================================ ================================================================================ TEST: conda (clean) classic python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 14.29s | peak memory: 775688KB ================================================================================ ================================================================================ TEST: conda (cache) classic python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 10.88s | peak memory: 357544KB ================================================================================ ================================================================================ TEST: mamba (clean) + python_abi 3.12 4_cp312 conda-forge 6kB Total download: 6kB time: 12.01s | peak memory: 403356KB ================================================================================ ================================================================================ TEST: mamba (cache) + python_abi 3.12 4_cp312 conda-forge 6kB Total download: 6kB time: 2.10s | peak memory: 326576KB ================================================================================ patching file conda-23.11/lib/python3.11/site-packages/conda/common/io.py patching file conda-23.11/lib/python3.11/site-packages/conda/gateways/logging.py ================================================================================ TEST: conda (clean) python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 15.71s | peak memory: 523708KB ================================================================================ ================================================================================ TEST: conda (cache) python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 10.23s | peak memory: 518628KB ================================================================================ ================================================================================ TEST: conda (clean) classic python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 11.90s | peak memory: 373992KB ================================================================================ ================================================================================ TEST: conda (cache) classic python_abi-3.12 | 4_cp312 6 KB conda-forge Total: 6 KB time: 10.94s | peak memory: 354872KB ================================================================================ ================================================================================ TEST: mamba (clean) + python_abi 3.12 4_cp312 conda-forge 6kB Total download: 6kB time: 12.05s | peak memory: 402260KB ================================================================================ ================================================================================ TEST: mamba (cache) + python_abi 3.12 4_cp312 conda-forge 6kB Total download: 6kB time: 2.09s | peak memory: 325768KB ================================================================================ ```
mbargull commented 9 months ago

N.B.: I have not looked into how the logging code is used with conda>=4.12 and hence don't know what additional changes are needed besides reverting the logger.setLevel(NOTSET)/handler.setLevel(level) changes. ... and I'll gladly leave this up to someone else :speak_no_evil: (the log handling is a bit convoluted and it's been ages I work on this).

jezdez commented 9 months ago

Wow, talk about a deep rabbit hole 🐰

mbargull commented 9 months ago

Wow, talk about a deep rabbit hole 🐰

Good thing is, that I was able to pin point this very quickly. I didn't even do any profiling, just a brutal (ulimit -Sv 1000000 && conda clean -qyi && conda create -qdnx python_abi) and see where it failed (needed some massaging to get a proper stack trace, though). Plus, seeing that is was in a isEnabledFor(logging.DEBUG) branch when it shouldn't, I knew exactly where to look... since, funnily enough, my very first contributions way back when were working with/around conda's logging setup :older_man: .

jaimergp commented 9 months ago

ulimit -Sv 1000000 &&

Oooh, that's a nice tip!

mbargull commented 9 months ago

Addendum:

Interestingly, with the classic solver we seem to take slightly different code paths with much less impact.

This is only happened because --solver=classic cheated by using current_repodata.json. Running the above test with CONDA_REPODATA_FNS=repodata.json set, we get the same peak for --solver=classic:

================================================================================
TEST: conda (clean)
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 28.54s | peak memory: 2950668KB
================================================================================
================================================================================
TEST: conda (cache)
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 10.49s | peak memory: 601512KB
================================================================================
================================================================================
TEST: conda (clean) classic
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 82.04s | peak memory: 3300296KB
================================================================================
================================================================================
TEST: conda (cache) classic
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 61.48s | peak memory: 1565864KB
================================================================================
================================================================================
TEST: mamba (clean)
  + python_abi     3.12  4_cp312  conda-forge      6kB
  Total download: 6kB
time: 12.28s | peak memory: 413124KB
================================================================================
================================================================================
TEST: mamba (cache)
  + python_abi     3.12  4_cp312  conda-forge      6kB
  Total download: 6kB
time: 2.11s | peak memory: 326260KB
================================================================================
patching file conda-23.11/lib/python3.11/site-packages/conda/common/io.py
patching file conda-23.11/lib/python3.11/site-packages/conda/gateways/logging.py
================================================================================
TEST: conda (clean)
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 15.31s | peak memory: 527096KB
================================================================================
================================================================================
TEST: conda (cache)
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 10.49s | peak memory: 601572KB
================================================================================
================================================================================
TEST: conda (clean) classic
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 67.71s | peak memory: 1575372KB
================================================================================
================================================================================
TEST: conda (cache) classic
    python_abi-3.12            |          4_cp312           6 KB  conda-forge
                                           Total:           6 KB
time: 63.28s | peak memory: 1614900KB
================================================================================
================================================================================
TEST: mamba (clean)
  + python_abi     3.12  4_cp312  conda-forge      6kB
  Total download: 6kB
time: 12.34s | peak memory: 402896KB
================================================================================
================================================================================
TEST: mamba (cache)
  + python_abi     3.12  4_cp312  conda-forge      6kB
  Total download: 6kB
time: 2.14s | peak memory: 325968KB
================================================================================
mbargull commented 9 months ago

ulimit -Sv 1000000 &&

Oooh, that's a nice tip!

It's a convenient thing because one can just add it on top of everything. But it's also of very limit use, TBH. I just got lucky here since it caught a steep peak; if you have memory creep over a longer time, it'll just give you an indicator that something is wrong, but not where... However, I do think we could use it (or something similar) in some simple (small and short) performance regression tests we can run on CI (orthogonal to a revival of conda-benchmarks).

jaimergp commented 9 months ago

There a few places where we are calling isEnabledFor that are worth revisiting:

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))
mbargull commented 9 months ago

There a few places where we are calling isEnabledFor that are worth revisiting:

Probably; but that would be orthogonal to this issue (i.e., should go into a separate issue). This issue is rather just to track that we set the loggers' levels correctly again.

zklaus commented 8 months ago

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 DEBUG. After that PR, the log level is now set at the handler. This means that all handlers have individual control over which events to process, allowing for detailed log files. However, it also means that all logging code must be run all the time because the logger does not know if any of its handlers need low level events, which in some cases can lead to excessive resource usage.

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.

mbargull commented 8 months ago

Thanks for working on this @zklaus!

I have been investigating this a bit. To sum up my understanding so far: [...]

Seems about right :thumbsup:. My understanding in other words: The logger's level guards which logging-related code is executed and hence must be the lower bound on what its handlers should process -- but it should also be a tight lower bound so we don't execute unneeded code whose output the handlers don't actually process.

  • We could track the minimal level needed, and set that as the log level at the logger

Yes, this should be the step with the highest priority so that we can avoid the performance impact under normal operation. Other steps can be done any time, but, IMO, we should correct the loggers' levels sooner (next release?) rather than later.

We could try to tackle the resource issues in the code related to low level logging

Yes, even under debug conditions, we shouldn't do expensive computations if we don't actually use their output.

We could try to rethink the guard from a simple log.isEnabledFor to a more comprehensive assessment without changing the lgging itself, for example by traversing the existing handlers.

I'm not really following this train of thought. But whatever we end up with, it should be conceptually simple and have low run time impact (generally, but especially during normal, non-debug operation).

We could rethink logging as a whole

Yes, the current logging setup is much more complicated as it should be and likely has quite a few deficiencies (depending on how conda's code is run, e.g., normal CLI vs usage as library [as in conda-build] vs usage with --json) because of that. In the last community meeting we talked about better/more readable output for conda-build -- but the same also goes for conda: whenever we tackle an epic issue around improving conda's output, the logging functionality will play part in it if/ when we strife for more consistent presentations.

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.

:+1:

jezdez commented 8 months ago

/cc @kenodegard

jezdez commented 8 months ago

We could rethink logging as a whole

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 logging, this needs to be more specific.

  • We could track the minimal level needed, and set that as the log level at the logger
  • We could try to tackle the resource issues in the code related to low level logging
  • We could try to rethink the guard from a simple log.isEnabledFor to a more comprehensive assessment without changing the lgging itself, for example by traversing the existing handlers.

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 logging easily leads to over-engineering the work-arounds.

mbargull commented 8 months ago

We could rethink logging as a whole 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 logging, this needs to be more specific.

Oh, I don't think we want or should to do anything about that in connection to this issue. Whenever we'd look into that, we'd have to carefully assess any moving parts (first action: write more regression tests for expected outputs under different scenarios). I completely agree, such changes should have none/as little impact as possible for the user. That being said, yes, "rethink logging as a whole" is not very specific -- for one, it doesn't even imply replacing logging with something else, but could just mean "rethinking the way conda uses logging (e.g., like the "leads to [...] work-arounds" you mentioned below).

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 logging easily leads to over-engineering the work-arounds.

Yes, our current code unfortunately carries such signs of this "easily leads to over-engineering the work-arounds." But I think the only thing mentioned as "low handing fruit" was just fixing the regression, i.e., re-setting the logger level ;).

mbargull commented 8 months ago

I've proposed gh-13628 as a fix for the excess resource usage due to this issue for now. We could/should include that PR in the 24.3.x milestone. It is of course orthogonal to the underlying logging issue (i.e., it only addresses the most prominent one, but there may be other code paths with unintended side effects and/or resource usage).

@jezdez, do you want me to open a separate issue just for the acute increased resource use which that PR then closes? (We'd need that issue if you wanted an "issue-only" checklist for the milestone.)

cc @beeankha, @ForgottenProgramme, @jezdez

jezdez commented 8 months ago

@mbargull Wow, what a horrible find! Yes please open a ticket for posterity and assign the March milestone.

jezdez commented 8 months ago

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

jezdez commented 8 months ago

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 isEnabledFor for the reasons given here.