[workflow] Preliminary timing information

cirq-google/cirq_google/json_test_data/cirq.google.ExecutableGroupResult.json

@@ -33,7 +33,8 @@
       "runtime_info": {
         "cirq_type": "cirq.google.RuntimeInfo",
         "execution_index": 0,
-        "qubit_placement": null
+        "qubit_placement": null,
+        "timings_s": []
       },
       "raw_data": {
         "cirq_type": "ResultDict",
@@ -70,7 +71,8 @@
       "runtime_info": {
         "cirq_type": "cirq.google.RuntimeInfo",
         "execution_index": 1,
-        "qubit_placement": null
+        "qubit_placement": null,
+        "timings_s": []
       },
       "raw_data": {
         "cirq_type": "ResultDict",
@@ -107,7 +109,8 @@
       "runtime_info": {
         "cirq_type": "cirq.google.RuntimeInfo",
         "execution_index": 2,
-        "qubit_placement": null
+        "qubit_placement": null,
+        "timings_s": []
       },
       "raw_data": {
         "cirq_type": "ResultDict",

cirq-google/cirq_google/json_test_data/cirq.google.ExecutableResult.json

@@ -36,7 +36,8 @@
           "col": 6
         }
       ]
-    ]
+    ],
+    "timings_s": []
   },
   "raw_data": {
     "cirq_type": "ResultDict",

cirq-google/cirq_google/json_test_data/cirq.google.RuntimeInfo.json

@@ -1,5 +1,6 @@
 {
   "cirq_type": "cirq.google.RuntimeInfo",
   "execution_index": 5,
-  "qubit_placement": null
+  "qubit_placement": null,
+  "timings_s": []
 }

cirq-google/cirq_google/json_test_data/cirq.google.RuntimeInfo.repr

@@ -1 +1 @@
-cirq_google.RuntimeInfo(execution_index=5, qubit_placement=None)
+cirq_google.RuntimeInfo(execution_index=5, qubit_placement=None, timings_s={})

cirq-google/cirq_google/workflow/quantum_runtime.py

@@ -13,8 +13,9 @@
 # limitations under the License.
 
 """Runtime information dataclasses and execution of executables."""
-
+import contextlib
 import dataclasses
+import time
 import uuid
 from typing import Any, Dict, Optional, List, TYPE_CHECKING
 
@@ -80,10 +81,14 @@ class RuntimeInfo:
             `cg.QuantumExecutable` was executed.
         qubit_placement: If a QubitPlacer was used, a record of the mapping
             from problem-qubits to device-qubits.
+        timings_s: The durations of measured subroutines. Each entry in this
+            dictionary maps subroutine name to the amount of time the subroutine
+            took in units of seconds.
     """
 
     execution_index: int
     qubit_placement: Optional[Dict[Any, cirq.Qid]] = None
+    timings_s: Dict[str, float] = dataclasses.field(default_factory=dict)
 
     @classmethod
     def _json_namespace_(cls) -> str:
@@ -93,13 +98,16 @@ def _json_dict_(self) -> Dict[str, Any]:
         d = dataclass_json_dict(self)
         if d['qubit_placement']:
             d['qubit_placement'] = list(d['qubit_placement'].items())
+        d['timings_s'] = list(d['timings_s'].items())
         return d
 
     @classmethod
     def _from_json_dict_(cls, **kwargs) -> 'RuntimeInfo':
         kwargs.pop('cirq_type')
         if kwargs.get('qubit_placement', None):
             kwargs['qubit_placement'] = {_try_tuple(k): v for k, v in kwargs['qubit_placement']}
+        if 'timings_s' in kwargs:
+            kwargs['timings_s'] = {k: v for k, v in kwargs['timings_s']}
         return cls(**kwargs)
 
     def __repr__(self) -> str:
@@ -175,6 +183,7 @@ class QuantumRuntimeConfiguration:
             seed will be used.
         qubit_placer: A `cg.QubitPlacer` implementation to map executable qubits to device qubits.
             The placer is only called if a given `cg.QuantumExecutable` has a `problem_topology`.
+            This subroutine's runtime is keyed by "placement" in `RuntimeInfo.timings_s`.
     """
 
     processor_record: 'cg.ProcessorRecord'
@@ -193,6 +202,21 @@ def __repr__(self) -> str:
         return _compat.dataclass_repr(self, namespace='cirq_google')
 
 
+@contextlib.contextmanager
+def _time_into_runtime_info(runtime_info: RuntimeInfo, name: str):
+    """A context manager that appends timing information into a cg.RuntimeInfo.
+
+    Timings are reported in fractional seconds as reported by `time.monotonic()`.
+
+    Args:
+        runtime_info: The runtime information object whose `.timings_s` dictionary will be updated.
+        name: A string key name to use in the dictionary.
+    """
+    start = time.monotonic()
+    yield
+    runtime_info.timings_s[name] = time.monotonic() - start
+
+
 def execute(
     rt_config: QuantumRuntimeConfiguration,
     executable_group: QuantumExecutableGroup,
@@ -261,12 +285,17 @@ def execute(
 
         circuit = exe.circuit
         if exe.problem_topology is not None:
-            circuit, mapping = rt_config.qubit_placer.place_circuit(
-                circuit, problem_topology=exe.problem_topology, shared_rt_info=shared_rt_info, rs=rs
-            )
-            runtime_info.qubit_placement = mapping
-
-        sampler_run_result = sampler.run(circuit, repetitions=exe.measurement.n_repetitions)
+            with _time_into_runtime_info(runtime_info, 'placement'):
+                circuit, mapping = rt_config.qubit_placer.place_circuit(
+                    circuit,
+                    problem_topology=exe.problem_topology,
+                    shared_rt_info=shared_rt_info,
+                    rs=rs,
+                )
+                runtime_info.qubit_placement = mapping
+
+        with _time_into_runtime_info(runtime_info, 'run'):
+            sampler_run_result = sampler.run(circuit, repetitions=exe.measurement.n_repetitions)
 
         exe_result = ExecutableResult(
             spec=exe.spec,

cirq-google/cirq_google/workflow/quantum_runtime_test.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 import glob
 import re
+import time
 import uuid
 from typing import List, cast, Any
 
@@ -22,6 +23,7 @@
 import cirq
 import cirq_google as cg
 from cirq_google.workflow.quantum_executable_test import _get_quantum_executables, _get_example_spec
+from cirq_google.workflow.quantum_runtime import _time_into_runtime_info
 
 
 def cg_assert_equivalent_repr(value):
@@ -41,6 +43,8 @@ def test_shared_runtime_info():
 
 def test_runtime_info():
     rtinfo = cg.RuntimeInfo(execution_index=5)
+    with _time_into_runtime_info(rtinfo, 'test'):
+        pass
     cg_assert_equivalent_repr(rtinfo)
 
 
@@ -107,6 +111,15 @@ def test_executable_group_result(tmpdir):
     _assert_json_roundtrip(egr, tmpdir)
 
 
+def test_timing():
+    rt = cg.RuntimeInfo(execution_index=0)
+    with _time_into_runtime_info(rt, 'test_proc'):
+        time.sleep(0.1)
+
+    assert 'test_proc' in rt.timings_s
+    assert rt.timings_s['test_proc'] > 0.05
+
+
 def _load_result_by_hand(tmpdir: str, run_id: str) -> cg.ExecutableGroupResult:
     """Load `ExecutableGroupResult` "by hand" without using
     `ExecutableGroupResultFilesystemRecord`."""
@@ -159,3 +172,7 @@ def test_execute(tmpdir, run_id_in):
     assert returned_exegroup_result == exegroup_result
     assert manual_exegroup_result == exegroup_result
     assert helper_loaded_result == exegroup_result
+
+    exe_result = returned_exegroup_result.executable_results[0]
+    assert 'placement' in exe_result.runtime_info.timings_s
+    assert 'run' in exe_result.runtime_info.timings_s