Scalene: a high-performance, high-precision CPU and memory profiler for Python
github.com
github.com
To wit:
$ python -m scalene trace.py
f1 1.3852 312499987500000
f2 1.2420 2812499962500000
f3 1.5018 1.5
trace.py: % of CPU time = 33.66% out of 4.13s.
Line | CPU % | [trace.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 | 17.99% | for i in range(n):
17 | 81.29% | s += i
18 | | return s
19 | |
20 | | @timed
21 | | def f2(n):
22 | 0.72% | 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(25_000_000)
31 | | f2(75_000_000)
32 | | f3(1.5)In short, a profiler that tells me that a program is spending a lot of time in C is not generally providing me particularly actionable information.
(In any event, the top-line report is that the Python part of the program only accounts for 33.66% of the execution time, which looks just about right.)
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.
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) 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)Kudos to everyone involved.
Thanks for being good with my grumpy feedback!
One profiler I used recently which isn't mentioned in the readme is pyflame (developed at uber):
https://pyflame.readthedocs.io/
pyflame likewise claims to run on unmodified source code and be fast enough to run in production, so it might be worth adding to the comparison. It generates flamegraphs, which greatly sped up debugging the other day when I needed to figure out why something was slow somewhere in a Django request-response callstack.
> While pyflame is a great project, it doesn't support Python 3.7 yet and doesn't work on OSX, Windows or FreeBSD.
I wonder how the CPU profiling in Scalene is different. It does not mention PyFlame or py-spy at all in the Readme. Of course, the memory profiler is some nice extra.
My team has a large body of profiling code written with kernprof and none of it modifies the underlying source. Profiler annotations are solely added automatically by the little profiler runner tooling we wrote.
Not to say other profiling tools aren’t worth it.
Pyflame: A Ptracing Profiler For Python. This project is deprecated and not maintained
I don't know how it's statistical profiling speed compares to scalene, but it would be great to see the comparison.
Also, does anyone know how the malloc interacts with pytorch?