Tests asserting "slow_fibonacci" in test_profiling flaky fail on i686/s390x builds in Fedora Linux #140381
Description
Bug report
Bug description:
There appears to be certain flakiness that happens on i686/s390x arches to tests in test_profiling which assert "slow_fibonacci" in the output across all Fedoras (41 to 44), different builds (debug, optimized, freethreading). Sometimes tests pass on rerun, sometimes not. The three offending tests are test_sample_target_script, test_sampling_basic_functionality, test_sample_target_module.
Debug build on s390x on Fedora 43:
FAIL: test_sample_target_script (test.test_profiling.test_sampling_profiler.TestSampleProfilerIntegration.test_sample_target_script)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/builddir/build/BUILD/python3.15-3.15.0_a1-build/Python-3.15.0a1/Lib/test/test_profiling/test_sampling_profiler.py", line 1924, in test_sample_target_script
self.assertIn("slow_fibonacci", output)
~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'slow_fibonacci' not found in 'Captured 5252 samples in 1.00 seconds\nSample rate: 5251.96 samples/sec\nError rate: 0.00%\nWarning: missed 4748 samples from the expected total of 10000 (47.48%)\n\x1b[1;34mProfile Stats:\x1b[0m\n\x1b[1;34m nsamples\x1b[0m \x1b[1;34m sample%\x1b[0m \x1b[1;34mtottime (ms)\x1b[0m \x1b[1;34m cumul%\x1b[0m \x1b[1;34mcumtime (ms)\x1b[0m \x1b[1;34mfilename:lineno(function)\x1b[0m\n 0/5175 0.0 0.000 98.5 517.500 \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m52\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 0/5175 0.0 0.000 98.5 517.500 \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m63\x1b[0m(\x1b[36m<module>\x1b[0m)\n 3493/3493 66.5 349.300 66.5 349.300 \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m15\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 1329/1329 25.3 132.900 25.3 132.900 \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m16\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 353/353 6.7 35.300 6.7 35.300 \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m14\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 77/77 1.5 7.700 1.5 7.700 \x1b[32m_sync_coordinator.py\x1b[0m:\x1b[33m95\x1b[0m(\x1b[36m_signal_readiness\x1b[0m)\n 0/77 0.0 0.000 1.5 7.700 \x1b[32m_sync_coordinator.py\x1b[0m:\x1b[33m211\x1b[0m(\x1b[36mmain\x1b[0m)\n 0/77 0.0 0.000 1.5 7.700 \x1b[32m_sync_coordinator.py\x1b[0m:\x1b[33m243\x1b[0m(\x1b[36m<module>\x1b[0m)\n\n\x1b[1;34mLegend:\x1b[0m\n \x1b[33mnsamples\x1b[0m: Direct/Cumulative samples (direct executing / on call stack)\n \x1b[33msample%\x1b[0m: Percentage of total samples this function was directly executing\n \x1b[33mtottime\x1b[0m: Estimated total time spent directly in this function\n \x1b[33mcumul%\x1b[0m: Percentage of total samples when this function was on the call stack\n \x1b[33mcumtime\x1b[0m: Estimated cumulative time (including time in called functions)\n \x1b[33mfilename:lineno(function)\x1b[0m: Function location and name\n\n\x1b[1;34mSummary of Interesting Functions:\x1b[0m\n\n\x1b[1;34mFunctions with Highest Direct/Cumulative Ratio (Hot Spots):\x1b[0m\n 1.000 direct/cumulative ratio, 98.5% direct samples: \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 1.000 direct/cumulative ratio, 1.5% direct samples: \x1b[32m_sync_coordinator.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36m_signal_readiness\x1b[0m)\n\n\x1b[1;34mFunctions with Highest Call Frequency (Indirect Calls):\x1b[0m\n 5175 indirect calls, 98.5% total stack presence: \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 5175 indirect calls, 98.5% total stack presence: \x1b[32mtmpj6l9__o1\x1b[0m:\x1b[33m\x1b[0m(\x1b[36m<module>\x1b[0m)\n 77 indirect calls, 1.5% total stack presence: \x1b[32m_sync_coordinator.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mmain\x1b[0m)\n\n\x1b[1;34mFunctions with Highest Call Magnification (Cumulative/Direct):\x1b[0m\n'
Optimized build on i686 on Fedora 44 and freethreading build on i686 on Fedora 42:
FAIL: test_sampling_basic_functionality (test.test_profiling.test_sampling_profiler.TestSampleProfilerIntegration.test_sampling_basic_functionality)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/builddir/build/BUILD/python3.15-3.15.0_a1-build/Python-3.15.0a1/Lib/test/test_profiling/test_sampling_profiler.py", line 1777, in test_sampling_basic_functionality
self.assertIn("slow_fibonacci", output)
~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'slow_fibonacci' not found in 'Captured 2001 samples in 2.00 seconds\nSample rate: 1000.48 samples/sec\nError rate: 0.00%\n\x1b[1;34mProfile Stats:\x1b[0m\n\x1b[1;34m nsamples\x1b[0m \x1b[1;34m sample%\x1b[0m \x1b[1;34m tottime (s)\x1b[0m \x1b[1;34m cumul%\x1b[0m \x1b[1;34m cumtime (s)\x1b[0m \x1b[1;34mfilename:lineno(function)\x1b[0m\n 0/1998 0.0 0.000 100.0 1.998 \x1b[32m<string>\x1b[0m:\x1b[33m68\x1b[0m(\x1b[36m<module>\x1b[0m)\n 0/1982 0.0 0.000 99.2 1.982 \x1b[32m<string>\x1b[0m:\x1b[33m57\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 1314/1314 65.8 1.314 65.8 1.314 \x1b[32m<string>\x1b[0m:\x1b[33m20\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 633/633 31.7 0.633 31.7 0.633 \x1b[32m<string>\x1b[0m:\x1b[33m19\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 31/31 1.6 0.031 1.6 0.031 \x1b[32m<string>\x1b[0m:\x1b[33m21\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 0/15 0.0 0.000 0.8 0.015 \x1b[32m<string>\x1b[0m:\x1b[33m63\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 1/14 0.1 0.001 0.7 0.014 \x1b[32m<string>\x1b[0m:\x1b[33m45\x1b[0m(\x1b[36mnested_calls\x1b[0m)\n 0/13 0.0 0.000 0.7 0.013 \x1b[32m<string>\x1b[0m:\x1b[33m43\x1b[0m(\x1b[36mnested_calls.<locals>.level1.<locals>.level2\x1b[0m)\n 0/13 0.0 0.000 0.7 0.013 \x1b[32m<string>\x1b[0m:\x1b[33m44\x1b[0m(\x1b[36mnested_calls.<locals>.level1\x1b[0m)\n 12/12 0.6 0.012 0.6 0.012 \x1b[32m<string>\x1b[0m:\x1b[33m29\x1b[0m(\x1b[36mmedium_computation\x1b[0m)\n 4/4 0.2 0.004 0.2 0.004 \x1b[32m<string>\x1b[0m:\x1b[33m22\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 1/1 0.1 0.001 0.1 0.001 \x1b[32m<string>\x1b[0m:\x1b[33m28\x1b[0m(\x1b[36mmedium_computation\x1b[0m)\n 1/1 0.1 0.001 0.1 0.001 \x1b[32m<string>\x1b[0m:\x1b[33m60\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 1/1 0.1 0.001 0.1 0.001 \x1b[32m<string>\x1b[0m:\x1b[33m41\x1b[0m(\x1b[36mnested_calls\x1b[0m)\n\n\x1b[1;34mLegend:\x1b[0m\n \x1b[33mnsamples\x1b[0m: Direct/Cumulative samples (direct executing / on call stack)\n \x1b[33msample%\x1b[0m: Percentage of total samples this function was directly executing\n \x1b[33mtottime\x1b[0m: Estimated total time spent directly in this function\n \x1b[33mcumul%\x1b[0m: Percentage of total samples when this function was on the call stack\n \x1b[33mcumtime\x1b[0m: Estimated cumulative time (including time in called functions)\n \x1b[33mfilename:lineno(function)\x1b[0m: Function location and name\n'
Debug build on s390x on Fedora 41:
FAIL: test_sample_target_module (test.test_profiling.test_sampling_profiler.TestSampleProfilerIntegration.test_sample_target_module)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/builddir/build/BUILD/python3.15-3.15.0_a1-build/Python-3.15.0a1/Lib/test/test_profiling/test_sampling_profiler.py", line 1958, in test_sample_target_module
self.assertIn("slow_fibonacci", output)
~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'slow_fibonacci' not found in 'Captured 5009 samples in 1.00 seconds\nSample rate: 5008.85 samples/sec\nError rate: 0.00%\nWarning: missed 4991 samples from the expected total of 10000 (49.91%)\n\x1b[1;34mProfile Stats:\x1b[0m\n\x1b[1;34m nsamples\x1b[0m \x1b[1;34m sample%\x1b[0m \x1b[1;34mtottime (ms)\x1b[0m \x1b[1;34m cumul%\x1b[0m \x1b[1;34mcumtime (ms)\x1b[0m \x1b[1;34mfilename:lineno(function)\x1b[0m\n 0/5009 0.0 0.000 100.0 500.900 \x1b[32mtest_module.py\x1b[0m:\x1b[33m63\x1b[0m(\x1b[36m<module>\x1b[0m)\n 0/4938 0.0 0.000 98.6 493.800 \x1b[32mtest_module.py\x1b[0m:\x1b[33m52\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 2260/2260 45.1 226.000 45.1 226.000 \x1b[32mtest_module.py\x1b[0m:\x1b[33m16\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 2015/2015 40.2 201.500 40.2 201.500 \x1b[32mtest_module.py\x1b[0m:\x1b[33m15\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 663/663 13.2 66.300 13.2 66.300 \x1b[32mtest_module.py\x1b[0m:\x1b[33m14\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 71/71 1.4 7.100 1.4 7.100 \x1b[32mtest_module.py\x1b[0m:\x1b[33m23\x1b[0m(\x1b[36mmedium_computation\x1b[0m)\n 0/71 0.0 0.000 1.4 7.100 \x1b[32mtest_module.py\x1b[0m:\x1b[33m38\x1b[0m(\x1b[36mnested_calls.<locals>.level1.<locals>.level2\x1b[0m)\n 0/71 0.0 0.000 1.4 7.100 \x1b[32mtest_module.py\x1b[0m:\x1b[33m39\x1b[0m(\x1b[36mnested_calls.<locals>.level1\x1b[0m)\n 0/71 0.0 0.000 1.4 7.100 \x1b[32mtest_module.py\x1b[0m:\x1b[33m40\x1b[0m(\x1b[36mnested_calls\x1b[0m)\n 0/71 0.0 0.000 1.4 7.100 \x1b[32mtest_module.py\x1b[0m:\x1b[33m58\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n\n\x1b[1;34mLegend:\x1b[0m\n \x1b[33mnsamples\x1b[0m: Direct/Cumulative samples (direct executing / on call stack)\n \x1b[33msample%\x1b[0m: Percentage of total samples this function was directly executing\n \x1b[33mtottime\x1b[0m: Estimated total time spent directly in this function\n \x1b[33mcumul%\x1b[0m: Percentage of total samples when this function was on the call stack\n \x1b[33mcumtime\x1b[0m: Estimated cumulative time (including time in called functions)\n \x1b[33mfilename:lineno(function)\x1b[0m: Function location and name\n\n\x1b[1;34mSummary of Interesting Functions:\x1b[0m\n\n\x1b[1;34mFunctions with Highest Direct/Cumulative Ratio (Hot Spots):\x1b[0m\n 1.000 direct/cumulative ratio, 98.6% direct samples: \x1b[32mtest_module.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mcpu_intensive_work\x1b[0m)\n 1.000 direct/cumulative ratio, 1.4% direct samples: \x1b[32mtest_module.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mmedium_computation\x1b[0m)\n\n\x1b[1;34mFunctions with Highest Call Frequency (Indirect Calls):\x1b[0m\n 5009 indirect calls, 100.0% total stack presence: \x1b[32mtest_module.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36m<module>\x1b[0m)\n 5009 indirect calls, 100.0% total stack presence: \x1b[32mtest_module.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mmain_loop\x1b[0m)\n 71 indirect calls, 1.4% total stack presence: \x1b[32mtest_module.py\x1b[0m:\x1b[33m\x1b[0m(\x1b[36mnested_calls.<locals>.level1.<locals>.level2\x1b[0m)\n\n\x1b[1;34mFunctions with Highest Call Magnification (Cumulative/Direct):\x1b[0m\n'
----------------------------------------------------------------------
CPython versions tested on:
3.15
Operating systems tested on:
Linux