Add timing info to dwave sample

dwave/cloud/cli.py

@@ -584,6 +584,7 @@ def sample(*, config_file, profile, endpoint, region, client_type, solver_def,
         endpoint=endpoint, region=region,
         client=client_type, solver=solver_def)
 
+    t0 = timer()
     client, solver = _get_client_solver(config, output)
 
     if random_problem:
@@ -617,16 +618,30 @@ def sample(*, config_file, profile, endpoint, region, client_type, solver_def,
     output("Using couplings: {quadratic}", quadratic=list(quadratic.items()), maxlen=maxlen)
     output("Sampling parameters: {sampling_params}", sampling_params=params)
 
+    t1 = timer()
     response = _sample(
         solver, problem=(linear, quadratic), params=params, output=output)
 
+    t2 = timer()
+
     if verbose:
         output("Result: {response!r}", response=response.result())
 
     output("Samples: {samples!r}", samples=response.samples, maxlen=maxlen)
     output("Occurrences: {num_occurrences!r}", num_occurrences=response.num_occurrences, maxlen=maxlen)
     output("Energies: {energies!r}", energies=response.energies, maxlen=maxlen)
 
+    output("\nWall clock time:")
+    output(" * Solver definition fetch: {wallclock_solver_definition:.3f} ms", wallclock_solver_definition=(t1-t0)*1000.0)
+    output(" * Problem submit and results fetch: {wallclock_sampling:.3f} ms", wallclock_sampling=(t2-t1)*1000.0)
+    output(" * Total: {wallclock_total:.3f} ms", wallclock_total=(t2-t0)*1000.0)
+    if response.timing:
+        output("\nQPU timing:")
+        for component, duration in sorted(response.timing.items()):
+            output(" * %(name)s = {%(name)s} us" % {"name": component}, **{component: duration})
+    else:
+        output("\nQPU timing data not available.")
+
 
 @cli.command()
 @config_file_options()

releasenotes/notes/add-timing-output-to-dwave-sample-e3adb8b197921e8d.yaml

@@ -0,0 +1,5 @@
+---
+features:
+  - |
+    Add wall time and QPU timing to ``dwave sample`` output.
+    See `#570 <https://github.com/dwavesystems/dwave-cloud-client/issues/570>`_.

tests/test_cli.py

@@ -279,6 +279,9 @@ def test_ping(self, config_file_option):
             solver.sample_ising.assert_called_with(
                 {3: 0}, {}, label=label, **params)
 
+            # verify output contains timing data
+            self.assertIn('Wall clock time', result.output)
+
         self.assertEqual(result.exit_code, 0)
 
     @parameterized.expand([
@@ -325,6 +328,9 @@ def test_sample(self, config_file_option):
             s.sample_ising.assert_called_with(
                 {0: 0}, {(0, 4): 1}, num_reads=10, label=label)
 
+            # verify output contains timing data
+            self.assertIn('Wall clock time', result.output)
+
         self.assertEqual(result.exit_code, 0)
 
     @parameterized.expand([