Thanks Oscar for the wonderful clarification! I rerun my code with SYMPY_USE_CACHE=no, now the results make much more sense.
[image: lambdify-no-cache.png] Davide. Il giorno mer 15 set 2021 alle ore 15:14 Oscar Benjamin < [email protected]> ha scritto: > > On Wed, 15 Sept 2021 at 13:41, Oscar Benjamin <[email protected]> > wrote: > >> On Tue, 14 Sept 2021 at 23:12, [email protected] < >> [email protected]> wrote: >> >>> Hello, >>> let's say I'd like to numerically evaluate a single sympy function over >>> an array using sympy as the module. Curiously, passing in regular Python's >>> float numbers makes the evaluation much faster then passing in Sympy's >>> Float instances. I tried several sympy functions, they tend to follow this >>> trend. >>> >> >> The 3 millisecond timing difference that you are asking about here is >> dwarfed by the actual 1 second time that it really takes to compute this >> result the first time. Most likely the time differences you see are just to >> do with exactly how efficient the cache lookups are for different types. >> > > If you want to see what is taking the time then use a profiler. From > isympy/ipython you can use %prun or if you want to run separate processes > you can use python -m cProfile but that will also time how long it takes to > import sympy so it's only useful for things that take at least several > seconds. > > In the first run the time is taken by sin.eval and most of that by the > extract_multiplicatively function. > > In [2]: %prun -s cumulative f(domain) > > 2069604 function calls (2047615 primitive calls) in 1.585 seconds > > Ordered by: cumulative time > > ncalls tottime percall cumtime percall filename:lineno(function) > 1 0.000 0.000 1.585 1.585 {built-in method > builtins.exec} > 1 0.001 0.001 1.585 1.585 <string>:1(<module>) > 1000 0.002 0.000 1.584 0.002 > <lambdifygenerated-1>:1(_lambdifygenerated) > 16989/1000 0.022 0.000 1.582 0.002 cache.py:69(wrapper) > 1000 0.014 0.000 1.579 0.002 function.py:450(__new__) > 1000 0.013 0.000 1.392 0.001 function.py:270(__new__) > 1000 0.012 0.000 1.270 0.001 trigonometric.py:266(eval) > 2997 0.029 0.000 0.988 0.000 > expr.py:2183(extract_multiplicatively) > 7993 0.020 0.000 0.835 0.000 assumptions.py:460(getit) > 8993 0.336 0.000 0.722 0.000 > facts.py:499(deduce_all_facts) > 6993/2997 0.007 0.000 0.529 0.000 > decorators.py:88(__sympifyit_wrapper) > 2997 0.010 0.000 0.525 0.000 numbers.py:1315(__truediv__) > 999 0.005 0.000 0.511 0.001 > expr.py:2453(could_extract_minus_sign) > 999 0.001 0.000 0.505 0.001 expr.py:1662(as_coefficient) > 999 0.001 0.000 0.480 0.000 numbers.py:759(__truediv__) > 999 0.001 0.000 0.478 0.000 decorators.py:254(_func) > 999 0.001 0.000 0.476 0.000 > decorators.py:129(binary_op_wrapper) > 999 0.003 0.000 0.474 0.000 expr.py:260(__truediv__) > 4996 0.015 0.000 0.459 0.000 assumptions.py:472(_ask) > 999 0.015 0.000 0.457 0.000 operations.py:46(__new__) > 999 0.037 0.000 0.408 0.000 mul.py:178(flatten) > 3997 0.005 0.000 0.357 0.000 assumptions.py:444(copy) > 3997 0.014 0.000 0.352 0.000 assumptions.py:432(__init__) > 198823 0.074 0.000 0.254 0.000 {built-in method > builtins.all} > 570492 0.158 0.000 0.209 0.000 facts.py:533(<genexpr>) > 1999 0.032 0.000 0.126 0.000 sets.py:1774(__new__) > 183867 0.083 0.000 0.083 0.000 facts.py:482(_tell) > 999 0.007 0.000 0.078 0.000 evalf.py:1425(evalf) > 15987 0.023 0.000 0.077 0.000 sympify.py:92(sympify) > 1000 0.003 0.000 0.066 0.000 function.py:214(nargs) > 7996 0.026 0.000 0.065 0.000 compatibility.py:501(ordered) > 6994 0.015 0.000 0.063 0.000 numbers.py:1197(_new) > 29977 0.020 0.000 0.057 0.000 <frozen > importlib._bootstrap>:1009(_handle_fromlist) > 391655 0.054 0.000 0.054 0.000 {method 'get' of 'dict' > objects} > 1998/999 0.007 0.000 0.053 0.000 evalf.py:1332(evalf) > 1998 0.053 0.000 0.053 0.000 mul.py:449(_gather) > 999 0.005 0.000 0.046 0.000 evalf.py:781(evalf_trig) > ... > > Now a second run in the same process just shows 1000 cache lookups: > > In [3]: %prun -s cumulative f(domain) > > 2003 function calls in 0.002 seconds > > Ordered by: cumulative time > > ncalls tottime percall cumtime percall filename:lineno(function) > 1 0.000 0.000 0.002 0.002 {built-in method > builtins.exec} > 1 0.001 0.001 0.002 0.002 <string>:1(<module>) > 1000 0.001 0.000 0.001 0.000 > <lambdifygenerated-1>:1(_lambdifygenerated) > 1000 0.001 0.000 0.001 0.000 cache.py:69(wrapper) > 1 0.000 0.000 0.000 0.000 {method 'disable' of > '_lsprof.Profiler' objects} > > This is the second run when the inputs are Expr: > > In [5]: %prun -s cumulative f(domain_sympy) > 5003 function calls in 0.014 seconds > > Ordered by: cumulative time > > ncalls tottime percall cumtime percall filename:lineno(function) > 1 0.000 0.000 0.014 0.014 {built-in method > builtins.exec} > 1 0.007 0.007 0.014 0.014 <string>:1(<module>) > 1000 0.002 0.000 0.008 0.000 > <lambdifygenerated-1>:1(_lambdifygenerated) > 1000 0.002 0.000 0.006 0.000 cache.py:69(wrapper) > 1000 0.001 0.000 0.004 0.000 numbers.py:1480(__hash__) > 1000 0.001 0.000 0.002 0.000 numbers.py:806(__hash__) > 1000 0.001 0.000 0.001 0.000 expr.py:126(__hash__) > 1 0.000 0.000 0.000 0.000 {method 'disable' of > '_lsprof.Profiler' objects} > > The cache lookups here are slower because the pure Python Expr.__hash__ > methods are slower than for numpy's float64.__hash__ which is implemented > in C. > > Either way this shows that the differences are all just to do with caching > and are not representative of the actual time that it would take to compute > these results once. The bulk of the time in the first run is ultimately > consumed by deduce_all_facts i.e. the old assumptions. Note that the old > assumptions are themselves cached on each Basic instance separately from > the main cache which can also affect timing results if you don't use a > separate process for timings: > > In [1]: e = sin(1) > > In [2]: e._assumptions > Out[2]: {} > > In [3]: e.is_real > Out[3]: True > > In [4]: e._assumptions > Out[4]: > {'real': True, > 'positive': True, > 'finite': True, > 'infinite': False, > 'extended_positive': True, > 'extended_real': True, > 'commutative': True, > 'imaginary': False, > 'hermitian': True, > 'complex': True, > 'extended_nonnegative': True, > 'nonpositive': False, > 'negative': False, > 'extended_nonpositive': False, > 'extended_nonzero': True, > 'extended_negative': False, > 'zero': False, > 'nonnegative': True, > 'nonzero': True} > > The deduce_all_facts function is the one that applies all of the > implications relating these different assumption predicates so that as soon > as one predicate (e.g. positive=True) is known then all of the others can > be stored in the _assumptions dict. Although this makes things faster on a > second assumptions query it does in fact consume the bulk of the time for > computing many things in SymPy. > > Assumptions queries that take place during automatic evaluation are often > a cause of slowness in SymPy. The bottom of the profile report shows evalf > being called 2000 times i.e. twice per evaluation of the sin function. The > evalf calls are part of the assumptions query and are reasonably fast for a > simple sin(float) but can be very expensive for large expressions. > > > -- > Oscar > > -- > You received this message because you are subscribed to the Google Groups > "sympy" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected]. > To view this discussion on the web visit > https://groups.google.com/d/msgid/sympy/CAHVvXxRmA9AYL3TnAJeM_crc%2BKc9kb3ADtLR%2BptZEQKYPbKspw%40mail.gmail.com > <https://groups.google.com/d/msgid/sympy/CAHVvXxRmA9AYL3TnAJeM_crc%2BKc9kb3ADtLR%2BptZEQKYPbKspw%40mail.gmail.com?utm_medium=email&utm_source=footer> > . > -- You received this message because you are subscribed to the Google Groups "sympy" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/sympy/CAO%3D1Z0_LqKn2syviLVpBVqOkZMCWC--5g_Z55yhndhs%3D5ZjX-A%40mail.gmail.com.
