Skip to content

Profiling Utilities

fusion_bench.utils.timer

timeit_context

A context manager for measuring and logging execution time of code blocks.

This context manager provides precise timing measurements with automatic logging of elapsed time. It supports nested timing contexts with proper indentation for hierarchical timing analysis, making it ideal for profiling complex operations with multiple sub-components.

Parameters:

  • msg (str, default: None ) –

    Custom message to identify the timed code block. If provided, logs "[BEGIN] {msg}" at start and includes context in the final timing report. Defaults to None.

  • loglevel (int, default: INFO ) –

    Python logging level for output messages. Uses standard logging levels (DEBUG=10, INFO=20, WARNING=30, etc.). Defaults to logging.INFO.

Example

Basic usage: 

with timeit_context("data loading"):
    data = load_large_dataset()
# Logs: [BEGIN] data loading
# Logs: [END]   Elapsed time: 2.34s

Nested timing: 

with timeit_context("model training"):
    with timeit_context("data preprocessing"):
        preprocess_data()
    with timeit_context("forward pass"):
        model(data)
# Output shows nested structure:
# [BEGIN] model training
#   [BEGIN] data preprocessing
#   [END]   Elapsed time: 0.15s
#   [BEGIN] forward pass
#   [END]   Elapsed time: 0.89s
# [END]   Elapsed time: 1.04s

Custom log level: 

with timeit_context("debug operation", loglevel=logging.DEBUG):
    debug_function()

Source code in fusion_bench/utils/timer.py 
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
class timeit_context:
    """
    A context manager for measuring and logging execution time of code blocks.

    This context manager provides precise timing measurements with automatic logging
    of elapsed time. It supports nested timing contexts with proper indentation
    for hierarchical timing analysis, making it ideal for profiling complex
    operations with multiple sub-components.

    Args:
        msg (str, optional): Custom message to identify the timed code block.
            If provided, logs "[BEGIN] {msg}" at start and includes context
            in the final timing report. Defaults to None.
        loglevel (int, optional): Python logging level for output messages.
            Uses standard logging levels (DEBUG=10, INFO=20, WARNING=30, etc.).
            Defaults to logging.INFO.

    Example:
        Basic usage:
        ```python
        with timeit_context("data loading"):
            data = load_large_dataset()
        # Logs: [BEGIN] data loading
        # Logs: [END]   Elapsed time: 2.34s
        ```

        Nested timing:
        ```python
        with timeit_context("model training"):
            with timeit_context("data preprocessing"):
                preprocess_data()
            with timeit_context("forward pass"):
                model(data)
        # Output shows nested structure:
        # [BEGIN] model training
        #   [BEGIN] data preprocessing
        #   [END]   Elapsed time: 0.15s
        #   [BEGIN] forward pass
        #   [END]   Elapsed time: 0.89s
        # [END]   Elapsed time: 1.04s
        ```

        Custom log level:
        ```python
        with timeit_context("debug operation", loglevel=logging.DEBUG):
            debug_function()
        ```
    """

    nest_level = -1

    def _log(self, msg):
        """
        Internal method for logging messages with appropriate stack level.

        This helper method ensures that log messages appear to originate from
        the caller's code rather than from internal timer methods, providing
        more useful debugging information.

        Args:
            msg (str): The message to log at the configured log level.
        """
        log.log(self.loglevel, msg, stacklevel=3)

    def __init__(self, msg: str = None, loglevel=logging.INFO) -> None:
        """
        Initialize a new timing context with optional message and log level.

        Args:
            msg (str, optional): Descriptive message for the timed operation.
                If provided, will be included in the begin/end log messages
                to help identify what is being timed. Defaults to None.
            loglevel (int, optional): Python logging level for timer output.
                Common values include:
                - logging.DEBUG (10): Detailed debugging information
                - logging.INFO (20): General information (default)
                - logging.WARNING (30): Warning messages
                - logging.ERROR (40): Error messages
                Defaults to logging.INFO.
        """
        self.loglevel = loglevel
        self.msg = msg

    def __enter__(self) -> None:
        """
        Enter the timing context and start the timer.

        This method is automatically called when entering the 'with' statement.
        It records the current timestamp, increments the nesting level for
        proper log indentation, and optionally logs a begin message.

        Returns:
            None: This context manager doesn't return a value to the 'as' clause.
                  All timing information is handled internally and logged automatically.
        """
        self.start_time = time.time()
        timeit_context.nest_level += 1
        if self.msg is not None:
            self._log("  " * timeit_context.nest_level + "[BEGIN] " + str(self.msg))

    def __exit__(self, exc_type, exc_val, exc_tb) -> None:
        """
        Exit the timing context and log the elapsed time.

        This method is automatically called when exiting the 'with' statement,
        whether through normal completion or exception. It calculates the total
        elapsed time and logs the results with proper nesting indentation.

        Args:
            exc_type (type): Exception type if an exception occurred, None otherwise.
            exc_val (Exception): Exception instance if an exception occurred, None otherwise.
            exc_tb (traceback): Exception traceback if an exception occurred, None otherwise.

        Returns:
            None: Does not suppress exceptions (returns None/False implicitly).
                  Any exceptions that occurred in the timed block will propagate normally.
        """
        end_time = time.time()
        elapsed_time = end_time - self.start_time
        self._log(
            "  " * timeit_context.nest_level
            + "[END]   "
            + str(f"Elapsed time: {elapsed_time:.2f}s")
        )
        timeit_context.nest_level -= 1
