FIX: LineProfiler.last_time always empty (and sometimes errors out)

[TTsangSC]

The bug(s)

The behaviors of LineProfiler.c_last_time and LineProfiler.last_time are inconsistent:

import line_profiler

prof = line_profiler.LineProfiler()

...

@prof
def func():
    return prof.c_last_time.copy(), prof.last_time.copy()

# They are always empty outside a profiled scope
assert not prof.c_last_time  # This may give a `KeyError` if no profiling was done on the thread
assert not prof.last_time
clt, lt = func()
assert not prof.c_last_time
assert not prof.last_time

# But not inside the profiled scope (like `func()`)
assert clt
assert lt  # This assertion fails, `.last_time` empty despite `c_last_time` being not
assert set(clt) == {hash(f.__wrapped__.__code__.co_code)}
assert set(lt) == {f.__wrapped__.__code__}

The causes

KeyError

Both .c_last_time and .last_time directly access the underlying ._c_last_time with the key threading.get_ident(). However, it is not necessarily set if line_profiler/_line_profiler.pyx::python_trace_callback() hasn't been called on the thread yet.

Failing assertion

The implementation of line_profiler/_line_profiler.pyx::LineProfiler.last_time (type: dict[CodeType, LastTime]) basically scans .c_last_time (type: dict[int, LastTime]) for line-hash keys matching values in .code_hash_map (type: dict[CodeType, list[int]]). However, as seen in python_trace_callback() in the same file (and hinted at in the above example), the keys in .c_last_time are block hashes (hashes of the whole bytecode) not line hashes (re-hashes thereof incorporating line-number information). Hence nothing matches and the empty result.

The fix

• .last_time has been fixed to do block_hash = hash(code.co_code) instead of to scan the code_hashes (which are line hashes) corresponding to code in .code_hash_map.
• .c_last_time now catches the KeyError when accessing ._c_last_time and gracefully returns an empty dict (updated 29 May) attaches a more informative error message.
• .last_time now uses .c_last_time instead of directly accessing ._c_last_time.
• To verify the fix, the test tests/test_line_profiler.py::test_last_time() is added.

Performance implications

Should be minimal since .last_time is documented as a legacy/backward-compatible API, and nothing else directly uses .c_last_time. (The performance-critical LineProfiler.disable() and python_trace_callback() both use ._c_last_time directly.)

Disclaimers

• Again, .last_time is documented as legacy, so one may argue that the PR is unnecessary. But since the API is here, I'd argue it should either be fixed or dropped.
• Haven't included a CHANGELOG entry since this is probably too small a fix to warrant that (as indicated by the last 3 merged PRs ([RFC] Broaden support for profiling generated code #341, test that generated code displays source code in profile #343, Prevent encoding error in IPython extension in Windows #342)).

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 87.36%. Comparing base (97ecd5c) to head (1db6433).
Report is 7 commits behind head on main.

Additional details and impacted files

@@           Coverage Diff           @@
##             main     #344   +/-   ##
=======================================
  Coverage   87.36%   87.36%           
=======================================
  Files          18       18           
  Lines        1630     1630           
  Branches      347      347           
=======================================
  Hits         1424     1424           
  Misses        151      151           
  Partials       55       55           

---

Continue to review full report in Codecov by Sentry.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 7ffc0f1...1db6433. Read the comment docs.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[Erotemic]

Let's fix it, but maybe we drop it in 5.0. I'd like to get all of your backwards compatible changes integrated, but I think we can make some API changes to build a better tool (e.g. use -l by default, drop code that only exists for backwards compat)

For the KeyError, is there any reason that is causing problem? I suppose an returning an empty dictionary is an ok solution, but it also would make sense to raise the KeyError too. The empty dict doesn't correspond to any thread dictionary, so yes it has the same type, but it feels conceptually different to me.

[TTsangSC]

The suppression of the KeyError was mostly motivated by how the whole threading thing (personally) reads like implementation details to me – and raising a KeyError when accessing an attribute (.[c_]last_time) seems somewhat unintuitive.

But then these mostly boil down to opinions anyway,¹ and you have a point in that the empty dict does somehow dissociate .c_last_time from the underlying ._c_last_time. Again, it's your call whether to keep that.

(If we were to revert to letting the KeyError bubble up, I wonder if it's a good idea to decorate the error message a bit to be more informative, like

try:
    return (<dict>self._c_last_time)[threading.get_ident()]
except KeyError:
    raise KeyError('no profiling data on '
                   f'thread id {threading.get_ident()}') from None

what do you think?)

Footnotes

1. And honestly nothing else really uses .[c_]last_time – it was just a bug I stumbled upon mid-ENH: use multiple profiler instances #347, when I tried to decouple LineProfiler from the Cython class and emulate its APIs (e543ffe) so that I can just keep one instance of the Cython class. Which of course was later rolled back (97739db) since I realized that it was a bookkeeping disaster, and didn't allow for profilers to only profiler subset of calls to the profiled function. ↩

[Erotemic]

I buy that a KeyError on a property is not intuitive. On the surface, that's a good enough reason that we can patch this in. Perhaps it would make more sense to return None instead? Is there anything that you need this patch for? If it's not getting in the way, I'd prefer to delay the behavior change to 5.0. But if it is causing meaningful difficulties, then we can patch it in for the next 4.x release.

[TTsangSC]

Nothing in particular; I'll roll back the KeyError change and just focus on the empty .last_time bug in this PR then.

[Erotemic]

I rebased this on the latest main to test before merging. Otherwise I think everything in here looks good.

[TTsangSC]

Thanks for the rebase. Yep this is a rather simple PR and we can probably merge it as-is.