GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython #103083

markshannon · 2023-03-28T14:34:41Z

This implements PEP 669.
There are a couple of things missing, but no harm in early review.

Issue: Implement and document PEP 669. #103082

…er VM.

markshannon · 2023-04-11T16:37:30Z

That might mean that there is an extra line event.

Do you have a function that produces this problem? (module level code is a pain to test)
I can then check that the line events match up.

fabioz · 2023-04-11T16:41:46Z

I was testing some things here and I got an easier repro:

Create a file named: snippet.py with the contents below:

import sys


def tracefunc(frame, event, arg):
    if frame.f_code.co_filename.endswith('snippet.py'):
        frame.f_trace = tracefunc
        print(frame, event, arg)
    return tracefunc

sys.settrace(tracefunc)
sys._getframe().f_trace = tracefunc

if __name__ == "__main__":
    N = len(sys.argv)  # break here

    if N >= 2:  # step 1
        arg1 = sys.argv[1]  # the debugger gets here even though N=1
        print(arg1)
    else:
        arg1 = 'MyString'  # step 2

    if N >= 3:  # step 3
        arg2 = int(sys.argv[2])  # the debugger gets here even though N=1
    else:
        arg2 = int(0)  # step 4

    print(N)  # still N=1 step 5
    # print(arg1)  # if you print this then it changes the debugger behavior above

If you run it with the master it'll print something as:

<frame at 0x0000022C16A1B110, file '...snippet.py', line 20, code <module>> line None
<frame at 0x0000022C16A1B110, file '...snippet.py', line 21, code <module>> line None
<frame at 0x0000022C16A1B110, file '...snippet.py', line 23, code <module>> line None
<frame at 0x0000022C16A1B110, file '...snippet.py', line 27, code <module>> line None
<frame at 0x0000022C16A1B110, file '...snippet.py', line 29, code <module>> line None
<frame at 0x0000022C16A1B110, file '...snippet.py', line 32, code <module>> line None
<frame at 0x0000022C16A1B110, file '...snippet.py', line 34, code <module>> line None
1
<frame at 0x0000022C16A1B110, file '...snippet.py', line 34, code <module>> return None

if you run it with this PR you'll get repeated lines, so, the output is something as:

<frame at 0x00000245D75A8880, file '...snippet.py', line 20, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 21, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 21, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 23, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 27, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 27, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 29, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 32, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 32, code <module>> line None
<frame at 0x00000245D75A8880, file '...snippet.py', line 34, code <module>> line None
1
<frame at 0x00000245D75A8880, file '...snippet.py', line 34, code <module>> return None

nedbat · 2023-04-11T22:19:18Z

Is there another module that behaves like this?

import sys

print(type(sys.monitoring))

import sys.monitoring

produces:

<class 'module'>
Traceback (most recent call last):
  File "/Users/nedbatchelder/coverage/trunk/../lab/pep669.py", line 5, in <module>
    import sys.monitoring
ModuleNotFoundError: No module named  'sys.monitoring'; 'sys' is not a package

It's a module but I can't import it directly.

gaogaotiantian · 2023-04-11T22:20:39Z

Is there another module that behaves like this?

import sys

print(type(sys.monitoring))

import sys.monitoring

produces:

<class 'module'>
Traceback (most recent call last):
  File "/Users/nedbatchelder/coverage/trunk/../lab/pep669.py", line 5, in <module>
    import sys.monitoring
ModuleNotFoundError: No module named  'sys.monitoring'; 'sys' is not a package

It's a module but I can't import it directly.

For the record, I had the same issue when I was using it and I was confused.

gvanrossum · 2023-04-11T22:27:54Z

Is there another module that behaves like this?

import sys

print(type(sys.monitoring))

import sys.monitoring

produces:

<class 'module'>
Traceback (most recent call last):
  File "/Users/nedbatchelder/coverage/trunk/../lab/pep669.py", line 5, in <module>
    import sys.monitoring
ModuleNotFoundError: No module named  'sys.monitoring'; 'sys' is not a package

It's a module but I can't import it directly.

But does it matter? There is no promise that sys.monitoring is a module. It's just a namespace ("let's do more of those!"). You can write import sys; sys.monitoring.set_events(...) or you can use from sys import modules; modules.set_events(...). I'd say having it be a module is better than having it be a class full of static methods. :-)

brandtbucher · 2023-04-11T22:42:56Z

Is there another module that behaves like this?

import sys

print(type(sys.monitoring))

