New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cython line profiling does not work on the last function defined #1947

Open
pganssle opened this Issue Oct 23, 2017 · 4 comments

Comments

Projects
None yet
4 participants
@pganssle

pganssle commented Oct 23, 2017

I haven't explored all the possible ways this could fail yet, but I'm finding that line_profiler fails when used on the last cpdef that I define. For a minimal working example:

setup.py:

from distutils.extension import Extension
from distutils.core import setup
from Cython.Build import cythonize

setup(
    ext_modules = cythonize([Extension("demo", ["demo.pyx"],
                             define_macros=[('CYTHON_TRACE', '1')])])
)

test_profile.py:

import line_profiler

from demo import cp_func
profile = line_profiler.LineProfiler(cp_func)
profile.runcall(cp_func, 20)
profile.print_stats()

demo.pyx:

# cython: linetrace=True
cimport cython

@cython.binding(True)
cpdef cp_func(n):
    n = n + 1
    return n

def d_func(n):
    n = n + 1
    return n

With this configuration:

$ python3 setup.py bdist_ext --inplace > /dev/null
$ python3 test_profile
Timer unit: 1e-06 s

Total time: 2e-06 s
File: demo.pyx
Function: cp_func at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           cpdef cp_func(n):
     6         1            1      1.0     50.0      n = n + 1
     7         1            1      1.0     50.0      return n
     8                                           
     9                                           def d_func(n):
    10                                               n = n + 1
    11                                               return n

So far so good. But now if I go into demo.pyx and remove d_func (which should theoretically have no bearing on how the profiling works, AFAIK), here's what I get:

$ python3 setup.py bdist_ext --inplace > /dev/null
$ python3 test_profile
Timer unit: 1e-06 s

Total time: 2e-06 s
File: demo.pyx
Function: cp_func at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           cpdef cp_func(n):

All the line information is gone! I've tested this with Python 3.6 on Arch Linux and Ubuntu 16. Cython versions 0.27.2 and 0.25.2, respectively.

@WeatherGod

This comment has been minimized.

Show comment
Hide comment
@WeatherGod

WeatherGod Oct 26, 2017

If one looks closely at the output of the test_profile.py for the collatz tests you would see something odd that I see in your output here, too:

bash-4.2$ python test_profile.py
Timer unit: 1e-06 s

Total time: 1.6e-05 s
File: /home/broot/Programs/tools/foobar/collatz.pyx
Function: collatz at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           def collatz(n):
     7         1            2      2.0     12.5      while n > 1:
     8        20            6      0.3     37.5          if n % 2 == 0:
     9        14            5      0.4     31.2              n //= 2
    10                                                   else:
    11         6            3      0.5     18.8              n = 3*n+1

Timer unit: 1e-06 s

Total time: 9e-06 s
File: /home/broot/Programs/tools/foobar/collatz.pyx
Function: cp_collatz at line 15

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    15                                           cpdef cp_collatz(n):
    16         1            1      1.0     11.1      while n > 1:
    17        20            6      0.3     66.7          if n % 2 == 0:
    18        14            2      0.1     22.2              n //= 2
    19                                                   else:
    20         6            0      0.0      0.0              n = 3*n+1
    21                                           
    22                                           
    23                                           @cython.binding(True)
    24                                           class PyClass(object):
    25                                               def py_pymethod(self):
    26                                                   x = 1
    27                                                   for i in range(10):
    28                                                       a = x + 2
    29                                                   return a * 3

Timer unit: 1e-06 s

Total time: 4e-06 s
File: /home/broot/Programs/tools/foobar/collatz.pyx
Function: py_pymethod at line 25

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    25                                               def py_pymethod(self):
    26         1            1      1.0     25.0          x = 1
    27         1            0      0.0      0.0          for i in range(10):
    28        10            2      0.2     50.0              a = x + 2
    29         1            1      1.0     25.0          return a * 3

<snip>

For the output for the cpdef cp_collatz, you also see the lines for the next def, PyClass.py_pymethod, but, in this particular case, the stats for py_pymethod does show up in the subsequent profile stat output. Don't know if it is related to the problem here... like a symptom of a deeper problem or not.

WeatherGod commented Oct 26, 2017

If one looks closely at the output of the test_profile.py for the collatz tests you would see something odd that I see in your output here, too:

bash-4.2$ python test_profile.py
Timer unit: 1e-06 s

Total time: 1.6e-05 s
File: /home/broot/Programs/tools/foobar/collatz.pyx
Function: collatz at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           def collatz(n):
     7         1            2      2.0     12.5      while n > 1:
     8        20            6      0.3     37.5          if n % 2 == 0:
     9        14            5      0.4     31.2              n //= 2
    10                                                   else:
    11         6            3      0.5     18.8              n = 3*n+1

Timer unit: 1e-06 s

Total time: 9e-06 s
File: /home/broot/Programs/tools/foobar/collatz.pyx
Function: cp_collatz at line 15

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    15                                           cpdef cp_collatz(n):
    16         1            1      1.0     11.1      while n > 1:
    17        20            6      0.3     66.7          if n % 2 == 0:
    18        14            2      0.1     22.2              n //= 2
    19                                                   else:
    20         6            0      0.0      0.0              n = 3*n+1
    21                                           
    22                                           
    23                                           @cython.binding(True)
    24                                           class PyClass(object):
    25                                               def py_pymethod(self):
    26                                                   x = 1
    27                                                   for i in range(10):
    28                                                       a = x + 2
    29                                                   return a * 3

Timer unit: 1e-06 s

Total time: 4e-06 s
File: /home/broot/Programs/tools/foobar/collatz.pyx
Function: py_pymethod at line 25

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    25                                               def py_pymethod(self):
    26         1            1      1.0     25.0          x = 1
    27         1            0      0.0      0.0          for i in range(10):
    28        10            2      0.2     50.0              a = x + 2
    29         1            1      1.0     25.0          return a * 3

<snip>

For the output for the cpdef cp_collatz, you also see the lines for the next def, PyClass.py_pymethod, but, in this particular case, the stats for py_pymethod does show up in the subsequent profile stat output. Don't know if it is related to the problem here... like a symptom of a deeper problem or not.

@jakirkham

This comment has been minimized.

Show comment
Hide comment
@jakirkham

jakirkham Jul 31, 2018

Contributor

@scoder, any thoughts on this one?

Contributor

jakirkham commented Jul 31, 2018

@scoder, any thoughts on this one?

@scoder

This comment has been minimized.

Show comment
Hide comment
@scoder

scoder Jul 31, 2018

Contributor

Definitely a bug, probably in Cython.Coverage.

Contributor

scoder commented Jul 31, 2018

Definitely a bug, probably in Cython.Coverage.

@jakirkham

This comment has been minimized.

Show comment
Hide comment
@jakirkham

jakirkham Aug 1, 2018

Contributor

This SO answer seems relevant.

Contributor

jakirkham commented Aug 1, 2018

This SO answer seems relevant.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment