Skip to content

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

Closed
Closed
[BUG] Profiling/tracing fails in Py3.12#5470
Labels
Python SemanticsGeneral Python (3) language semanticsdefect
Milestone
3.1

Description

@scoder
scoder
opened on Jun 6, 2023

Describe the bug

PEP-669 (https://peps.python.org/pep-0669/) and its implementation in python/cpython#103083 change the internals of CPython's tracing in Py3.12. We need to adapt. Currently, profiling fails in Py3.12.

Compilation was already fixed in 03c498d (#5450), but that doesn't make the feature work again.

Test failure:

Details 
======================================================================
FAIL: pstats_profile_test ()
Doctest: pstats_profile_test
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 2228, in runTest
    raise self.failureException(self.format_failure(new.getvalue()))
AssertionError: Failed doctest test for pstats_profile_test
  File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 1, in pstats_profile_test

----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 8, in pstats_profile_test
Failed example:
    short_stats['f_def']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[5]>", line 1, in <module>
        short_stats['f_def']
        ~~~~~~~~~~~^^^^^^^^^
    KeyError: 'f_def'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 10, in pstats_profile_test
Failed example:
    short_stats['f_cdef']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[6]>", line 1, in <module>
        short_stats['f_cdef']
        ~~~~~~~~~~~^^^^^^^^^^
    KeyError: 'f_cdef'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 12, in pstats_profile_test
Failed example:
    short_stats['f_cpdef']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[7]>", line 1, in <module>
        short_stats['f_cpdef']
        ~~~~~~~~~~~^^^^^^^^^^^
    KeyError: 'f_cpdef'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 14, in pstats_profile_test
Failed example:
    short_stats['f_inline']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[8]>", line 1, in <module>
        short_stats['f_inline']
        ~~~~~~~~~~~^^^^^^^^^^^^
    KeyError: 'f_inline'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 16, in pstats_profile_test
Failed example:
    short_stats['f_inline_prof']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[9]>", line 1, in <module>
        short_stats['f_inline_prof']
        ~~~~~~~~~~~^^^^^^^^^^^^^^^^^
    KeyError: 'f_inline_prof'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 22, in pstats_profile_test
Failed example:
    short_stats['f_raise']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[11]>", line 1, in <module>
        short_stats['f_raise']
        ~~~~~~~~~~~^^^^^^^^^^^
    KeyError: 'f_raise'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 25, in pstats_profile_test
Failed example:
    short_stats['withgil_prof']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[12]>", line 1, in <module>
        short_stats['withgil_prof']
        ~~~~~~~~~~~^^^^^^^^^^^^^^^^
    KeyError: 'withgil_prof'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 41, in pstats_profile_test
Failed example:
    short_stats['f_raise']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[16]>", line 1, in <module>
        short_stats['f_raise']
        ~~~~~~~~~~~^^^^^^^^^^^
    KeyError: 'f_raise'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 44, in pstats_profile_test
Failed example:
    short_stats['m_def']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[17]>", line 1, in <module>
        short_stats['m_def']
        ~~~~~~~~~~~^^^^^^^^^
    KeyError: 'm_def'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 46, in pstats_profile_test
Failed example:
    short_stats['m_cdef']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[18]>", line 1, in <module>
        short_stats['m_cdef']
        ~~~~~~~~~~~^^^^^^^^^^
    KeyError: 'm_cdef'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 48, in pstats_profile_test
Failed example:
    short_stats['m_cpdef'] - (200 if CPDEF_METHODS_COUNT_TWICE else 0)  # FIXME!
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[19]>", line 1, in <module>
        short_stats['m_cpdef'] - (200 if CPDEF_METHODS_COUNT_TWICE else 0)  # FIXME!
        ~~~~~~~~~~~^^^^^^^^^^^
    KeyError: 'm_cpdef'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 56, in pstats_profile_test
Failed example:
    sorted(callees(s, 'test_profile'))  #doctest: +NORMALIZE_WHITESPACE
Expected:
    ['f_cdef', 'f_cpdef', 'f_def',
     'f_inline', 'f_inline_prof',
     'f_raise',
     'm_cdef', 'm_cpdef', 'm_def',
     'withgil_prof']
Got:
    []
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 66, in pstats_profile_test
Failed example:
    short_stats['generator']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[25]>", line 1, in <module>
        short_stats['generator']
        ~~~~~~~~~~~^^^^^^^^^^^^^
    KeyError: 'generator'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 69, in pstats_profile_test
Failed example:
    short_stats['generator_exception']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[26]>", line 1, in <module>
        short_stats['generator_exception']
        ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
    KeyError: 'generator_exception'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 72, in pstats_profile_test
Failed example:
    short_stats['genexpr']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[27]>", line 1, in <module>
        short_stats['genexpr']
        ~~~~~~~~~~~^^^^^^^^^^^
    KeyError: 'genexpr'
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 75, in pstats_profile_test
Failed example:
    sorted(callees(s, 'test_generators'))
Expected:
    ['call_generator', 'call_generator_exception', 'generator_expr']
Got:
    []
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 78, in pstats_profile_test
Failed example:
    list(callees(s, 'call_generator'))
Expected:
    ['generator']
Got:
    []
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 87, in pstats_profile_test
Failed example:
    list(callees(s, 'generator_expr'))
Expected:
    ['genexpr']
Got:
    []
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/6/run/c/pstats_profile_test/pstats_profile_test.cpython-312-x86_64-linux-gnu.so", line 107, in pstats_profile_test
Failed example:
    python_stats_dict['python_generator'] == cython_stats_dict['generator']
Exception raised:
    Traceback (most recent call last):
      File "/opt/hostedtoolcache/Python/3.12.0-beta.1/x64/lib/python3.12/doctest.py", line 1357, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest pstats_profile_test[42]>", line 1, in <module>
        python_stats_dict['python_generator'] == cython_stats_dict['generator']
                                                 ~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^
    KeyError: 'generator'

Code to reproduce the behaviour:

No response

Expected behaviour

No response

OS

No response

Python version

3.12.0b1

Cython version

current master (3.0.0b3)

Additional context

No response

Activity

  1. scoder
    added
    defect
    Python SemanticsGeneral Python (3) language semantics
    on Jun 6, 2023
  2. scoder
    added this to the 3.0 milestone on Jun 6, 2023

  3. h-vetinari commented on Jun 6, 2023

    @h-vetinari
    h-vetinari
    on Jun 6, 2023 · Hidden as off-topic
  4. scoder
    modified the milestones: 3.0, 3.0.x on Jul 23, 2023

  5. zoj613 commented on Aug 29, 2023

    @zoj613
    zoj613
    on Aug 29, 2023
    Contributor

    Is there a chance that this could be in before the final release of 3.12? Also will this functionality be restored for 0.2.x version?

  6. scoder commented on Aug 29, 2023

    @scoder
    scoder
    on Aug 29, 2023
    ContributorAuthor

    Is there a chance that this could be in before the final release of 3.12?

    If someone repairs it in time, then yes. Investigations and/or PR is welcome.

    Basically, someone has to figure out how tracing can be done in Python 3.12 now. The CPython project broke their C-API, so they probably have a (documented?) idea somewhere how to migrate.

    will this functionality be restored for 0.2.x version?

    This is out of scope for future 0.29.x releases. We could add an explicit C warning there, though, when users try to use tracing in Py3.12. You can use Python 3.11 for profiling/tracing with 0.29.x.

  7. scoder commented on Nov 12, 2023

    @scoder
    scoder
    on Nov 12, 2023
    ContributorAuthor

    Quote from @da-woods in #5813

    Profiling on Py3.12+ is currently broken. Here are my notes from looking into it:

    • PyEval_SetProfile is now "legacy". It still works, and I believe Cython would still interact correctly with it if it were used. However, the standard library profile modules don't use it.
    • The current preferred way is via sys.monitoring, and this is what profile/cProfile do.
    • PyEval_SetProfile sets up functions using the new "monitoring" approach, however, things that use the new "monitoring" approach don't trigger the old PyEval_SetProfile way. Therefore, if we want to interact with all profiling tools we really need to use the new "monitoring" approach.
    • I think the right thing to do would be to call _Py_call_instrumentation (or something similar). Unfortunately these are internal symbols so fail at the link stage (even if include the internal headers).
    • There doesn't seem to be an easy way to check if profiling is enabled. However, _Py_call_instrumentation looks to return very quickly if it isn't, so I think that's OK.
    • The linking errors are largely where I got stuck - there doesn't seem to be any accessible way to trigger a profiling event manually.

  8. scoder commented on Nov 12, 2023

    @scoder
    scoder
    on Nov 12, 2023
    ContributorAuthor

    I created python/cpython#111997 for designing a new signalling C-API in CPython.

  9. da-woods commented on Nov 12, 2023

    @da-woods
    da-woods
    on Nov 12, 2023
    Collaborator

    My proposal for now is just to remove the test from Python 3.12: #5815.

    I suspect if people really needed to profile Cython+Python 3.12 they could cprofile/profile from Python 3.11 and it'd work (because they'd use the "legacy" method). But I don't think that's something we should provide ourself.

  10. scoder commented on Nov 21, 2023

    @scoder
    scoder
    on Nov 21, 2023
    ContributorAuthor

    Some more information that I was able to collect:

    We probably need to build a line table. CPython has C code for this in assemble.c, but we need a Python implementation that runs at translation time and an idea for a reasonable mapping of Cython's code positions to reportable event positions.

    The code enum (bits 3-6) is defined here:
    https://github.com/python/cpython/blob/d67f947c72af8a215db2fd285e5de9b1e671fde1/Include/cpython/code.h#L378-L389

  11. tvalentyn commented on Apr 2, 2024

    @tvalentyn
    tvalentyn
    on Apr 2, 2024

    This is out of scope for future 0.29.x releases.

    I noticed that 0.29.x releases produce a cpp code that doesn't compile, when cython: profile=True directive is set. However, on Cython 3.x, the code compiles. Given that:

    Profiling on Py3.12+ is currently broken

    what is the current behavior on Cython 3.x when cython: profile=True is present? Is it silently ignored?

    Would it make sense to adjust Cython 0.29 to ignore this directive for Python 3.12 , or 0.29.x family is no longer developed and the workaround to ignore the profiling directive won't be back-ported? Thanks.

  12. da-woods commented on Apr 2, 2024

    @da-woods
    da-woods
    on Apr 2, 2024
    Collaborator

    what is the current behavior on Cython 3.x when cython: profile=True is present? Is it silently ignored?

    If I remember right, it doesn't do anything. Not deliberately but because it just invokes the old profiling mechanism, but Python is only listening for the new one.

    Would it make sense to adjust Cython 0.29 to ignore this directive for Python 3.12 , or 0.29.x family is no longer developed and the workaround to ignore the profiling directive won't be back-ported?

    0.29.x is "important bug fixes only". My feeling is that this doesn't meet the criteria, but if it were a simple change then we'd consider it.

  13. tvalentyn commented on Apr 2, 2024

    @tvalentyn
    tvalentyn
    on Apr 2, 2024

    if it were a simple change then we'd consider it.

    I came up with: #6125. We could include it if we expect usage of Cython 0.29 on 3.12.
    Does Cython have a plan to cap an upper bound of allowed Python minor version for the 0.29 version family?

  14. scoder commented on Apr 15, 2024

    @scoder
    scoder
    on Apr 15, 2024
    ContributorAuthor

    I've started on an implementation for Py3.13, based on the newly designed monitoring C-API. I'll see how that goes.
    python/cpython#111997

  15. ionelmc
    added a commit that references this issue on May 1, 2024

    XFail these on 3.12, ref cython/cython#5470

    3fbc676
  16. vfazio
    added a commit that references this issue on Jun 12, 2024

    ci: add Python 3.12 to matrices

    6df947e

  17. ogiarch commented on Dec 2, 2024

    @ogiarch
    ogiarch
    on Dec 2, 2024

    @scoder, I see that the issue you linked in your most recent comment above is now closed. Do we know what work remains to fix this? I'd love to be able to profile my .pyx functions with cProfile in Python 3.13, if possible.

  18. scoder
    modified the milestones: 3.0.x, 3.1 on Feb 11, 2025

  19. scoder commented on Feb 11, 2025

    @scoder
    scoder
    on Feb 11, 2025
    ContributorAuthor

    This is not going to be changed in Cython 3.0.x any more. 3.1 has a new implementation, so I'll close this ticket.

  20. scoder
    closed this as completedon Feb 11, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    Python SemanticsGeneral Python (3) language semanticsdefect

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions