Tests run slow on Conda / macOS

[orlitzky]

Using https://github.com/sagemath/sage/pull/40819/files as an example, there are several doctests that raise "slow doctest" warnings only on macOS. Here is an example, run on my slowest CPU from a fresh start of sage (nothing cached):

sage: var('x,y,z')
(x, y, z)
sage: eqs = [-y^2+z^2, -x^2+y^2-3*z^2-z-1, -y*z-z^2-x-y+2, -x^2-12*z^2-y+z]
sage: %timeit -c -n1 -r1 solve_mod(eqs, 11)
1.3 s ± 0 ns per loop (mean ± std. dev. of 1 run, 1 loop each)

But the CI is showing,

slow doctest:: Test ran for 15.24s cpu, 25.71s wall
slow doctest:: Test ran for 21.44s cpu, 38.39s wall

Something similar happens in src/sage/geometry/polyhedron/palp_database.py, so it isn't only symbolics, or modular arithmetic that are the problem.

We're already measuring CPU seconds, and I don't think there are any processors slower than mine that run macOS, so I'm wondering if maybe some libraries were compiled without optimization on these CI runners?

I will note that psutil is loaded on-the-fly on macOS to measure CPU time, but the penalty for that should only hurt the first doctest in a series (and the problem isn't with the first doctest).

[orlitzky]

@dimpase profiled two of these:

%prun solve_mod([5*x + y == 3, 2*x - 3*y == 9], 3*5*7*11*19*23*29, solution_dict = True)

       	9495 function calls (9365 primitive calls) in 13.489 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2039   13.336    0.007   13.339    0.007 relation.py:1818(<genexpr>)
       35    0.076    0.002    0.076    0.002 {built-in method _functools.reduce}
       14    0.042    0.003    0.121    0.009 expression_conversions.py:978(relation)
       	7    0.008    0.001    0.008    0.001 polynomial_ring_constructor.py:837(_multi_variate)
       	2    0.007    0.004    0.007    0.004 {method '__exit__' of 'sqlite3.Connection' objects}
       	7    0.004    0.001   13.457    1.922 relation.py:1734(_solve_mod_prime_power)
       	1    0.004    0.004    0.004    0.004 {method 'execute' of 'sqlite3.Connection' objects}

%prun k(2).sqrt(algorithm="cipolla")^2 == k(2)

         122239 function calls (122238 primitive calls) in 9.261 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      307    4.847    0.016    9.157	0.030 polynomial_quotient_ring_element.py:385(__invert__)
      614    4.260    0.007    4.264    0.007 multi_polynomial_sequence.py:213(PolynomialSequence)
     7960    0.029    0.000    0.042    0.000 polynomial_ring.py:335(_element_constructor_)
     4303    0.020    0.000    0.039    0.000 polynomial_quotient_ring_element.py:108(__init__)

Both of these ultimately use polynomial rings. In the first, we coerce a list of equations into a polynomial ring:

mrunning *= p  # modulus
R = Integers(mrunning)
S = PolynomialRing(R, len(vars), vars)
eqns_mod = [S(eq) for eq in eqns]
...
ans = [t for t in possibles if all(e(*t) == 0 for e in eqns_mod)]

where, in this case,

sage: type(S)
<class 'sage.rings.polynomial.multi_polynomial_libsingular.MPolynomialRing_libsingular'>

In the second example, we have what looks like an NTL polynomial,

sage: type(k(2)._polynomial)
<class 'sage.rings.polynomial.polynomial_modn_dense_ntl.Polynomial_dense_mod_p'>

but if we look under the hood at the inverse_mod() method on k(2)._polynomial, it also invokes singular:

from sage.rings.polynomial.polynomial_singular_interface import can_convert_to_singular
P = a.parent()
if can_convert_to_singular(P):
    from sage.rings.polynomial.polynomial_ring_constructor import PolynomialRing
    try:
        R = PolynomialRing(P.base_ring(), P.variable_names(), implementation="singular")
    except NotImplementedError:
        # PolynomialRing over RDF/CDF etc. are still not implemented in libsingular
        # (in particular singular_ring_new) even though they are implemented in _do_singular_init_
        pass
    else:
        return P(R(a).inverse_mod(R.ideal(m)))

[dimpase]

I profiled on plain macOS with Homebrew, not on Conda.

[dimpase]

Something similar happens in src/sage/geometry/polyhedron/palp_database.py

this is again polynomial arithmetic. Seems like subs - substitution of values into variables - is slow.
(profiled on Intel macOS, as above)

sage: %prun for lp in PALPreader(2): cone = Cone([(1,r[0],r[1]) for r in lp.vertices()]); fan = Fan([cone]); X = ToricVariety(fan); ideal = X.affine_algebraic_patch(cone).defining_ideal(); lp.n_vertices(); ideal.hilbert_series()

317569 function calls (315026 primitive calls) in 5.467 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      224    4.790    0.021    4.798    0.021 multi_polynomial_ideal.py:4830(subs)
      128    0.139    0.001    0.151    0.001 multi_polynomial_ideal.py:485(_groebner_basis_libsingular)
     2323    0.034    0.000    0.056    0.000 toric_lattice.py:401(__call__)
     2476    0.022    0.000    0.026    0.000 matrix_space.py:1051(_element_constructor_)
      400    0.019    0.000    0.124    0.000 digraph.py:523(__init__)

[dimpase]

I even tried to build Sage's singular rather than using the Homebrew's one, but it turns out to be the same in th end.

The next step is to rule out that it's clang, rather than something macOS?

[orlitzky]

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      224    4.790    0.021    4.798    0.021 multi_polynomial_ideal.py:4830(subs)

This is indeed suspicious. Same number of calls on my riscv, but 10x faster:

      224    0.445    0.002    1.472    0.007 multi_polynomial_ideal.py:4830(subs)

The next step is to rule out that it's clang, rather than something macOS?

It's hard to imagine that Apple's compiler is the problem on Apple's OS, but it wouldn't be the dumbest thing I've ever seen. Can you tell what CXXFLAGS are getting used?

Another possibility is that, with Singular being built with NTL support (--with-ntl), the recent improvements to NTL on Apple hardware might make a difference.

[orlitzky]

blarg, the Conda/macOS CI crashed over at #41225

[dimpase]

blarg, the Conda/macOS CI crashed over at #41225

that's a technical CI snafu, not that NTL is any problem. On the Intel Mac I already have NTL 11.6.0 and Singular compiled with it, from source.

[dimpase]

To go with PALP example, I extracted data for the subs run; it is

R.<z0,z1,z2,z3,z4,z5,z6,z7,z8,z9>=QQ[]
I=R.ideal([-z3*z5 + z0*z1, z3*z4 - z0*z6, z4*z5 - z0*z8, -z6*z7 + z2*z3, -z5*z9 + z1*z7, -z3*z6 + z0*z8, -z6*z8 + z1*z7])
in_dict={z0: z8, z1: z9, z2: z0, z3: z1, z4: z2, z5: z3, z6: z4, z7: z5, z8: z6, z9: z7}
%prun I.subs(in_dict)

On (fast) Linux:

 17 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 multi_polynomial_ideal.py:4830(subs)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 ideal.py:256(__init__)
 

On M1 macOS (quite similar picture on Intel Mac):

         87 function calls (86 primitive calls) in 0.027 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.018    0.018    0.018    0.018 {method 'execute' of 'sqlite3.Connection' objects}
      2/1    0.009    0.004    0.018    0.018 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 multi_polynomial_ideal.py:4830(subs)
        1    0.000    0.000    0.000    0.000 inspect.py:3157(_bind)
        1    0.000    0.000    0.018    0.018 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 ideal.py:256(__init__)
        1    0.000    0.000    0.000    0.000 inspect.py:2971(apply_defaults)

What is that sqlite3 doing there?! (perhaps from %prun ?). Anyhow, seems like <string>:1(<module>) - some silly, slow messing around with strings?

Anyhow, timeit('I.subs(in_dict)') on M1 Mac is ~100 times slower: 25 loops, best of 3: 8.71 ms per loop vs
76.7 μs.