fix: Reduce logging system overhead (#3416)

* test: Non-regression test

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* fix: Use penultimate libsolv's log level

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* Only run `test_env_spdlog_overhead_regression` on Linux

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

Co-authored-by: Johan Mabille <johan.mabille@gmail.com>

* Add time-out on test and rename conda env

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

Co-authored-by: Hind Montassif <hind.montassif@gmail.com>

* Decrease timout to 15 seconds and use dry-run

A dry run takes slightly less than 10 seconds.

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* Use bounded value of `output_params.verbosity` as in 1.x

See: https://github.com/mamba-org/mamba/blob/1.x/libmamba/src/core/pool.cpp#L72

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* Instead define and use and alternative `set_level`

I was hesitating between the previous solution and
this one (which is not really ideal either) but
which at least does not leak the `Context`.

Friend function could be used but we get this kind of
issue, but I am currently meeting this problem:
https://www.open-std.org/jtc1/sc22/wg21/docs/cwg_defects.html#2174

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* Revert "Instead define and use and alternative `set_level`"

This reverts commit f1f41b71d0.

* Simply hardcode the verbosity level to 3

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

Co-authored-by: Hind Montassif <hind.montassif@gmail.com>

* Increase timeout from 15 to 30 seconds

15 seconds is not sufficient as shown on the CI.

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* From 30 sec to 60 sec

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* DEBUG No timeout

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* test: Remove edge-case for unlinks

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* test: Adapt number of unlinks on Linux

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* Assert success

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

Co-authored-by: Hind Montassif <hind.montassif@gmail.com>

* docs: Update comments

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* `const`-qualify `level`

* Use 100 seconds for the timeout

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

Co-authored-by: Hind Montassif <hind.montassif@gmail.com>

* Use 200 seconds for the timeout

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* Adapt according to `1.x`'s behavior

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

* fixup! Adapt according to `1.x`'s behavior

* Revert changes to handle CI failures

This is handled by another PR.

See: https://github.com/mamba-org/mamba/pull/3417

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>

---------

Signed-off-by: Julien Jerphanion <git@jjerphan.xyz>
Co-authored-by: Johan Mabille <johan.mabille@gmail.com>
Co-authored-by: Hind Montassif <hind.montassif@gmail.com>

dev/environment-dev.yml

@@ -29,6 +29,7 @@ dependencies:
   - mitmproxy
   - pytest >=7.3.0
   - pytest-asyncio
+  - pytest-timeout
   - pytest-xprocess
   - requests
   - sel(win): pywin32

libmamba/src/solver/libsolv/database.cpp

@@ -109,7 +109,18 @@ namespace mamba::solver::libsolv
 
     void Database::set_logger(logger_type callback)
     {
-        ::pool_setdebuglevel(pool().raw(), std::numeric_limits<int>::max());  // All
+        // We must not use more than the penultimate level of verbosity of libsolv (which is 3) to
+        // avoid the most verbose messages (of type SOLV_DEBUG_RULE_CREATION | SOLV_DEBUG_WATCHES),
+        // which might spam the output and make mamba hang. See:
+        // https://github.com/openSUSE/libsolv/blob/27aa6a72c7db73d78aa711ae412231768e77c9e0/src/pool.c#L1623-L1637
+        // TODO: Make `level` configurable once the semantics and UX for verbosity are clarified.
+        // Currently, we use the behavior of `1.x` whose default value for the verbosity level was
+        // `0` in which case `::pool_setdebuglevel` was not called. See:
+        // https://github.com/mamba-org/mamba/blob/4f269258b4237a342da3e9891045cdd51debb27c/libmamba/include/mamba/core/context.hpp#L88
+        // See: https://github.com/mamba-org/mamba/blob/1.x/libmamba/src/core/pool.cpp#L72
+        // Instead use something like:
+        // const int level = Context().output_params.verbosity - 1;
+        // ::pool_setdebuglevel(pool().raw(), level);
         pool().set_debug_callback(
             [logger = std::move(callback)](const solv::ObjPoolView&, int type, std::string_view msg) noexcept
             {

micromamba/tests/env-logging-overhead-regression.yaml

@@ -0,0 +1,17 @@
+# This environment was observed to have the spdlog-based logging system make
+# mamba hang when environments are created with:
+#
+#   {micromamba,mamba} env create -n repro-create -f ./env-logging-overhead-regression.yaml
+#
+# or updated with:
+#
+#   {micromamba,mamba} env update -n repro-create -f ./env-logging-overhead-regression.yaml
+#
+channels:
+  - conda-forge
+dependencies:
+  - python=3.9
+  - xeus-cling=0.6.0
+  - xtensor=0.20.8
+  - xtensor-blas=0.16.1
+  - notebook

micromamba/tests/test_create.py

@@ -143,6 +143,24 @@ def test_env_lockfile_different_install_after_create(tmp_home, tmp_root_prefix,
     helpers.install("-p", env_prefix, "-f", install_spec_file, "-y", "--json")
 
 
+# Only run this test on Linux, as it is the only platform where xeus-cling
+# (which is part of the environment) is available.
+@pytest.mark.timeout(20)
+@pytest.mark.skipif(platform.system() != "Linux", reason="Test only available on Linux")
+@pytest.mark.parametrize("shared_pkgs_dirs", [True], indirect=True)
+def test_env_logging_overhead_regression(tmp_home, tmp_root_prefix, tmp_path):
+    # Non-regression test https://github.com/mamba-org/mamba/issues/3415.
+
+    env_prefix = tmp_path / "myenv"
+    create_spec_file = tmp_path / "env-logging-overhead-regression.yaml"
+
+    shutil.copyfile(__this_dir__ / "env-logging-overhead-regression.yaml", create_spec_file)
+
+    # Must not hang
+    res = helpers.create("-p", env_prefix, "-f", create_spec_file, "-y", "--json", "--dry-run")
+    assert res["success"]
+
+
 @pytest.mark.parametrize("shared_pkgs_dirs", [True], indirect=True)
 @pytest.mark.parametrize("root_prefix_type", (None, "env_var", "cli"))
 @pytest.mark.parametrize("target_is_root", (False, True))