Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add support for sys.monitoring events. #9482

Merged
merged 8 commits into from Apr 26, 2024

Conversation

stuartarchibald
Copy link
Contributor

Python 3.12 introduced a new event monitoring system sys.monitoring. This patch augments Numba's dispatcher so as to emit events associated with a Python function starting and returning from execution. Tools monitoring for such events will therefore be able to identify execution of Numba's pure machine code regions as though they were actual Python functions. This allows tools such a cProfile to record Numba compiled function execution and report them as part of their output.

Fixes #9289

Python 3.12 introduced a new event monitoring system
`sys.monitoring`. This patch augments Numba's dispatcher so as to
emit events associated with a Python function starting and
returning from execution. Tools monitoring for such events will
therefore be able to identify execution of Numba's pure machine
code regions as though they were actual Python functions. This
allows tools such a ``cProfile`` to record Numba compiled function
execution and report them as part of their output.

Fixes numba#9289
Copy link
Member

@sklam sklam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have

  • read through the code to understand the implementation
  • manual run cProfile to compare py3.9 vs py3.12 results

Still have to review the code and cross check Python impl.

@sklam sklam added this to the 0.60.0-rc1 milestone Mar 12, 2024
@sklam
Copy link
Member

sklam commented Apr 3, 2024

nevermind, it's just typical "leak" in numba.tests.test_profiler.TestProfiler.test_profiler.

original message

Valgrind showing these when running python runtests.py numba/tests/test_profiler.py:


