Add telemetry events for interop (#1990)

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

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)

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": {},
         }

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,15 +45,15 @@ 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)},
     )
 
 
 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",
+    )