Skip to content

test_profile: ProfileTest.test_cprofile() failed on AMD64 Windows PGO Tailcall 3.x #159117

Open
#159664
Open
test_profile: ProfileTest.test_cprofile() failed on AMD64 Windows PGO Tailcall 3.x#159117
#159664
Labels
OS-windowstestsTests in the Lib/test dirtopic-profilingtype-bugAn unexpected behavior, bug, or error

Description

@vstinner
vstinner
opened on Oct 10, 2026

AMD64 Windows PGO Tailcall 3.x: https://buildbot.python.org/#/builders/1870/builds/1504

If I read correctly, self.do_profiling() just returned... an empty string?

======================================================================
FAIL: test_cprofile (test.test_profile.ProfileTest.test_cprofile)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/var/lib/buildbot/worker/cstratak-CentOS9-x86_64/3.15.cstratak-CentOS9-x86_64.refleak/build/Lib/test/test_profile.py", line 70, in test_cprofile
    self.fail("\n".join(fail))
    ~~~~~~~~~^^^^^^^^^^^^^^^^^
AssertionError: 
Stats.print_stats output for Profile does not fit expectation:
--- 
+++ 
@@ -1,9 +1 @@
-       28   27.972    0.999   27.972    0.999 profilee.py:110(__getattr__)
-        1  269.996  269.996  999.769  999.769 profilee.py:25(testfunc)
-     23/3  149.937    6.519  169.917   56.639 profilee.py:35(factorial)
-       20   19.980    0.999   19.980    0.999 profilee.py:48(mul)
-        2   39.986   19.993  599.830  299.915 profilee.py:55(helper)
-        4  115.984   28.996  119.964   29.991 profilee.py:73(helper1)
-        2   -0.006   -0.003  139.946   69.973 profilee.py:84(helper2_indirect)
-        8  311.976   38.997  399.912   49.989 profilee.py:88(helper2)
-        8   63.976    7.997   79.960    9.995 profilee.py:98(subhelper)
+

Stats.print_callers output for Profile does not fit expectation:
--- 
+++ 
@@ -1,17 +1 @@
-:0(append)                        <- profilee.py:73(helper1)(4)  119.964
-:0(exception)                     <- profilee.py:73(helper1)(4)  119.964
-:0(hasattr)                       <- profilee.py:73(helper1)(4)  119.964
-                                     profilee.py:88(helper2)(8)  399.912
-profilee.py:110(__getattr__)      <- :0(hasattr)(12)   11.964
-                                     profilee.py:98(subhelper)(16)   79.960
-profilee.py:25(testfunc)          <- <string>:1(<module>)(1)  999.767
-profilee.py:35(factorial)         <- profilee.py:25(testfunc)(1)  999.769
-                                     profilee.py:35(factorial)(20)  169.917
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-profilee.py:48(mul)               <- profilee.py:35(factorial)(20)  169.917
-profilee.py:55(helper)            <- profilee.py:25(testfunc)(2)  999.769
-profilee.py:73(helper1)           <- profilee.py:55(helper)(4)  599.830
-profilee.py:84(helper2_indirect)  <- profilee.py:55(helper)(2)  599.830
-profilee.py:88(helper2)           <- profilee.py:55(helper)(6)  599.830
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-profilee.py:98(subhelper)         <- profilee.py:88(helper2)(8)  399.912
+

Stats.print_callees output for Profile does not fit expectation:
--- 
+++ 
@@ -1,17 +1 @@
-:0(hasattr)                       -> profilee.py:110(__getattr__)(12)   27.972
-<string>:1(<module>)              -> profilee.py:25(testfunc)(1)  999.769
-profilee.py:110(__getattr__)      ->
-profilee.py:25(testfunc)          -> profilee.py:35(factorial)(1)  169.917
-                                     profilee.py:55(helper)(2)  599.830
-profilee.py:35(factorial)         -> profilee.py:35(factorial)(20)  169.917
-                                     profilee.py:48(mul)(20)   19.980
-profilee.py:48(mul)               ->
-profilee.py:55(helper)            -> profilee.py:73(helper1)(4)  119.964
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-                                     profilee.py:88(helper2)(6)  399.912
-profilee.py:73(helper1)           -> :0(append)(4)   -0.004
-profilee.py:84(helper2_indirect)  -> profilee.py:35(factorial)(2)  169.917
-                                     profilee.py:88(helper2)(2)  399.912
-profilee.py:88(helper2)           -> :0(hasattr)(8)   11.964
-                                     profilee.py:98(subhelper)(8)   79.960
-profilee.py:98(subhelper)         -> profilee.py:110(__getattr__)(16)   27.972
+

----------------------------------------------------------------------
Ran 625 tests in 55.273s

FAILED (failures=1, skipped=1)
test test_profiling failed

