bawr_hszm

Loading data before you fork works pretty well, but the overall effectiveness heavily depends on the type of data involved. If it's something like numpy arrays or similar large, indivisible objects, you're golden. If you want to preload and share something like a huge nested Python dictionary or other large collections of small objects, you immediately collide with the reference counters.

Basically, since the reference count is kept right before the object data, as soon as the child process touches it - even just to look at it! - you immediately trigger a copy on write on the nearest 4k of memory, which tends to add up fast if you're not careful. Even if you never touch 99% of them, the garbage collector is happy to do it for you.

At my previous job it was bad enough that I ended up writing a small patch to be able to set some refcounts to 0xFF...FF and treat them specially, never changing their value. (Yes, this also meant that they never got destroyed properly, and the extra checks made our codebase around 4% slower, but it was an acceptable tradeoff. No, the patch was no longer small by the time it hit production.)

I like it, and I appreciate that you changed your mind - I'm still staunchly in the flamgraph camp of capturing and displaying whole stacks, but now I could see using this for small code samples, especially with the memory usage information added on top.

Thanks for being good with my grumpy feedback!

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.

Sadly, relying on Python's signal handling is not enough to get robust profiling information the moment your code is spending a significant chunk of time outside of simple Python calls. This is because signals don't get delivered to the Python level until the interpreter comes back from C land, and it's possible to get stuck in C land even with pure Python code.

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)