import sys.monitoring

produces:

<class 'module'>
Traceback (most recent call last):
  File "/Users/nedbatchelder/coverage/trunk/../lab/pep669.py", line 5, in <module>
    import sys.monitoring
ModuleNotFoundError: No module named  'sys.monitoring'; 'sys' is not a package

It's a module but I can't import it directly.

This happens basically whenever a module imports another module:

>>> import ast
>>> type(ast.sys)
<class 'module'>
>>> import ast.sys
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named  'ast.sys'; 'ast' is not a package

🙃

Perhaps a good mental model for sys.monitoring is that the top line of the sys module is import _something_super_secret as monitoring.

markshannon · 2023-04-12T09:19:53Z

It is a bit bit weird that from sys import monitoring as m doesn't work.
We should probably fix that.

I expect to (hopefully before 3.12) use some sort of lazy loading to avoid creating the monitoring object if it isn't needed.

markshannon · 2023-04-12T09:27:04Z

@fabioz Thanks for the reproducer.

…to new value.

markshannon · 2023-04-12T11:01:02Z

OK. I'm merging this.

I think this is stable enough to merge, and we can probably get better bug reports with this merged than on a branch.

fabioz · 2023-04-12T11:06:11Z

@markshannon from the fix you seem to have put there, it'd still fail if the user set the tracing to None and then back to the actual trace function...

markshannon · 2023-04-12T11:33:59Z

I think that is the current behavior, is it not?

If you restart tracing, then you want a line event for the current line.
At least, pdb seems to want that. If I don't clear the "last traced line", when setting f_trace, then the pdb tests fail.

TBH, it is all an undocumented black box, so some guess work is required.
It seems the best we can do is add test cases, so if you have any more tests I'd be grateful.

erlend-aasland · 2023-04-12T11:44:17Z

Darn, I was just about to complete my second review.

$ ./python.exe -m test -R : test_monitoring  # <= fails

erlend-aasland · 2023-04-06T22:54:23Z

Include/internal/pycore_frame.h

+    Having stacktop <= 0 ensures that invalid
+    values are not visible to the cycle GC.
+    We choose -1 rather than 0 to assist debugging. */


Suggested change

Having stacktop <= 0 ensures that invalid

values are not visible to the cycle GC.

We choose -1 rather than 0 to assist debugging. */

Having stacktop <= 0 ensures that invalid

values are not visible to the cycle GC.

We choose -1 rather than 0 to assist debugging. */

erlend-aasland · 2023-04-06T23:01:23Z

Python/ceval.c

-        DTRACE_FUNCTION_ENTRY();
+        /* Because this avoids the RESUME,
+         * we need to update instrumentation */
+        _Py_Instrument(frame->f_code, tstate->interp);


The return value of _Py_Instrument is ignored here. Since it might set an exception, I'd expect a goto exit_unwind on error here.

We are already handling an exception here, so the exception isn't lost, it replaces the thrown exception.
The question is whether to raise it back to the caller, or to inject into the coroutine/generator?

If unwinding were done in a separate function from evaluation, then the thrown exception would unwind the stack, then the new exception would be raised on continued execution, which would be better.

I'm inclined to leave it for now, and let it get fixed as a side effect of separating evaluation and unwinding.

erlend-aasland · 2023-04-06T23:06:17Z

Python/instrumentation.c