Linked PRs

Activity

  1. vstinner
    added
    testsTests in the Lib/test dir
    OS-windows
    topic-profiling
    on Oct 10, 2026

  2. vstinner commented on Oct 10, 2026

    @vstinner
    vstinner
    on Oct 10, 2026
    MemberAuthor

    Similar but different failure on s390x Fedora Stable Refleaks 3.15: https://buildbot.python.org/#/builders/2050/builds/381

    This time, the output is not completely empty:

    ======================================================================
FAIL: test_cprofile (test.test_profile.ProfileTest.test_cprofile)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/var/lib/buildbot/worker/cstratak-fedora-stable-s390x/3.15.cstratak-fedora-stable-s390x.refleak/build/Lib/test/test_profile.py", line 70, in test_cprofile
    self.fail("\n".join(fail))
    ~~~~~~~~~^^^^^^^^^^^^^^^^^
AssertionError: 
Stats.print_stats output for Profile does not fit expectation:
--- 
+++ 
@@ -1,9 +1,4 @@
-       28   27.972    0.999   27.972    0.999 profilee.py:110(__getattr__)
-        1  269.996  269.996  999.769  999.769 profilee.py:25(testfunc)
-     23/3  149.937    6.519  169.917   56.639 profilee.py:35(factorial)
-       20   19.980    0.999   19.980    0.999 profilee.py:48(mul)
-        2   39.986   19.993  599.830  299.915 profilee.py:55(helper)
-        4  115.984   28.996  119.964   29.991 profilee.py:73(helper1)
-        2   -0.006   -0.003  139.946   69.973 profilee.py:84(helper2_indirect)
-        8  311.976   38.997  399.912   49.989 profilee.py:88(helper2)
-        8   63.976    7.997   79.960    9.995 profilee.py:98(subhelper)
+        1  890.000  890.000  890.000  890.000 profilee.py:110(__getattr__)
+        1   98.999   98.999  999.996  999.996 profilee.py:25(testfunc)
+        1    0.999    0.999  900.997  900.997 profilee.py:55(helper)
+        1    9.999    9.999  899.998  899.998 profilee.py:73(helper1)

Stats.print_callers output for Profile does not fit expectation:
--- 
+++ 
@@ -1,17 +1,5 @@
-:0(append)                        <- profilee.py:73(helper1)(4)  119.964
-:0(exception)                     <- profilee.py:73(helper1)(4)  119.964
-:0(hasattr)                       <- profilee.py:73(helper1)(4)  119.964
-                                     profilee.py:88(helper2)(8)  399.912
-profilee.py:110(__getattr__)      <- :0(hasattr)(12)   11.964
-                                     profilee.py:98(subhelper)(16)   79.960
-profilee.py:25(testfunc)          <- <string>:1(<module>)(1)  999.767
-profilee.py:35(factorial)         <- profilee.py:25(testfunc)(1)  999.769
-                                     profilee.py:35(factorial)(20)  169.917
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-profilee.py:48(mul)               <- profilee.py:35(factorial)(20)  169.917
-profilee.py:55(helper)            <- profilee.py:25(testfunc)(2)  999.769
-profilee.py:73(helper1)           <- profilee.py:55(helper)(4)  599.830
-profilee.py:84(helper2_indirect)  <- profilee.py:55(helper)(2)  599.830
-profilee.py:88(helper2)           <- profilee.py:55(helper)(6)  599.830
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-profilee.py:98(subhelper)         <- profilee.py:88(helper2)(8)  399.912
+:0(hasattr)                   <- profilee.py:73(helper1)(1)  899.998
+profilee.py:110(__getattr__)  <- :0(hasattr)(1)  889.999
+profilee.py:25(testfunc)      <- <string>:1(<module>)(1)  999.995
+profilee.py:55(helper)        <- profilee.py:25(testfunc)(1)  999.996
+profilee.py:73(helper1)       <- profilee.py:55(helper)(1)  900.997

