Skip to content

test_perf_profiler fails on Linux (both AArch64 and x86) #124613

Closed
@diegorusso

Description

@diegorusso

Bug report

Bug description:

Our CI picked up this failure recently. We are using Ubuntu 24.04 and it is failing both on AArch64 and x86.

$ ./python -m test test_perf_profiler -v
== CPython 3.14.0a0 (heads/main-dirty:7a839d6013, Sep 26 2024, 14:53:59) [GCC 13.2.0]
== Linux-6.8.0-44-generic-aarch64-with-glibc2.39 little-endian
== Python build: release
== cwd: /home/user/work/ce-sw/repos/cpython/build/build/test_python_worker_1359145æ
== CPU count: 8
== encodings: locale=UTF-8 FS=utf-8
== resources: all test resources are disabled, use -u option to unskip tests

Using random seed: 1215453149
0:00:00 load avg: 0.44 Run 1 test sequentially in a single process
0:00:00 load avg: 0.44 [1/1] test_perf_profiler
test_pre_fork_compile (test.test_perf_profiler.TestPerfProfiler.test_pre_fork_compile) ... skipped 'Unwinding is unreliable with frame pointers'
test_python_calls_appear_in_the_stack_if_perf_activated (test.test_perf_profiler.TestPerfProfiler.test_python_calls_appear_in_the_stack_if_perf_activated) ... skipped 'Unwinding is unreliable with frame pointers'
test_python_calls_do_not_appear_in_the_stack_if_perf_deactivated (test.test_perf_profiler.TestPerfProfiler.test_python_calls_do_not_appear_in_the_stack_if_perf_deactivated) ... skipped 'Unwinding is unreliable with frame pointers'
test_python_calls_appear_in_the_stack_if_perf_activated (test.test_perf_profiler.TestPerfProfilerWithDwarf.test_python_calls_appear_in_the_stack_if_perf_activated) ... perf record -g --call-graph=dwarf,65528 -F99 -k1 -o /tmp/tmp52ljdy43/perf_output.perf -- /home/user/work/ce-sw/repos/cpython/build/python -Xperf_jit /tmp/tmp52ljdy43/perftest.py
FAIL
test_python_calls_do_not_appear_in_the_stack_if_perf_deactivated (test.test_perf_profiler.TestPerfProfilerWithDwarf.test_python_calls_do_not_appear_in_the_stack_if_perf_deactivated) ... perf record -g --call-graph=dwarf,65528 -F99 -k1 -o /tmp/tmpj41x5k9d/perf_output.perf -- /home/user/work/ce-sw/repos/cpython/build/python /tmp/tmpj41x5k9d/perftest.py
ok
test_sys_api (test.test_perf_profiler.TestPerfTrampoline.test_sys_api) ... ok
test_sys_api_get_status (test.test_perf_profiler.TestPerfTrampoline.test_sys_api_get_status) ... ok
test_sys_api_with_existing_trampoline (test.test_perf_profiler.TestPerfTrampoline.test_sys_api_with_existing_trampoline) ... ok
test_sys_api_with_invalid_trampoline (test.test_perf_profiler.TestPerfTrampoline.test_sys_api_with_invalid_trampoline) ... ok
test_trampoline_works (test.test_perf_profiler.TestPerfTrampoline.test_trampoline_works) ... ok
test_trampoline_works_with_forks (test.test_perf_profiler.TestPerfTrampoline.test_trampoline_works_with_forks) ... ok

