diff --git a/pip/qsharp/interop/qiskit/backends/backend_base.py b/pip/qsharp/interop/qiskit/backends/backend_base.py index d7da53b608..5faf2c2557 100644 --- a/pip/qsharp/interop/qiskit/backends/backend_base.py +++ b/pip/qsharp/interop/qiskit/backends/backend_base.py @@ -4,7 +4,7 @@ from abc import ABC, abstractmethod import datetime import logging -import time +from time import monotonic from typing import Dict, Any, List, Optional, Union from warnings import warn @@ -258,7 +258,7 @@ def _run( def run_job( self, run_input: List[QuantumCircuit], job_id: str, **options ) -> Result: - start = time.time() + start = monotonic() compilations = self._compile(run_input, **options) @@ -277,7 +277,9 @@ def run_job( output["status"] = "COMPLETED" output["backend_name"] = self.name output["backend_version"] = self.backend_version - output["time_taken"] = str(time.time() - start) + + duration = monotonic() - start + output["time_taken"] = str(duration) output["config"] = { "qasm_export_options": str(self._build_qasm_export_options(**options)), "qiskit_pass_options": str(self._build_qiskit_pass_options(**options)), @@ -298,10 +300,11 @@ def _compile(self, run_input: List[QuantumCircuit], **options) -> List[Compilati assert isinstance( circuit, QuantumCircuit ), "Input must be a QuantumCircuit." - start = time.time() + start = monotonic() qasm = self._qasm3(circuit, **args) - end = time.time() - time_taken = str(end - start) + end = monotonic() + + time_taken = end - start compilation = Compilation(circuit, qasm, time_taken) compilations.append(compilation) return compilations diff --git a/pip/qsharp/interop/qiskit/jobs/qsjob.py b/pip/qsharp/interop/qiskit/jobs/qsjob.py index 9c0936abff..08f3e00a57 100644 --- a/pip/qsharp/interop/qiskit/jobs/qsjob.py +++ b/pip/qsharp/interop/qiskit/jobs/qsjob.py @@ -4,6 +4,7 @@ from abc import ABC, abstractmethod from concurrent.futures import Executor, Future import logging +from time import monotonic from typing import Callable, Dict, Optional, Any from qiskit.providers import BackendV2 @@ -15,7 +16,7 @@ from qiskit.providers import JobV1, JobStatus, JobError from ..execution import DetaultExecutor - +from .... import telemetry_events from ....estimator import EstimatorResult logger = logging.getLogger(__name__) @@ -43,6 +44,7 @@ def __init__( self._executor: Executor = executor or DetaultExecutor() self._job_callable = job_callable self._status = JobStatus.INITIALIZING + self._submit_start_time = None def submit(self): """Submit the job to the backend for execution. @@ -53,14 +55,20 @@ def submit(self): if self._future is not None: raise JobError("Job has already been submitted.") + self._submit_start_time = monotonic() self._future = self._executor.submit( self._job_callable, self._run_input, self.job_id(), **self._input_params ) + self.add_done_callback(self._submit_duration) @abstractmethod def result(self, timeout: Optional[float] = None) -> Any: pass + @abstractmethod + def _submit_duration(self, _future: Future): + pass + def _result(self, timeout: Optional[float] = None) -> Any: """Return the results of the job.""" if self._future is None: @@ -110,8 +118,45 @@ class QsSimJob(QsJob): def result(self, timeout: Optional[float] = None) -> Result: return self._result(timeout=timeout) + def submit(self): + """Submit the job to the backend for execution. + + Raises: + JobError: if trying to re-submit the job. + """ + shots = self._input_params.get("shots", -1) + telemetry_events.on_qiskit_run(shots, 1) + + super().submit() + + def _submit_duration(self, _future: Future): + end_time = monotonic() + duration_in_sec = end_time - self._submit_start_time + duration_in_ms = duration_in_sec * 1000 + + shots = self._input_params.get("shots", -1) + telemetry_events.on_qiskit_run_end(shots, 1, duration_in_ms) + class ReJob(QsJob): def result(self, timeout: Optional[float] = None) -> EstimatorResult: return self._result(timeout=timeout) + + def submit(self): + """Submit the job to the backend for execution. + + Raises: + JobError: if trying to re-submit the job. + """ + + telemetry_events.on_qiskit_run_re() + + super().submit() + + def _submit_duration(self, _future: Future): + end_time = monotonic() + duration_in_sec = end_time - self._submit_start_time + duration_in_ms = duration_in_sec * 1000 + + telemetry_events.on_qiskit_run_re_end(duration_in_ms) diff --git a/pip/qsharp/interop/qiskit/jobs/qsjobset.py b/pip/qsharp/interop/qiskit/jobs/qsjobset.py index b02d017af6..32f0283f74 100644 --- a/pip/qsharp/interop/qiskit/jobs/qsjobset.py +++ b/pip/qsharp/interop/qiskit/jobs/qsjobset.py @@ -4,6 +4,7 @@ from concurrent.futures import Executor, Future import datetime +from time import monotonic import logging from typing import Dict, List, Optional, Any from uuid import uuid4 @@ -17,6 +18,7 @@ from .qsjob import QsSimJob, RunInputCallable from ..execution import DetaultExecutor +from .... import telemetry_events logger = logging.getLogger(__name__) @@ -41,8 +43,8 @@ def __init__( self._job_indexes: List[int] = [] self._executor: Executor = executor or DetaultExecutor() self._job_callable = job_callable - self._start_time: datetime.datetime = None - self._end_time: datetime.datetime = None + self._start_time: float = None + self._end_time: float = None def submit(self): """Submit the job to the backend for execution. @@ -52,7 +54,9 @@ def submit(self): """ if len(self._jobs) > 0: raise JobError("Jobs have already been submitted.") - self._start_time = datetime.datetime.now() + self._start_time = monotonic() + shots = self._input_params.get("shots", -1) + telemetry_events.on_qiskit_run(shots, len(self._run_input)) job_index = 0 for circuit in self._run_input: job_id = str(uuid4()) @@ -71,7 +75,13 @@ def submit(self): self._jobs.append(job) def _job_done(self, _future: Future): - self._end_time = datetime.datetime.now() + self._end_time = monotonic() + if all(job.in_final_state() for job in self._jobs): + # all jobs are done, so we can log the telemetry event + shots = self._input_params.get("shots", -1) + duration_in_ms = (self._end_time - self._start_time) * 1000 + num_circuits = len(self._run_input) + telemetry_events.on_qiskit_run_end(shots, num_circuits, duration_in_ms) def cancel(self): """Attempt to cancel the job.""" @@ -108,7 +118,9 @@ def result(self, timeout: Optional[float] = None) -> Result: output["date"] = str(datetime.datetime.now().isoformat()) output["backend_name"] = self.backend().name output["backend_version"] = self.backend().backend_version - output["time_taken"] = str(self._end_time - self._start_time) + + duration = self._end_time - self._start_time + output["time_taken"] = str(duration) output["header"] = { "metadata": {}, } diff --git a/pip/qsharp/telemetry_events.py b/pip/qsharp/telemetry_events.py index c69693d6d2..f4865229db 100644 --- a/pip/qsharp/telemetry_events.py +++ b/pip/qsharp/telemetry_events.py @@ -12,15 +12,15 @@ # See some of the notes at: https://learn.microsoft.com/en-us/azure/azure-monitor/essentials/metrics-custom-overview#design-limitations-and-considerations -def get_shots_bucket(shots: int) -> int: - if shots <= 1: +def get_next_power_of_ten_bucket(value: int) -> int: + if value <= 1: return 1 - elif shots >= 1000000: + elif value >= 1000000: # Limit the buckets upper bound return 1000000 else: # Bucket into nearest (rounded up) power of 10, e.g. 75 -> 100, 450 -> 1000, etc. - return 10 ** math.ceil(math.log10(shots)) + return 10 ** math.ceil(math.log10(value)) # gets the order of magnitude for the number of qubits @@ -45,7 +45,7 @@ def on_run(shots: int) -> None: log_telemetry( "qsharp.run", 1, - properties={"shots": get_shots_bucket(shots)}, + properties={"shots": get_next_power_of_ten_bucket(shots)}, ) @@ -53,7 +53,7 @@ def on_run_end(durationMs: float, shots: int) -> None: log_telemetry( "qsharp.run.durationMs", durationMs, - properties={"shots": get_shots_bucket(shots)}, + properties={"shots": get_next_power_of_ten_bucket(shots)}, type="histogram", ) @@ -85,3 +85,44 @@ def on_estimate_end(durationMs: float, qubits: Union[str, int]) -> None: properties={"qubits": get_qubits_bucket(qubits)}, type="histogram", ) + + +# Qiskit telemetry events + + +def on_qiskit_run(shots: int, num_circuits: int) -> None: + log_telemetry( + "qiskit.run", + 1, + properties={ + "shots": get_next_power_of_ten_bucket(shots), + "circuits": get_next_power_of_ten_bucket(num_circuits), + }, + ) + + +def on_qiskit_run_end(shots: int, num_circuits: int, duration_ms: float) -> None: + log_telemetry( + "qiskit.run.durationMs", + duration_ms, + properties={ + "shots": get_next_power_of_ten_bucket(shots), + "circuits": get_next_power_of_ten_bucket(num_circuits), + }, + type="histogram", + ) + + +def on_qiskit_run_re() -> None: + log_telemetry( + "qiskit.run.re", + 1, + ) + + +def on_qiskit_run_re_end(duration_ms: float) -> None: + log_telemetry( + "qiskit.run.re.durationMs", + duration_ms, + type="histogram", + )