Skip to content

_perf

Python-side perf checkpoints recorded on the C# session load timeline.

Checkpoints are recorded on pyRevitLabs.Common.LoadTimeline, the clock the C# loader times the whole session load with, and logged as DEBUG [PERF:py] lines that interleave with its [PERF] lines. Outside a session load there is no active timeline and every call does nothing, so checkpoints left in library modules cost nothing when commands import them.

Every checkpoint is recorded on the timeline, but only those at or over _ROLLUP_THRESHOLD_MS get their own log line. Cheaper ones are counted into a per-module rollup line, so the log keeps the steps worth acting on and still says what the omitted ones cost in total.

Self-contained on purpose: imports only sys at module load so it can be the first line of pyrevit/init.py without triggering circular loads. The timeline type is resolved on first use. The pyRevit logger is never imported from here, since importing it before pyrevit/init.py finishes fails and costs time inside the very checkpoints being measured; it is used once another import has loaded it. Lines recorded before then are held and logged, in order, ahead of the first line after it.

Classes

time_block(label)

Bases: object

Context manager: time a block as a child span of the innermost open span.

Thresholded and rolled up like mark(). A block that earns its own line is logged at exit, indented two extra spaces past mark() lines to mirror C# sub-item indentation ([PERF] <name>:). Does nothing outside a session load.

Source code in pyrevitlib/pyrevit/_perf.py 
171
172
173
def __init__(self, label):
    self.label = label
    self._span = None

Attributes

label = label instance-attribute

Functions:

flush()

Log the rollup line for any checkpoints still held.

A rollup line is held until a checkpoint from another module arrives, so the last module of a load needs this to reach the log. Call once at the end of a session load; harmless at any other time.

Source code in pyrevitlib/pyrevit/_perf.py 
119
120
121
122
123
124
125
126
def flush():
    """Log the rollup line for any checkpoints still held.

    A rollup line is held until a checkpoint from another module arrives, so the
    last module of a load needs this to reach the log. Call once at the end of a
    session load; harmless at any other time.
    """
    _flush_rollup()

elapsed_load_seconds()

Seconds since the current session load started, or None outside a load.

Source code in pyrevitlib/pyrevit/_perf.py 
129
130
131
132
133
134
def elapsed_load_seconds():
    """Seconds since the current session load started, or None outside a load."""
    timeline = _active_timeline()
    if timeline is None:
        return None
    return timeline.ElapsedMilliseconds / 1000.0

mark(label)

Record a perf checkpoint.

Measures the time since the previous checkpoint in the innermost open timeline span, or since that span started. Deltas therefore never reach back into another script or loader step.

Checkpoints at or over _ROLLUP_THRESHOLD_MS get a DEBUG [PERF:py] line of their own; cheaper ones are counted into the rollup line for the label's module, the part before the first colon.

Note

Checkpoints taken before the pyRevit logger has been loaded are held and logged, in order, once it has, so their log timestamps run late but their deltas are exact.

Source code in pyrevitlib/pyrevit/_perf.py 
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
def mark(label):
    """Record a perf checkpoint.

    Measures the time since the previous checkpoint in the innermost open
    timeline span, or since that span started. Deltas therefore never reach
    back into another script or loader step.

    Checkpoints at or over `_ROLLUP_THRESHOLD_MS` get a DEBUG `[PERF:py]` line
    of their own; cheaper ones are counted into the rollup line for the label's
    module, the part before the first colon.

    Note:
        Checkpoints taken before the pyRevit logger has been loaded are held
        and logged, in order, once it has, so their log timestamps run late
        but their deltas are exact.
    """
    timeline = _active_timeline()
    if timeline is None:
        return
    span = timeline.CurrentSpan
    if span is None:
        return
    _record(label, span.Lap())