Side-effect of log/Maxima: Code producing a "Time Leak"
Simon King
in a recent post, i reported a phenomenon that i met when i was using
log: When i repeat a computation then the Wall time rapidly increases
while the CPU time is about constant in each repetition.
My original code would be far too long, but i succeeded to produce
reasonably short code that provides the same phenomenon. The code
(logtest.pyx) is below.
Here is the protocol of the Sage session (after sage -cython
logtest.pyx and compilation, of course):
sage: from logtest import *
sage: m=random_matrix(GF(7),5,5)
sage: M=TestIt(m,1)
sage: for i in range(50):
....: if (i==0) or (i==49):
....: time X=MulTest(M,40)
....: else:
....: X=MulTest(M,40)
....:
CPU times: user 0.24 s, sys: 0.05 s, total: 0.28 s
Wall time: 0.62
CPU times: user 0.29 s, sys: 0.09 s, total: 0.38 s
Wall time: 1.55
In other words,
1. there is huge difference between CPU and Wall Times, and
2. the difference between CPU and Wall time has been more than doubled
between the first and the 50th repetition of the same computation. And
in my "real" application, the effect was much more dramatic!
Perhaps you can detect the source of trouble by the following code
(logtest.pyx):
---------------------------------------------------------------------------------------
import sage
import sage.all
from sage.all import log
from sage.all import exp
class KeepIt:
ITEM = 0
def __init__(self, f=1):
if f<=0:
raise ArithmeticError, "positive parameter expected"
self.__class__.ITEM = int(log(f,10))
cdef class TestIt:
cdef object Data
def __init__(self, D, f):
KeepIt(f)
self.Data = D
def __copy__(self):
OUT=TestIt(self.Data, 10^(KeepIt.ITEM)-1)
# i don't claim that this deserves the name __copy__ ...
def __repr__(self):
return "Level %d for object of type %s"%
(KeepIt.ITEM,type(self.Data))
def __mul__(TestIt self, TestIt X):
return TestIt(self.Data*X.Data, KeepIt.ITEM+11)
def __str__(self):
return str(self.Data)
def MulTest(TestIt M, n):
cdef TestIt X
X=M
for i from 0 < i < n:
X=X*M
return X
-----------------------------------------------------------------------------------------------------------------
Note that changing a single line fixes the Wall time leak:
...
class KeepIt:
ITEM = 0
def __init__(self, f=1):
if f<=0:
raise ArithmeticError, "positive parameter expected"
self.__class__.ITEM = len(str(f))-1
...
Now, the result of the above Sage session becomes:
--------------------
sage: for i in range(50):
....: if (i==0) or (i==49):
....: time X=MulTest(M,4000)
....: else:
....: X=MulTest(M,4000)
....:
CPU times: user 0.25 s, sys: 0.01 s, total: 0.26 s
Wall time: 0.27
CPU times: user 0.26 s, sys: 0.01 s, total: 0.27 s
Wall time: 0.27
----------------------
It is clear why the CPU time decreased (now MulTest makes 4000 rather
than 40 multiplications). But i think it is estonishing that now there
is almost no difference between CPU and Wall time. Since the only
change was to replace log, i believe that the Wall time leak is a side-
effect of log (or of the Maxima interface).
Cheers
Simon