==3321719== 8 bytes in 1 blocks are definitely lost in loss record 47 of 4,298
==3321719==    at 0x483DF0F: operator new(unsigned long) (vg_replace_malloc.c:483)
==3321719==    by 0x576333F4: allocate (new_allocator.h:114)
==3321719==    by 0x576333F4: allocate (alloc_traits.h:444)
==3321719==    by 0x576333F4: _M_allocate (stl_vector.h:343)
==3321719==    by 0x576333F4: reserve (vector.tcc:78)
==3321719==    by 0x576333F4: addDefinition (_dispatcher.cpp:435)
==3321719==    by 0x576333F4: Dispatcher_Insert(Dispatcher*, _object*, _object*) (_dispatcher.cpp:586)
==3321719==    by 0x556BF9: method_vectorcall_VARARGS_KEYWORDS (descrobject.c:365)
==3321719==    by 0x546CF0: UnknownInlinedFun (pycore_call.h:92)
==3321719==    by 0x546CF0: PyObject_Vectorcall (call.c:325)
==3321719==    by 0x52D15B: _PyEval_EvalFrameDefault (bytecodes.c:2706)
==3321719==    by 0x581CF9: UnknownInlinedFun (pycore_ceval.h:89)
==3321719==    by 0x581CF9: UnknownInlinedFun (ceval.c:1683)
==3321719==    by 0x581CF9: UnknownInlinedFun (call.c:419)
==3321719==    by 0x581CF9: UnknownInlinedFun (pycore_call.h:92)
==3321719==    by 0x581CF9: method_vectorcall (classobject.c:91)
==3321719==    by 0x53179E: UnknownInlinedFun (call.c:387)
==3321719==    by 0x53179E: _PyEval_EvalFrameDefault (bytecodes.c:3254)
==3321719==    by 0x524E56: UnknownInlinedFun (pycore_ceval.h:89)
==3321719==    by 0x524E56: UnknownInlinedFun (ceval.c:1683)
==3321719==    by 0x524E56: UnknownInlinedFun (call.c:419)
==3321719==    by 0x524E56: _PyObject_FastCallDictTstate (call.c:133)
==3321719==    by 0x562BD5: _PyObject_Call_Prepend (call.c:508)
==3321719==    by 0x63F815: slot_tp_call (typeobject.c:8769)
==3321719==    by 0x520D4A: _PyObject_MakeTpCall (call.c:240)
==3321719==    by 0x52D15B: _PyEval_EvalFrameDefault (bytecodes.c:2706)
==3321719== 
==3321719== 8 bytes in 1 blocks are definitely lost in loss record 48 of 4,298
==3321719==    at 0x483DF0F: operator new(unsigned long) (vg_replace_malloc.c:483)
==3321719==    by 0x57633695: allocate (new_allocator.h:114)
==3321719==    by 0x57633695: allocate (alloc_traits.h:444)
==3321719==    by 0x57633695: _M_allocate (stl_vector.h:343)
==3321719==    by 0x57633695: void std::vector<_object*, std::allocator<_object*> >::_M_realloc_insert<_object* const&>(__gnu_cxx::__normal_iterator<_object**, std::vector<_object*, std::allocator<_object*> > >, _object* const&) (vector.tcc:440)
==3321719==    by 0x576334A5: push_back (stl_vector.h:1195)
==3321719==    by 0x576334A5: addDefinition (_dispatcher.cpp:439)
==3321719==    by 0x576334A5: Dispatcher_Insert(Dispatcher*, _object*, _object*) (_dispatcher.cpp:586)
==3321719==    by 0x556BF9: method_vectorcall_VARARGS_KEYWORDS (descrobject.c:365)
==3321719==    by 0x546CF0: UnknownInlinedFun (pycore_call.h:92)
==3321719==    by 0x546CF0: PyObject_Vectorcall (call.c:325)
==3321719==    by 0x52D15B: _PyEval_EvalFrameDefault (bytecodes.c:2706)
==3321719==    by 0x581CF9: UnknownInlinedFun (pycore_ceval.h:89)
==3321719==    by 0x581CF9: UnknownInlinedFun (ceval.c:1683)
==3321719==    by 0x581CF9: UnknownInlinedFun (call.c:419)
==3321719==    by 0x581CF9: UnknownInlinedFun (pycore_call.h:92)
==3321719==    by 0x581CF9: method_vectorcall (classobject.c:91)
==3321719==    by 0x53179E: UnknownInlinedFun (call.c:387)
==3321719==    by 0x53179E: _PyEval_EvalFrameDefault (bytecodes.c:3254)
==3321719==    by 0x524E56: UnknownInlinedFun (pycore_ceval.h:89)
==3321719==    by 0x524E56: UnknownInlinedFun (ceval.c:1683)
==3321719==    by 0x524E56: UnknownInlinedFun (call.c:419)
==3321719==    by 0x524E56: _PyObject_FastCallDictTstate (call.c:133)
==3321719==    by 0x562BD5: _PyObject_Call_Prepend (call.c:508)
==3321719==    by 0x63F815: slot_tp_call (typeobject.c:8769)
==3321719==    by 0x520D4A: _PyObject_MakeTpCall (call.c:240)

