Line break will double 'Hit'

[hermitgreen]

I have test code

class T:
    def __init__(self, data):
        self.data = data


@profile
def main():
    a = T(1)
    d = T(T(1))
    e = T(
        T(1))
    g = T(T(T(1)))
    h = T(
        T(
        T(1)))
    i = T(
        T(
        T(
        T(1))))

main()

then I try

kernprof -l test.py
python -m line_profiler test.py.lprof

then I get

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           @profile
     7                                           def main():
     8         1          5.0      5.0     29.4      a = T(1)
     9         1          2.0      2.0     11.8      d = T(T(1))
    10         2          2.0      1.0     11.8      e = T(
    11         1          1.0      1.0      5.9          T(1))
    12         1          2.0      2.0     11.8      g = T(T(T(1)))
    13         2          0.0      0.0      0.0      h = T(
    14         2          0.0      0.0      0.0          T(
    15         1          0.0      0.0      0.0          T(1)))
    16         2          1.0      0.5      5.9      i = T(
    17         2          2.0      1.0     11.8          T(
    18         2          1.0      0.5      5.9          T(
    19         1          1.0      1.0      5.9          T(1))))

It's seems line break will double hit and get a wrong per hit time. Is this a bug?

[Erotemic]

I noticed something similar today in my own use. Because I'm not the original author, I'm not sure if this is intended behavior or not. If someone want's to dig into this, it would be good to have docs on why this happens.

[embray]

I just discovered this as well. It seems to be a regression because I was comparing the same code on Python 2 (with line_profiler < 3.0) and on Python 3 with latest version, and this did not happen on the Python 2 version.

Relatedly it seems on Python 2 the first line does not have any time recorded, whereas on Python 3 it shows the full time for that line but it's double-counted, leading to misleading results.

Not sure if this is part of an intentional change or not. Will investigate further...

[Erotemic]

@embray Thank you for the additional details. Any further contribution on this issue would be very much appreciated. :) I don't have a firm grasp on the issue.

There is also a chance that the bug was fixed in the 4.0 branch: #165 but it hasn't been verified either way.

[embray]

From what I can tell it kind of makes sense. The first count is from any sub-expressions on the first physical line (typically ~0us if it's just something like x = func(), while the second count is for the entire logical expression/statement.

A little confusing but makes sense in a way. Maybe just a documentation patch is sufficient. But I'll try the 4.0 branch.

[Theelx]

There is also a chance that the bug was fixed in the 4.0 branch: #165 but it hasn't been verified either way.

Actually, I was investigating a difference in reported line hits on some random programs in my personal test suite between v3 line_profiler and the potential v4, and I wonder if this could be the cause. I originally figured v4 had a bug, but if this is actually happening in v3, then I'm fairly sure v4 fixes the bug.

[usbhub]

I'm still having this issue with line-profiler 4.1.2. Seems to me like a bug as just separating arguments onto a new line to reduce line width will make the hits double counted and half the real per hit time.

[Rainlin007]

I'm still having this issue with line-profiler 4.1.3.