Stats.print_callees output for Profile does not fit expectation:
--- 
+++ 
@@ -1,17 +1,6 @@
-:0(hasattr)                       -> profilee.py:110(__getattr__)(12)   27.972
-<string>:1(<module>)              -> profilee.py:25(testfunc)(1)  999.769
-profilee.py:110(__getattr__)      ->
-profilee.py:25(testfunc)          -> profilee.py:35(factorial)(1)  169.917
-                                     profilee.py:55(helper)(2)  599.830
-profilee.py:35(factorial)         -> profilee.py:35(factorial)(20)  169.917
-                                     profilee.py:48(mul)(20)   19.980
-profilee.py:48(mul)               ->
-profilee.py:55(helper)            -> profilee.py:73(helper1)(4)  119.964
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-                                     profilee.py:88(helper2)(6)  399.912
-profilee.py:73(helper1)           -> :0(append)(4)   -0.004
-profilee.py:84(helper2_indirect)  -> profilee.py:35(factorial)(2)  169.917
-                                     profilee.py:88(helper2)(2)  399.912
-profilee.py:88(helper2)           -> :0(hasattr)(8)   11.964
-                                     profilee.py:98(subhelper)(8)   79.960
-profilee.py:98(subhelper)         -> profilee.py:110(__getattr__)(16)   27.972
+:0(hasattr)                   -> profilee.py:110(__getattr__)(1)  890.000
+<string>:1(<module>)          -> profilee.py:25(testfunc)(1)  999.996
+profilee.py:110(__getattr__)  ->
+profilee.py:25(testfunc)      -> profilee.py:55(helper)(1)  900.997
+profilee.py:55(helper)        -> profilee.py:73(helper1)(1)  899.998
+profilee.py:73(helper1)       -> :0(hasattr)(1)  889.999

----------------------------------------------------------------------
Ran 625 tests in 54.221s

FAILED (failures=1, skipped=1)
test test_profiling failed
  3. vstinner
    added
    type-bugAn unexpected behavior, bug, or error
    on Oct 10, 2026

  4. vstinner commented on Oct 18, 2026

    @vstinner
    vstinner
    on Oct 18, 2026
    MemberAuthor

    Another example on aarch64 CentOS9 Refleaks 3.x: https://buildbot.python.org/#/builders/840/builds/2864

    FAIL: test_cprofile (test.test_profile.ProfileTest.test_cprofile)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/var/lib/buildbot/worker/cstratak-CentOS9-aarch64/3.x.cstratak-CentOS9-aarch64.refleak/build/Lib/test/test_profile.py", line 70, in test_cprofile
    self.fail("\n".join(fail))
    ~~~~~~~~~^^^^^^^^^^^^^^^^^
AssertionError: 
Stats.print_stats output for Profile does not fit expectation:
--- 
+++ 
@@ -1,9 +1,7 @@
-       28   27.972    0.999   27.972    0.999 profilee.py:110(__getattr__)
-        1  269.996  269.996  999.769  999.769 profilee.py:25(testfunc)
-     23/3  149.937    6.519  169.917   56.639 profilee.py:35(factorial)
-       20   19.980    0.999   19.980    0.999 profilee.py:48(mul)
-        2   39.986   19.993  599.830  299.915 profilee.py:55(helper)
-        4  115.984   28.996  119.964   29.991 profilee.py:73(helper1)
-        2   -0.006   -0.003  139.946   69.973 profilee.py:84(helper2_indirect)
-        8  311.976   38.997  399.912   49.989 profilee.py:88(helper2)
-        8   63.976    7.997   79.960    9.995 profilee.py:98(subhelper)
+       12   11.988    0.999   11.988    0.999 profilee.py:110(__getattr__)
+        1   98.999   98.999  999.938  999.938 profilee.py:25(testfunc)
+        1   18.994   18.994  900.939  900.939 profilee.py:55(helper)
+        2   57.992   28.996   59.982   29.991 profilee.py:73(helper1)
+        1   -0.001   -0.001  671.996  671.996 profilee.py:84(helper2_indirect)
+        4  127.990   31.997  821.964  205.491 profilee.py:88(helper2)
+        3   23.991    7.997   29.985    9.995 profilee.py:98(subhelper)
Stats.print_callers output for Profile does not fit expectation:
--- 
+++ 
@@ -1,17 +1,13 @@
-:0(append)                        <- profilee.py:73(helper1)(4)  119.964
-:0(exception)                     <- profilee.py:73(helper1)(4)  119.964
-:0(hasattr)                       <- profilee.py:73(helper1)(4)  119.964
-                                     profilee.py:88(helper2)(8)  399.912
-profilee.py:110(__getattr__)      <- :0(hasattr)(12)   11.964
-                                     profilee.py:98(subhelper)(16)   79.960
-profilee.py:25(testfunc)          <- <string>:1(<module>)(1)  999.767
-profilee.py:35(factorial)         <- profilee.py:25(testfunc)(1)  999.769
-                                     profilee.py:35(factorial)(20)  169.917
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-profilee.py:48(mul)               <- profilee.py:35(factorial)(20)  169.917
-profilee.py:55(helper)            <- profilee.py:25(testfunc)(2)  999.769
-profilee.py:73(helper1)           <- profilee.py:55(helper)(4)  599.830
-profilee.py:84(helper2_indirect)  <- profilee.py:55(helper)(2)  599.830
-profilee.py:88(helper2)           <- profilee.py:55(helper)(6)  599.830
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-profilee.py:98(subhelper)         <- profilee.py:88(helper2)(8)  399.912
+:0(append)                        <- profilee.py:73(helper1)(2)   59.982
+:0(exception)                     <- profilee.py:73(helper1)(2)   59.982
+:0(hasattr)                       <- profilee.py:73(helper1)(2)   59.982
+                                     profilee.py:88(helper2)(4)  821.964
+profilee.py:110(__getattr__)      <- :0(hasattr)(6)  665.983
+                                     profilee.py:98(subhelper)(6)   29.985
+profilee.py:25(testfunc)          <- <string>:1(<module>)(1)  999.937
+profilee.py:55(helper)            <- profilee.py:25(testfunc)(1)  999.938
+profilee.py:73(helper1)           <- profilee.py:55(helper)(2)  900.939
+profilee.py:84(helper2_indirect)  <- profilee.py:55(helper)(1)  900.939
+profilee.py:88(helper2)           <- profilee.py:55(helper)(3)  900.939
+                                     profilee.py:84(helper2_indirect)(1)  671.996
+profilee.py:98(subhelper)         <- profilee.py:88(helper2)(3)  821.964
Stats.print_callees output for Profile does not fit expectation:
--- 
+++ 
@@ -1,17 +1,12 @@
-:0(hasattr)                       -> profilee.py:110(__getattr__)(12)   27.972
-<string>:1(<module>)              -> profilee.py:25(testfunc)(1)  999.769
+:0(hasattr)                       -> profilee.py:110(__getattr__)(6)   11.988
+<string>:1(<module>)              -> profilee.py:25(testfunc)(1)  999.938
 profilee.py:110(__getattr__)      ->
