[workflow] Preliminary timing information

[mpharrigan]

Add a RuntimeInfo field to store timing information. Augment the execute loop to record some basic timing info. Provide a utility context manager to make it easier to record timing information.

[dstrain115]

Be more specific. What are the keys and values? Are the values in seconds, millis, micros, nanos, etc?
Also, I would consider changing the name to include units for clarity.

[mpharrigan]

added docstrings and changed name

[MichaelBroughton]

I think we might be re-inventing the wheel a little bit here. Why can't we just use something like the built-in python logger ? Also wondering if the use of logging and handlers would greatly simplify the saver and logger variables used here as well ?

[mpharrigan]

@MichaelBroughton python logging functionality would likely be useful for fleshing out the logger stuff.

This PR concerns itself with timing various phases of the execution. We don't want to stream this data to the console; we want to save it as numeric data to do analysis/plotting/databasing. Wall-clock performance is a key dimension to benchmark in a quantum system. However, if you have some concrete ideas on how to leverage python functionality to do this I'm happy to hear it.

[MichaelBroughton]

This was the kind of thing I had in mind:

import logging
import random

logging.basicConfig(format="%(levelname)s %(asctime)s - %(message)s")


class PartialStateFromRunning(object):
    def __init__(self):
        self.complicated_data = [1, 2, 3, 4, 5]

    def to_str(self):
        return str(self.complicated_data)


class MyPrintyHandler(logging.Handler):
    def __init__(self):
        super().__init__()

    def emit(self, record):
        # print(record)
        # print('I CAN DO ANYTHING HERE!')
        # print('Timey stuff', record.created)
        # print(record.__dict__)
        return


class MySaveyHandler(logging.Handler):
    def __init__(self, run_state):
        super().__init__()
        self.run_state = run_state

    def emit(self, record):
        if record.levelno == logging.INFO:
                # pretend to save to DB or file or whatever.
        	print('SAVING RUN STATE', self.run_state)
        	print('DATA=', self.run_state.to_str())
        return


def do_placement(state):
    state.complicated_data += [random.random()]


def do_run(state):
    state.complicated_data += [1234]


my_big_global_state = PartialStateFromRunning()

plain_logger = logging.getLogger("testbed.logger")

# Add any handlers to the logger.
print_handler = MyPrintyHandler()
save_handler = MySaveyHandler(my_big_global_state)  # can link to global state objects.
plain_logger.addHandler(print_handler)
plain_logger.addHandler(save_handler)

# Let a user change this around as they like.
plain_logger.setLevel(logging.DEBUG)

for i in range(10):

    # Keep main computation logging events the same, but can now emmit events to handlers
    # to do more intricate saving/storing/printing whatever.
    plain_logger.info(f"Beginning placement {i}")
    do_placement(my_big_global_state)
    plain_logger.info(f"Finished placement {i}")
    plain_logger.debug(f"Resulting placement {123455987765}")
    plain_logger.info(f"Beginning run {i}")
    do_run(my_big_global_state)
    plain_logger.info(f"Finished run {i}")
    plain_logger.debug(f"All bitstring data {10101010101010}")

Key ideas here are:

1. LogRecords always have time information with them so it's easy to track timing
2. If we want the ability to scale the number of "events" that should take place after something significant happens (an individual run finishing, a placement being computed, whatever) adding handlers will scale much better than adding more contexts and complicating the inner loop to accommodate each of these events.
3. With logging levels we can keep more careful track of what events happen when based around logging levels and the connotations they carry as apposed to forcing the reader to have to parse some big docstring or config setups.

Here are some other Handler patterns .

[mpharrigan]

Point taken that log messages capture timestamps. However, I've modified this PR to use time.monotonic() because we're interested in measuring durations. Do you know what clock source the logging module uses?

We don't want to let users add arbitrary handlers. We want a taxonomy of runtime features. If you just want arbitrary code execution, you might be better off writing your own execution loop.

I don't want whether or not we save durations to be affected by the logging level.

[MichaelBroughton]

We don't want to stream this data to the console; we want to save it as numeric data to do analysis/plotting/databasing. Wall-clock performance is a key dimension to benchmark in a quantum system

Point taken that log messages capture timestamps. However, I've modified this PR to use time.monotonic() because we're interested in measuring durations. Do you know what clock source the logging module uses?

Durations can be calculated from taking the difference of two timestamps from LogRecords which are computed using time.time() in addition to this you can compute the durations of events by using the relativeCreated property of a LogRecord. I'm also a little confused here, if we want to do things like databasing or plotting, wouldn't we want full blown time data and not just duration data. If a user wants to comb over it later for durations they could do that, but I can also certainly see a case where a user would want to know at roughly what time something was run or finished etc.

We don't want to let users add arbitrary handlers. We want a taxonomy of runtime features. If you just want arbitrary code execution, you might be better off writing your own execution loop.

Right, I was more referring to internally we should use these because it's easier to hook up logging Handlers in a structured fashion than it is to keep having to change the inner loop. A user could then turn them on and off easily with whatever function arguments they want i.e. run(..., do_savey_things=True, do_printy_things=False).

[mpharrigan]

I think you're conflating things a bit. I think we've talked before about moving data saving and printing to a callback-y format, which I agree with; but that's not the point of this PR.

Here, I want to measure e.g. how long it takes to run an executable and how long it takes to do various preprocessing steps. It seems like the logging module would be akin to fitting a square peg into a round hole. The one feature that we get is the automatic inclusion of timestamps; but I really don't think it's onerous to call time.time() ourselves, especially when I now get to use the much more suitable time.monotonic() since I'm primarily interested in durations (and the former can get screwed up if the system clock changes during execution; happy day after daylight savings day!)

re: durations from timestamps: you need to make sure you have a timing (or logging) call before and after your function call of interest. Context managers are a good fit here. You can imagine an alternative scenario where you rely on each phase being demarcated with a logging call. But if you add or remove phases, you need to update which quantities you're subtracting to get the duration.

[mpharrigan]

@MichaelBroughton are you ok moving forward with the PR as written?

[verult]

Should the timing be recorded if there's an error? I saw for example RandomDevicePlacer.place_circuit() could raise a ValueError.

[mpharrigan]

I think so(?) Curious to hear your thoughts

[MichaelBroughton]

Looks good just a nit from me. After our discussions if all we want is timing for RunTimeInfo, I think this code can be made a lot shorter also. WIll leave to @dstrain115 for final say here.

[MichaelBroughton]

Nit: this docstring (and ones above it too) seems like it is more ambiguous than it needs to be. Thoughts on: timings: Dictionary mapping from str to float. Each entry corresponds to the number of seconds a particular execution subroutine took. <name all subroutines that are tracked> ?

Mentioning things are timed in fractional seconds made me think "what denomination is used here do I have 40 half seconds which is really 20 full seconds etc. ?"

[mpharrigan]

reworded inspired by your suggestion. I think I took "fractional seconds" from the python docs, but I agree it is weird

[mpharrigan]

I'm going to punt on listing all the possible names, as 1) it will likely change in the next couple of PRs 2) will depend on the particular QuantumRuntimeConfiguration, and I would like to document it there so all docstrings can point to one place.

[MichaelBroughton]

I'm not a huge fan of this module coupling it's functionality to RunTimeInfo just so we can mutate a key in some dictionary for a specific type of object. It feels like a weird hybrid of accessor and mutator where we could very easily just have one or the other.

If all we need to do is get timing information for RuntTimeInfo why not just add something like:

@contextlib.contextmanager
def _add_time_to_runtime(cur_runtime) -> None:
    start = time.time()
    yield
    cur_runtime.whatever = time.time() - start

to the top of the quantum_runtime.py module and use that instead ? Or make a more general timer that doesn't couple to this part of the codebase ?

[mpharrigan]

changed to a private context manager. changed to use decorator instead of class.

[mpharrigan]

@MichaelBroughton @dstrain115 @verult ptal