Logging callbacks have too much overhead on libmambapy

[jaimergp]

Troubleshooting docs

• My problem is not solved in the Troubleshooting docs

Anaconda default channels

• I do NOT use the Anaconda default channels (pkgs/* etc.)

How did you install Mamba?

Mambaforge or latest Miniforge

Search tried in issue tracker

logging debug

Latest version of Mamba

• My problem is not solved with the latest version

Tried in Conda?

Not applicable

Describe your issue

2.x API includes logging callbacks so the information reported by libsolv or libmamba can be routed through a Python callable via libmambapy.solver.libsolv.Database.set_logger(). However, this becomes very slow when the libsolv throughput is too large (e.g. verbosity=DEBUG). It causes a slowdown so large that the solver takes minutes to finish.

Are there any ways to have a less resource consuming way? I don't need fancy formatting or full control, just the ability to decide when to send different levels to stdout based on the verbosity chosen by the user.

mamba info / micromamba info

This is with libmambapy 2.0.0rc3

Logs

N/A

environment.yml

N/A

~/.condarc

N/A

[jjerphan]

Thank you for the report.

We have observed a tangential issue for some environments whose resolution via libsolv was hanging due to the logging system. Both issue have the same root cause: all of the possible logs of libsolv are emitted by default as we set log_level to std::numeric_limits<int>::max().

See: https://github.com/openSUSE/libsolv/blob/27aa6a72c7db73d78aa711ae412231768e77c9e0/src/pool.c#L1623-L1637

mamba/libmamba/src/solver/libsolv/database.cpp

Lines 90 to 108 in 08d7b4e

	namespace
	{
	auto libsolv_to_log_level(int type) -> LogLevel
	{
	if (type & SOLV_FATAL)
	{
	return LogLevel::Fatal;
	}
	if (type & SOLV_ERROR)
	{
	return LogLevel::Error;
	}
	if (type & SOLV_WARN)
	{
	return LogLevel::Warning;
	}
	return LogLevel::Debug;
	}
	}

mamba/libmamba/src/solver/libsolv/database.cpp

Lines 110 to 127 in 08d7b4e

	void Database::set_logger(logger_type callback)
	{
	::pool_setdebuglevel(pool().raw(), std::numeric_limits<int>::max()); // All
	pool().set_debug_callback(
	[logger = std::move(callback)](const solv::ObjPoolView&, int type, std::string_view msg) noexcept
	{
	try
	{
	logger(libsolv_to_log_level(type), msg);
	}
	catch (const std::exception& e)
	{
	std::cerr << "Developer error: error in libsolv logging function: \n"
	<< e.what();
	}
	}
	);
	}

mamba/libmamba/src/core/package_database_loader.cpp

Lines 31 to 53 in 154012f

	void add_spdlog_logger_to_database(solver::libsolv::Database& db)
	{
	db.set_logger(
	[logger = spdlog::get("libsolv")](solver::libsolv::LogLevel level, std::string_view msg)
	{
	switch (level)
	{
	case (solver::libsolv::LogLevel::Fatal):
	logger->critical(msg);
	break;
	case (solver::libsolv::LogLevel::Error):
	logger->error(msg);
	break;
	case (solver::libsolv::LogLevel::Warning):
	logger->warn(msg);
	break;
	case (solver::libsolv::LogLevel::Debug):
	logger->debug(msg);
	break;
	}
	}
	);
	}

An option can be for (release) builds not to emit debug logs unless if explicitly asked by users (with verbosity=DEBUG as you propose).

[jjerphan]

#3416 addresses the performance regression. We think that the handling of log levels and of verbosity better be implemented in another PR.

[jjerphan]

@jaimergp: can you report if you have observed improvements with 2.0.0rc4?

[jaimergp]

@jaimergp: can you report if you have observed improvements with 2.0.0rc4?

In the sense that there are no performance overheads, yes. But I can't seem to be able to invoke obtain the libsolv logs anymore.

Isn't this sufficient?

    libmamba_context = libmambapy.Context(
        libmambapy.ContextOptions(
            enable_signal_handling=False,
            enable_logging=True,
        )
    )
    # Output params
    libmamba_context.output_params.json = context.json
    if libmamba_context.output_params.json:
        libmambapy.cancel_json_output(libmamba_context)
    libmamba_context.output_params.quiet = context.quiet
    libmamba_context.set_log_level(
        {
            4: libmambapy.LogLevel.TRACE,
            3: libmambapy.LogLevel.DEBUG,
            2: libmambapy.LogLevel.INFO,
            1: libmambapy.LogLevel.WARNING,
            0: libmambapy.LogLevel.ERROR,
        }[context.verbosity]
    )

This ^ correctly gives the libmamba logs, but not for libsolv. I thought I needed to call set_logger() on the Database instances:

        params = ChannelResolveParams(
            platforms=set(self.subdirs),
            channel_alias=CondaURL.parse(str(context.channel_alias)),
            custom_channels=ChannelResolveParams.ChannelMap(custom_channels),
            custom_multichannels=ChannelResolveParams.MultiChannelMap(custom_multichannels),
            home_dir=str(Path.home()),
            current_working_dir=os.getcwd(),
        )
        db = Database(params)
        db.set_logger(logger_callback)

with logger_callback():

def logger_callback(level: libmambapy.solver.libsolv.LogLevel, msg: str, logger=_db_log):
    # from libmambapy.solver.libsolv import LogLevel
    # levels = {
    #     LogLevel.Debug: logging.DEBUG, # 0 -> 10
    #     LogLevel.Warning: logging.WARNING, # 1 -> 30
    #     LogLevel.Error: logging.ERROR, # 2 -> 40
    #     LogLevel.Fatal: logging.FATAL, # 3 -> 50
    # }
    if level.value == 0:
        # This incurs a large performance hit!
        logger.debug(msg)
    else:
        logger.log((level.value + 2) * 10, msg)

But no luck?

[jjerphan]

Yes, we entirely disabled libsolv's logs for now. We need to think about how to properly handle them as well as alternative solvers'.

Feel free to open a PR to propose a solution.

[jaimergp]

Would it be reasonable to let libsolv print to stderr directly in debug level?

[jjerphan]

Probably.

Edit: I do not have bandwidth to properly think about it now.

[JeanChristopheMorinPerso]

Not being able to get solver logs from python is quite inconvenient. I had a case this morning where it would have saved me time to have at least some kind of logs.

[jjerphan]

In the short-term, we could can consider changing those lines:

mamba/libmamba/src/solver/libsolv/database.cpp

Lines 112 to 123 in c9c4580

	// 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);

to add such an hard-coded logic for now:

const int level = 3;
::pool_setdebuglevel(pool().raw(), level);

Alternatively discussions in #2288 need to be resumed.