How do Ruby and Python profilers work?
jvns.ca
jvns.ca
new Thread('sampler') {
run() {
while (true) {
samples.add(Thread.getAllStackTraces());
Thread.sleep(1ms);
}
}
}.start();
For C/C++ program you can use signals to implement the above. That's how the Firefox profiler works.
The idea of this PEP is to add frame evaluation into cPython. As the PEP says "For instance, it would not be difficult to implement a tracing or profiling function at the call level with this API"
Elizaveta Shashkova (a PyCharm developer at JetBrains) gave a really good talk on the subject at this years PyCon ( https://www.youtube.com/watch?v=NdObDUbLjdg ).
At PyOhio I gave a hastily-prepared lighting talk on building a statistical profiler in Python. I'll link to it here because, although going in much less detail than Julia's post, it shows a visualization technique and an example of the sort of payoff you get from profiling.
https://www.polibyte.com/2017/08/05/building-statistical-pro...
> The main disadvantage of tracing profilers implemented in this way is
> that they introduce a fixed amount for every function call / line of code
> executed. This can cause you to make incorrect decisions! For example, if
> you have 2 implementations of something – one with a lot of function calls
> and one without, which take the same amount of time, the one with a lot of
> function calls will appear to be slower when profiled.
It's theoretically possible to mitigate the problem identified (keep track of how much time you spend profiling, and reduce the time tracked spent in the function by that amount). However, it's harder to have a tracing profiler which only profiles some functions, and harder to specify those.
The nice thing about sampling profiles is that it's very easy to configure the performance impact and easy to get a good sample by just running for longer.
That is an annoyance but not an issue. A 3x performance degradation, or even a 10x one, can be very annoying. But that performance degradation is uneven means profiling is unreliable, and that's a problem I've had semi-frequently with tracing profilers: the function call counts are reliable, but the timings/percentages aren't always, and you may see a hotspot under profiler, optimise it to the hilt, run without profiling and… nothing changed. Because the hotspot was mostly a profiler artefact.
Use asterisks around the paragraph, that renders as italics.
Thanks.
But it's still a very interesting blog post !
I started it about 2.5 years ago because I wasn't really happy with existing Python tracing tools. I didn't like:
a) the performance hit when tracing non-trivial programs,
b) the inability to say: "hey, trace all code living in modules mymodule1 and mymodule2; ignore everything else", and
c) the inability to say: "screw it, trace everything", and have an efficient means to persist tens of gigabytes worth of data (i.e. don't separate in-memory representation from on-disk representation).
So I came up with this tracing project, creatively named: tracer.
It has relatively low overhead, efficiently and optimally persists tens of gigabytes worth of data to disk with minimal overhead, and allows for module-based tracing directives so that you can capture info about your project and ignore all the other stuff (like stdlib and package code).
Like all fun pet projects, once the easy stuff was done, this one devolved into writing assembly to do remote thread injection (https://github.com/tpn/tracer/blob/master/Asm/InjectionThunk...), coming up with new "string table" data structure as an excuse to use some AVX2 intrinsics (https://github.com/tpn/tracer/blob/master/StringTable/Prefix...), and writing a sqlite3 virtual table interface to the flat-file memory maps, complete with CUDA kernels (https://github.com/tpn/tracer/blob/master/TraceStore/TraceSt...).
Edit: something pretty fascinating I observed in the wild when running this code: a tracing-enabled Python run of a large project ran faster than a normal, non-traced version of Python in a low-memory environment (a VM with 8GB of RAM). My guess is that splaying the PyCodeObject structures each frame invocation has the very beneficial side effect of reducing the likelihood the OS swaps the underlying pages out at a later date (https://github.com/tpn/tracer/blob/master/Python/PythonFunct...).
I recently strated playing with uftrace, a tracing framework for C++ using instrumented binaries. I got it working on CPython and I like it so far.
The CLI seems to be well done. I haven't looked in detail your tracer (a README would help), but maybe there are some ideas that can be exchanged.
This thread has a link to the repo and a video:
https://www.reddit.com/r/ProgrammingLanguages/comments/7djre...
If I had to guess... I'd say... almost all of it? :-)
I like systems programming in C on NT these days far more than Linux systems programming. Once you've gotten used to how NT does I/O and threading, it's tough to look back. Sure is lonely going against the grain, though.
(Just added a README, in that I copy and pasted some notes I wrote a month or so ago into a text file. I'll add more stuff (you know, like, instructions) soon.)
Does this mean the PyParallel is dead?
Or finding out about a tiny function which is called thousands of times and adds up over time, but each execution is so fast you rarely ever see it on a sample profile.
This can be messed with in a bunch of ways - aggressive inlining, being further subdivided because it's a template...
- Finding where we checked a file for modification on the main thread every few seconds, to consider reloading resources, causing us a 5ms spike that would sometimes cause us to miss vsync.
- Spotting a framerate hitch caused by the main thread stalling out on a contested logging lock under some specific set of circumstances for a frame or two.
- Spotting frames where overly aggressive background jobs simply starved the main thread out of CPU cycles.
- Which specific subanimations of a set (complete with names because I'm using an explicit API that lets me annotate them) are causing our optimization code to exhibit O(scary) behavior.
There's nothing here that you couldn't eventually figure out and solve with a debugger and a sampling profiler, but instrumenting profilers - and profiler APIs that let you add your own annotations - make the job way easier in my experience.
You're correct that production ruby applications should try to avoid calling fork() at runtime, which excludes all the standard library mechanisms for shelling out. posix-spawn [1] is an alternative that works well.
Also, I believe forking shouldn't actually double memory usage because of copy on write.
(Edit: ^happily I am wrong about this, though I believe the copy on write thing below is still correct, see further discussion)
Copy on write does definitely help here, only for Ruby > 2.0.
Why couldn't you just read /proc/self/status and /proc/self/smaps in process? Would be like an order of magnitude less expensive.
Best way to get the right answer on the internet is to post the wrong one.
> the only way to is shell out and scrape the output of ps
All `ps` is doing is reading files in proc. The memory info it prints is in `/proc/$pid/status`. Ruby can trivially read `/proc/self/status` to get that very naive view of how much memory it's using.
That isn't a useful amount of memory because, well, it doesn't actually show where object allocations go.
> Copy on write does definitely help here, only for Ruby > 2.0.
I believe she meant the operating system's copy-on-write of memory. Forking a copy of a process is actually very cheap because it's copy-on-write. That has nothing to do with ruby or its version and has been true in linux for as long as linux has existed.
I really don't understand what you're trying to say or why you mention ps at all.
Yep, great point, I am simply wrong about this.
> I believe she meant the operating system's copy-on-write of memory. Forking a copy of a process is actually very cheap because it's copy-on-write. That has nothing to do with ruby or its version and has been true in linux for as long as linux has existed.
Re: Copy on write the way Ruby implements GC in < 2.0 screws this up:
> The way ruby creates objects, the GC flag or reserved bit is stored in the object itself. So, as you would have guessed by now, when the GC runs in one of the processes, the GC flag would be modified in all the objects even if they are present in the shared pool. Now, the OS would sense this and trigger a copy-on-write making private copies of the objects in each child’s memory space.
https://medium.com/@rcdexta/whats-the-deal-with-ruby-gc-and-...
print File.readlines('/proc/self/status').select {|line| line =~ /VmRSS/}[0]