+};
+
+static inline bool
+opcode_has_event(int opcode) {


Suggested change

opcode_has_event(int opcode) {

opcode_has_event(uint8_t opcode)

{

erlend-aasland · 2023-04-06T23:07:02Z

Python/instrumentation.c

+}
+
+static inline bool
+is_instrumented(int opcode) {


Suggested change

is_instrumented(int opcode) {

is_instrumented(uint8_t opcode)

{

erlend-aasland · 2023-04-06T23:08:23Z

Python/instrumentation.c

+    assert(test); \
+} while (0)
+
+bool valid_opcode(int opcode) {


Suggested change

bool valid_opcode(int opcode) {

bool valid_opcode(int opcode)

{

erlend-aasland · 2023-04-12T11:14:44Z

Python/instrumentation.c

+    _PyInterpreterFrame *frame, _Py_CODEUNIT *instr, _Py_CODEUNIT *target
+) {


Suggested change

_PyInterpreterFrame *frame, _Py_CODEUNIT *instr, _Py_CODEUNIT *target

) {

_PyInterpreterFrame *frame, _Py_CODEUNIT *instr, _Py_CODEUNIT *target)

{

erlend-aasland · 2023-04-12T11:17:44Z

Python/instrumentation.c

+
+#define C_RETURN_EVENTS \
+    ((1 << PY_MONITORING_EVENT_C_RETURN) | \
+    (1 << PY_MONITORING_EVENT_C_RAISE))


Suggested change

(1 << PY_MONITORING_EVENT_C_RAISE))

(1 << PY_MONITORING_EVENT_C_RAISE))

erlend-aasland · 2023-04-12T11:18:22Z

Python/instrumentation.c

+        interp->monitoring_tool_names[tool_id] == NULL
+    ) {


Suggested change

interp->monitoring_tool_names[tool_id] == NULL

) {

interp->monitoring_tool_names[tool_id] == NULL)

{

erlend-aasland · 2023-04-12T11:32:57Z

Python/instrumentation.c

+    else {
+        return MOST_SIGNIFICANT_BITS[bits];
+    }


Suggested change

else {

return MOST_SIGNIFICANT_BITS[bits];

}

return MOST_SIGNIFICANT_BITS[bits];

erlend-aasland · 2023-04-12T11:34:20Z

Python/instrumentation.c

+
+/* Should use instruction metadata for this */
+static bool
+is_super_instruction(int opcode) {


Suggested change

is_super_instruction(int opcode) {

is_super_instruction(uint8_t opcode)

{

fabioz · 2023-04-12T11:49:14Z

I think that is the current behavior, is it not?

If you restart tracing, then you want a line event for the current line. At least, pdb seems to want that. If I don't clear the "last traced line", when setting f_trace, then the pdb tests fail.

TBH, it is all an undocumented black box, so some guess work is required. It seems the best we can do is add test cases, so if you have any more tests I'd be grateful.

Ok, I'll try another round of the debugger tests to see if there's more breakage -- that previous issue didn't really let me get further, so, I'll check and report back -- with bugs in the tracker if that's the case I guess ;)

fabioz · 2023-04-12T12:08:37Z

@markshannon I just checked and changing the tracing shouldn't duplicate line events in the new tracer (it should only report when the line actually changes).

I created #103471 with a test case for this (which works in Python 3.11 and fails in the current master).

bedevere-bot · 2023-04-12T13:33:40Z

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Hi! The buildbot AMD64 Arch Linux TraceRefs 3.x has failed when building commit 411b169.

What do you need to do:

Don't panic.
Check the buildbot page in the devguide if you don't know what the buildbots are or how they work.
Go to the page of the buildbot that failed (https://buildbot.python.org/all/#builders/484/builds/3091) and take a look at the build logs.
Check if the failure is related to this commit (411b169) or if it is a false positive.
If the failure is related to this commit, please, reflect that on the issue and make a new Pull Request with a fix.

You can take a look at the buildbot page here:

https://buildbot.python.org/all/#builders/484/builds/3091

Summary of the results of the build (if available):

Click to see traceback logs

Note: switching to '411b1692811b2ecac59cb0df0f920861c7cf179a'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by switching back to a branch.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -c with the switch command. Example:

  git switch -c <new-branch-name>

Or undo this operation with:

  git switch -

Turn off this advice by setting config variable advice.detachedHead to false

HEAD is now at 411b169281 GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython (GH-103083)
Switched to and reset branch 'main'

In file included from Python/instrumentation.c:9:
./Include/internal/pycore_object.h:20:35: warning: initialization of ‘PyObject *’ {aka ‘struct _object *’} from ‘int’ makes pointer from integer without a cast [-Wint-conversion]
   20 | #define _PyObject_IMMORTAL_REFCNT 999999999
      |                                   ^~~~~~~~~
Python/instrumentation.c:19:5: note: in expansion of macro ‘_PyObject_IMMORTAL_REFCNT’
   19 |     _PyObject_IMMORTAL_REFCNT,
      |     ^~~~~~~~~~~~~~~~~~~~~~~~~
./Include/internal/pycore_object.h:20:35: note: (near initialization for ‘DISABLE._ob_next’)
   20 | #define _PyObject_IMMORTAL_REFCNT 999999999
      |                                   ^~~~~~~~~
Python/instrumentation.c:19:5: note: in expansion of macro ‘_PyObject_IMMORTAL_REFCNT’
   19 |     _PyObject_IMMORTAL_REFCNT,
      |     ^~~~~~~~~~~~~~~~~~~~~~~~~
Python/instrumentation.c:20:5: warning: initialization of ‘PyObject *’ {aka ‘struct _object *’} from incompatible pointer type ‘PyTypeObject *’ {aka ‘struct _typeobject *’} [-Wincompatible-pointer-types]
   20 |     &PyBaseObject_Type
      |     ^
Python/instrumentation.c:20:5: note: (near initialization for ‘DISABLE._ob_prev’)
./Include/internal/pycore_object.h:20:35: warning: initialization of ‘PyObject *’ {aka ‘struct _object *’} from ‘int’ makes pointer from integer without a cast [-Wint-conversion]
   20 | #define _PyObject_IMMORTAL_REFCNT 999999999
      |                                   ^~~~~~~~~
Python/instrumentation.c:25:5: note: in expansion of macro ‘_PyObject_IMMORTAL_REFCNT’
   25 |     _PyObject_IMMORTAL_REFCNT,
      |     ^~~~~~~~~~~~~~~~~~~~~~~~~
./Include/internal/pycore_object.h:20:35: note: (near initialization for ‘_PyInstrumentation_MISSING._ob_next’)
   20 | #define _PyObject_IMMORTAL_REFCNT 999999999
      |                                   ^~~~~~~~~
Python/instrumentation.c:25:5: note: in expansion of macro ‘_PyObject_IMMORTAL_REFCNT’
   25 |     _PyObject_IMMORTAL_REFCNT,
      |     ^~~~~~~~~~~~~~~~~~~~~~~~~
Python/instrumentation.c:26:5: warning: initialization of ‘PyObject *’ {aka ‘struct _object *’} from incompatible pointer type ‘PyTypeObject *’ {aka ‘struct _typeobject *’} [-Wincompatible-pointer-types]
   26 |     &PyBaseObject_Type
      |     ^
Python/instrumentation.c:26:5: note: (near initialization for ‘_PyInstrumentation_MISSING._ob_prev’)
Modules/gcmodule.c:450: visit_decref: Assertion "!_PyObject_IsFreed(op)" failed
Enable tracemalloc to get the memory block allocation traceback

object address  : 0x7f159fa02740
object refcount : 1
object type     : 0x563902ad8980
object type name: dict
object repr     : make: *** [Makefile:1282: Python/frozen_modules/abc.h] Segmentation fault (core dumped)

find: ‘build’: No such file or directory
find: ‘build’: No such file or directory
find: ‘build’: No such file or directory
find: ‘build’: No such file or directory
make: [Makefile:2676: clean-retain-profile] Error 1 (ignored)

… CPython (pythonGH-103083) * The majority of the monitoring code is in instrumentation.c * The new instrumentation bytecodes are in bytecodes.c * legacy_tracing.c adapts the new API to the old sys.setrace and sys.setprofile APIs

…here it was removed from the struct. See PEP-669 (https://peps.python.org/pep-0669/) and the implementation in python/cpython#103083. There is more to be done to properly support PEP-669, but this makes it compile. See #5450

markshannon added 30 commits November 11, 2022 12:22

Initial experimental implementation of PEP 669.

e85d910

First draft implementing small subset of PEP 669.

6283ee8

Support disabling and restarting.

4edb7b7

Support multiple tools per event.

852c40b

Tidy up of monitoring internals

416b314

Fix legacy tracing.

7971979

Implement support for multiple tools.

9896902

Get support for line tracing mostly working. Needs to wait for regist…

f432a66

…er VM.

Merge branch 'main' into pep-669-incremental

fb29b34

Fix up INSTRUMENTED_OPCODES vector.

15a1ccd

Fix instrumented branches to call instrumentation with correct target.

9abb339

Merge main and assorted fixups to handle new instruction.

3ba6a39

Add PY_THROW event handling and fix up line table.

aa09895

LINE events working for sys.setrace.

9e5d87d

Add lots of internal debugging for instrumentation.

e52cbe6

Add more tests. Get those and some other passing.

6c8be7e

Fix LINE instrumentation and frame.set_lineno support (mostly)

c9e1e21

Refining line event generation.

e52e8d3

Get sys.settrace tests passing.

f434ec7

Monitor 'internal' StopIteration raises.

b680084

Check for NULLs.

e6e7cf1

Fix up a few tests

5bbc83e

Turn off debugging output by default.

7fe9a43

Remove debugging printfs

8b9f996

Avoid refleak.

9b02640

Record last traced line on frame object.

2cadf32

Get a couple more top-level tests passing.

1f54d77

Update magic number

43a3f3e

Remove debug print statement.

3d436cf

Raise SystemError if frame is missing.

691bcf5

markshannon added 2 commits April 12, 2023 11:02

Reset last traced line number when setting frame.f_trace only if set …

168b34a

…to new value.

Tidy up test case.

f07a080

markshannon merged commit 411b169 into python:main Apr 12, 2023

bedevere-bot removed the awaiting merge label Apr 12, 2023

erlend-aasland reviewed Apr 12, 2023

View reviewed changes

markshannon deleted the pep-669 branch April 12, 2023 12:49

tacaswell mentioned this pull request Apr 13, 2023

Fix #323: Support Python 3.12 python-greenlet/greenlet#327

Merged

arhadthedev mentioned this pull request Apr 19, 2023

gh-103082: Fix shifted field initialization in instrumentation.c #103561

Merged

furkanonder mentioned this pull request May 7, 2023

Missing DTrace probes #104280

Open

scoder mentioned this pull request Jun 6, 2023

[BUG] Profiling/tracing fails in Py3.12 cython/cython#5470

Open

gvanrossum mentioned this pull request Aug 8, 2023

Bytecode documentation issues for Python 3.12 #107457

Closed

20 tasks

AlexWaygood mentioned this pull request Oct 16, 2023

Stubtest: add some hacks so that sys.monitoring is checked in typeshed's CI python/mypy#16269

Open

nedbat mentioned this pull request Nov 29, 2023

Add sys.monitoring from Python 3.12 python/typeshed#10890

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython #103083

GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython #103083

markshannon commented Mar 28, 2023 •

edited

Loading

markshannon commented Apr 11, 2023

fabioz commented Apr 11, 2023 •

edited

Loading

nedbat commented Apr 11, 2023 •

edited

Loading

gaogaotiantian commented Apr 11, 2023

gvanrossum commented Apr 11, 2023

brandtbucher commented Apr 11, 2023 •

edited

Loading

markshannon commented Apr 12, 2023

markshannon commented Apr 12, 2023

markshannon commented Apr 12, 2023

fabioz commented Apr 12, 2023

markshannon commented Apr 12, 2023

erlend-aasland commented Apr 12, 2023

erlend-aasland Apr 6, 2023

erlend-aasland Apr 6, 2023

markshannon Apr 12, 2023

erlend-aasland Apr 6, 2023

erlend-aasland Apr 6, 2023

erlend-aasland Apr 6, 2023

erlend-aasland Apr 12, 2023

erlend-aasland Apr 12, 2023

erlend-aasland Apr 12, 2023

erlend-aasland Apr 12, 2023

erlend-aasland Apr 12, 2023

fabioz commented Apr 12, 2023

fabioz commented Apr 12, 2023

bedevere-bot commented Apr 12, 2023

	opcode_has_event(int opcode) {
	opcode_has_event(uint8_t opcode)
	{

	is_instrumented(int opcode) {
	is_instrumented(uint8_t opcode)
	{

	bool valid_opcode(int opcode) {
	bool valid_opcode(int opcode)
	{

		_PyInterpreterFrame frame, _Py_CODEUNIT instr, _Py_CODEUNIT *target
		) {

	(1 << PY_MONITORING_EVENT_C_RAISE))
	(1 << PY_MONITORING_EVENT_C_RAISE))

	is_super_instruction(int opcode) {
	is_super_instruction(uint8_t opcode)
	{

GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython #103083

GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython #103083

Conversation

markshannon commented Mar 28, 2023 • edited Loading

markshannon commented Apr 11, 2023

fabioz commented Apr 11, 2023 • edited Loading

nedbat commented Apr 11, 2023 • edited Loading

gaogaotiantian commented Apr 11, 2023

gvanrossum commented Apr 11, 2023

brandtbucher commented Apr 11, 2023 • edited Loading

markshannon commented Apr 12, 2023

markshannon commented Apr 12, 2023

markshannon commented Apr 12, 2023

fabioz commented Apr 12, 2023

markshannon commented Apr 12, 2023

erlend-aasland commented Apr 12, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fabioz commented Apr 12, 2023

fabioz commented Apr 12, 2023

bedevere-bot commented Apr 12, 2023

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

markshannon commented Mar 28, 2023 •

edited

Loading

fabioz commented Apr 11, 2023 •

edited

Loading

nedbat commented Apr 11, 2023 •

edited

Loading

brandtbucher commented Apr 11, 2023 •

edited

Loading