gh-108753: Enhance pystats

[vstinner]

• Add PYTHONSTATS environment variable.
• Add PyConfig._pystats member.
• Add tests on sys functions and on setting PyConfig._pystats to 1.
• At exit, only dump statistics if PyConfig._pystats is non-zero.
• Add Include/cpython/pystats.h and Include/internal/pycore_pystats.h header files.
• Rename '_py_stats' variable to '_Py_stats'.
• Exclude Include/cpython/pystats.h from the Py_LIMITED_API.
• Move pystats.h include from object.h to Python.h.
• Add _Py_StatsOn() and _Py_StatsOff() functions. Remove '_py_stats_struct' variable from the API: make it static in specialize.c.
• Document API in Include/pystats.h and Include/cpython/pystats.h.
• Complete pystats documentation in Doc/using/configure.rst.

• Issue: Enhance Py_STATS: statistics on Python performance #108753

---

📚 Documentation preview 📚: https://cpython-previews--108754.org.readthedocs.build/

[vstinner]

Currently, running Python always writes many lines of statistics to stderr at Python exit when the /tmp/py_stats/ directory doesn't exist.

$ rm -rf /tmp/py_stats/
$ ./python -c pass
opcode[11].specializable : 1
opcode[52].specializable : 1
opcode[12].specializable : 1
opcode[53].specializable : 1
opcode[56].specializable : 1
opcode[67].specializable : 1
opcode[75].specializable : 1
opcode[97].specializable : 1
opcode[114].specializable : 1
opcode[123].specializable : 1
opcode[129].specializable : 1
opcode[150].specializable : 1
opcode[154].specializable : 1
opcode[168].specializable : 1
opcode[173].specializable : 1
opcode[183].specializable : 1
Calls to PyEval_EvalDefault: 0
Calls to Python functions inlined: 0
Frames pushed: 0
Frame objects created: 0
Calls via PyEval_EvalFrame[0] : 0
Calls via PyEval_EvalFrame[1] : 0
Calls via PyEval_EvalFrame[2] : 0
Calls via PyEval_EvalFrame[3] : 0
Calls via PyEval_EvalFrame[4] : 0
Calls via PyEval_EvalFrame[5] : 0
Calls via PyEval_EvalFrame[6] : 0
Calls via PyEval_EvalFrame[7] : 0
Calls via PyEval_EvalFrame[8] : 0
Calls via PyEval_EvalFrame[9] : 0
Object allocations from freelist: 0
Object frees to freelist: 0
Object allocations: 0
Object allocations to 512 bytes: 0
Object allocations to 4 kbytes: 0
Object allocations over 4 kbytes: 0
Object frees: 0
Object new values: 0
Object interpreter increfs: 0
Object interpreter decrefs: 0
Object increfs: 0
Object decrefs: 0
Object materialize dict (on request): 0
Object materialize dict (new key): 0
Object materialize dict (too big): 0
Object materialize dict (str subclass): 0
Object dematerialize dict: 0
Object method cache hits: 0
Object method cache misses: 0
Object method cache collisions: 0
Object method cache dunder hits: 0
Object method cache dunder misses: 0
Optimization attempts: 0
Optimization traces created: 0
Optimization traces executed: 0
Optimization uops executed: 0
GC[0] collections: 0
GC[0] object visits: 0
GC[0] objects collected: 0
GC[1] collections: 0
GC[1] object visits: 0
GC[1] objects collected: 0
GC[2] collections: 0
GC[2] object visits: 0
GC[2] objects collected: 0

These logs are useless since stats gathering is off by default.

It's just not convenient. With this PR, statistics are only dumped when -X pystats command line option or PYTHONSTATS env var is used.

$ rm -rf /tmp/py_stats/
$ ./python -c pass
# no logs

Using python -X pystats, logs are dumped but also gathered, so it's more useful :-)

$ rm -rf /tmp/py_stats/
$ ./python -X pystats -c pass
(...)
GC[0] collections: 5
GC[0] object visits: 34984
GC[0] objects collected: 24
GC[1] collections: 0
GC[1] object visits: 0
GC[1] objects collected: 0
GC[2] collections: 3
GC[2] object visits: 88364
GC[2] objects collected: 1703

Statistics are not zero anymore.

[vstinner]