numba/tests/test_sys_monitoring.py Show resolved Hide resolved
numba/_dispatcher.cpp Show resolved Hide resolved
numba/_dispatcher.cpp Show resolved Hide resolved
numba/_dispatcher.cpp Outdated Show resolved Hide resolved
Adds support to Numba's dispatcher for the ``sys.monitoring.events``
of type ``RAISE`` and `PY_UNWIND``. Associated unit tests are added
and cProfile testing is updated. Docs are updated to match.
Resolved conflicts:
	numba/tests/support.py
If a Numba function is being run under cProfile and the
function raises an exception, the dispatcher must handle
this correctly. It is not valid to call
`PyFrame_FastToLocals` without saving and restoring the
exception state across the call as it can clear the
exception state itself. This patch fixes this problem and
also stops calling `PyFrame_LocalsToFast` in Python 3.11
where the "whats-new" docs claim that the frames are now
looked after by the virutal machine.
@stuartarchibald stuartarchibald marked this pull request as ready for review April 24, 2024 14:29
Fixes some RST syntax and a couple of grammatical errors.
@stuartarchibald stuartarchibald mentioned this pull request Apr 24, 2024
41 tasks
@sklam
Copy link
Member

sklam commented Apr 24, 2024

BFID numba_smoketest_cpu_yaml_193

@sklam sklam added the Pending BuildFarm For PRs that have been reviewed but pending a push through our buildfarm label Apr 24, 2024
@sklam
Copy link
Member

sklam commented Apr 24, 2024

There's an elusive bug that is only revealed by minimal test sequence:

python runtests.py numba.tests.test_sys_monitoring.TestMonitoring.test_disable_from_callback numba.tests.test_sys_monitoring.TestMonitoring.test_start_event

output:

test_start_event (numba.tests.test_sys_monitoring.TestMonitoring.test_start_event) ... FAIL

Stdout:
[call(<code object foo at 0x111c61f10, file "/Users/siu/dev/numba/numba/tests/test_sys_monitoring.py", line 16>, 0)]

======================================================================
FAIL: test_start_event (numba.tests.test_sys_monitoring.TestMonitoring.test_start_event)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/siu/dev/numba/numba/tests/test_sys_monitoring.py", line 136, in test_start_event
    self.check_py_start_calls(cb)
  File "/Users/siu/dev/numba/numba/tests/test_sys_monitoring.py", line 77, in check_py_start_calls
    self.assertEqual(mockcalls.call_count, 2)
AssertionError: 1 != 2

Stdout:
[call(<code object foo at 0x111c61f10, file "/Users/siu/dev/numba/numba/tests/test_sys_monitoring.py", line 16>, 0)]

----------------------------------------------------------------------
Ran 2 tests in 0.165s

Copy link
Member

@sklam sklam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

#9482 (comment) is the only pending problem and I have no idea why it is happening.

Code and documentation looks great

@gmarkall
Copy link
Member

There's an elusive bug that is only revealed by minimal test sequence

I can reproduce this locally too.

This works around a potential bug in CPython where the state
associated with a monitoring tool can "leak" in an unexpected
manner.

This patch also removes the use of the functools cache on the
generator for test functions, this to eliminate any potential
state being stored on the code objects associated with the
test functions.
@stuartarchibald
Copy link
Contributor Author

Thanks for finding a MWR and helping debug this @sklam, commit 5d652e7 works around the problem.

@stuartarchibald stuartarchibald added 4 - Waiting on reviewer Waiting for reviewer to respond to author and removed 3 - Ready for Review labels Apr 26, 2024
@stuartarchibald
Copy link
Contributor Author

stuartarchibald commented Apr 26, 2024

Note for the future. Were this feature request implemented python/cpython#111997 the code in this patch could be adapted to use it opposed to having to rely on CPython internal details.

Edit: This PR python/cpython#116413 implements the above. Looks like it will be in Python 3.13.

Copy link
Member

@sklam sklam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Workaround confirmed. One minor issue with the code comments

# It is necessary to restart events that have been disabled. The
# "disabled" state of the `PY_START` event for the tool
# `self.tool_id` "leaks" into subsequent tests. These tests then end
# up failing as events that should trigger do not! It's not really
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

            # up failing as events that should trigger do not! It's not really
                                                      ^^^^^^^

you mean that should not trigger?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The comment is trying to convey that "subsequent tests fail as events in them that should be triggered are not being triggered" (this was why the Mock.call_count value was 1 too small, an event that should have triggered did not).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My english parser segfaulted when reading it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've tried to make this comment more clear in 25535b3. Please take a look and see what you think. Thanks!

@sklam
Copy link
Member

sklam commented Apr 26, 2024

Reported issue to python/cpython#118327
5d652e7 is the workaround.

@stuartarchibald
Copy link
Contributor Author

Reported issue to python/cpython#118327 5d652e7 is the workaround.

Thanks for reporting this @sklam, much appreciated.

@sklam sklam added 5 - Ready to merge Review and testing done, is ready to merge and removed 4 - Waiting on reviewer Waiting for reviewer to respond to author labels Apr 26, 2024
@sklam sklam merged commit 64e7cdb into numba:main Apr 26, 2024
21 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
5 - Ready to merge Review and testing done, is ready to merge Effort - long Long size effort needed Pending BuildFarm For PRs that have been reviewed but pending a push through our buildfarm
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[Python 3.12] [Task] Profiler test failures due to Python 3.12 bytecode changes.
3 participants