Re: [Python-Dev] proposal+patch: sys.gettickeraccumulation()
Brett C. wrote:
Ralf W. Grosse-Kunstleve wrote:
Brett C. wrote:
I have been mulling over this proposal and I think I am finally settling on +0 as long as it can be shown that it does not hurt performance at all (yes, it shouldn't but this is the eval loop we are talking about and that thing is a touchy beast).
Is there a standard benchmark I could use to demonstrate the impact of the two new additions on the runtime? Thanks!
=) Parrotbench and PyBench would be enough for me to sign off on any performance hit. There is also pystone.
I have done my homework now, based on parrotbench. Timings are below. The most important conclusion from my viewpoint is that my original goal can be achieved with a small patch and with a runtime penalty that is in the noise. However, mysterious runtime behavior of Objects/longobject.c lead me to change my original patch, and to the unanswered question "could small rearrangements in longobject.c potentially boost performance by 45% on some platforms?" Please don't be put off by the size of this message. My patch is essentially just one line in ceval.c (_Py_TickerAccumulation++)! To restate my original goal: I am looking for a simple way to answer the question: How much of a speedup can I expect if I reimplement a piece of Python code in C or C++? Note that I am not asking how much time is spent in Python including all the extensions that come with it, but how much time is spent in the Python bytecode interpreter loop. To clarify, look at the timings for two tests in parrotbench: b1 5.8287 time 30049474 ticks 0.1940 us/tick b2 1.5944 time 482584 ticks 3.3039 us/tick Each of the tests was run with range(10) in b.py to increase accuracy. The first column shows time.time() differences, the second the number of bytecodes processed in ceval.c, and the last column shows micro-seconds per tick. Why is the us/tick value for b2 17 times larger than that for b1? The answer is that b2 makes heavy use of long integers, and that a lot of time is spent in Objects/longobject.c doing long-integer arithmetic. Compared to b1, relatively little time is spent interpreting bytecodes. Back to the original question: how much sense does it make to reimplement b1 or b2 in C? Simply looking at the us/tick values is telling me that I can expect much more of a performance boost by reimplementing b1 rather than b2. This is because b2 spends a lot of time in C already. A similar situation arises if extensions like Numeric are used. Computationally intensive operations like matrix multiplication and matrix inversion are already done at C speed. The us/tick let us quickly estimate how disappointed we would be after moving Python code to C or C++. We get this estimate without having to do detailed source code analysis, and before we have wasted our time doing the recoding (we have been through this a couple of times ...). The timings below show that the patched Python which counts the number of interpreted bytecodes is in the worst case 0.6% slower than the original Python, but some tests even run faster at face value: $gcc296_compiled/original/python -O b_timings.py | grep reporter b0 16.8831 time b1 5.9553 time b2 1.5914 time b3 10.8149 time b4 5.2528 time b5 11.6437 time b6 11.0248 time b7 27.6960 time all 90.9276 time $gcc296_compiled/work/python -O b_timings.py | grep reporter b0 16.9193 time 50979585 ticks 0.3319 us/tick b1 5.8287 time 30049474 ticks 0.1940 us/tick b2 1.5944 time 482584 ticks 3.3039 us/tick b3 10.7931 time 43577404 ticks 0.2477 us/tick b4 5.2865 time 18463044 ticks 0.2863 us/tick b5 11.6086 time 17065750 ticks 0.6802 us/tick b6 10.0992 time 60000464 ticks 0.1683 us/tick b7 27.6830 time 1928644 ticks 14.3536 us/tick all 89.8760 time 222548399 ticks 0.4038 us/tick The b7 test is the same as b2 but with xrange(10000) instead of xrange(1000), and with all print statements removed. Ratios (rounded to 3 decimals): 16.9193/16.8831=1.002 5.8287/5.9553 =0.979 1.5944/1.5914 =1.002 10.7931/10.8149=0.998 5.2865/5.2528 =1.006 11.6086/11.6437=0.997 10.0992/11.0248=0.916 27.6830/27.6960=1.000 Therefore I'd argue that the runtime penalty for the one additional long long increment in ceval.c (_Py_TickerAccumulation++) is in the noise. The timings were collected on a 2.8GHz Dual Xeon, Redhat WS 3. Python was compiled under Red Hat 7.3 with gcc 2.96. See below why. My latest patch can be found at the end of this posting. It can be applied to the Python-2.4 distribution like this: tar zxf Python-2.4.tgz patch --strip=1 -d Python-2.4 < patch_file ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ Now to the mysterious runtime behavior of Objects/longobject.c In the original Python 2.4 sources _Py_Ticker is decremented in two places: In the interpreter loop in Python/ceval.c: if (--_Py_Ticker < 0) { In Objects/longobject.c: #define SIGCHECK(PyTryBlock) \ if (--_Py_Ticker < 0) { \ _Py_Ticker = _Py_CheckInterval; \ if (PyErr_CheckSignals()) { PyTryBlock; } \ } This macro is used in four places. My initial patch was to insert updates of a new, global _Py_TickerAccumulation variable in these two places: Python/ceval.c: a try: finally: block uninterruptable. */ goto fast_next_opcode; } + _Py_TickerAccumulation += _Py_CheckInterval - _Py_Ticker; _Py_Ticker = _Py_CheckInterval; tstate->tick_counter++; Objects/longobject.c: #define SIGCHECK(PyTryBlock) \ if (--_Py_Ticker < 0) { \ + _Py_TickerAccumulation += _Py_CheckInterval - _Py_Ticker; \ _Py_Ticker = _Py_CheckInterval; \ if (PyErr_CheckSignals()) { PyTryBlock; } \ } This lead to the timings below. All timings were collected on the same machine, but the original and the patched Pythons were each compiled with two different compilers, gcc 2.96 and gcc 3.2.3. The important timings to look at are those for b2 and b7 again. $gcc296_compiled/original/python -O b_timings.py | grep reporter b0 16.8831 time b1 5.9553 time b2 1.5914 time b3 10.8149 time b4 5.2528 time b5 11.6437 time b6 11.0248 time b7 27.6960 time all 90.9276 time $gcc323_compiled/original/python -O b_timings.py | grep reporter b0 18.6390 time b1 6.4681 time b2 2.2588 time b3 11.0215 time b4 5.6490 time b5 12.3022 time b6 10.3815 time b7 40.2735 time all 107.0636 time This shows that the gcc 2.96 optimizer is generally a little bit better than the gcc 3.2.3 optimizer, but not by very much. Except for the b2 and b7 tests. E.g. 40.2735/27.6960 = 1.454! Now with the patches in both ceval.c and longobject.c: $gcc296_compiled/ticker/python -O b_timings.py | grep reporter b0 17.1190 time 60792625 ticks 0.2816 us/tick b1 6.1171 time 30049474 ticks 0.2036 us/tick b2 1.8764 time 705754 ticks 2.6587 us/tick b3 10.7070 time 43577404 ticks 0.2457 us/tick b4 5.2677 time 22944694 ticks 0.2296 us/tick b5 11.7448 time 17433190 ticks 0.6737 us/tick b6 10.9603 time 60000504 ticks 0.1827 us/tick b7 33.2320 time 2837124 ticks 11.7133 us/tick all 97.0893 time 238342235 ticks 0.4074 us/tick $gcc323_compiled/ticker/python -O b_timings.py | grep reporter b0 18.3115 time 60792625 ticks 0.3012 us/tick b1 6.1193 time 30049474 ticks 0.2036 us/tick b2 2.2522 time 705754 ticks 3.1912 us/tick b3 11.2202 time 43577404 ticks 0.2575 us/tick b4 5.4596 time 22944694 ticks 0.2379 us/tick b5 11.8197 time 17433190 ticks 0.6780 us/tick b6 10.7407 time 60000504 ticks 0.1790 us/tick b7 40.2397 time 2837124 ticks 14.1833 us/tick all 106.2283 time 238342235 ticks 0.4457 us/tick The gcc 3.2.3 timings for b7 are hardly affected by my patch in longobject.c, but the gcc 2.96 timing shoots up from 27.6960 to 33.2320. Still not as bad as the gcc 3.2.3 timing, but why? Interestingly, if I declare _Py_TickerAccumulation as long instead of PY_LONG_LONG, the gcc 2.96 timing is also hardly affected by my patch in longobject.c. Even more interestingly, if I change longobject.c like this... #define SIGCHECK(PyTryBlock) \ { \ if (PyErr_CheckSignals()) { PyTryBlock; } \ } the runtime is also hardly affected (times not shown in this posting) even though PyErr_CheckSignals() is executed 100 times more often. Curious to learn how other compilers deal with longobject.c I collected timings with this compiler: Compaq C V6.3-028 on Compaq Tru64 UNIX V5.1 (Rev. 732) $compaq_compiled/original/python -O b_timings.py | grep reporter b1 19.4492 time b2 4.9395 time b3 23.6787 time b5 28.2568 time b6 21.6230 time b7 86.5283 time all 192.0498 time $compaq_compiled/ticker/python -O b_timings.py | grep reporter b1 19.4775 time 30049474 ticks 0.6482 us/tick b2 4.9971 time 704784 ticks 7.0902 us/tick b3 24.2559 time 43577404 ticks 0.5566 us/tick b5 26.3320 time 17420746 ticks 1.5115 us/tick b6 21.7227 time 60000464 ticks 0.3620 us/tick b7 86.9395 time 2836154 ticks 30.6540 us/tick all 190.8936 time 165555937 ticks 1.1530 us/tick The b0 and b4 timings are missing because of exceptions that I didn't investigate. As with the gcc 3.2.3 compilation, my longobject.c patch hardly makes a difference. What does all this mean? Does the gcc 2.96 surprise tell us that small rearrangements in longobject.c could potentially boost performance by 45% on some platforms? Since I am not interested in optimizing longobject.c this is where I stopped. Eventually I decided that the problematic patch in longobject.c is not helping me with my original goal as stated near the beginning of this posting. I am only interested in counting the iterations of the interpreter loop. However, the _Py_Ticker decrements in longobject.c are not inside the interpreter loop, but in C loops! This means _Py_Ticker is useless for my purposes. Therefore I decoupled _Py_Ticker and _Py_TickerAccumulation. BTW: I think strictly speaking this documentation is incorrect because of the _Py_Ticker manipulations in longobject.c: sys.setcheckinterval.__doc__: Tell the Python interpreter to check for asynchronous events every n instructions. I feel very dizzy now after dealing with all the timings and the nasty details. A lot of fallout caused by the simple idea to add one innocent line to ceval.c. I hope it makes sense to somebody! Cheers, Ralf ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ diff -r -u original/Include/ceval.h work/Include/ceval.h --- original/Include/ceval.h 2004-10-10 19:40:35.000000000 -0700 +++ work/Include/ceval.h 2004-11-30 23:27:11.000000000 -0800 @@ -68,6 +68,11 @@ /* this used to be handled on a per-thread basis - now just two globals */ PyAPI_DATA(volatile int) _Py_Ticker; +#ifndef HAVE_LONG_LONG +PyAPI_DATA(volatile long) _Py_TickerAccumulation; +#else +PyAPI_DATA(volatile PY_LONG_LONG) _Py_TickerAccumulation; +#endif PyAPI_DATA(int) _Py_CheckInterval; /* Interface for threads. diff -r -u original/PC/os2emx/python24.def work/PC/os2emx/python24.def --- original/PC/os2emx/python24.def 2004-10-10 19:40:50.000000000 -0700 +++ work/PC/os2emx/python24.def 2004-11-30 23:27:11.000000000 -0800 @@ -743,6 +743,7 @@ "_Py_CheckRecursionLimit" "_Py_CheckInterval" "_Py_Ticker" + "_Py_TickerAccumulation" ; From python24_s.lib(compile) "PyCode_New" diff -r -u original/Python/ceval.c work/Python/ceval.c --- original/Python/ceval.c 2004-11-23 10:06:08.000000000 -0800 +++ work/Python/ceval.c 2004-12-03 19:39:36.000000000 -0800 @@ -373,6 +373,7 @@ pendinglast = j; _Py_Ticker = 0; + _Py_TickerAccumulation = 0; things_to_do = 1; /* Signal main loop */ busy = 0; /* XXX End critical section */ @@ -476,6 +477,11 @@ per thread, now just a pair o' globals */ int _Py_CheckInterval = 100; volatile int _Py_Ticker = 100; +#ifndef HAVE_LONG_LONG +volatile long _Py_TickerAccumulation = 0; +#else +volatile PY_LONG_LONG _Py_TickerAccumulation = 0; +#endif PyObject * PyEval_EvalCode(PyCodeObject *co, PyObject *globals, PyObject *locals) @@ -770,6 +776,7 @@ async I/O handler); see Py_AddPendingCall() and Py_MakePendingCalls() above. */ + _Py_TickerAccumulation++; if (--_Py_Ticker < 0) { if (*next_instr == SETUP_FINALLY) { /* Make the last opcode before diff -r -u original/Python/sysmodule.c work/Python/sysmodule.c --- original/Python/sysmodule.c 2004-08-12 11:19:17.000000000 -0700 +++ work/Python/sysmodule.c 2004-12-03 19:36:52.000000000 -0800 @@ -442,6 +442,20 @@ "getcheckinterval() -> current check interval; see setcheckinterval()." ); +static PyObject * +sys_gettickeraccumulation(PyObject *self, PyObject *args) +{ +#ifndef HAVE_LONG_LONG + return PyInt_FromLong(_Py_TickerAccumulation); +#else + return PyLong_FromLongLong(_Py_TickerAccumulation); +#endif +} + +PyDoc_STRVAR(gettickeraccumulation_doc, +"gettickeraccumulation() -> current count of bytecodes processed by the interpreter." +); + #ifdef WITH_TSC static PyObject * sys_settscdump(PyObject *self, PyObject *args) @@ -763,6 +777,8 @@ setcheckinterval_doc}, {"getcheckinterval", sys_getcheckinterval, METH_NOARGS, getcheckinterval_doc}, + {"gettickeraccumulation", sys_gettickeraccumulation, METH_NOARGS, + gettickeraccumulation_doc}, #ifdef HAVE_DLOPEN {"setdlopenflags", sys_setdlopenflags, METH_VARARGS, setdlopenflags_doc},
To restate my original goal:
I am looking for a simple way to answer the question: How much of a speedup can I expect if I reimplement a piece of Python code in C or C++? . . . Ratios (rounded to 3 decimals): 16.9193/16.8831=1.002 5.8287/5.9553 =0.979 1.5944/1.5914 =1.002 10.7931/10.8149=0.998 5.2865/5.2528 =1.006 11.6086/11.6437=0.997 10.0992/11.0248=0.916 27.6830/27.6960=1.000
Therefore I'd argue that the runtime penalty for the one additional long long increment in ceval.c (_Py_TickerAccumulation++) is in the noise.
The measurements are too imprecise to draw any worthwhile conclusions. Try running: python timeit.py -r9 "pass" That ought to give more stable measurements. The proposed "analysis tool" has no benefit to a majority of Python users. Even a 1% hit is not worth it.
I am only interested in counting the iterations of the interpreter loop. However, the _Py_Ticker decrements in longobject.c are not inside the interpreter loop, but in C loops! This means _Py_Ticker is useless for my purposes. Therefore I decoupled _Py_Ticker and _Py_TickerAccumulation.
Why add this to everyone's build? Just put it in when doing your own analysis. The eval loop already pays a penalty for Py2.4's extra function tracing code. And ceval.c has been cluttered with #ifdefs for hardware timestamps. And there have been other additions for signal handling and whatnot. This is enough.
. A lot of fallout caused by the simple idea to add one innocent line to ceval.c.
I do not find it to be innocent. A great of work was expended over the years just trying to eliminate a small step or two from the eval-loop. Those efforts should not be discarded lightly. -1 on adding it directly. -0 on adding it as a #ifdeffed compile option (with the default being to exclude it). Raymond Hettinger
(Old message)
=) Parrotbench and PyBench would be enough for me to sign off on any performance hit. There is also pystone.
pystone is good a predicting the relative performance of python apps on difference hardware/software environments. As a tool for evaluating proposed language changes, it completely sucks and should *never* be used for anything other than an extra informational datapoint. The foremost issue is that it exercises only a tiny portion of the language. Its design makes it worse than totally useless for evaluating eval-loop overhead. It runs a loop twice, once with benchmarking code and once without. Only the difference is reported. In theory, that means that all eval-loop speedups and slowdowns are netted out of the result. In practice, the reported result may indicate exactly the opposite of reality because the empty loop has vastly different cache effects than the benchmarked loop. For useful timings, run timeit on the specific feature in question. Then check for overall impact using pybench, parrotbench, and test_decimal. Raymond
On Monday 06 December 2004 11:33, Raymond Hettinger wrote:
pystone is good a predicting the relative performance of python apps on difference hardware/software environments.
This comes up so often that I'm almost tempted to add a disclaimer to the pystone output. I can't count the number of times people have tried to claim that pystone showed that a change was good/neutral.
participants (3)
-
Anthony Baxter -
Ralf W. Grosse-Kunstleve -
Raymond Hettinger