3 ms·

I can understand this approach, but I fundamentally disagree with it - the first duty of a profiling tool is not to mislead the user. In this example, the prog

I can understand this approach, but I fundamentally disagree with it - the first duty of a profiling tool is not to mislead the user. In this example, the program spends a third of the time just sleeping / blocked, a third of the time on CPU but at the C level, and the remainder just evaluating Python loops. Unless you already know how it's implemented, that 33.66% is not easy to interpret, and the docs don't mention what exactly is being profiled. Specifically, these samples aren't a % of CPU time, they're a % of real time that we happened to have been able to do a Python-level interrupt, and even that isn't a great explanation. I think most users would still expect line 22 to get traced properly. I very much do want to know about C time, too, because it's very much actionable for most of the optimizations I end up making in production systems. That said, I don't think this line of discussion is super productive for either of us, we seem to have different goals in mind, which is fine. ;) So I'll close by saying that I was impressed by your LD_PRELOAD hacks for memory profiling, which isn't an approach that I've ever seen in other Python profilers.

emeryberger 7y ago
Re: being impressed by the memory profiling hacks, thanks! :) And you persuaded me. New version to be uploaded momentarily that attributes time to line 22. % python3 -m scalene sample-sample.py f1 1.8081 312499987500000 f2 1.7910 2812499962500000 f3 1.5034 1.5 sample-sample.py: % of CPU time = 70.53% out of 5.10s. Line | CPU % | [sample-sample.py] 1 | | #!/usr/bin/env python 2 | | 3 | | import time 4 | | 5 | | def timed(f): 6 | | def f_timed(*args, **kwargs): 7 | | t = time.time() 8 | | r = f(*args, **kwargs) 9 | 0.32% | t = time.time() - t 10 | | print('%s %.4f %s' % (f.__name__, t, r)) 11 | | return f_timed 12 | | 13 | | @timed 14 | | def f1(n): 15 | | s = 0 16 | 8.58% | for i in range(n): 17 | 41.34% | s += i 18 | | return s 19 | | 20 | | @timed 21 | | def f2(n): 22 | 49.76% | return sum(range(n)) 23 | | 24 | | @timed 25 | | def f3(t): 26 | | time.sleep(t) 27 | | return t 28 | | 29 | | if __name__ == '__main__': 30 | | f1(25000000) 31 | | f2(75000000) 32 | | f3(1.5)
- emeryberger 7y ago
  This discussion inspired me to refine Scalene's output further. Scalene now separates out CPU time spent in Python from time spent in C (that is, not executing in the interpreter). I think this is the best of both worlds: all CPU time is accounted for, and it's easy for users to see what code is running where. Thanks! sample-sample.py: % of CPU time = 99.58% out of 3.34s. | CPU % | CPU % | Line | (Python) | (C) | [sample-sample.py] -------------------------------------------------------------------------------- 1 | | | #!/usr/bin/env python 2 | | | 3 | | | import time 4 | | | 5 | | | def timed(f): 6 | | | def f_timed(*args, **kwargs): 7 | | | t = time.time() 8 | | | r = f(*args, **kwargs) 9 | | | t = time.time() - t 10 | | | print('%s %.4f %s' % (f.__name__, t, r)) 11 | | | return f_timed 12 | | | 13 | | | @timed 14 | | | def f1(n): 15 | | | s = 0 16 | 6.61% | 0.41% | for i in range(n): 17 | 35.17% | 3.97% | s += i 18 | | | return s 19 | | | 20 | | | @timed 21 | | | def f2(n): 22 | 0.30% | 53.53% | return sum(range(n)) 23 | | | 24 | | | @timed 25 | | | def f3(t): 26 | | | time.sleep(t) 27 | | | return t 28 | | | 29 | | | if __name__ == '__main__': 30 | | | f1(25000000) 31 | | | f2(75000000) 32 | | | f3(1.5)
  - gshulegaard 7y ago
    Just wanted to take a moment to appreciate the awesome response to feedback and new added feature.
    - kinow 7y ago

emeryberger 7y ago

Re: being impressed by the memory profiling hacks, thanks! :) And you persuaded me. New version to be uploaded momentarily that attributes time to line 22. % python3 -m scalene sample-sample.py f1 1.8081 312499987500000 f2 1.7910 2812499962500000 f3 1.5034 1.5 sample-sample.py: % of CPU time = 70.53% out of 5.10s. Line | CPU % | [sample-sample.py] 1 | | #!/usr/bin/env python 2 | | 3 | | import time 4 | | 5 | | def timed(f): 6 | | def f_timed(*args, **kwargs): 7 | | t = time.time() 8 | | r = f(*args, **kwargs) 9 | 0.32% | t = time.time() - t 10 | | print('%s %.4f %s' % (f.__name__, t, r)) 11 | | return f_timed 12 | | 13 | | @timed 14 | | def f1(n): 15 | | s = 0 16 | 8.58% | for i in range(n): 17 | 41.34% | s += i 18 | | return s 19 | | 20 | | @timed 21 | | def f2(n): 22 | 49.76% | return sum(range(n)) 23 | | 24 | | @timed 25 | | def f3(t): 26 | | time.sleep(t) 27 | | return t 28 | | 29 | | if __name__ == '__main__': 30 | | f1(25000000) 31 | | f2(75000000) 32 | | f3(1.5)

emeryberger 7y ago
This discussion inspired me to refine Scalene's output further. Scalene now separates out CPU time spent in Python from time spent in C (that is, not executing in the interpreter). I think this is the best of both worlds: all CPU time is accounted for, and it's easy for users to see what code is running where. Thanks! sample-sample.py: % of CPU time = 99.58% out of 3.34s. | CPU % | CPU % | Line | (Python) | (C) | [sample-sample.py] -------------------------------------------------------------------------------- 1 | | | #!/usr/bin/env python 2 | | | 3 | | | import time 4 | | | 5 | | | def timed(f): 6 | | | def f_timed(*args, **kwargs): 7 | | | t = time.time() 8 | | | r = f(*args, **kwargs) 9 | | | t = time.time() - t 10 | | | print('%s %.4f %s' % (f.__name__, t, r)) 11 | | | return f_timed 12 | | | 13 | | | @timed 14 | | | def f1(n): 15 | | | s = 0 16 | 6.61% | 0.41% | for i in range(n): 17 | 35.17% | 3.97% | s += i 18 | | | return s 19 | | | 20 | | | @timed 21 | | | def f2(n): 22 | 0.30% | 53.53% | return sum(range(n)) 23 | | | 24 | | | @timed 25 | | | def f3(t): 26 | | | time.sleep(t) 27 | | | return t 28 | | | 29 | | | if __name__ == '__main__': 30 | | | f1(25000000) 31 | | | f2(75000000) 32 | | | f3(1.5)
- gshulegaard 7y ago
  Just wanted to take a moment to appreciate the awesome response to feedback and new added feature.
  - kinow 7y ago