======================================================================
FAIL: test_python_calls_appear_in_the_stack_if_perf_activated (test.test_perf_profiler.TestPerfProfilerWithDwarf.test_python_calls_appear_in_the_stack_if_perf_activated)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/user/work/ce-sw/repos/cpython/Lib/test/test_perf_profiler.py", line 357, in test_python_calls_appear_in_the_stack_if_perf_activated
    self.assertIn(f"py::bar:{script}", stdout)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'py::bar:/tmp/tmp52ljdy43/perftest.py' not found in 'python 1359175 378278.191585:   10101010 task-clock:ppp: \n\t    b5794db789fc _PyInterpreterState_GET+0x8 (inlined)\n\t    b5794db789fc get_state+0x8 (inlined)\n\t    b5794db789fc _PyObject_Malloc+0x8 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db2c383 _PyLong_FromMedium+0xff (inlined)\n\t    b5794db2c383 PyLong_FromLong+0xff (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8e087 _PyEval_EvalFrameDefault+0xa4f7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.201687:   10101010 task-clock:ppp: \n\t    b5794db250f0 x_add+0x20 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.211789:   10101010 task-clock:ppp: \n\t    b5794db789fc _PyInterpreterState_GET+0x8 (inlined)\n\t    b5794db789fc get_state+0x8 (inlined)\n\t    b5794db789fc _PyObject_Malloc+0x8 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db25143 _PyLong_New+0x73 (inlined)\n\t    b5794db25143 x_add+0x73 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.221886:   10101010 task-clock:ppp: \n\t    b5794db60eac _PyInterpreterState_GET+0xc (inlined)\n\t    b5794db60eac get_state+0xc (inlined)\n\t    b5794db60eac _PyObject_Free+0xc (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db60eac _PyObject_Free+0xc (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da88257 _PyEval_EvalFrameDefault+0x46c7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.231989:   10101010 task-clock:ppp: \n\t    b5794db25218 long_normalize+0x148 (inlined)\n\t    b5794db25218 x_add+0x148 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.242093:   10101010 task-clock:ppp: \n\t    b5794da88034 _PyEval_EvalFrameDefault+0x44a4 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.252194:   10101010 task-clock:ppp: \n\t    b5794da88020 _PyEval_EvalFrameDefault+0x4490 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.262291:   10101010 task-clock:ppp: \n\t    b5794da88250 _PyEval_EvalFrameDefault+0x46c0 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.272398:   10101010 task-clock:ppp: \n\t    b5794da8822c _PyEval_EvalFrameDefault+0x469c (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.282497:   10101010 task-clock:ppp: \n\t    b5794db78ac4 pymalloc_pool_extend+0xd0 (inlined)\n\t    b5794db78ac4 pymalloc_alloc+0xd0 (inlined)\n\t    b5794db78ac4 _PyObject_Malloc+0xd0 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db2c383 _PyLong_FromMedium+0xff (inlined)\n\t    b5794db2c383 PyLong_FromLong+0xff (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8e087 _PyEval_EvalFrameDefault+0xa4f7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.292598:   10101010 task-clock:ppp: \n\t    b5794db250f0 x_add+0x20 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.302700:   10101010 task-clock:ppp: \n\t    b5794db60eac _PyInterpreterState_GET+0xc (inlined)\n\t    b5794db60eac get_state+0xc (inlined)\n\t    b5794db60eac _PyObject_Free+0xc (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db60eac _PyObject_Free+0xc (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da88257 _PyEval_EvalFrameDefault+0x46c7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.312798:   10101010 task-clock:ppp: \n\t    b5794db250f0 x_add+0x20 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.322900:   10101010 task-clock:ppp: \n\t    b5794db25124 _PyLong_New+0x54 (inlined)\n\t    b5794db25124 x_add+0x54 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.333001:   10101010 task-clock:ppp: \n\t    b5794da8a200 _PyEval_EvalFrameDefault+0x6670 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.343099:   10101010 task-clock:ppp: \n\t    b5794da89784 Py_INCREF+0x5bf4 (inlined)\n\t    b5794da89784 _Py_NewRef+0x5bf4 (inlined)\n\t    b5794da89784 _PyEval_EvalFrameDefault+0x5bf4 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.353200:   10101010 task-clock:ppp: \n\t    b5794db25214 long_normalize+0x144 (inlined)\n\t    b5794db25214 x_add+0x144 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.363305:   10101010 task-clock:ppp: \n\t    b5794da89784 Py_INCREF+0x5bf4 (inlined)\n\t    b5794da89784 _Py_NewRef+0x5bf4 (inlined)\n\t    b5794da89784 _PyEval_EvalFrameDefault+0x5bf4 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.373421:   10101010 task-clock:ppp: \n\t    b5794db2c3d4 PyLong_FromLong+0x150 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8e087 _PyEval_EvalFrameDefault+0xa4f7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.383504:   10101010 task-clock:ppp: \n\t    b5794db251b8 x_add+0xe8 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.393612:   10101010 task-clock:ppp: \n\t    b5794da897b0 _PyEval_EvalFrameDefault+0x5c20 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.403708:   10101010 task-clock:ppp: \n\t    b5794db60eac _PyInterpreterState_GET+0xc (inlined)\n\t    b5794db60eac get_state+0xc (inlined)\n\t    b5794db60eac _PyObject_Free+0xc (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db60eac _PyObject_Free+0xc (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da88257 _PyEval_EvalFrameDefault+0x46c7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.413813:   10101010 task-clock:ppp: \n\t    b5794db77c14 PyObject_Malloc+0x14 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794db25143 _PyLong_New+0x73 (inlined)\n\t    b5794db25143 x_add+0x73 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.423910:   10101010 task-clock:ppp: \n\t    b5794db60f28 _PyObject_Free+0x88 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da88257 _PyEval_EvalFrameDefault+0x46c7 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.434011:   10101010 task-clock:ppp: \n\t    b5794db251dc x_add+0x10c (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    b5794da8800f _PyEval_EvalFrameDefault+0x447f (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\npython 1359175 378278.444112:   10101010 task-clock:ppp: \n\t    b5794da8e080 _PyEval_EvalFrameDefault+0xa4f0 (/home/user/work/ce-sw/repos/cpython/build/python)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\t    e917a72f05cb py::foo:/tmp/tmp52ljdy43/perftest.py+0xb (/tmp/perf-1359175.map)\n\n'

----------------------------------------------------------------------
Ran 11 tests in 2.981s

FAILED (failures=1, skipped=3)
test test_perf_profiler failed
test_perf_profiler failed (1 failure)

== Tests result: FAILURE ==

1 test failed:
    test_perf_profiler

Total duration: 5.2 sec
Total tests: run=11 failures=1 skipped=3
Total test files: run=1/1 failed=1
Result: FAILURE

CPython versions tested on:

CPython main branch

Operating systems tested on:

Linux

Linked PRs

Metadata

Metadata

Assignees

No one assigned

    Labels

    testsTests in the Lib/test dirtype-bugAn unexpected behavior, bug, or error

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions