Debug code guarded with log.isEnabledFor(logging.DEBUG) is always run #13541
Description
What happened?
In conda>=4.12 there is a seemingly innocuous change in the logging code:
- 487a02b#diff-f5c41f7e31bcc7aced31c4cad11ada6abc5478d93492e4b77715528d4642666eL331-L340
- 487a02b#diff-5c8832d586a9cd64e3162e388dfd6569fd77a0fe2031e04f2e287d4c088bb675R212
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
- in https://github.com/conda/conda/blob/23.11.0/conda/auxlib/logz.py#L165
- called from https://github.com/conda/conda/blob/23.11.0/conda/gateways/repodata/__init__.py#L152
- originating from https://github.com/conda/conda-libmamba-solver/blob/23.12.0/conda_libmamba_solver/index.py#L239
Additional Context
Full reproducer showing the reduced resource usage when the logger level is not set to NOTSET:
output
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
================================================================================
Metadata
Metadata
Assignees
Labels
Type
Projects
Status