[BUG] Large files compile very slowly in the C compiler

[da-woods]

Describe the bug

It takes a very long time for the C compiler to run on large files like ExprNodes.py and Nodes.py. This is seen in the CI -all tests repeatedly timing out (although partly this is because we can't compile them in parallel on Python 2.7)

One possible indicator is the warning from gcc:

note: variable tracking size limit exceeded with ‘-fvar-tracking-assignments’, retrying without

(although that could potentially be toggled independently or the limit increased)

Obviously it's inevitable that a big Cython file will generate a big C file and that a big C file will take a while to compile, but potentially we could do better.

There's a few gcc flags to try to profile compilation time (https://stackoverflow.com/questions/13559818/profiling-the-c-compilation-process), and they suggest that the module init function (where all the module-level user code goes) is the main culprit (unsurprisingly)

Environment (please complete the following information):

• Linux, CI, most obviously in Python 2.7

Additional context

I tried a couple of approaches to fix the problem.

1. First I created small sub-scopes within the module init function. https://github.com/da-woods/cython/tree/morelocaltemps. This didn't achieve any speedup or get rid of the warning, but may be worth using some of the change for other reasons (da-woods@c901416#commitcomment-57239451)
2. Second, I tried to split each stat at module-level into a separate function (Split up module init function #4386). This gave appreciable speed-ups for large modules. However the PR was very intended as a proof of concept with little attention to code quality....

I think a variant of the second approach is probably worthwhile. My current thought that we shouldn't do it on a "per-stat" basis but maybe give each class creation a separate function (that's easy to do for cdef classes, slightly harder for regular classes). That would likely give the appropriate granularity and keep things grouped in logical units.

Improvements made to mitigate this in Cython 3.1

More efficient string constant storage:

• f39526d
• 368a750 (fixed in f5f83fb)
• 0d5af7b

Shorter code generation:

• e6c621a
• 6526ecf
• 9047418
• 12241b8

More efficient code object creation that no longer permanently stores tuples in the global module state:

• f5763fa

[scoder]

Looking around a bit, it seems that variable tracking is mostly a debugging feature. Would be nice to locally disable it somehow, but I can't find a way to do that. In any case, the fact that large files break that feature shouldn't trouble us.

I feel inclined to give a low priority to this issue. Not zero – if we can reduce the C compiler runtime, cool (also in terms of CO2 emissions), but it's only really an issue for large and very large modules, which are rare for simply practical reasons.

[da-woods]

Looking around a bit, it seems that variable tracking is mostly a debugging feature. Would be nice to locally disable it somehow, but I can't find a way to do that. In any case, the fact that large files break that feature shouldn't trouble us.

Yeah - I also looked and couldn't find a way to disable it locally

I feel inclined to give a low priority to this issue. Not zero – if we can reduce the C compiler runtime, cool (also in terms of CO2 emissions), but it's only really an issue for very large modules, which are rare for simply practical reasons.

I agree - I was only really interested because it's causing the python 2.7 -all jobs to time out. I mainly created the issue because I wasn't planning to do any more on it for now and wanted to record where I'd got to before forgetting it. So low priority!

[scoder]

To add some more data points, the slowest test files to compile in clang are actually not those that have the most complex module init functions but a large number of types (including closures) and functions:

compile-c   :  1425.27 sec  (1071,  1.331 / run) - slowest: 'c:test_unicode' (28.38s), 'c:test_coroutines_pep492' (27.53s), 'c:test_asyncgen' (14.11s), 'c:memslice' (13.31s), 'c:exttype_total_ordering' (13.10s), 'c:test_grammar' (12.91s), 'c:fused_def' (12.85s), 'c:numpy_test' (12.06s)

https://github.com/cython/cython/runs/3996856486?check_suite_focus=true

Can't say why that is. clang seems really slow here in comparison to gcc:

compile-c   :   161.93 sec  (1078,  0.150 / run) - slowest: 'c:numpy_test' (20.83s), 'c:test_unicode' (0.48s), 'c:relaxed_strides' (0.47s), 'c:test_coroutines_pep492' (0.46s), 'c:libc_stdio' (0.42s), 'c:behnel4' (0.40s), 'c:embedded' (0.38s), 'c:a_capi' (0.34s)

https://github.com/cython/cython/runs/3996853937?check_suite_focus=true

I checked the CFLAGS and they should say `-O0' in both cases, which should be honoured by both gcc and clang alike as saying "do not spend time optimising the code".

[da-woods]

On my laptop (just running test_unicode) I get

clang:

compile-c   :    45.93 sec  (   1, 45.928 / run) - slowest: 'c:test_unicode' (45.93s)
compile-cpp :    42.76 sec  (   1, 42.757 / run) - slowest: 'cpp:test_unicode' (42.76s)

gcc

compile-c   :    57.95 sec  (   1, 57.948 / run) - slowest: 'c:test_unicode' (57.95s)
compile-cpp :    48.91 sec  (   1, 48.909 / run) - slowest: 'cpp:test_unicode' (48.91s)

(that's with CLAGS=-Og, just because -O0 produces a lot of warnings when I use it).

I'd say there's ccache is probably doing something here?

[scoder]

Ah, yeah, right. We don't have ccache on macOS. Probably something we should change.

[scoder]

BTW, I agree that class creations should give a good granularity for a split. I think that's worth trying out.

[oscarbenjamin]

For python-flint I notice a 50% slowdown in compilation time for Cython 3.0.0a11 compared to Cython 0.29.32 (flintlib/python-flint#29 (comment)).

It goes from ~1 minute to ~1.5 minutes for a full setup.py build_ext --inplace so it's not a huge problem in python-flint's case but it seems like a regression that I guess could have bigger impact for some other projects.

[da-woods]

@oscarbenjamin do you know if that's in the pyx->c stage or the c-->so stage?

[oscarbenjamin]

@oscarbenjamin do you know if that's in the pyx->c stage or the c-->so stage?

Is there an easy way to measure that?

It looks to me like the c-->so stage because I'm only compiling a single extension module and I can see warnings from the C compiler after around 5 seconds i.e.:

$ time python setup.py build_ext --inplace
<snip>
Compiling src/flint/pyflint.pyx because it depends on src/flint/functions.pyx.
[1/1] Cythonizing src/flint/pyflint.pyx
running build_ext

## ----------- takes 5 seconds to get here

building 'flint._flint' extension
INFO: C compiler: x86_64-linux-gnu-gcc -pthread -Wno-unused-result -Wsign-compare -DNDEBUG -g -fwrapv -O2 -Wall -g -fstack-protector-strong -Wformat -Werror=format-security -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fPIC

INFO: compile options: '-I/usr/local/include -I/home/oscar/current/sympy/python-flint/.local/venv/include -I/usr/local/include/flint -I/home/oscar/current/sympy/python-flint/.local/venv/include/flint -I/home/oscar/current/sympy/python-flint/.local/venv/include -I/usr/include/python3.8 -c'
INFO: x86_64-linux-gnu-gcc: src/flint/pyflint.c
src/flint/pyflint.c: In function ‘__pyx_pf_5flint_6_flint_14dirichlet_char_4__init__’:
src/flint/pyflint.c:194837:23: warning: comparison between signed and unsigned integer expressions [-Wsign-compare]
       if (((__pyx_t_5 > __pyx_t_6) != 0)) {
                       ^
src/flint/pyflint.c: At top level:
src/flint/pyflint.c:29053:18: warning: ‘__pyx_f_5flint_6_flint_any_as_fmpz_mpoly’ defined but not used [-Wunused-function]
 static PyObject *__pyx_f_5flint_6_flint_any_as_fmpz_mpoly(CYTHON_UNUSED PyObject *__pyx_v_x) {
                  ^
INFO: x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-Bsymbolic-functions -Wl,-z,relro -g -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -DNDEBUG -g -fwrapv -O2 -Wall build/temp.linux-x86_64-3.8/src/flint/pyflint.o -L/home/oscar/current/sympy/python-flint/.local/venv/lib -L/usr/local/lib -larb -lflint -o /home/oscar/current/sympy/python-flint/src/flint/_flint.cpython-38-x86_64-linux-gnu.so

# ----------- takes 1 minute to get here:

real	0m54.163s
user	0m53.124s
sys	0m0.828s

That's with Cython 0.29.32 and it looks like about 5 seconds cythonising and then 50 seconds in the C compiler.

With Cython 3.0.0a11 it's more like about 5 seconds cythonising and then 70 seconds in the C compiler:

real	1m26.277s
user	1m24.480s
sys	0m1.568s

The C file generated by 3.0.0a11 is about 30% bigger in terms of lines (293186 lines vs 224736) which matches the increased compilation time.

[da-woods]

Thanks @oscarbenjamin - you're rough guess at where the cythonization ends and the c compilation begins is probably right. Cython on it's own can be run with cython <source_file_name> and that might be the easiest way to measure Cython vs C.

A few notes:

• There was a bit of a slowdown in building the lexer(?) due to unicode support - it just vastly increased the size of a certain look-up table we had to build. See cython3.0: 3x compile-time regression compared to 0.29 ; steady growth of compilation time from release to release #3646. We think we clawed most of that back though by changing what was compiled.
• A big chunk of the extra file size is probably limited API support. I wouldn't expect that to impact compilation time much - the preprocessor should probably be able to eliminate large chunks of code pretty quickly.
• Personally I'd guess the biggest difference might be because we now default to binding=True (which generates a big chunk more C code, in exchange for more introspectability). That might be a useful thing to check (if you have time to test it).

I have a few ideas about how to speed this up that I'd like to try. I wouldn't expect them to make 3.0 though - they're potentially fairly big changes.

[oscarbenjamin]

It takes about 10 seconds to cythonise:

# cython 3.0.0a11
$ time cython -2 --module-name flint._flint flint/pyflint.pyx
warning: flint/_flint.pxd:18:0: The 'DEF' statement is deprecated and will be removed in a future Cython version. Consider using global variables, constants, and in-place literals instead. See https://github.com/cython/cython/issues/4310
<snip more warnings>
real	0m10.466s
user	0m10.356s
sys	0m0.104s

That part is only slightly faster with 0.29:

# cython 0.29.32
$ time cython -2 --module-name flint._flint flint/pyflint.pyx

real	0m9.191s
user	0m9.076s
sys	0m0.112s

[da-woods]

One more thing to try if you have time - can you try the full compilation with the binding compiler directive set to True and then False (I think you can add it to https://github.com/fredrik-johansson/python-flint/blob/d6e239d6bf4871a4d90f389177b805fec5368e98/setup.py#L48).

If you don't have time I can have a look myself in a few days, but it looks like I'd need to work out a few dependencies first, which I'm trying to avoid.

[oscarbenjamin]

One more thing to try if you have time - can you try the full compilation with the binding compiler directive set to True and then False

That makes a big difference actually. With Cython 3.0.0a11 and binding:True I get a 3 minute build. With binding:False it's a 1.5 minute build so that's a 2x speedup.

What exactly does the binding parameter do?

(In the other timings reported below I didn't set the binding parameter at all which I guess means that it defaults to True)

If you don't have time I can have a look myself in a few days, but it looks like I'd need to work out a few dependencies first, which I'm trying to avoid.

It's not as bad as it looks because there is a script to download and build the dependencies that takes about 15 minutes so the full repro is

git clone https://github.com/fredrik-johansson/python-flint.git
cd python-flint/
source bin/activate 
bin/build_dependencies_unix.sh
# Need numpy and cython at this point
time python setup.py build_ext --inplace

(I'm assuming that you're on a Unixy system with compilers etc. Don't try this at home on Windows, although the problem is worse there for mingw64.)

The dependency build is faster if you comment out this part:
https://github.com/fredrik-johansson/python-flint/blob/d6e239d6bf4871a4d90f389177b805fec5368e98/bin/build_dependencies_unix.sh#L183-L185

Having just repeated the repro steps above I found that it actually took 3 minutes rather than the 1.5 minutes I previously reported:

$ time python setup.py build_ext --inplace
...
real	3m10.113s
user	3m8.504s
sys	0m1.468s

I guess the difference is because some parts of the compilation are maybe being cached which makes it a bit difficult to reason about timings. I've just tried repeating this a couple of times with cython 3.0.0a11 and 0.29.32:

touch src/flint/*.pyx
time python setup.py build_ext --inplace

I'm now consistently getting ~3 minutes for 3.0.0a11 and ~1 minute for 0.29.32 so a 3x slowdown. I'm not sure why this is different from previous timings.

I remember now that the reason I noticed a slowdown with cython 3.0.0a11 in the first place was because I was trying to make a coverage-enabled build which is slower in both cases. With cython 0.29:

$ time PYTHON_FLINT_COVERAGE=true python setup.py build_ext --inplace
...
real	1m36.786s
user	1m34.848s
sys	0m1.072s

And with 3.0.0a11 (actually master):

$ time PYTHON_FLINT_COVERAGE=true python setup.py build_ext --inplace
...
real	3m50.796s
user	3m48.324s
sys	0m1.460s

[da-woods]

What exactly does the binding parameter do?

It wraps functions in a CyFunction object, which adds a whole load of introspectable attributes. For example things like __annotations__, __defaults__. It makes them look a lot more like Python functions.

It's expected to slow things down because it does generate a lot more code to initialize these at start up. So it isn't worrying that it has an effect, although obviously it would be good if we could minimise the effect.

(In the other timings reported below I didn't set the binding parameter at all which I guess means that it defaults to True)

It defaults to True on Cython 3 and False in 0.29.x. so it's likely one of the more significant differences.

I guess the difference is because some parts of the compilation are maybe being cached which makes it a bit difficult to reason about timings.

Passing --force to setup.py should eliminate most of the caching. No need to rerun everything though.

Thanks