DEBUG log messages emitted on imports

mtreinish commented 2 years ago

Environment

Qiskit Terra version: main (but previous release likely also have the issues
Python version: 3.10
Operating system: Linux

What is happening?

When importing some modules, including the root qiskit namespace, DEBUG log messages get emitted. For example

import qiskit emits:

DEBUG:qiskit.quantum_info.synthesis.two_qubit_decompose:Requested fidelity: None calculated fidelity: 1.0 actual fidelity 0.9999999999999997

and import qiskit.test emits:

DEBUG:qiskit.test.testing_options:{'skip_online': False, 'mock_online': False, 'run_slow': False, 'rec': False}

How can we reproduce the issue?

import logging
logging.basicConfig(level="DEBUG")
import qiskit

What should happen?

We shouldn't be emitting runtime log messages during an import. This is primarily a side effect of code being executed at the module level on import, normally to setup global objects, but emitting these log messages on import is missing the context and really serves no useful purpose.

Any suggestions?

First we need to find all the places this is happening in the tree (I only tested these two paths there might be others). Then we either remove the logging if it serves no purpose (arguable the qiskit.test example falls in this category )or filter the logs from code that is executed on import (the decomposition falls in this example because normally logging the decomposition fidelity can be useful when code is explicitly calling the synthesis routines).

jakelishman commented 2 years ago

For the record, I imported every single component of Terra, and this is the full set of log messages:

In [1]: import logging
   ...: logging.basicConfig(level=logging.NOTSET)
   ...: logging.getLogger("matplotlib").setLevel(logging.WARNING)
   ...: logging.getLogger("asyncio").setLevel(logging.WARNING)
   ...: import importlib
   ...: import pathlib
   ...: for path in pathlib.Path("qiskit").glob("**/*.py"):
   ...:     parents = list(path.parents)[-2::-1]
   ...:     mod = ".".join(str(x.name) for x in parents)
   ...:     if path.name != "__init__.py":
   ...:         mod += "." + path.name[:-3]
   ...:     importlib.import_module(mod)

DEBUG:qiskit.quantum_info.synthesis.two_qubit_decompose:Requested fidelity: None calculated fidelity: 1.0 actual fidelity 0.9999999999999997
INFO:SKQ.SnobFit:
------------------------------------------------------------------------
W. Huyer and A. Neumaier, "Snobfit - Stable Noisy Optimization by Branch and Fit",
 ACM Trans. Math. Software 35 (2008), Article 9.
Software available at www.mat.univie.ac.at/~neum/software/snobfit
------------------------------------------------------------------------
DEBUG:qiskit.test.testing_options:{'skip_online': False, 'mock_online': False, 'run_slow': False, 'rec': False}
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.30208 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.09584 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.07391 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.05817 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.05412 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.05102 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.04506 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.05293 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.06604 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.06390 (ms)
INFO:qiskit.compiler.assembler:Total Assembly Time - 0.06199 (ms)

I think the qiskit.compiler.assembler messages are coming from outside Terra (they appear when the version table is loaded, which loads up the other modules), but I didn't check too deeply where.

mtreinish commented 2 years ago

The test one is something we should just get rid of it's parsing a weird environment variable that sets key value pairs as a single string. Those aren't really used anywhere anymore (except for the caveats related to #862 and something else might be using it) except for the slow test skip piece which is easy enough to pivot to a better mechanism.

The assembler calls are probably from aer on import. It runs some circuits to determine the capabilities of the binary executable: https://github.com/Qiskit/qiskit-aer/blob/24c51a675b8653c8ad2af587d40b795ac94c07c7/qiskit/providers/aer/backends/backend_utils.py#L119-L153 we probably should switch that to some metadata we set to the binary that can be read and avoid doing that on import.

mtreinish commented 2 years ago

The synthesis log message is being caused by this global: https://github.com/Qiskit/qiskit-terra/blob/main/qiskit/quantum_info/synthesis/two_qubit_decompose.py#L1405 which gets used by most of the transpiler and is part of the default set of what gets pulled in on import qiskit.

jakelishman commented 2 years ago

I made the two-qubit decompose variable lazy in #7525 (it was the last thing loading any component of scipy on import), so now the log will appear at the point of first call - I think the message itself is actually useful, and it'd be good to keep. Similarly the SnobFit log message is caused by algorithms loading the optimiser of the same name (it occurs when you import the optional package), so in #7525 that's also now deferred to the point of first use, and we don't have control over it anyway.

The testing options used to be loaded immediately on import, but with #7525 they'll now only be loaded when one of the testing decorators is used that accesses the options, so that'll provide the context - it could be useful still in that sense, so long as we actually support the QISKIT_TESTS environment variable. If not, then we may as well remove the whole thing, and the log with it.

Qiskit / qiskit