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.SystemResourceTimes(user: float, system: float, real: float)¶

Bases: object

A dataclass to hold system resource timings. The real attribute holds the real time elapsed, while user and system hold the user and system CPU times, respectively. These attributes are all floats, and are measured in seconds.

user: float¶

system: float¶

real: float¶

toString(precision=4)¶

__init__(user: float, system: float, real: float) → None¶

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.SystemResourceTimer(**kwargs)¶

Bases: schrodinger.utils.profiling.Timer

Context decorator that will track and report real, user, and system times elapsed. Provides a system_resource_times property that works like the elapsed property but contains all three times in a frozen dataclass.

__init__(**kwargs)¶

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 system_resource_times: schrodinger.utils.profiling.SystemResourceTimes¶

PRECISION: int = 4¶

TIME_FORMAT: str = '%Y-%m-%d %H:%M:%S'¶

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.

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, sort_by=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, sort_by=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).
sort_by (pstats.SortKey or str) – The method of sorting the output, defaults to alphanumeric

schrodinger.utils.profiling.profile_memory(logger=None, level=10)¶

Reports the change in virtual memory usage between when the context was entered and when the context was exited. Useful for determining how much memory was allocated when creating an object.

Parameters

logger (Optional[logging.logger]) – A logger to report memory usage.
level (int) – The logger level.