GOPHERSPACE.DE - P H O X Y
gophering on hngopher.com
HN Gopher Feed (2017-12-18) - page 1 of 10
 
___________________________________________________________________
How do Ruby and Python profilers work?
88 points by ingve
https://jvns.ca/blog/2017/12/17/how-do-ruby---python-profilers-w...
___________________________________________________________________
 
richardwhiuk - 2 hours ago
  > 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.  I'm not
convinced this is the main disadvantage of tracing profilers. The
main disadvantage is that the perf impact tends to be much more
severe.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.
 
  unwind - 1 hours ago
  Please don't indent, it doesn't work to make block quotes. The
  qoute is very hard to read on mobile.Use asterisks around the
  paragraph, that renders as italics.Thanks.
 
  masklinn - 2 hours ago
  > The main disadvantage is that the perf impact tends to be much
  more severe.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.
 
trentnelson - 2 hours ago
I guess this is as good a time as any to make my post-PyParallel
pet project public (holy alliteration Batman):
https://github.com/tpn/tracer.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", andc) 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/tra
cer/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...).
 
  chubot - 2 hours ago
  Hm interesting -- what parts of it are tied to Windows?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 vi
  deo:https://www.reddit.com/r/ProgrammingLanguages/comments/7djre.
  ..
 
    trentnelson - 2 hours ago
    > Hm interesting -- what parts of it are tied to Windows?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.)
 
wdewind - 3 hours ago
One of the things that makes Ruby so difficult to profile is that
in order to do anything really fun (like get memory usage, for
instance), you need to shell out, which means you're
forking/doubling your memory footprint immediately, which means you
probably can't do this in production.  This is especially
frustrating because by far the biggest issue you'll have with a
Ruby (especially Rails) app is memory usage, so trying to pinpoint
what of the many things that are currently running on your box are
blowing up your memory can be non-trivial.
 
  semiquaver - 3 hours ago
  On linux you can get a process' memory usage by reading the
  `/proc` pseudo-filesystem.  See [0], which uses that approach
  when supported.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.[0]
  https://github.com/schneems/get_process_mem[1]
  https://github.com/rtomayko/posix-spawn
 
  jvns - 3 hours ago
  Why do you have to fork to get a memory profile? I don't know
  anything about memory profiling yet (I collected a bunch of links
  in
  https://gist.github.com/jvns/b81eb039f6373bc577d7dbdd978581b...
  but haven't read their source yet) but I'd like to know more. It
  seems like it should be possible to get a memory profile in
  production without a prohibitive amount of overhead though.Also,
  I believe forking shouldn't actually double memory usage because
  of copy on write.
 
    [deleted]
 
    wdewind - 3 hours ago
    Ruby can't tell how much memory it is using from within the
    process, the only way to is shell out and scrape the output of
    ps.  I would love to be wrong about this, I did a fair amount
    of research and all the profiling libraries I read used this
    method.  One thing I've done instead is use object allocation,
    which is available from the builtin benchmarker, as a proxy for
    memory usage.  I don't have a good sense of how accurate that
    is, but anecdotally it seemed useful and correlated to stuff
    like page load times.(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.
 
      TheDong - 2 hours ago
      I don't have much experience in ruby profiling, but what
      you're saying doesn't make sense.> the only way to is shell
      out and scrape the output of psAll `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.
 
        wdewind - 2 hours ago
        > 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.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-...
 
      [deleted]
 
      sciurus - 2 hours ago
      Run the code snippet below to prove to yourself that a Ruby
      process can get its memory usage.    print
      File.readlines('/proc/self/status').select {|line| line =~
      /VmRSS/}[0]  This is not what people mean when they talk
      about memory profiling, but it looked like what you were
      talking about, so I thought I'd share it.
 
      anarazel - 2 hours ago
      > the only way to is shell out and scrape the output of psWhy
      couldn't you just read /proc/self/status and /proc/self/smaps
      in process? Would be like an order of magnitude less
      expensive.
 
        wdewind - 2 hours ago
        Because I have a shitty knowledge of Unix :)Best way to get
        the right answer on the internet is to post the wrong one.
 
ekimekim - 1 hours ago
An amazing part of sampling-based profilers: They're so low
overhead, you can leave them on permanently in production. And
since all they're taking is counts, you can combine results from
multiple instances very easily. Put this together and it forms an
easy, highly insightful part of your production monitoring systems.
Notice a service being slow? You can instantly see its live
flamegraph, check a function's average runtime over time, etc.
 
blt - 2 hours ago
As far as I can tell, there's not much of a reason to use an
instrumenting profiler over a sampling one. Is there some niche use
case? Maybe to experimentally validate some claim about average
case computational complexity?
 
  viraptor - 2 hours ago
  Catching the runtime of a function that's executed very
  infrequently for example and has execution time extremely
  dependent on the context. (Which makes an isolated reproducer
  hard to achieve)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.
 
    sciurus - 42 minutes ago
    If that fast function is called enough to "add up", it should
    show up in the statistical profiler's samples. The likelihood
    of a function being sampled is influenced by the cumulative run
    time of all its calls, not the run time of an individual call.
 
  hyperpape - 1 hours ago
  I don't use tracing much because it produces such bad results,
  but I often find myself looking at a profile and thinking "I
  really wish I knew how many times this method was called".
 
viraptor - 1 hours ago
I'm surprised that no system-wide tracers were included (unless I
missed something?). You can use dtrace / systemtap with both ruby
and python (>=3.6). You still have to extract the bits you're
interested in, but the hooks for function entry/exit and GC are
exposed, so you can effectively add a targeted profiler/tracer at
runtime.
 
sciurus - 2 hours ago
This is a really nice blog post! It covers the ecosystem well and
goes into the right level of detail to help someone unfamiliar with
the tools understand how they work.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...
 
alex- - 51 minutes ago
It might be interesting to some to know that relatively recently
(2016) PEP 523 ( https://www.python.org/dev/peps/pep-0523/ ) was
created which provides a more efficient alternative to
PyEval_SetTrace or PyEval_SetProfile for some use cases.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 ).