Incorrect hit count on a multi-line call

[sam-mosleh]

Description

When a function call is split across several source lines, line_profiler reports twice as many hits on the opening f( line as there are actual executions of that call.

Reproducer

from line_profiler import LineProfiler
def main() -> None:
    for _ in range(100):
        print(
            1,
        )
if __name__ == "__main__":
    profile = LineProfiler(main)
    profile.runcall(main)
    profile.print_stats()

Output

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     2                                           def main() -> None:
     3       101      16000.0    158.4      9.0      for _ in range(100):
     4       200     152000.0    760.0     85.9          print(
     5       100       9000.0     90.0      5.1              1,
     6                                                   )

Expectation

print must show 100 hits not 200

Note

Happy to open a PR if maintainers allow me to do so.

[TTsangSC]

Interesting behavior; thanks for reporting! But as detailed below I'm not even sure if it should be considered a bug, and if it is, how to fix it.¹

What probably happened

I'm guessing that the double-counting is because:

• The interpreter does whatever operations (in this case, probably just [LOAD_NAME('print')]) needed to prepare the callable, emitting a line event on the line (#4).
• Then it moves onto the subsequent lines to prepare the positional and keyword args passed to the callable, if any. In this case it probably just [PUSH_NULL, LOAD_SMALL_INT(1)] on line #5, because the call is on a non-method callable.
• Then it actually passes the call args back to the callable with an operation on the original line (in this case, probably CALL(1) on line #4, where the 1 indicates the number of args (excl. NULL), not the literal arg 1). This thus emits a second line event.

Note that this behavior does not necessarily manifest as a double-count:

$ kernprof -lv - <<-!
def main():
    for i in range(10):
        (
            print
        )(
            i)
main()
!
0
1
...
9
Wrote profile results to ...
...
Line #      Hits         Time  Per Hit   % Time  Line Contents                                                                                                                    
==============================================================                                                                                                                    
     1                                           def main():                                                                                                                      
     2        11          3.0      0.3     12.5      for i in range(10):                                                                                                            
     3        10         16.0      1.6     66.7          (                                                                                                                            
     4        10          3.0      0.3     12.5              print                                                                                                                      
     5                                                   )(                                                                                                                           
     6        10          2.0      0.2      8.3              i)  

This setup makes it clear that 10 counts are from the call (line #3) and another 10 from loading the print name (line #4).

Is it a bug though?

Point is, there are indeed 2 real line events associated with your line #4, and such occasional dissonance with the user's intuition is the cost of keeping track of line events instead of other units of code, e.g. function calls (which cProfile does) or statements. Say we have the following code:

foo(); bar(baz())
foobar()

Here:

• line_profiler reports 2 line events because, well, there are two lines of code, each executed once from top-down. The timing infos from the foo(), bar(...), and baz() calls will all get lumped into "the duration line #1 took", and the foobar() call alone constitutes the #2 timing.
• Meanwhile cProfile doesn't see lines and only function calls, so it would report separate timing infos for the four calls (foo(), bar(...), etc.)
• And the hypothetical statement profiler would report three timing infos, for resp. foo(), bar(...), and foobar().

With different units of bookkeeping, we get different groupings of timing infos. But they are all "correct" insofar as they do what is advertised and are self-consistent.

While your use-case is way too common to be considered an edge case, and having the counts adjusted in this and similar case would result in more intuitive stats:

• I am not sure if there's a way to meaningfully fix it in a self-consistent way – we will have to make a decision saying that some line events don't count as a hit. But since you mentioned being open to writing a PR maybe you have some ideas... in which case we're all ears.¹
• Even if we were to come up with such a scheme, since line events are rather spartan (both with the newer sys.monitoring and the so-called "legacy" trace system), containing no info other than the active code object and the line number, it would be impossible to identify which line event is which, and thus whether it should contribute to the hit count or not.
• While both tracing systems have opcode-level and call-level events:
  • The 'call' and 'opcode' events in the "legacy" system carry no additional info whatsoever, making it impossible to figure out what exactly is being called where.
  • sys.monitoring.events.INSTRUCTION events are labeled with the offset, so it should theoretically be possible to e.g. retrieve their respective opcodes and line numbers. But we'll still need to be able to detect that e.g. on a dis.CALL instruction we are looping back onto a previous line where we've prepared the callable and manage the num-hit bookkeeping there. This specifically may be possible, but see the discussion below.
  • sys.monitoring.events.CALL events comes with the Python object called, but that doesn't help either – we don't have the context of where said object has been created/loaded, or indeed even where the call has been made.

A sysmon-based fix...?

As mentioned above, we may be able to do the requisite accounting to fix your specific case by keeping track of sys.monitoring.events.INSTRUCTION events:

• Maintain a stack (ln_stack) of line numbers, representing the line numbers of instructions where objects are pushed onto the interpreter stack (int_stack).

• Scan all instructions and synchronize ln_stack and int_stack.

• When a CALL instruction is caught, check the argc and pop the corresponding number of entries from ln_stack, distinguishing between the bottom line number (corresponding to the callable) and the others (the args).

• If

  • The CALL instruction's line number coincides with that of the callable, and
  • There exists arg(s) on other line numbers,

  we conclude that the call will result in an "undesirable"/"spurious"/whatever line event, and thus the next line event on the CALL instruction's line should not count as a separate hit.

But of course there are obvious drawbacks:

• No equivalent for the "legacy" trace system.

• Maintaining the stack is probably expensive... using C++ (std::stack) will probably help immensely, but the per-instruction workflow still represents considerable overhead:

  • Retrieve the opcode (indexing .co_code) and the line number (PyCode_Addr2Line()).
  • Classify whether the opcode manipulates the int_stack.
  • If so, manipulate ln_stack correspondingly (pop a number or push the line number).

  Note that we currently interact with sys.monitoring.events.LINE events (obviously), and also .PY_RETURN, .PY_YIELD, .RAISE, and .RERAISE events for practical reasons. Having something firing for each .INSTRUCTION event will probably increase overhead by an order of magnitude compared to what we have now.

Other related behaviors

In #215 it was noticed that the for ...: line always has one extra hit compared with the looped lines inside. While this initially seems counterintuitive, it does make sense:

• Consider

  for _ in []:
      print(1)

  We step into the for ...: line once (1 hit) to check if we have anything to iterate over. Since we don't, the print() statement is skipped (0 hits).
• Now consider

  for i in range(10):
      print(i)

  We get 1 hit on the for ...: line for every item in range(10), where we bind the item to i and also pass it to the loop body (the print() statement). After the last item we return to the for ...: line and see that the range() is exhausted, and hence get another hit. Hence the for ...: line ends up with 11 hits and the print(...) line 10.

So... yeah. Sometimes line events do not line up with our intuitions, but there are probably rhymes and reasons behind that, and YMMV as to whether that constitutes a bug, or in fact reveals the workings of the interpreter.

Footnotes

1. Note however that I'm just a contributor here. Maybe someone else will have differing and/or better ideas, but since they seem to be busy I'll just take the liberty to start the discussion. ↩ ↩²

[Erotemic]

I'm inclined to not fix given that there there isn't a cheap mechanism to compute the intuitive number. Better documentation "what does a hit mean" might make sense.

[sam-mosleh]

@TTsangSC Thanks for the detailed explanation! My plan is to find each CALL-like opcode’s start line with PyCode_Addr2Location, store start_line_hash -> end_line_no in an unordered_map once when the function is added, and probe that map only when a LINE event jumps backward.
@Erotemic That could also work as a workaround, but it would be a bit awkward. I rely heavily on the PerHit column when optimizing, and this issue currently reports about half the true value, which breaks some of the assumptions I make from the report. Fixing this would improve DX a lot.

On cost: the scan runs once in add_function, at the same order as the existing per-byte PyCode_Addr2Line loop, so I believe this plan has the same overhead as the current tracer.

[TTsangSC]

... yeah I dun goofed, it should have been obvious that the bytecode analysis and characterization of calls could've been done at .add_function() time.

PyCode_Addr2Location() probably works for the purpose; will do more tests to verify. A catch is that it's 3.11+ and we currently support down to 3.10. On the one hand, 3.10 will EoL in November anyway maybe we can just drop it; on the other, that may have implications regarding our release cycle.¹

A 3.10 compatible fallback would require thinking more about how the end line number for each CALL should be extracted, since the call instruction comes after all the instructions prepping the callable and its arguments.² But as mentioned in the previous reply we can probably just disassemble the bytecode and mirror the stack, and since it's a one-time thing per code object the cost should be bearable.

And of course, as previously emphasized, the unintuitive raw number is technically and objectively correct; any adjustment we make thereto will be a subjective decision that must be made cautiously. Currently I'm thinking in the lines of either:

• Introducing a CLI flag or an environment variable so that devs wanting the adjustments can opt in and gather those numbers instead of the raw hits, or
• Updating the layout of entries (read: dicts) in LineStats.timings to allow for a new optional column for the adjusted hits.

The latter is probably the more flexible, unambiguous, and backward-compatible option.

Footnotes

1. But then again we've already dropped 3.8 and 3.9 in Update CI - Drop 3.8 / 3.9 #428 (in main but yet unreleased), so I guess it's a discussion we'll be having either way. ↩

2. Notably we cannot simply look at the line number of the instruction immediately preceding the CALL, because as demoed in my previous reply your issue doesn't manifest in all multiline calls. This caveat may also apply to the line-number bounds yielded by PyCode_Addr2Location(), but again we'll have to verify that. ↩

[TTsangSC]

Interestingly, the same type of behavior is observed when using multiline constructions for building collections and strings, like:

def build_multiline_list():
    for _ in range(10):
        print(
            ['foo',  # `BUILD_LIST(2)` here pulls from 'bar' and 'foo' from the stack
             'bar'],
        )


def build_multiline_string():
    a = 1
    for _ in range(10):
        print(
            'foo'  # `BUILD_STRING(2)` here pulls from f'bar{a}' and 'foo' from the stack
             f'bar{a}',
        )

When profiling either of the functions, one would get 20 hits on both the print line (due to the LOAD_GLOBAL and CALL instructions) and the commented line (due to the LOAD_CONST and BUILD_* instructions).

[TTsangSC]

I'm starting to doubt whether this can be handled in a consistent and cost-effective way. Consider the following:

(py3.14)  $ python -c "import dis, sys, pprint; pprint.pprint(list(dis.get_instructions(sys.stdin.read())))" <<-!                                                                 
print(
    1,
    *args,                                                                                                                                                                        
    sep='\n',
    **kwargs
)                                                                                                                                                                                 
!                                                                                                                                                                                 
[Instruction(opname='RESUME', opcode=128, arg=0, argval=0, argrepr='', offset=0, start_offset=0, starts_line=True, line_number=0, label=None, positions=Positions(lineno=0, end_lineno=1, col_offset=0, end_col_offset=0), cache_info=None),
 Instruction(opname='LOAD_NAME', opcode=93, arg=0, argval='print', argrepr='print', offset=2, start_offset=2, starts_line=True, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=1, col_offset=0, end_col_offset=5), cache_info=None),
 Instruction(opname='PUSH_NULL', opcode=33, arg=None, argval=None, argrepr='', offset=4, start_offset=4, starts_line=False, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=1, col_offset=0, end_col_offset=5), cache_info=None),
 Instruction(opname='LOAD_SMALL_INT', opcode=94, arg=1, argval=1, argrepr='', offset=6, start_offset=6, starts_line=True, line_number=2, label=None, positions=Positions(lineno=2, end_lineno=2, col_offset=4, end_col_offset=5), cache_info=None),
 Instruction(opname='BUILD_LIST', opcode=46, arg=1, argval=1, argrepr='', offset=8, start_offset=8, starts_line=True, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='LOAD_NAME', opcode=93, arg=1, argval='args', argrepr='args', offset=10, start_offset=10, starts_line=True, line_number=3, label=None, positions=Positions(lineno=3, end_lineno=3, col_offset=5, end_col_offset=9), cache_info=None),
 Instruction(opname='LIST_EXTEND', opcode=79, arg=1, argval=1, argrepr='', offset=12, start_offset=12, starts_line=True, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='CALL_INTRINSIC_1', opcode=53, arg=6, argval=6, argrepr='INTRINSIC_LIST_TO_TUPLE', offset=14, start_offset=14, starts_line=False, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='LOAD_CONST', opcode=82, arg=1, argval='sep', argrepr="'sep'", offset=16, start_offset=16, starts_line=False, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='LOAD_CONST', opcode=82, arg=2, argval='\n', argrepr="'\\n'", offset=18, start_offset=18, starts_line=True, line_number=4, label=None, positions=Positions(lineno=4, end_lineno=4, col_offset=8, end_col_offset=12), cache_info=None),
 Instruction(opname='BUILD_MAP', opcode=47, arg=1, argval=1, argrepr='', offset=20, start_offset=20, starts_line=True, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='LOAD_NAME', opcode=93, arg=2, argval='kwargs', argrepr='kwargs', offset=22, start_offset=22, starts_line=True, line_number=5, label=None, positions=Positions(lineno=5, end_lineno=5, col_offset=6, end_col_offset=12), cache_info=None),
 Instruction(opname='DICT_MERGE', opcode=66, arg=1, argval=1, argrepr='', offset=24, start_offset=24, starts_line=True, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='CALL_FUNCTION_EX', opcode=4, arg=None, argval=None, argrepr='', offset=26, start_offset=26, starts_line=False, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None),
 Instruction(opname='RETURN_VALUE', opcode=35, arg=None, argval=None, argrepr='', offset=28, start_offset=28, starts_line=False, line_number=1, label=None, positions=Positions(lineno=1, end_lineno=6, col_offset=0, end_col_offset=1), cache_info=None)]

Points of note:

• Many of the instructions are resolved to the same .positions (= PyCode_Addr2Location()).
• Note especially 5 instructions with .start_line=True, .line_number=1:
  • The initial LOAD_NAME(...) for print,
  • The BUILD_LIST(...) and LIST_EXTEND(...) for constructing the positional args from the mixture of literal and variable args, and
  • The BUILD_MAP(...) and DICT_MERGE(...) for constructing the keyword args from the mixture of literal and variable args.

And when line-profiled, indeed we get 5 hits on line 1 per invocation. To catch this:

• Only looking at PyCode_Addr2Location() will be insufficient, since the above (5 hits on the call line per call), your original case (2 hits per call), and my slight modification thereof (1 hit per call) won't be distinguishable.
• Only keeping track of where the callable and the arguments themselves are pushed onto the stack will also be insufficient, because all three objects (print and the args and kwargs passed to it) are somehow counted as having been pushed onto the stack on line 1.

It may be necessary to not just keep tabs on the line numbers comprising each component of each stack item, but actually simulate the number of times they are hit during the construction of the item.

[TTsangSC]

Pardon me while I continue to think out loud. I have an experimental "fix" for this on the branch adjust-multiline-call-hits, which just post-processes and normalizes the line-hit figures with the number of "duplicate" line events dis reports per line.¹ This however doesn't fully work because duplicates doesn't only happen on lines with CALL_* and BUILD_* opcodes; they also occur e.g. for for loops as mentioned (#215). As such, the normalization wouldn't work for the latter, and especially when the two are mixed on the same line: see multiline_call_and_for_loop_on_same_line() in the example script below, where we get 4 line events from constructing the iterable with the pairwise() call, and then 9 + 1 line events from the for loop.

(Note: NONE of the claims about version-dependent behaviors has been verified on the 3.15 release candidate.)

Example script

See the script below for some more cases analogous to/interacting with the original issue:

(click to expand)

from __future__ import annotations

from argparse import ArgumentParser
from collections.abc import Generator, Sequence
from inspect import unwrap
from itertools import count, pairwise


def main(args: Sequence[str] | None = None) -> None:
    funcs = {}
    for name, value in globals().items():
        if name == 'main' or name.startswith('_'):
            continue
        try:
            # Use `unwrap()` because `kernprof` wraps the functions in
            # autoprofiling mode
            code = unwrap(value).__code__
        except AttributeError:
            continue
        if code.co_filename == __file__:
            funcs[name] = value

    parser = ArgumentParser()
    parser.add_argument('func', choices=funcs)
    funcs[parser.parse_args(args).func]()


def multiline_call_and_for_loop_on_separate_lines(
    n: int = 10, /, *args, **kwargs,
) -> None:
    """
    On the line where :py:func:`print` is called, we have the following
    line events:

    - Loading the callable (1 hit per INVOCATION)

    - Call-args construction (4 hits per INVOCATION: prepare callable,
      mixed posargs, mixed kwargs, make the call)

    The for-loop line also gets 1 hit per LOOP + 1 extra hit per
    INVOCATION (`FOR_ITER`) + another 1 extra hit per INVOCATION
    (:py:func:`range` call-arg construction).
    """
    for i in range(
        n,
    ):
        print(
            i,
            *args,
            sep='  ',
            **kwargs
        )


def multiline_call_and_while_loop(
    n: int = 10, /, *args, **kwargs,
) -> None:
    """
    On the line where :py:func:`print` is called, we have the following
    line events:

    - Loading the callable (1 hit per INVOCATION)

    - Call-args construction (4 hits per INVOCATION: prepare callable,
      mixed posargs, mixed kwargs, make the call)

    The while-loop line also gets 1 hit per LOOP + 1 extra hit per
    INVOCATION (`POP_JUMP_IF_FALSE` (!= 3.11) or
    `POP_JUMP_FORWARD_IF_FALSE`).
    """
    counter = count()
    while (
        i := next(counter)
    ) < n:
        print(
            i,
            *args,
            sep='  ',
            **kwargs
        )


def multiline_call_and_for_loop_on_same_line(
    n: int = 10, /, *args, **kwargs,
) -> None:
    """
    On the line where :py:func:`pairwise` is called, we have the
    following line events:

    - For loop (1 hit per LOOP + 1 extra hit per INVOCATION)
      (Note: only in 3.12+)

    - Loading the callable (1 hit per INVOCATION)

    - Call-args construction (3 hits per INVOCATION: prepare callable,
      mixed posargs, make the call)

    The :py:func:`print` line also sees 2-3 line events per INVOCATION
    due to the loading and calling of the callable, and the construction
    of the list comprehension in 3.12+.
    """
    print([
        foo
        for (
            foo,
            *_,
        ) in pairwise(
            range(n),
            *args,
            **kwargs,
        )
    ])


def multiline_call_and_generator(n: int = 10) -> None:
    """
    Each :py:func:`print` line sees 2 line events per INVOCATION
    due to the loading and calling of the callable.

    The first line of the string argument also emits 2-4 line events per
    INVOCATION because of (1) a stack push for the first substring and a
    subsequent (2) string construction from all substrings.
    """
    for i in _gen(n):
        print(
            'In `use_generator()`: '
            f'{i}',
        )


def _gen(n: int) -> Generator[int, None, None]:
    """
    Each :py:func:`print` line sees 2 line events per INVOCATION
    due to the loading and calling of the callable.

    The first line of the string argument also emits 2-4 line events per
    INVOCATION because of (1) a stack push for the first substring and a
    subsequent (2) string construction from all substrings. In
    Python < 3.12 there were also 2 extra regressions to said line due
    to the 2 f-strings sandwiched in the middle.

    Notably, the ``yield`` expression doesn't result in extra line
    events.
    """
    substr = 'received'
    for i in range(n):
        print(
            'In `_gen()`: '
            f'{i}',
        )
        print(
            'In `_gen()`: '
            f'yielded {i}, '
            f'{substr} '
            f'{yield i}',
        )


if __name__ == '__main__':
    main()

A possible fix...

In principle, one can take a simplified line-based approach, maybe closer to your original proposal:

• At .add_function() time, use PyCode_Addr2Location()² to get the "line spans" of relevant instructions (CALL_* and BUILD_*).
• At profiling time, as long as line events stay inside the span of one such instruction, only count the first hit on the line associated with it.

This however has the following subtleties:

• Do note however, that anything that requires reference to prior line events would entail maintaining frame-local states doing profiling time, and thus cannot be overhead-free.
• Only looking at line numbers or line hashs is unsound – imagine a case where we have e.g. a function calling itself, esp. a generator/coroutine function. In such cases, we could have easily changed between frames without moving outside the line(-hash) range.
• As such, we'll have to detect such frame changes by mechanisms other than line numbers. This can be done by using a bookkeeping object (say _LineRangeBookkeepHelper, for ease of further discussion), using it to check whether we're still inside a line range. The object's state should be refreshed/reset upon entering each frame.³ However, this means any frame change (e.g. function call) would interrupt the deduplication.
• Maintaining a stack of _LineRangeBookkeepHelper synced to the frame stack would resolve the problem with function calls. However, such maintenance is expensive, and does not mesh well with generators/coroutines:
  • The naive approach is to just create a new _LineRangeBookkeepHelper (or refresh it) upon resuming a coroutine frame. This however means that "duplicates" happening before and after the yield will be handled separately, resulting in deduplication from n line events to 2 instead of 1 (see _gen() in the example).
  • Another is to special-case coroutines and maintain separate references thereto until each coroutine returns or errors out. However, this makes things more difficult for sys.monitoring because it works with code objects not individual frames, and thus we may need to use inspect.currentframe() to retrieve and identify the frame on top of the stack, if possible at all.
• This points to the need to have _LineRangeBookkeepHelpers associated with individual frames. Ideally, we can just use a mapping from frames/frame ids to _LineRangeBookkeepHelpers. However:
  • The aforementioned caveat for frame retrieval with sys.monitoring applies.
  • Maintenance is still needed, e.g. destroying/resetting _LineRangeBookkeepHelpers when we return or throw from their corresponding frames. This is especially important because Python recycles dead object IDs for new objects, resulting in possible clash if we have helpers associated with dead frames. (But of course that is already supposed to be done – we don't want to haul an infinitely growing number of _LineRangeBookkeepHelpers around as the profile code runs.
• More fundamentally, forget about frames – instructions themselves can have overlapping or even identical spans, and it may become ambiguous how deduplication should proceed when we're simultaneously inside multiple spans.

... and yet another

Alternatively, note that so far the key issue with adjust-multiline-call-hits is that we should only be adjusting the line-event counts associated with the CALL_* and BUILD_* instructions. (Caveat: maybe there're more problematic cases that we haven't discovered yet. But one thing at a time.) For this purpose, count normalization is probably okay, unless line-hit counts from loops muddy the water.

The strategy then becomes:

• At .add_function() time, for each relevant instruction (CALL_* or BUILD_*), gather:

  • The number of line events on its .lineno, and
  • All the instructions on said line.

• The above is mostly okay, save for the edge cases where:

  • The instruction is used as/in the iterable in a for loop or a comprehension, and the for is on the same line as the instruction (see multiline_call_and_for_loop_on_separate_lines()). This:
    • In Python 3.12+:
      • Stuffs an extra END_FOR instruction (which triggers a line event) onto the line,
      • In comprehensions (see multiline_call_and_for_loop_on_same_line()), if the iteration variables are set up on a different line from the iterable, makes the FOR_ITER instruction trigger a line event.
    • In non-comprehensions, if the for loop trails a function returning None implicitly, stuffs instructions ([RETURN_CONST (None)] for 3.12 and 3.13; [LOAD_CONST (None), RETURN_VALUE] otherwise) onto the line. If Python < 3.12, these instructions trigger the end-of-loop line event in lieu of END_FOR.
    • Introduces REAL for-loop line hits that shouldn't be normalized.
  • The instruction is used as/in the condition in a while loop, and the while is on the same line as the instruction (see multiline_call_and_while_loop()). This:
    • In Python 3.14+, if the while loop trails a function returning None implicitly, stuffs instructions ([LOAD_CONST (None), RETURN_VALUE]) onto the line.
    • In Python < 3.14, duplicates the instructions setting up the condition.

  While for loops are easy to detect since they compiles down to contain the FOR_ITER instruction, the same can't be said for while loops since they are conditional jumps (POP_JUMP_FORWARD_IF_FALSE (3.11) or POP_JUMP_IF_FALSE (otherwise)),⁴ which aren't really distinguishable from other similar jumps like if statements and x if y else z ternaries. But we can probably figure that out by detecting the corresponding backwards jump, which is in the form of either a JUMP_BACKWARD (3.12+), POP_JUMP_BACKWARD_IF_TRUE (3.11), or POP_JUMP_IF_TRUE (3.10)⁴ to the instruction directly following the first jump.

• Take care of the above edge cases by:

  • Adjusting the "duplicity counts" map (say ndups) from line numbers to "duplicate" line events accorndingly.
  • Keep an extra map (say loop_codes) from opcode (FOR_ITER (if a for loop) or the POP_JUMP_*/JUMP_BACKWARD (if a while loop)) offsets representing loop iterations to their respective line numbers.

• At profiling time it remains to:

  • Keep track of line events and count each hit as before, say in raw_counts.
  • Keep track of the instructions executed, and increment a loop-hit count (say in loop_counts) each time a corresponding instruction in loop_codes is hit.

• At .get_stats() time, when calculating the adjusted stats, instead of the current adj_count = raw_counts[lineno] / ndups.get(lineno, 1), do adj_count = (raw_counts[lineno] - loop_counts.get(lineno, 0)) / ndups.get(lineno, 1) + loop_counts.get(lineno, 0).

However, like with the previous approach, this would also introduce profiling-time overhead, since we now have to capture opcode events.⁵ Can't have nothing for nothing I guess, but at least with this one I have a clearer idea as to its possible implementation.

Footnotes

1. The adjustment factors are stored as an optional private attribute on LineStats. As such, the object remains backward compatible in terms of layout, and one can un-pickle old .lprof files into new instances (without said private attribute). ↩

2. Again, this is 3.11+ only; the same goes for the pure-Python equivalent (dis.Instruction.positions). ↩

3. Frame changes can be detected by tracing legacy 'call', 'return', and 'exception' events; or sys.monitoring.events.PY_START, .PY_YIELD, .PY_RESUME, .PY_THROW, .PY_RETURN, .RAISE, and .RERAISE events. ↩

4. If the while condition is negated, the complements of the truth-value specific instructions are used. ↩ ↩²

5. In my initial reply I incorrectly surmised that sys.monitoring is necessary for instruction-level tracing; I forgot about how the current opcode can be retrieved by (1) setting FrameType.f_trace_opcodes to true, (2) handling 'opcode' events in the trace callback, and inspecting FrameType.f_lasti to retrieve the active bytecode offset. ↩