Qiskit-terra: Random crashes on TextProgressBar

[manoelmarques]

Information

• Qiskit Terra version: 0.16.0
• Python version: 3.7
• Operating system: Ubuntu 18.04, but actually any OS VM with 1 processor core

What is the current behavior?

Aqua uses TextProgressBar in several places and so it happens that sometimes the usage is reentrant. The problem is that the event infrastructure in Terra is global and sometimes we get crashes on the instance variable the TextBarProgress keeps (self.iter) since a single TextProgressBar receives all those events from parallel_map in mixed orders when actually they should apply to separate progress bars

Steps to reproduce the problem

This fails on a VM with 1 processor core:

import logging
import numpy as np

# Qiskit components
from qiskit import Aer, __qiskit_version__
from qiskit.circuit.library import RealAmplitudes, EfficientSU2
from qiskit.chemistry.components.initial_states import HartreeFock
from qiskit.aqua import QuantumInstance, set_qiskit_aqua_logging
from qiskit.aqua.algorithms import VQE, NumPyMinimumEigensolver
from qiskit.chemistry import set_qiskit_chemistry_logging
from qiskit.chemistry.applications import MolecularGroundStateEnergy
from qiskit.chemistry.core import TransformationType, QubitMappingType
from qiskit.aqua.components.optimizers import COBYLA, SPSA, SLSQP, CG, L_BFGS_B
from qiskit.chemistry.drivers import PySCFDriver, UnitsType
from qiskit.chemistry.components.variational_forms import UCCSD

set_qiskit_chemistry_logging(logging.DEBUG)
set_qiskit_aqua_logging(logging.DEBUG)
logging.info(__qiskit_version__)
logger = logging.getLogger(__name__)


def cb_create_solver_vqe(num_particles, num_orbitals,
                         qubit_mapping, two_qubit_reduction, z2_symmetries):
    print('z2 symmetries : {}'.format(z2_symmetries))

    initial_state = HartreeFock(num_orbitals, num_particles, qubit_mapping,
                                two_qubit_reduction, z2_symmetries.sq_list)
    var_form = UCCSD(num_orbitals=num_orbitals,
                     num_particles=num_particles,
                     initial_state=initial_state,
                     qubit_mapping=qubit_mapping,
                     two_qubit_reduction=two_qubit_reduction,
                     z2_symmetries=z2_symmetries)

    initial_point =  0.01*np.random.uniform(-2*np.pi, np.pi, size = var_form.num_parameters) 
    optimizer =  SLSQP(maxiter = 1)

    vqe = VQE(var_form=var_form, optimizer=optimizer,
              initial_point=initial_point, include_custom=True)
    vqe.quantum_instance = QuantumInstance(Aer.get_backend('qasm_simulator'), shots=1)
    return vqe


def cb_create_solver_nes(num_particles, num_orbitals,
                         qubit_mapping, two_qubit_reduction, z2_symmetries):
    nes = NumPyMinimumEigensolver()
    return nes


DO_CLASSICAL = False


def main():
    # Molecule
    print('Begin main')
    # mol_geom = ["Li -0.1137 -2.139 0.0; S 0.0 0.0 0.0; H 1.353 0.0 0.0"]
    mol_geom = ['Li 0.0 0.0 1.375; H 0.0 0.0 -1.375']
    num_geom = len(mol_geom)
    results = np.zeros([num_geom])
    for i in range(num_geom): 
        atom = mol_geom[i]
        print('mol geom[{}]: {}'.format(i,atom))
        driver = PySCFDriver(atom=atom, unit=UnitsType.ANGSTROM,charge=0, spin=0, basis='sto3g')

        mgse = MolecularGroundStateEnergy(driver, transformation=TransformationType.PARTICLE_HOLE,
                                          qubit_mapping=QubitMappingType.PARITY,
                                          two_qubit_reduction=True, freeze_core=True,
                                          orbital_reduction=[], z2symmetry_reduction='auto')
        solver = cb_create_solver_nes if DO_CLASSICAL else cb_create_solver_vqe
        result = mgse.compute_energy(solver)
        print(result)   


if __name__ == "__main__":
    main()

What is the expected behavior?

TextProgressBar should receive events in order and just the ones that apply to that instance.

Suggested solutions

We thought of one solution that might work: The parallel_map method and TextProgressBar class would accept some optional event id. The id could be appended/prepended to the global Terra event string so that when time comes to emit the event in parallel map, it knows how to emit the ones that are start or end etc. This way there would be no clobbering of states.

And the publisher/subscriber would still work the same way not allowing the same event string more than once.