__enter__()

Enter the timing context and start the timer.

This method is automatically called when entering the 'with' statement. It records the current timestamp, increments the nesting level for proper log indentation, and optionally logs a begin message.

Returns:

  • None ( None ) –

    This context manager doesn't return a value to the 'as' clause. All timing information is handled internally and logged automatically.

Source code in fusion_bench/utils/timer.py 
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
def __enter__(self) -> None:
    """
    Enter the timing context and start the timer.

    This method is automatically called when entering the 'with' statement.
    It records the current timestamp, increments the nesting level for
    proper log indentation, and optionally logs a begin message.

    Returns:
        None: This context manager doesn't return a value to the 'as' clause.
              All timing information is handled internally and logged automatically.
    """
    self.start_time = time.time()
    timeit_context.nest_level += 1
    if self.msg is not None:
        self._log("  " * timeit_context.nest_level + "[BEGIN] " + str(self.msg))
__exit__(exc_type, exc_val, exc_tb)

Exit the timing context and log the elapsed time.

This method is automatically called when exiting the 'with' statement, whether through normal completion or exception. It calculates the total elapsed time and logs the results with proper nesting indentation.

Parameters:

  • exc_type (type) –

    Exception type if an exception occurred, None otherwise.

  • exc_val (Exception) –

    Exception instance if an exception occurred, None otherwise.

  • exc_tb (traceback) –

    Exception traceback if an exception occurred, None otherwise.

Returns:

  • None ( None ) –

    Does not suppress exceptions (returns None/False implicitly). Any exceptions that occurred in the timed block will propagate normally.

Source code in fusion_bench/utils/timer.py 
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
def __exit__(self, exc_type, exc_val, exc_tb) -> None:
    """
    Exit the timing context and log the elapsed time.

    This method is automatically called when exiting the 'with' statement,
    whether through normal completion or exception. It calculates the total
    elapsed time and logs the results with proper nesting indentation.

    Args:
        exc_type (type): Exception type if an exception occurred, None otherwise.
        exc_val (Exception): Exception instance if an exception occurred, None otherwise.
        exc_tb (traceback): Exception traceback if an exception occurred, None otherwise.

    Returns:
        None: Does not suppress exceptions (returns None/False implicitly).
              Any exceptions that occurred in the timed block will propagate normally.
    """
    end_time = time.time()
    elapsed_time = end_time - self.start_time
    self._log(
        "  " * timeit_context.nest_level
        + "[END]   "
        + str(f"Elapsed time: {elapsed_time:.2f}s")
    )
    timeit_context.nest_level -= 1
__init__(msg=None, loglevel=logging.INFO)

Initialize a new timing context with optional message and log level.

Parameters:

  • msg (str, default: None ) –

    Descriptive message for the timed operation. If provided, will be included in the begin/end log messages to help identify what is being timed. Defaults to None.

  • loglevel (int, default: INFO ) –

    Python logging level for timer output. Common values include: - logging.DEBUG (10): Detailed debugging information - logging.INFO (20): General information (default) - logging.WARNING (30): Warning messages - logging.ERROR (40): Error messages Defaults to logging.INFO.

Source code in fusion_bench/utils/timer.py 
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
def __init__(self, msg: str = None, loglevel=logging.INFO) -> None:
    """
    Initialize a new timing context with optional message and log level.

    Args:
        msg (str, optional): Descriptive message for the timed operation.
            If provided, will be included in the begin/end log messages
            to help identify what is being timed. Defaults to None.
        loglevel (int, optional): Python logging level for timer output.
            Common values include:
            - logging.DEBUG (10): Detailed debugging information
            - logging.INFO (20): General information (default)
            - logging.WARNING (30): Warning messages
            - logging.ERROR (40): Error messages
            Defaults to logging.INFO.
    """
    self.loglevel = loglevel
    self.msg = msg