profiling cython

[Martin Rubey]

Hi there!

I'd like to profile some performance-critical cythonized sage code. I
read that this can be done by writing

# cython: profile=True

at the very beginning of my file (which is configs.spyx). However, I
have the suspicion that this does not work entirely.

I get the following without "# cython: profile=True"

sage: %prun print len([i for i in I])
18480
129364 function calls in 41.181 CPU seconds

Ordered by: internal time

ncalls tottime percall cumtime percall filename:lineno(function)
18480 40.185 0.002 40.185 0.002 {_home_martin_martin_TeXSource_Mathematik_configs_spyx_13.children}
18481 0.869 0.000 41.136 0.002 backtrack.py:810(__iter__)
1 0.045 0.045 41.181 41.181 <string>:1(<module>)
18480 0.034 0.000 40.219 0.002 <ipython console>:1(<lambda>)
36958 0.024 0.000 0.024 0.000 {method 'add' of 'set' objects}
18482 0.012 0.000 0.012 0.000 {len}
18480 0.011 0.000 0.011 0.000 {method 'pop' of 'set' objects}
1 0.000 0.000 0.000 0.000 {method 'copy' of 'set' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}

and roughly the same with "# cython: profile=True":

sage: %prun print len([i for i in I])
18480
129364 function calls in 40.860 CPU seconds

Ordered by: internal time

ncalls tottime percall cumtime percall filename:lineno(function)
18480 39.885 0.002 39.885 0.002 {_home_martin_martin_TeXSource_Mathematik_configs_spyx_13.children}
18481 0.852 0.000 40.817 0.002 backtrack.py:810(__iter__)
1 0.044 0.044 40.860 40.860 <string>:1(<module>)
18480 0.032 0.000 39.918 0.002 <ipython console>:1(<lambda>)
36958 0.024 0.000 0.024 0.000 {method 'add' of 'set' objects}
18482 0.012 0.000 0.012 0.000 {len}
18480 0.011 0.000 0.011 0.000 {method 'pop' of 'set' objects}
1 0.000 0.000 0.000 0.000 {method 'copy' of 'set' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}

In particular, the function children calls several subroutines, so I'd expect to see them here...

What am I doing wrong?

Many thanks,

Martin

[Robert Bradshaw]

It's really hard to diagnose without seeing some code, but my guess is
that either

1) The methods called in children are not in a python file compiled
with #cython: profile=True
2) The spyx file gets a header prepended, meaning that the #cython ...
pragmas are not at the top of the file anymore, and so are not
applied. (Similar issues happen with __future__ imports).

or both.

- Robert

[Martin Rubey]

Robert Bradshaw <robe...@math.washington.edu> writes:

> It's really hard to diagnose without seeing some code,

yes, sorry about that,

> but my guess is that either
>
> 1) The methods called in children are not in a python file compiled
> with #cython: profile=True
> 2) The spyx file gets a header prepended, meaning that the #cython ...
> pragmas are not at the top of the file anymore, and so are not
> applied. (Similar issues happen with __future__ imports).
>
> or both.

Hm, I think I can at least partially exclude 1), since children calls at
least one method in the same file which is probably (relatively) expensive. How
could I circumvent 2)?

Martin

[Simon King]

On 13 Apr., 15:53, Martin Rubey <martin.ru...@math.uni-hannover.de>
wrote:

> > 2) The spyx file gets a header prepended, meaning that the #cython ...
> > pragmas are not at the top of the file anymore, and so are not
> > applied. (Similar issues happen with __future__ imports).
>

> ... How
> could I circumvent 2)?

Just guessing: Use .pyx instead of .spyx, if that is possible in your
case?

[Martin Rubey]

Simon King <simon...@uni-jena.de> writes:

I just tried this, but it makes no difference. Thank you anyway for the
hint!

Is there a way to check that a given function is profiled? I'll try to
make it artificially expensive..

Martin

[Robert Bradshaw]

If it's being profiled, it should show up in the stats. Is profiling
set up on _home_martin_martin_TeXSource_Mathematik_configs_spyx_13?

- Robert

[Martin Rubey]

Robert Bradshaw <robe...@math.washington.edu> writes:

Please bear with me - what would that mean? Yes, the first line of

/home/martin/martin/TeXSource/Mathematik/configs.spyx

contains this

# cython: profle=True

But I didn't do anything else. What should I do?

Thanks again,

Martin

PS: the experiment shows that it is *not* profiled. The called
subroutine shows up (a call to is_prime(largenumber)), but not the
function itself...

[Simon King]

On 14 Apr., 12:06, Martin Rubey <martin.ru...@math.uni-hannover.de>
wrote:

> Please bear with me - what would that mean?  Yes, the first line of
>
> /home/martin/martin/TeXSource/Mathematik/configs.spyx
>
> contains this
>
> # cython: profle=True

Note the type (profle versus profile). Is it the same in the file?

Cheers,
Simon

[Martin Rubey]

Simon King <simon...@uni-jena.de> writes:

> On 14 Apr., 12:06, Martin Rubey <martin.ru...@math.uni-hannover.de>
> wrote:
>> Please bear with me - what would that mean?  Yes, the first line of
>>
>> /home/martin/martin/TeXSource/Mathematik/configs.spyx
>>
>> contains this
>>
>> # cython: profle=True
>
> Note the type (profle versus profile). Is it the same in the file?

No, sorry, in the file it's correct.

Martin

[Robert Bradshaw]

On Thu, Apr 14, 2011 at 3:06 AM, Martin Rubey

The problem, I think, is that something gets inserted in converting an
.spyx file to a .pyx file. (Maybe? I actually don't ever use .spyx,
let alone via Mathematik) I have no idea how you're eventually
compiling the .spyx file.

- Robert