So each parallel_map method invocation would have 3 unique events: one start, one end and one update.

[levbishop]

I think tqdm progress bars can support this. Maybe we can consider using them instead of our home grown bars?
EDIT: Never mind, I misunderstood the issue

[nonhermitian]

This has nothing to do with the progress bars themselves. Rather it is the pubsub mechanism and how things listen to very general events that can easily conflict with others.

[renier]

You can see this consistently when using the UCCSD() function in aqua under the following conditions:

• You enable the DEBUG log level
• local_hardware_info() sees only one CPU, or you export QISKIT_IN_PARALLEL=TRUE before running the program.

# https://github.com/Qiskit/qiskit-aqua/blob/0.7.5/qiskit/chemistry/components/variational_forms/uccsd.py#L239-L241
def _build_hopping_operators(self):
        if logger.isEnabledFor(logging.DEBUG):
            TextProgressBar(sys.stderr)

UCCSD instantiates progress bar subscriptions when in DEBUG log level. These functions can send an empty value list to parallel_map(). This case was seen already in #3634 and was fixed by making it return early where otherwise the progress bar would blow up with a division by zero.

However, even though the parallel_map returns early, the progress bar was already subscribed AND is uninitialized until there is a terra.parallel.start event.

For some reason I have not figured out, the update function on the progress bar can still get called in this uninitialized state, which results in this traceback:

Traceback (most recent call last):
  File "qprogram.py", line 99, in <module>
    result = main(callback = user_feedback,backend=Aer.get_backend("statevector_simulator"))
  File "qprogram.py", line 86, in main
    two_qubit_reduction=qubit_reduction, num_time_slices=1)
  File "/usr/local/lib/python3.7/site-packages/qiskit/chemistry/components/variational_forms/uccsd.py", line 157, in __init__
    self._hopping_ops, self._num_parameters = self._build_hopping_operators()
  File "/usr/local/lib/python3.7/site-packages/qiskit/chemistry/components/variational_forms/uccsd.py", line 249, in _build_hopping_operators
    num_processes=aqua_globals.num_processes)
  File "/usr/local/lib/python3.7/site-packages/qiskit/tools/parallel.py", line 149, in parallel_map
    _callback(0)
  File "/usr/local/lib/python3.7/site-packages/qiskit/tools/parallel.py", line 115, in _callback
    Publisher().publish("terra.parallel.done", nfinished[0])
  File "/usr/local/lib/python3.7/site-packages/qiskit/tools/events/pubsub.py", line 135, in publish
    return self._broker.dispatch(event, *args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/qiskit/tools/events/pubsub.py", line 97, in dispatch
    subscriber.callback(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/qiskit/tools/events/progressbar.py", line 139, in _update_progress_bar
    self.update(progress)
  File "/usr/local/lib/python3.7/site-packages/qiskit/tools/events/progressbar.py", line 163, in update
    filled_length = int(round(50 * n / self.iter))
TypeError: unsupported operand type(s) for /: 'int' and 'NoneType'

self.iter is None, since the progress bar start() was never called to set it.

     # https://github.com/Qiskit/qiskit-terra/blob/0.15.1/qiskit/tools/events/progressbar.py#L158
     filled_length = int(round(50 * n / self.iter))  # self.iter is None

The progress bar could check if it has been initialized based on self.touched before updating. However, a race condition would mean that something else that was not able to subscribe (collided due to an existing subscription) would still go on and publish events which would trigger a subscribed/uninitialized listener. Perhaps this is the cause for the above.

[mtreinish]

So I agree with the problem here it looks like the previous subscriber when aqua calls parallel_map([], ...) doesn't exit out. I think the fix for comparing the subscribers object ids is a good way to handle this. It does feel like there is an aqua bug here (which is what I mentioned in #3634) but this is simple enough to fix. The other thing which I tried was to force the text progress bar subscriber to exit when the fast paths for len() 0 and 1:

--- a/qiskit/tools/parallel.py
+++ b/qiskit/tools/parallel.py
@@ -101,21 +101,25 @@ def parallel_map(  # pylint: disable=dangerous-default-value
         terra.parallel.finish: All the parallel tasks have finished.
     """
     if len(values) == 0:
+        Publisher().publish("terra.parallel.start", len(values))
+        Publisher().publish("terra.parallel.finish")
         return []
     if len(values) == 1:
+        Publisher().publish("terra.parallel.start", len(values))
+        Publisher().publish("terra.parallel.finish")
         return [task(values[0], *task_args, **task_kwargs)]

Which also fixed the failures, but still seems more hacky than comparing the object ids.