With these changes, the test suite now pass on Python built with Py_STATS, since statistics are no longer dumped into stderr by default.

[vstinner]

$ rm -rf /tmp/py_stats/
$ ./python -m test -j0 -r
(...)
442 tests OK.
(...)
Tests result: SUCCESS

[vstinner]

cc @brandtbucher @iritkatriel

[mdboom]

Thanks for this!

Using python -X pystats, logs are dumped but also gathered, so it's more useful :-)

Unfortunately, this makes it harder to not collect stats during startup. The way it's typically used in pyperf, for example, is for stats to automatically turn on and off only around the actual benchmarking code. pyperf could be updated (probably) to call sys._stats_clear() before the first sys._stats_on(), perhaps, but it's almost never desirable to collect stats from an entire run -- that feels like the wrong default.

I think I'd prefer the flag/envvar to only control the dumping at exit. But, thinking even more about it, maybe we should just disable the printing to stderr altogether and just create the output directory if it doesn't exist (and raise an exception if that fails). We don't use the stderr in the benchmarking infrastructure, and it doesn't play well with multiple processes (which pyperf almost always creates). That would remove the need for the envvar/flag, and there would only be two, not three, things users would need to do.

I like the refactor here outside of the specialization code where this began -- we definitely do anticipate this growing beyond that. And being able to pass the tests is great -- maybe (as a separate discussion) this config should be tested in a buildbot.

[mdboom]

I like these docs. Should we also name the "keys" in the output corresponding to each of these? I know the output format isn't really "designed" and there are no guarantees of stability there, but still...

[vstinner]

I think I'd prefer the flag/envvar to only control the dumping at exit.

Currently, without my change, python3 -X pystats enables statistics gathering as soon as possible during Python startup (very early in Python initialization). My change left this part unchanged.

I have no preference for this question. I almost never used Py_STATS build (especially because the default output is so verbose that it wasted my time).

[mdboom]

Currently, without my change, python3 -X pystats enables statistics gathering as soon as possible during Python startup (very early in Python initialization). My change left this part unchanged.

Ah, got it. Sorry I missed that. So for sure we want to decouple "start collecting as early as possible" from "dumping at exit". I think just removing dumping to stderr might be the easiest way to do that, but I'd certainly want to hear from others who use this -- maybe that's something really convenient someone relies on.

[vstinner]

The way it's typically used in pyperf, for example, is for stats to automatically turn on and off only around the actual benchmarking code. pyperf could be updated (probably) to call sys._stats_clear() before the first sys._stats_on(), perhaps, but it's almost never desirable to collect stats from an entire run -- that feels like the wrong default.

In general, I think that it's a good practice to reset statistics and start gathering stats when the benchmark starts, and then turns off gathering stats when the benchmark stops. I would be compatible with the current behavior of this PR, no?

[mdboom]

In general, I think that it's a good practice to reset statistics and start gathering stats when the benchmark starts, and then turns off gathering stats when the benchmark stops. I would be compatible with the current behavior of this PR, no?

If I understand correctly, with this change, pyperf would have to be modified to clear stats the first time a benchmark is run (but not subsequent times a benchmark is run), in order to get the stats out at the end. Right now, it doesn't have to worry about stats prior to the first benchmark run. Also, the orchestration process would have to clear and turn off stats, which I don't think it currently does.

[vstinner]

To run a benchmark, I don't think that using python3 -X pystats is helpful. Why not using the sys API directly?

import math
import sys

def cpu_intensive():
    len(str(math.factortial(1000)))

def bench():
    sys._stats_clear()  # just in case if it was already enabled
    sys._stats_on()
    cpu_intensive()
    sys._stats_off()
    sys._stats_dump()
    # not sure what happens if Python dumps again stats at exit
    # would sys._stats_clear() help here?

bench()

[mdboom]

Sorry, I wasn't clear. My point is just that this is a breaking change for pyperf, which could be updated, of course.

The pseudo code is more like:

def bench():
    sys._stats_clear()
    for _ in range(n):
        sys._stats_on()
        cpu_intensive()
        sys._stats_off()
    sys._stats_dump()

Since -X pystats now controls both the recording at startup and the dumping at the end, we need to either:

• Use -X pystats and clear before the first benchmark run (but not subsequent ones)
• Don't use -X pystats and dump after the last benchmark run.

