Log time for execute steps (#3922)

* Added logging for total transpile time * Added logging for total assembly time * Added total schedule time logging * Added total schedule time logging * Added logging for job submission and fixed linting errors * Fixed linting errors * Update qiskit/compiler/assemble.py time.time returns a time in seconds. Co-Authored-By: Kevin Krsulich <[email protected]> * Update qiskit/execute.py Change LOG to logger for consistency Co-Authored-By: Kevin Krsulich <[email protected]> * Update test/python/basicaer/test_qasm_simulator.py log_output better than output Co-Authored-By: Kevin Krsulich <[email protected]> * Made updates to job submission based on PR comments * Fixed styling error * Fixed test error * Revert "Update qiskit/compiler/assemble.py " This reverts commit 86219c7. * Update test/python/compiler/test_transpiler.py Co-Authored-By: Matthew Treinish <[email protected]> * Update test/python/compiler/test_assembler.py Co-Authored-By: Matthew Treinish <[email protected]> * Update test/python/basicaer/test_qasm_simulator.py Co-Authored-By: Matthew Treinish <[email protected]> Co-authored-by: Kevin Krsulich <[email protected]> Co-authored-by: Kevin Krsulich <[email protected]> Co-authored-by: Matthew Treinish <[email protected]>
Qiskit · Apr 7, 2020 · 9d7c711 · 9d7c711
1 parent 5571747
commit 9d7c711
Show file tree

Hide file tree

Showing 7 changed files with 163 additions and 2 deletions.
diff --git a/qiskit/compiler/assemble.py b/qiskit/compiler/assemble.py
@@ -15,6 +15,8 @@
 """Assemble function for converting a list of circuits into a qobj"""
 import uuid
 import copy
+import logging
+from time import time
 
 from typing import Union, List, Dict, Optional
 from qiskit.circuit import QuantumCircuit, Qubit, Parameter
@@ -29,6 +31,13 @@
 from qiskit.pulse.channels import PulseChannel
 from qiskit.pulse import Schedule
 
+LOG = logging.getLogger(__name__)
+
+
+def _log_assembly_time(start_time, end_time):
+    log_msg = "Total Assembly Time - %.5f (ms)" % ((end_time - start_time) * 1000)
+    LOG.info(log_msg)
+
 
 # TODO: parallelize over the experiments (serialize each separately, then add global header/config)
 def assemble(experiments: Union[QuantumCircuit, List[QuantumCircuit], Schedule, List[Schedule]],
@@ -117,6 +126,7 @@ def assemble(experiments: Union[QuantumCircuit, List[QuantumCircuit], Schedule,
     Raises:
         QiskitError: if the input cannot be interpreted as either circuits or schedules
     """
+    start_time = time()
     experiments = experiments if isinstance(experiments, list) else [experiments]
     qobj_id, qobj_header, run_config_common_dict = _parse_common_args(backend, qobj_id, qobj_header,
                                                                       shots, memory, max_credits,
@@ -129,6 +139,8 @@ def assemble(experiments: Union[QuantumCircuit, List[QuantumCircuit], Schedule,
         # If circuits are parameterized, bind parameters and remove from run_config
         bound_experiments, run_config = _expand_parameters(circuits=experiments,
                                                            run_config=run_config)
+        end_time = time()
+        _log_assembly_time(start_time, end_time)
         return assemble_circuits(circuits=bound_experiments, qobj_id=qobj_id,
                                  qobj_header=qobj_header, run_config=run_config)
 
@@ -140,6 +152,8 @@ def assemble(experiments: Union[QuantumCircuit, List[QuantumCircuit], Schedule,
                                        parametric_pulses,
                                        **run_config_common_dict)
 
+        end_time = time()
+        _log_assembly_time(start_time, end_time)
         return assemble_schedules(schedules=experiments, qobj_id=qobj_id,
                                   qobj_header=qobj_header, run_config=run_config)
 

diff --git a/qiskit/compiler/schedule.py b/qiskit/compiler/schedule.py
@@ -16,6 +16,9 @@
 Convenience entry point into pulse scheduling, requiring only a circuit and a backend. For more
 control over pulse scheduling, look at `qiskit.scheduler.schedule_circuit`.
 """
+import logging
+
+from time import time
 from typing import List, Optional, Union
 
 from qiskit.circuit.quantumcircuit import QuantumCircuit
@@ -24,6 +27,13 @@
 from qiskit.providers import BaseBackend
 from qiskit.scheduler import schedule_circuit, ScheduleConfig
 
+LOG = logging.getLogger(__name__)
+
+
+def _log_schedule_time(start_time, end_time):
+    log_msg = "Total Scheduling Time - %.5f (ms)" % ((end_time - start_time) * 1000)
+    LOG.info(log_msg)
+
 
 def schedule(circuits: Union[QuantumCircuit, List[QuantumCircuit]],
              backend: Optional[BaseBackend] = None,
@@ -49,6 +59,7 @@ def schedule(circuits: Union[QuantumCircuit, List[QuantumCircuit]],
     Raises:
         QiskitError: If ``inst_map`` and ``meas_map`` are not passed and ``backend`` is not passed
     """
+    start_time = time()
     if inst_map is None:
         if backend is None:
             raise QiskitError("Must supply either a backend or InstructionScheduleMap for "
@@ -62,4 +73,6 @@ def schedule(circuits: Union[QuantumCircuit, List[QuantumCircuit]],
     schedule_config = ScheduleConfig(inst_map=inst_map, meas_map=meas_map)
     circuits = circuits if isinstance(circuits, list) else [circuits]
     schedules = [schedule_circuit(circuit, schedule_config, method) for circuit in circuits]
+    end_time = time()
+    _log_schedule_time(start_time, end_time)
     return schedules[0] if len(schedules) == 1 else schedules
diff --git a/qiskit/compiler/transpile.py b/qiskit/compiler/transpile.py
@@ -13,6 +13,8 @@
 # that they have been altered from the originals.
 
 """Circuit transpile function"""
+import logging
+from time import time
 import warnings
 from typing import List, Union, Dict, Callable, Any, Optional, Tuple
 from qiskit.circuit.quantumcircuit import QuantumCircuit
@@ -34,6 +36,8 @@
                                                    level_2_pass_manager,
                                                    level_3_pass_manager)
 
+LOG = logging.getLogger(__name__)
+
 
 def transpile(circuits: Union[QuantumCircuit, List[QuantumCircuit]],
               backend: Optional[BaseBackend] = None,
@@ -165,10 +169,15 @@ def callback_func(**kwargs):
     circuits = circuits if isinstance(circuits, list) else [circuits]
 
     # transpiling schedules is not supported yet.
+    start_time = time()
     if all(isinstance(c, Schedule) for c in circuits):
         warnings.warn("Transpiling schedules is not supported yet.", UserWarning)
         if len(circuits) == 1:
+            end_time = time()
+            _log_transpile_time(start_time, end_time)
             return circuits[0]
+        end_time = time()
+        _log_transpile_time(start_time, end_time)
         return circuits
 
     if pass_manager is not None:
@@ -201,7 +210,11 @@ def callback_func(**kwargs):
     circuits = parallel_map(_transpile_circuit, list(zip(circuits, transpile_args)))
 
     if len(circuits) == 1:
+        end_time = time()
+        _log_transpile_time(start_time, end_time)
         return circuits[0]
+    end_time = time()
+    _log_transpile_time(start_time, end_time)
     return circuits
 
 
@@ -234,6 +247,11 @@ def _check_circuits_coupling_map(circuits, transpile_args, backend):
                                   'in the coupling_map')
 
 
+def _log_transpile_time(start_time, end_time):
+    log_msg = "Total Transpile Time - %.5f (ms)" % ((end_time - start_time) * 1000)
+    LOG.info(log_msg)
+
+
 def _transpile_circuit(circuit_config_tuple: Tuple[QuantumCircuit, Dict]) -> QuantumCircuit:
     """Select a PassManager and run a single circuit through it.
     Args:

diff --git a/qiskit/execute.py b/qiskit/execute.py
@@ -21,11 +21,21 @@
 
 .. autofunction:: execute
 """
+import logging
+from time import time
 from qiskit.compiler import transpile, assemble, schedule
 from qiskit.qobj.utils import MeasLevel, MeasReturnType
 from qiskit.pulse import Schedule
 from qiskit.exceptions import QiskitError
 
+logger = logging.getLogger(__name__)
+
+
+def _log_submission_time(start_time, end_time):
+    log_msg = ("Total Job Submission Time - %.5f (ms)"
+               % ((end_time - start_time) * 1000))
+    logger.info(log_msg)
+
 
 def execute(experiments, backend,
             basis_gates=None, coupling_map=None,  # circuit transpile options
@@ -214,7 +224,6 @@ def execute(experiments, backend,
 
             job = execute(qc, backend, shots=4321)
     """
-
     # transpiling the circuits using given transpile options
     if pass_manager is not None:
         _check_conflicting_argument(optimization_level=optimization_level, basis_gates=basis_gates,
@@ -264,7 +273,11 @@ def execute(experiments, backend,
                     )
 
     # executing the circuits on the backend and returning the job
-    return backend.run(qobj, **run_config)
+    start_time = time()
+    job = backend.run(qobj, **run_config)
+    end_time = time()
+    _log_submission_time(start_time, end_time)
+    return job
 
 
 def _check_conflicting_argument(**kargs):

diff --git a/test/python/basicaer/test_qasm_simulator.py b/test/python/basicaer/test_qasm_simulator.py
@@ -15,6 +15,9 @@
 """Test QASM simulator."""
 
 import unittest
+import io
+from logging import StreamHandler, getLogger
+import sys
 
 import numpy as np
 
@@ -26,6 +29,13 @@
 from qiskit.test import providers
 
 
+class StreamHandlerRaiseException(StreamHandler):
+    """Handler class that will raise an exception on formatting errors."""
+
+    def handleError(self, record):
+        raise sys.exc_info()
+
+
 class TestBasicAerQasmSimulator(providers.BackendTestCase):
     """Test the Basic qasm_simulator."""
 
@@ -40,6 +50,31 @@ def setUp(self):
         transpiled_circuit.name = 'test'
         transpiled_circuit = transpile(transpiled_circuit, backend=self.backend)
         self.qobj = assemble(transpiled_circuit, shots=1000, seed_simulator=self.seed)
+        logger = getLogger()
+        logger.setLevel('DEBUG')
+        self.log_output = io.StringIO()
+        logger.addHandler(StreamHandlerRaiseException(self.log_output))
+
+    def assertExecuteLog(self, log_msg):
+        """ Runs execute and check for logs containing specified message"""
+        shots = 100
+        qr = QuantumRegister(2, 'qr')
+        cr = ClassicalRegister(4, 'cr')
+        circuit = QuantumCircuit(qr, cr)
+        execute(
+            circuit,
+            backend=self.backend,
+            shots=shots,
+            seed_simulator=self.seed)
+        self.log_output.seek(0)
+        # Filter unrelated log lines
+        output_lines = self.log_output.readlines()
+        execute_log_lines = [x for x in output_lines if log_msg in x]
+        self.assertTrue(len(execute_log_lines) > 0)
+
+    def test_submission_log_time(self):
+        """Check Total Job Submission Time is logged"""
+        self.assertExecuteLog('Total Job Submission Time')
 
     def test_qasm_simulator_single_shot(self):
         """Test single shot run."""

diff --git a/test/python/compiler/test_assembler.py b/test/python/compiler/test_assembler.py
@@ -15,6 +15,9 @@
 """Assembler Test."""
 
 import unittest
+import io
+from logging import StreamHandler, getLogger
+import sys
 
 import numpy as np
 import qiskit.pulse as pulse
@@ -868,5 +871,36 @@ def test_single_and_deprecated_acquire_styles(self):
         self.assertEqual(assembled_acquire.memory_slot, [0, 1, 2, 3, 4])
 
 
+class StreamHandlerRaiseException(StreamHandler):
+    """Handler class that will raise an exception on formatting errors."""
+
+    def handleError(self, record):
+        raise sys.exc_info()
+
+
+class TestLogAssembler(QiskitTestCase):
+    """Testing the log_assembly option."""
+
+    def setUp(self):
+        logger = getLogger()
+        logger.setLevel('DEBUG')
+        self.output = io.StringIO()
+        logger.addHandler(StreamHandlerRaiseException(self.output))
+        self.circuit = QuantumCircuit(QuantumRegister(1))
+
+    def assertAssembleLog(self, log_msg):
+        """ Runs assemble and checks for logs containing specified message"""
+        assemble(self.circuit, shots=2000, memory=True)
+        self.output.seek(0)
+        # Filter unrelated log lines
+        output_lines = self.output.readlines()
+        assembly_log_lines = [x for x in output_lines if log_msg in x]
+        self.assertTrue(len(assembly_log_lines) == 1)
+
+    def test_assembly_log_time(self):
+        """Check Total Assembly Time is logged"""
+        self.assertAssembleLog('Total Assembly Time')
+
+
 if __name__ == '__main__':
     unittest.main(verbosity=2)
diff --git a/test/python/compiler/test_transpiler.py b/test/python/compiler/test_transpiler.py
@@ -16,7 +16,10 @@
 
 import math
 import unittest
+import io
+from logging import StreamHandler, getLogger
 from unittest.mock import patch
+import sys
 from ddt import ddt, data
 
 from qiskit import BasicAer
@@ -696,6 +699,37 @@ def test_measure_doesnt_unroll_ms(self, optimization_level):
         self.assertEqual(qc, out)
 
 
+class StreamHandlerRaiseException(StreamHandler):
+    """Handler class that will raise an exception on formatting errors."""
+
+    def handleError(self, record):
+        raise sys.exc_info()
+
+
+class TestLogTranspile(QiskitTestCase):
+    """Testing the log_transpile option."""
+
+    def setUp(self):
+        logger = getLogger()
+        logger.setLevel('DEBUG')
+        self.output = io.StringIO()
+        logger.addHandler(StreamHandlerRaiseException(self.output))
+        self.circuit = QuantumCircuit(QuantumRegister(1))
+
+    def assertTranspileLog(self, log_msg):
+        """ Runs the transpiler and check for logs containing specified message"""
+        transpile(self.circuit)
+        self.output.seek(0)
+        # Filter unrelated log lines
+        output_lines = self.output.readlines()
+        transpile_log_lines = [x for x in output_lines if log_msg in x]
+        self.assertTrue(len(transpile_log_lines) > 0)
+
+    def test_transpile_log_time(self):
+        """Check Total Transpile Time is logged"""
+        self.assertTranspileLog('Total Transpile Time')
+
+
 class TestTranspileCustomPM(QiskitTestCase):
     """Test transpile function with custom pass manager"""