-profilee.py:25(testfunc)          -> profilee.py:35(factorial)(1)  169.917
-                                     profilee.py:55(helper)(2)  599.830
-profilee.py:35(factorial)         -> profilee.py:35(factorial)(20)  169.917
-                                     profilee.py:48(mul)(20)   19.980
-profilee.py:48(mul)               ->
-profilee.py:55(helper)            -> profilee.py:73(helper1)(4)  119.964
-                                     profilee.py:84(helper2_indirect)(2)  139.946
-                                     profilee.py:88(helper2)(6)  399.912
-profilee.py:73(helper1)           -> :0(append)(4)   -0.004
-profilee.py:84(helper2_indirect)  -> profilee.py:35(factorial)(2)  169.917
-                                     profilee.py:88(helper2)(2)  399.912
-profilee.py:88(helper2)           -> :0(hasattr)(8)   11.964
-                                     profilee.py:98(subhelper)(8)   79.960
-profilee.py:98(subhelper)         -> profilee.py:110(__getattr__)(16)   27.972
+profilee.py:25(testfunc)          -> profilee.py:55(helper)(1)  900.939
+profilee.py:55(helper)            -> profilee.py:73(helper1)(2)   59.982
+                                     profilee.py:84(helper2_indirect)(1)  671.996
+                                     profilee.py:88(helper2)(3)  821.964
+profilee.py:73(helper1)           -> :0(append)(2)   -0.002
+profilee.py:84(helper2_indirect)  -> profilee.py:88(helper2)(1)  821.964
+profilee.py:88(helper2)           -> :0(hasattr)(4)  665.983
+                                     profilee.py:98(subhelper)(3)   29.985
+profilee.py:98(subhelper)         -> profilee.py:110(__getattr__)(6)   11.988
----------------------------------------------------------------------
Ran 645 tests in 68.975s
FAILED (failures=1, skipped=2)
test test_profiling failed

  5. Cha-Imaa commented on Oct 18, 2026

    @Cha-Imaa
    Cha-Imaa
    on Oct 18, 2026

    I reproduced a mechanism that can explain the empty and partial statistics: _lsprof uses sys.monitoring, but profiler_dealloc() still calls _PyEval_SetProfile(tstate, NULL, NULL). If an enabled C profiler loses its monitoring callbacks and is later destroyed, it clears an unrelated sys.setprofile() callback. Garbage collection during ProfileTest.do_profiling() can therefore stop the pure Python profiler partway through the workload.

    I opened #159664 to remove that obsolete cleanup, with a deterministic regression test and a NEWS entry. The regression test fails before the change and passes afterward on a Windows AMD64 debug build. The profiling, profile, sys.setprofile, monitoring, and pstats suites pass, as do reference-leak checks for both profiler implementations. I have not tested the original PGO tail-call or s390x configurations.

  6. Cha-Imaa
    added 2 commits that reference this issue on Oct 18, 2026

    Merge remote-tracking branch 'origin/main' into pythongh-159117-profi…

    b79a6f4

    Merge branch 'main' into pythongh-159117-profiler-dealloc

    4f1bdc9
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

    OS-windowstestsTests in the Lib/test dirtopic-profilingtype-bugAn unexpected behavior, bug, or error

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions