schrodinger.utils.profiling module

Profiling and timing decorators and context managers.

For more information on profiling python code, see also https://confluence.schrodinger.com/display/SOFTWAREDEV/Profiling

class schrodinger.utils.profiling.Timer(*, activity=None, logger=None, level=20)

Bases: object

Track and report wall time elapsed during a function or code block execution. Can be used as a function decorator or context manager.

Both the context manager and decorator will output time-related messages to the log at the specified logging level. The context manager can be assigned to a variable, which can be accessed inside the context to get elapsed time and log checkpoints. It can also be inspected after the context is closed to get total time elapsed. Elapsed time does not update after context is closed (until a new context is opened).

Before we get into examples, let’s set up our imports and logger boilerplate:

>>> from schrodinger.utils import log
>>> from schrodinger.utils.profiling import Timer
>>>
>>> logger = log.get_output_logger(__name__)
>>> logger.setLevel(log.DEBUG)

Now, to use this class as a context manager:

>>> with Timer(activity='do foo', logger=logger, level=log.DEBUG) as t:
...     for _ in range(100):
...         # Do something expensive here
...         pass
...     # Write a checkpoint message to log
...     checkpoint = t.checkpoint('first thing done')
...     for _ in range(100):
...         # Do something else here
...         pass
Timer - do foo - Starting - ...
Timer - do foo - Checkpoint - first thing done - ... s
Timer - do foo - Completed - ... s

Alternatively, to use the class as a decorator:

>>> @Timer(logger=logger, level=log.INFO)
... def do_foo():
...     for _ in range(100):
...         pass
>>> do_foo()
Timer - do_foo - Starting - ...
Timer - do_foo - Completed - ... s
Variables
  • TIME_FORMAT – The time format string used by strftime when reporting the time that measurement began.

  • PRECISION – The precision to be used when reporting elapsed seconds.

TIME_FORMAT: str = '%Y-%m-%d %H:%M:%S'
PRECISION: int = 4
__init__(*, activity=None, logger=None, level=20)
Parameters
  • activity (Optional[str]) – A description of the activity to be timed. If this class is used as a decorator and activity is NoneType, the function name will be used.

  • logger (Optional[logging.Logger]) – A logger to receive timing messages. If none is provided, messages will be printed to stdout using the builtin print function. To silence messages entirely, use a logger with a NullHandler.

  • level (int) – The logger level to use for timing messages.

property elapsed: float

Fractional seconds elapsed since context was entered. If context manager has already exited, this is the total execution time of the code block inside the context manager.

Returns

Fractional seconds elapsed since the start time.

checkpoint(description=None) float

Write a checkpoint to the log and get elapsed time. Be aware that logging can add non-negligible time to a code block’s execution. Empirically, each call to this function appears add about 0.5ms.

Parameters

description – A description of the checkpoint. If not supplied, the sequential checkpoint number will be used.

Returns

Fractional seconds elapsed since the start time.

class schrodinger.utils.profiling.RecordingTimer(*, activity=None, logger=None, level=20)

Bases: schrodinger.utils.profiling.Timer

Decorator that will print the duration of the execution of decorated function or method to the log every time it’s called. Will also report summary statistics of all call times at program exit, much like a flat profiler.

PRECISION: int = 4
TIME_FORMAT: str = '%Y-%m-%d %H:%M:%S'
__init__(*, activity=None, logger=None, level=20)
Parameters
  • activity (Optional[str]) – A description of the activity to be timed. If this class is used as a decorator and activity is NoneType, the function name will be used.

  • logger (Optional[logging.Logger]) – A logger to receive timing messages. If none is provided, messages will be printed to stdout using the builtin print function. To silence messages entirely, use a logger with a NullHandler.

  • level (int) – The logger level to use for timing messages.

checkpoint(description=None) float

Write a checkpoint to the log and get elapsed time. Be aware that logging can add non-negligible time to a code block’s execution. Empirically, each call to this function appears add about 0.5ms.

Parameters

description – A description of the checkpoint. If not supplied, the sequential checkpoint number will be used.

Returns

Fractional seconds elapsed since the start time.

property elapsed: float

Fractional seconds elapsed since context was entered. If context manager has already exited, this is the total execution time of the code block inside the context manager.

Returns

Fractional seconds elapsed since the start time.

schrodinger.utils.profiling.profile_call(func, *args, profile_filename=None, **kwargs)

Profile a single function call.

Parameters
  • func (Callable) – The function to profile. All arguments to profile_call other than profile_filename will be passed to this function.

  • profile_filename (str) – The name of the file to save the profiling data to. Note that this argument is keyword-only and is required.

Returns

The value returned by func.

Return type

object

class schrodinger.utils.profiling.Profiler(outfile=None)

Bases: contextlib.ContextDecorator

Profile a block of code or function. This class can be used as either a decorator or a context manager.

Measurements are cumulative. Thus if the same instance is used multiple times, the stats from all previous uses of that instance will be included in the profiling summary output. To “use an instance multiple times” in this context means either repeated calls to a decorated function or using the same instance to enter several contexts with repeated uses of the with keyword.

__init__(outfile=None)
Parameters

outfile (Optional[str]) – The file name to be used for the profiling summary output (traditionally ‘.prof’ extension). If no outfile is provided, output will be printed to stdout. Note that if the same instance is used multiple times, the file will be updated with the latest values and the previous output will be overwritten (see class documentation for details).