I'm not opposed, but an alternative that wouldn't require updating pyperf and re-evaluating it would be to remove support for dumping to stderr, presuming nobody uses that. (The usual suspects are probably @markshannon and @brandtbucher).

[vstinner]

My usage case is to gets statistics on a command without having to modify the code: ./python -X pystats -m test test_sys writes statistics to stderr (or to a file, depending if the directory was created). The granularity is: gather statistics on the whole program.

For me, it's a similar usage that running a program in a profiler or anything collecting data about the executed program: collect data and then write the output.

If you need a less coarse statistics gathering than "the whole program", I would suggest you... to not use the -X pystats. If you already call sys functions in pyperf, you can enable/disable precisly when/how statistics are collected, you can control when/how statistics are written: in that case, you don't need -X pystats.

If you think that there is an use case to use -X pystats and use sys functions, maybe we need an API to control if statistics are written at exit or not. But I would prefer to not have to add new functions.

---

Ok, maybe there is a way to please all use cases. What if... what if it would be possible to disable writing statistics at exit using existing API? For me, it sounds bad to write statistics if the following functions are called:

sys._stats_off()
sys._stats_clear()
# stats are all zero and Python is not going to collect stats anymore
# no need to dump empty stats (all zeros)

[vstinner]

I modified my PR to not dump statistics if they are all equal to zero.

sys._stats_dump() now returns a bool to say if stats were dumped or not. It returns False if all stats are equal to zero: which is the case if _stats_off() was called and then either _stats_dump() or _stats_clear().

$ ./python -X pystats
Python 3.13.0a0 (heads/pystats-dirty:1d6c666abc, Sep  5 2023, 19:57:37) [GCC 13.2.1 20230728 (Red Hat 13.2.1-1)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> sys._stats_off()
>>> sys._stats_dump()
(... tons of statistics as expected ...)
GC[0] collections: 13
GC[0] object visits: 103088
GC[0] objects collected: 127
GC[1] collections: 1
GC[1] object visits: 59544
GC[1] objects collected: 34
GC[2] collections: 0
GC[2] object visits: 0
GC[2] objects collected: 0
True

# True means that yes, there was something interesting to dump

>>> sys._stats_dump()
False

# nah! Python doesn't want to dump stats since _stats_off() was called
# and _stats_dump() cleared all statistics (make it all zeros)

>>> exit()

# what? nothing! stats are no longer dumped *one more time*

@mdboom: Does it solve your use case?

[vstinner]

This script can also be used to test my PR. Run it with -X pystats:

import sys
import gc

def heavy_code():
    for _ in range(10**4):
        pass
    for _ in range(3):
        gc.collect()

def mybench():
    sys._stats_clear()

    sys._stats_on()
    heavy_code()
    sys._stats_off()

    dumped = sys._stats_dump()
    print("stats dumped?", dumped)

    dumped = sys._stats_dump()
    print("oops, called twice! dumped?", dumped)

mybench()
print("exit")

[mdboom]

This is fine, but I think pyperf will need to be updated to remain correct. It still will only dump at exit if -X pystats is set, or _pystats_dump() is called directly. I'm fine with updating pyperf to retain existing behavior -- I just wanted to point out that it would need to be done and tested etc.

I think if you just revert this diff below (and update your new docs accordingly), it's probably ok -- it will dump stats on end if any were collected (which should be the case when running inside pyperf as-is):

Since it's now only dumping if there are any collected stats, it should also solve what I understand you set out to solve.

[vstinner]

This is fine

Good :-)

I think pyperf will need to be updated to remain correct

This change is only for Python 3.13, you have time to adapt pyperf if needed :-) pyperf spawns subprocesses, you can control if they are run with -X pystats and/or PYTHONSTATS env var. pyperf removes most environment variables by default.

I think if you just revert this diff below

You're right. Always calling _Py_PrintSpecializationStats(1); in _PyEval_Fini() is fine, since it now does nothing if statistics are all zeros. I updated my PR.

[mdboom]

A couple of minor nits, but other than that, looks good to me.

Thanks for pushing through for something that doesn't break pyperf!

[vstinner]

@mdboom: Thanks for the review, I accepted your suggestions. Oops, I didn't notice that stats are dumped to stderr, not stdout.