Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

transpilation-related commands take extremely long time in Jupyter notebook #8783

Closed
kevinsung opened this issue Sep 23, 2022 · 13 comments · Fixed by #9063
Closed

transpilation-related commands take extremely long time in Jupyter notebook #8783

kevinsung opened this issue Sep 23, 2022 · 13 comments · Fixed by #9063
Labels
bug Something isn't working

Comments

@kevinsung
Copy link
Contributor

kevinsung commented Sep 23, 2022

Environment

  • Qiskit Terra version: 8a3e760
  • Python version: 3.9.13
  • Operating system: Arch Linux

What is happening?

In a Jupyter notebook, the following code cell sometimes takes a very long time (about one minute):

from qiskit.providers.fake_provider import FakeLagosV2
from qiskit.transpiler.passmanager_config import PassManagerConfig

backend = FakeLagosV2()
pass_manager_config = PassManagerConfig.from_backend(backend)

How can we reproduce the issue?

The most consistent way I have found to reproduce this issue is to first execute a seemingly unrelated cell that causes an error:

from qiskit import QuantumCircuit, QuantumRegister
from qiskit.circuit.library import *
from qiskit.providers.fake_provider import FakeLagosV2
from qiskit.transpiler.preset_passmanagers import common

backend = FakeLagosV2()
translation = common.generate_translation_passmanager(
    backend.target
)

qubits = QuantumRegister(5)
circuit = QuantumCircuit(qubits)
circuit.append(XXPlusYYGate(0.1), [0, 1])

transpiled = translation.run(circuit)

After running this cell, the following cell takes a long time (about one minute):

from qiskit.providers.fake_provider import FakeLagosV2
from qiskit.transpiler.passmanager_config import PassManagerConfig

backend = FakeLagosV2()
pass_manager_config = PassManagerConfig.from_backend(backend)

Interrupting the kernel while it is executing gives the following stack trace:

---------------------------------------------------------------------------
KeyboardInterrupt                         Traceback (most recent call last)
Input In [2], in <cell line: 5>()
      2 from qiskit.transpiler.passmanager_config import PassManagerConfig
      4 backend = FakeLagosV2()
----> 5 pass_manager_config = PassManagerConfig.from_backend(backend)

File ~/projects/qiskit-terra/qiskit/transpiler/passmanager_config.py:133, in PassManagerConfig.from_backend(cls, backend, **pass_manager_options)
    131         res.basis_gates = getattr(config, "basis_gates", None)
    132     else:
--> 133         res.basis_gates = backend.operation_names
    134 if res.inst_map is None:
    135     if backend_version < 2:

File ~/projects/qiskit-terra/qiskit/providers/backend.py:351, in BackendV2.operation_names(self)
    348 @property
    349 def operation_names(self) -> List[str]:
    350     """A list of instruction names that the backend supports."""
--> 351     return list(self.target.operation_names)

File ~/projects/qiskit-terra/qiskit/providers/fake_provider/fake_backend.py:171, in FakeBackendV2.target(self)
    169     if self._defs_dict is None:
    170         self._set_defs_dict_from_json()
--> 171     self._target = convert_to_target(
    172         conf_dict=self._conf_dict,
    173         props_dict=self._props_dict,
    174         defs_dict=self._defs_dict,
    175     )
    177 return self._target

File ~/projects/qiskit-terra/qiskit/providers/fake_provider/utils/backend_converter.py:112, in convert_to_target(conf_dict, props_dict, defs_dict)
    109 # If pulse defaults exists use that as the source of truth
    110 if defs_dict is not None:
    111     # TODO remove the usage of PulseDefaults as it will be deprecated in the future
--> 112     pulse_defs = PulseDefaults.from_dict(defs_dict)
    113     inst_map = pulse_defs.instruction_schedule_map
    114     for inst in inst_map.instructions:

File ~/projects/qiskit-terra/qiskit/providers/models/pulsedefaults.py:279, in PulseDefaults.from_dict(cls, data)
    277 if "discriminator" in in_data:
    278     in_data["discriminator"] = Discriminator.from_dict(in_data.pop("discriminator"))
--> 279 return cls(**in_data)

File ~/projects/qiskit-terra/qiskit/providers/models/pulsedefaults.py:206, in PulseDefaults.__init__(self, qubit_freq_est, meas_freq_est, buffer, pulse_library, cmd_def, meas_kernel, discriminator, **kwargs)
    204 self.converter = QobjToInstructionConverter(pulse_library)
    205 for inst in cmd_def:
--> 206     pulse_insts = [self.converter(inst) for inst in inst.sequence]
    207     schedule = Schedule(*pulse_insts, name=inst.name)
    208     schedule.metadata["publisher"] = CalibrationPublisher.BACKEND_PROVIDER

File ~/projects/qiskit-terra/qiskit/providers/models/pulsedefaults.py:206, in <listcomp>(.0)
    204 self.converter = QobjToInstructionConverter(pulse_library)
    205 for inst in cmd_def:
--> 206     pulse_insts = [self.converter(inst) for inst in inst.sequence]
    207     schedule = Schedule(*pulse_insts, name=inst.name)
    208     schedule.metadata["publisher"] = CalibrationPublisher.BACKEND_PROVIDER

File ~/projects/qiskit-terra/qiskit/qobj/converters/pulse_instruction.py:443, in QobjToInstructionConverter.__call__(self, instruction)
    441 def __call__(self, instruction):
    442     method = self.bind_name.get_bound_method(instruction.name)
--> 443     return method(self, instruction)

File ~/projects/qiskit-terra/qiskit/qobj/converters/pulse_instruction.py:580, in QobjToInstructionConverter.convert_shift_phase(self, instruction)
    578 t0 = instruction.t0
    579 channel = self.get_channel(instruction.ch)
--> 580 phase = self.disassemble_value(instruction.phase)
    582 return instructions.ShiftPhase(phase, channel) << t0

File ~/projects/qiskit-terra/qiskit/qobj/converters/pulse_instruction.py:484, in QobjToInstructionConverter.disassemble_value(value_expr)
    472 """A helper function to format instruction operand.
    473 
    474 If parameter in string representation is specified, this method parses the
   (...)
    481     Parsed operand value. ParameterExpression object is returned if value is not number.
    482 """
    483 if isinstance(value_expr, str):
--> 484     str_expr = parse_string_expr(value_expr, partial_binding=False)
    485     value_expr = str_expr(**{pname: Parameter(pname) for pname in str_expr.params})
    486 return value_expr

File ~/projects/qiskit-terra/qiskit/pulse/parser.py:326, in parse_string_expr(source, partial_binding)
    323 for match, sub in subs:
    324     source = source.replace(match, sub)
--> 326 return PulseExpression(source, partial_binding)

File ~/projects/qiskit-terra/qiskit/pulse/parser.py:87, in PulseExpression.__init__(self, source, partial_binding)
     84         raise PulseError(f"{source} is invalid expression.") from ex
     86 # parse parameters
---> 87 self.visit(self._tree)

File /usr/lib/python3.9/ast.py:407, in NodeVisitor.visit(self, node)
    405 method = 'visit_' + node.__class__.__name__
    406 visitor = getattr(self, method, self.generic_visit)
--> 407 return visitor(node)

File ~/projects/qiskit-terra/qiskit/pulse/parser.py:172, in PulseExpression.visit_Expression(self, node)
    163 def visit_Expression(self, node: ast.Expression) -> ast.Expression:
    164     """Evaluate children nodes of expression.
    165 
    166     Args:
   (...)
    170         Evaluated value.
    171     """
--> 172     tmp_node = copy.deepcopy(node)
    173     tmp_node.body = self.visit(tmp_node.body)
    175     return tmp_node

File /usr/lib/python3.9/copy.py:172, in deepcopy(x, memo, _nil)
    170                 y = x
    171             else:
--> 172                 y = _reconstruct(x, memo, *rv)
    174 # If is its own copy, don't memoize.
    175 if y is not x:

File /usr/lib/python3.9/copy.py:270, in _reconstruct(x, memo, func, args, state, listiter, dictiter, deepcopy)
    268 if state is not None:
    269     if deep:
--> 270         state = deepcopy(state, memo)
    271     if hasattr(y, '__setstate__'):
    272         y.__setstate__(state)

File /usr/lib/python3.9/copy.py:146, in deepcopy(x, memo, _nil)
    144 copier = _deepcopy_dispatch.get(cls)
    145 if copier is not None:
--> 146     y = copier(x, memo)
    147 else:
    148     if issubclass(cls, type):

File /usr/lib/python3.9/copy.py:230, in _deepcopy_dict(x, memo, deepcopy)
    228 memo[id(x)] = y
    229 for key, value in x.items():
--> 230     y[deepcopy(key, memo)] = deepcopy(value, memo)
    231 return y

File /usr/lib/python3.9/copy.py:172, in deepcopy(x, memo, _nil)
    170                 y = x
    171             else:
--> 172                 y = _reconstruct(x, memo, *rv)
    174 # If is its own copy, don't memoize.
    175 if y is not x:

File /usr/lib/python3.9/copy.py:270, in _reconstruct(x, memo, func, args, state, listiter, dictiter, deepcopy)
    268 if state is not None:
    269     if deep:
--> 270         state = deepcopy(state, memo)
    271     if hasattr(y, '__setstate__'):
    272         y.__setstate__(state)

File /usr/lib/python3.9/copy.py:146, in deepcopy(x, memo, _nil)
    144 copier = _deepcopy_dispatch.get(cls)
    145 if copier is not None:
--> 146     y = copier(x, memo)
    147 else:
    148     if issubclass(cls, type):

File /usr/lib/python3.9/copy.py:230, in _deepcopy_dict(x, memo, deepcopy)
    228 memo[id(x)] = y
    229 for key, value in x.items():
--> 230     y[deepcopy(key, memo)] = deepcopy(value, memo)
    231 return y

    [... skipping similar frames: deepcopy at line 146 (18 times), _deepcopy_dict at line 230 (17 times), _reconstruct at line 270 (17 times), deepcopy at line 172 (17 times)]

File /usr/lib/python3.9/copy.py:205, in _deepcopy_list(x, memo, deepcopy)
    203 append = y.append
    204 for a in x:
--> 205     append(deepcopy(a, memo))
    206 return y

    [... skipping similar frames: deepcopy at line 146 (3 times), _deepcopy_dict at line 230 (2 times), _reconstruct at line 270 (2 times), deepcopy at line 172 (2 times)]

File /usr/lib/python3.9/copy.py:205, in _deepcopy_list(x, memo, deepcopy)
    203 append = y.append
    204 for a in x:
--> 205     append(deepcopy(a, memo))
    206 return y

    [... skipping similar frames: deepcopy at line 146 (29 times), _deepcopy_dict at line 230 (22 times), _reconstruct at line 270 (22 times), deepcopy at line 172 (22 times), _deepcopy_list at line 205 (6 times)]

File /usr/lib/python3.9/copy.py:205, in _deepcopy_list(x, memo, deepcopy)
    203 append = y.append
    204 for a in x:
--> 205     append(deepcopy(a, memo))
    206 return y

    [... skipping similar frames: deepcopy at line 172 (3 times), _deepcopy_dict at line 230 (2 times), _reconstruct at line 270 (2 times), deepcopy at line 146 (2 times)]

File /usr/lib/python3.9/copy.py:270, in _reconstruct(x, memo, func, args, state, listiter, dictiter, deepcopy)
    268 if state is not None:
    269     if deep:
--> 270         state = deepcopy(state, memo)
    271     if hasattr(y, '__setstate__'):
    272         y.__setstate__(state)

File /usr/lib/python3.9/copy.py:146, in deepcopy(x, memo, _nil)
    144 copier = _deepcopy_dispatch.get(cls)
    145 if copier is not None:
--> 146     y = copier(x, memo)
    147 else:
    148     if issubclass(cls, type):

File /usr/lib/python3.9/copy.py:230, in _deepcopy_dict(x, memo, deepcopy)
    228 memo[id(x)] = y
    229 for key, value in x.items():
--> 230     y[deepcopy(key, memo)] = deepcopy(value, memo)
    231 return y

File /usr/lib/python3.9/copy.py:172, in deepcopy(x, memo, _nil)
    170                 y = x
    171             else:
--> 172                 y = _reconstruct(x, memo, *rv)
    174 # If is its own copy, don't memoize.
    175 if y is not x:

File /usr/lib/python3.9/copy.py:264, in _reconstruct(x, memo, func, args, state, listiter, dictiter, deepcopy)
    262 if deep and args:
    263     args = (deepcopy(arg, memo) for arg in args)
--> 264 y = func(*args)
    265 if deep:
    266     memo[id(x)] = y

File /usr/lib/python3.9/copyreg.py:95, in __newobj__(cls, *args)
     94 def __newobj__(cls, *args):
---> 95     return cls.__new__(cls, *args)

File <string>:1, in <lambda>(_cls, type, string, start, end, line, index, startpos, endpos)

KeyboardInterrupt: 

What should happen?

It should execute in at most a few seconds; certainly not one minute.

Any suggestions?

No response

@kevinsung kevinsung added the bug Something isn't working label Sep 23, 2022
@jlapeyre
Copy link
Contributor

I run your example on the command line (ipython): 1) the code that produces an error 2) The code that runs slow in Jupyter

The code does not run slow. It finishes in about 100 ms. I am using Python 3.10.5 . Did you try the command line ?

@kevinsung
Copy link
Contributor Author

No, I did not. Are you able to reproduce the issue in a Jupyter notebook?

@jlapeyre
Copy link
Contributor

jlapeyre commented Sep 23, 2022

I'll try. I'm installing terra in a python 3.9 venv so I can test that. While it's installing requirements, I'll try Jupyter.

@jlapeyre
Copy link
Contributor

I do not see the slowdown in Jupyter. Still 100ms to execute the example after first running the code that errors.

  • Python 3.10.
  • Fedora Linux

@jlapeyre
Copy link
Contributor

jlapeyre commented Sep 23, 2022

@kevinsung, I do see the slowdown with the following

  • Python 3.9.14
  • Terra 8a3e760
  • Arch linux
  • ipython 8.5.0, command line

If I change only the Python version to 3.10.5, I do not see the slowdown.

EDIT: I also confirm that the bug does not occur if I omit first running the "unrelated" code that errors.

@kevinsung
Copy link
Contributor Author

This is very interesting. Thanks for the investigation @jlapeyre !

@jlapeyre
Copy link
Contributor

It appears that the number of calls to this line
https://github.com/Qiskit/qiskit-terra/blob/f98ddc6ddaf68475b9aca717fa8c91646c60a2da/qiskit/pulse/parser.py#L172
does not change when running the test code with and without the "preamble". But, the time for each deepcopy call is much larger if the preamble runs first, which accounts for the slow down. Furthermore I don't see anything that looks like a memory leak. Replacing deepcopy by copy here avoids the slow down, but of course may not give correct behavior.

It seems almost certain that some state is being preserved unintentionally. (Mutable) state is the root of all evil. I won't be able to continue with this till at least after Thursday. I guess someone with a bit more familiarity with this code might find the problem quickly.

@kevinsung
Copy link
Contributor Author

I've found an example that causes slowdown with Python 3.10. Copy the following into a code cell. The first time you execute the cell, it's fast (and results in an error). Subsequent executions are very slow.

%%time

from qiskit import *
from qiskit.circuit.library import *
from qiskit.providers.fake_provider import FakeBelemV2
from qiskit.quantum_info import Operator
from qiskit.transpiler import PassManager
from qiskit.transpiler.passes import *
from qiskit.transpiler.passmanager import StagedPassManager
from qiskit.transpiler.passmanager_config import PassManagerConfig
from qiskit.transpiler.preset_passmanagers.common import *
from qiskit.transpiler.preset_passmanagers.plugin import *


def generate_pass_manager(backend) -> PassManager:
    plugin_manager = PassManagerStagePluginManager()
    pass_manager_config = PassManagerConfig.from_backend(backend)

    init = generate_unroll_3q(backend.target)
    layout = PassManager()
    layout.append(
        SabreLayout(backend.coupling_map, max_iterations=4, seed=None, swap_trials=20)
    )
    layout += generate_embed_passmanager(backend.coupling_map)
    routing = plugin_manager.get_passmanager_stage(
        "routing", "sabre", pass_manager_config, optimization_level=3
    )
    # TODO should not have to pass basis_gates separately
    # see https://github.com/Qiskit/qiskit-terra/pull/8784
    translation = generate_translation_passmanager(
        backend.target, basis_gates=backend.operation_names
    )

    return StagedPassManager(
        init=init,
        layout=layout,
        pre_routing=None,
        routing=routing,
        translation=translation,
        pre_optimization=None,
        optimization=None,
        scheduling=None,
    )


system_register = QuantumRegister(4)
control_register = QuantumRegister(1)
circuit = QuantumCircuit(system_register, control_register)
circuit.append(
    RZZGate(0.1).control(1),
    list(control_register) + [system_register[0], system_register[1]],
)

backend = FakeBelemV2()
pass_manager = generate_pass_manager(backend)
transpiled = pass_manager.run(circuit)

assert Operator.from_circuit(transpiled).equiv(
    Operator.from_circuit(circuit), atol=1e-8
)

@jlapeyre
Copy link
Contributor

jlapeyre commented Oct 7, 2022

That's a good clue. It's pretty clear that it's unlikely that the bug is in Python (3.9 or 3.10), but rather our code is erroneously keeping some state. Probably when creating ASTs.

@alexanderivrii
Copy link
Contributor

FWIW, I have run the code above in the jupyter notebook, windows 10, python 3.10, trunk version of terra; on the first run it takes about 2.3s; on every consecutive run it takes about 130 ms -- so for me it's actually much faster on subsequent executions. And I have run the above experiment several times -- the results are consistent across runs.

@nonhermitian
Copy link
Contributor

I can reproduce this as well when raising an error and then trying to transpile.

First do

from qiskit import *
from qiskit.providers.fake_provider import FakeHanoi

backend = FakeHanoi()

for edge in backend.coupling_map:
    print(edge)

which raises an attribute error because the backend is v1, not v2. Then do:

qc = QuantumCircuit(1)
qc.x(0)
qc.measure_all()

transpile(qc, backend)

This always hangs.

@nonhermitian
Copy link
Contributor

It does not happen for BackendV2 objects

@jakelishman
Copy link
Member

I wasn't able to use any of these cells to reliably reproduce the issue, but I think #9063 should hopefully fix the issue? I saw the deepcopy as looking very questionable, so I just made it shallow, and propagated through the shallow copy to any mutated nodes.

Could people verify if it fixes their problems?

@mergify mergify bot closed this as completed in #9063 Nov 3, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants