[Openmcl-devel] profiler

[John Carroll]

Here are a couple of old posts about a more elaborate sampling profiler I implemented some years ago:

lisp.mcl.general
Re: MCL profiler?
http://osdir.com/ml/lisp.mcl.general/2002-11/msg00022.html

Openmcl-devel
Profiling with profile.lisp in CCL?
https://lists.clozure.com/pipermail/openmcl-devel/2009-June.txt

I originally implemented this profiler in Macintosh CL and then ported it to Clozure CL in 2011. It's at http://users.sussex.ac.uk/~johnca/profile.lisp

The profiler is modelled on the one in Allegro Common Lisp, and provides information not just about the functions at the top of the stack but about the contexts in which they were called. This gives a better idea of the code that is actually taking the time. In the example below, the internal function CCL::>-2 finds itself at the top of the stack 85% of the time, and it's there because CCL::FIXNUM-SFLOAT-COMPARE is taking 79% of the execution time. 

? (pro:with-profiling (loop for i from 1 to 1e8 sum i))
Execution time profile from 4304 samples
  Parents
Function
  Children                                  Relative  Absolute
----
CCL::>-2                                                   85%
  CCL::FIXNUM-SFLOAT-COMPARE                     79%
  CCL::INTEGER-DECODE-SHORT-FLOAT                 5%
  CCL::%TRUNCATE-SHORT-FLOAT->FIXNUM              3%
  CCL::%INT-TO-SFLOAT                             1%
----
  CCL::>-2                                       98%
CCL::FIXNUM-SFLOAT-COMPARE                                 69%
  CCL::INTEGER-DECODE-SHORT-FLOAT                40%
  CCL::FIXNUM-DECODE-SHORT-FLOAT                  5%
----
  CCL::FIXNUM-SFLOAT-COMPARE                     86%
  CCL::>-2                                       14%
CCL::INTEGER-DECODE-SHORT-FLOAT                            32%
  CCL::FIXNUM-DECODE-SHORT-FLOAT                 47%
  LSH                                             5%
  CCL::SINGLE-FLOAT-BITS                          2%
----
  CCL::INTEGER-DECODE-SHORT-FLOAT                79%
  CCL::FIXNUM-SFLOAT-COMPARE                     21%
CCL::FIXNUM-DECODE-SHORT-FLOAT                             19%
  LSH                                            38%
----
  CCL::FIXNUM-DECODE-SHORT-FLOAT                 84%
  CCL::INTEGER-DECODE-SHORT-FLOAT                16%
LSH                                                         8%
----
  CCL::>-2                                      100%
CCL::%TRUNCATE-SHORT-FLOAT->FIXNUM                          2%
----
  CCL::>-2                                      100%
CCL::%INT-TO-SFLOAT                                         1%
----
  CCL::INTEGER-DECODE-SHORT-FLOAT               100%
CCL::SINGLE-FLOAT-BITS                                      1%
5000000050000000

BUT... this profiler can cause invalid memory operation errors. I think this is due to the fact that it conses in order to collect information about the call stack, and this consing activity does not interact well with CCL memory management.

I would be very happy if someone could fix this problem or could devise a different approach that outputs similar information.

John


On 1 Aug 2016, at 15:30, R. Matthew Emerson <rme at clozure.com> wrote:

> Max Rottenkolber took little snippet of code that I wrote and polished it up and documented it, and I thought some of you might find it interesting or useful if you haven't seen it yet.
> 
> Max says:
> 
> Still, my search was not in vain. rme sent me a very helpful paste, whose contents he described as “a crude userland-based sampling profiler”. Here is how it works: it peeks into the call stack of a running process repeatedly to find out which function is being run, and counts how often it finds the process busy with a given function. With the collected information it can then report an estimate of where time is spent.
> 
> 
> http://mr.gy/blog/sam.html
> 
> https://github.com/eugeneia/sam