<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
  <head>
    <meta http-equiv="content-type" content="text/html;
      charset=ISO-8859-1">
  </head>
  <body text="#000000" bgcolor="#ffffff">
    Hello world,<br>
    <br>
    since I moved from Java development to Python development, I really
    miss the sampling profiler of jvisualvm (<a
      class="moz-txt-link-freetext" href="http://visualvm.java.net/">http://visualvm.java.net/</a>).


    Perhaps it is only me but especially for long running GUI
    applications, I would really like to know why it sometimes slows
    down to a crawl.<br>
    <br>
    cProfile is not really useful for this as it makes the software
    unresponsive alone. Also if using multiple threads (like doing some
    I/O in background, when using <a class="moz-txt-link-freetext"
      href="http://www.lag.net/paramiko/">http://www.lag.net/paramiko/</a>)
    it will give meaningless results.<br>
    <br>
    I looked for an existing profiler and found statprof, mentioned in
    this blog: <a class="moz-txt-link-freetext"
      href="http://wingolog.org/archives/2005/10/28/profiling">http://wingolog.org/archives/2005/10/28/profiling</a><br>
    <br>
    However, this still fails profiling multiple threads. I don't think
    one can do any better without touching the interpreter core. So
    that's what I tried...<br>
    <br>
    My approach implements the profiler from the following parts:<br>
    <ol>
      <li>Sample Trigger: A timer that triggers taking samples of all
        threads at fixed intervals.</li>
      <li>Sampling function injection: Ensures that a sampling function
        is called on each thread at the first opportunity after the
        sample trigger fired.</li>
      <li>Sampling function: A function that assigns the current time
        slice to the executing code on the thread it is called on.</li>
    </ol>
    Only the second part has to be implemented in the Python interpreter
    core, the sample trigger and sampling functions can be provided by
    external modules. My implementation of (2) can be found at <a
      class="moz-txt-link-freetext"
      href="https://bitbucket.org/bluehorn/sampling_prof">https://bitbucket.org/bluehorn/sampling_prof</a><br>
    <br>
    I also prepared a first implementation of (1) and (3) at <a
      class="moz-txt-link-freetext"
      href="https://bitbucket.org/bluehorn/profiler_util">https://bitbucket.org/bluehorn/profiler_util</a>.
    Using that library, I can profile pybench with a 3 % slowdown
    (taking 100 profiling samples per second):<br>
    <br>
    $ export PYTHON_PATH=$HOME/python-work/profiler_util<br>
    $ python3 -m sampling_profiler -- Tools/pybench/pybench.py -c
    stock.pybench -f prof.pybench<br>
    [...]<br>
    Totals:                          3119ms  3072ms   +1.5%  3198ms 
    3108ms   +2.9%<br>
    <br>
    This also shows that the string benchmark takes the most time:<br>
    <tt><br>
      Thread MainThread (3842 samples, 38.434401 seconds)<br>
------------------------------------------------------------------------<br>
      cpu_time    (cum)  ticks  (cum) samples (cum)
      filename:lineno                          function<br>
         0.548    0.548     55     55     55     55
      Tools/pybench/Strings.py:455             test<br>
         0.448    0.448     45     45     45     45
      Tools/pybench/Strings.py:568             calibrate<br>
         0.428    0.428     43     43     43     43
      Tools/pybench/Constructs.py:484          test<br>
         0.380    0.380     38     38     38     38
      Tools/pybench/Calls.py:445               f<br>
         0.324    0.324     34     34     34     34
      Tools/pybench/Calls.py:122               f<br>
    </tt><br>
    The output is explained as follows:<br>
    <br>
    cpu_time: cpu time in seconds accounted to that line.<br>
    (cum): This is the cpu time including the cumulative time of the
    functions called on that line. Gathering that data means that the
    sampling function has to walk the stack for each sample, which will
    cause a dramatic slowdown for deeply recursive calls. There should
    be a switch to disable this.<br>
    ticks: Number of sampling profiler ticks accounted to that line. For
    my example (where sample ticks are equidistant in wall time) this is
    a measure of the time spent in that line, including any blocking
    calls (especially I/O).<br>
    (cum): ... including called functions<br>
    samples: Number of times the sampling profiler function was called
    for that line. This should equal ticks unless execution of that line
    took longer than a profiler tick.<br>
    <br>
    The remaining output should be obvious.<br>
    <br>
    I have to admit that this is far from finished, but I hope to get
    some feedback and perhaps even help by posting it here.<br>
    <br>
    What do you think?<br>
    <br>
    Greetings, Torsten<br>
    <br>
  </body>
</html>