Strange timeit output while using maxima interface

[Golam Mortuza Hossain]

Hi,

While doing some symbolic computations that require
Maxima interface, "timeit" reports progressively
longer duration for the same computation.

---------
sage: f(x) = function('f',x);
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 71.6 ms per loop
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 89.1 ms per loop
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 101 ms per loop
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 127 ms per loop
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 159 ms per loop
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 231 ms per loop
sage: timeit('bool( f(x) == 0 )')
5 loops, best of 3: 305 ms per loop
-----------

Is something leaking in the maxima interface?

Cheers,
Golam

[Minh Nguyen]

Hi Golam,

There is definitely memory leak. Here is the output of a valgrind session:

[mvngu@sage ~]$ sage -valgrind --leak-check=full --show-reachable=yes
----------------------------------------------------------------------
| Sage Version 4.1, Release Date: 2009-07-09 |
| Type notebook() for the GUI, and license() for information. |
----------------------------------------------------------------------
/usr/local/sage/local/bin/sage-ipython
Log file is /home/mvngu/.sage/valgrind/sage-memcheck.%p
Using default flags:
--leak-resolution=high
--log-file=/home/mvngu/.sage/valgrind/sage-memcheck.%p
--leak-check=full --num-callers=25
--suppressions=/usr/local/sage/local/lib/valgrind/sage.supp
Python 2.6.2 (r262:71600, Jul 10 2009, 10:49:45)
[GCC 4.2.4 (Ubuntu 4.2.4-1ubuntu3)] on linux2
Type "help", "copyright", "credits" or "license" for more information.

sage: f(x) = function('f',x)
sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 779 ms per loop

sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 676 ms per loop

sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 837 ms per loop

sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 791 ms per loop

sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 755 ms per loop

sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 860 ms per loop

sage: timeit('bool( f(x) == 0 )')

5 loops, best of 3: 815 ms per loop

Here's a leak summary:

==11471== LEAK SUMMARY:
==11471== definitely lost: 8 bytes in 1 blocks.
==11471== possibly lost: 473,247 bytes in 1,119 blocks.
==11471== still reachable: 48,988,835 bytes in 32,885 blocks.
==11471== suppressed: 0 bytes in 0 blocks.

--
Regards
Minh Van Nguyen

[Simon King]

Dear Golam, dear All,

On 27 Jul., 04:01, Golam Mortuza Hossain <gmhoss...@gmail.com> wrote:
> Hi,
>
> While doing some symbolic computations that require
> Maxima interface, "timeit" reports progressively
> longer duration for the same computation.
>
> ---------
> sage: f(x) = function('f',x);
> sage: timeit('bool( f(x) == 0 )')
> 5 loops, best of 3: 71.6 ms per loop
> sage: timeit('bool( f(x) == 0 )')
> 5 loops, best of 3: 89.1 ms per loop

Finally someone comes up with a very short example of this
phenomenon!

It bothered me a long time ago, resulting one of my first posts on
sage-support, archived at http://www.mail-archive.com/sage-s...@googlegroups.com/msg01727.html

The code that I posted there was far too complicated, I guess. But
later, I posted trac ticket #4731 with a much simpler code, see
http://trac.sagemath.org/sage_trac/ticket/4731

Appararently nobody was ever working on it.

Your code is probably very close to the source of trouble. So, perhaps
now is about time to start fixing the ticket #4731?

Cheers,
Simon

[Golam Mortuza Hossain]

Thanks Minh and Simon!

On Mon, Jul 27, 2009 at 8:13 AM, Simon King<simon...@uni-jena.de> wrote:
>> ---------
>> sage: f(x) = function('f',x);
>> sage: timeit('bool( f(x) == 0 )')
>> 5 loops, best of 3: 71.6 ms per loop
>> sage: timeit('bool( f(x) == 0 )')
>> 5 loops, best of 3: 89.1 ms per loop
>
> Finally someone comes up with a very short example of this
> phenomenon!
>

> The code that I posted there was far too complicated, I guess. But
> later, I posted trac ticket #4731 with a much simpler code, see
> http://trac.sagemath.org/sage_trac/ticket/4731
>
> Appararently nobody was ever working on it.

Yeah. Thats what it seems :-)

I did bit more digging trying to pin-point the culprit. In a fresh
sage prompt if I try the following:

------
sage: timeit('integrate(sin(x)/x, x)')
5 loops, best of 3: 524 ms per loop
------

where as if I try above directly in the maxima
(./sage -sh && cd local/bin && ./maxima )

-------
(%i2) integrate( sin(x)/x, x);
Evaluation took 0.0120 seconds (0.0100 elapsed)
...
(%i3) integrate( sin(x)/x, x);
Evaluation took 0.0080 seconds (0.0090 elapsed)
...
-------

Assuming time reported in both systems can be
compared, I made two observations:

(1) Repeated use of same command within maxima (directly)
shows no degradation of evaluation time where as doing
the same within Sage clearly shows progressive degradation.

(2) In a fresh prompt: for the same computation, maxima took
120 ms where as the Sage reports 524ms!!
Am I doing something terribly wrong? Or is it just because of
pexpect overhead?

Cheers,
Golam