# Profiling

## Using the Linux oprofile system-level profiler

`oprofile` is a system-level profiler that's available for most modern Linux distributions.

Use of oprofile and its companion programs isn't really documented here; what is described is a way of generating symbolic information that enables profiling summaries generated by the `opreport` program to identify lisp functions meaningfully.

### Generating a lisp image for use with oprofile

Modern Linux uses the 'ELF" (Executable and Linking Format) object file format; the oprofile tools can associate symbolic names with addresses in a memory-mapped file if that file appears to be an ELF object file and if it contains ELF symbol information that describes those memory regions. So, the general idea is to make a lisp heap image that looks enough like an ELF shared library to fool the `oprofile` tools (we don't actually load heap images via ELF dynamic linking technology, but we can make it look like we did.)

### Prerequisites

- `oprofile` itself, which is almost certainly available via your distribution's package management system if not already preinstalled.

- `libelf`, which provides utilities for reading and writing ELF files (and is likewise likely preinstalled or readily installable.) Somewhat confusingly, there are two libelf implementations in widespread use on Linux, and different distributions refer to them by different names (they may be available as part of an 'elfutils' package.) The oprofile insterface was designed to work with a libelf implementation whose version number is currently around 147; the other (incompatible) libelf implementation has a version number around 0.8. It may be necessary to install the corresponding development package (-dev or -devel, usuallly) in order to actually be able to use the libelf shared library.

### Generating ELF symbols for Lisp functions

In order to create a lisp heap image which can be used for `oprofile`- based profiling, we need to:

1. load any code that we want to profile

2. generate a file that contains ELF symbol information describing the names and addresses of all lisp functions.

   This step involves doing (from within &CCL;)

       ? (require "ELF")
       "ELF"
       ("ELF")

       ? (ccl::write-elf-symbols-to-file "home:elf-symbols")

   The argument to CCL::WRITE-ELF-SYMBOLS-TO-FILE can be any writable pathname. The function will do whatever's necessary to nail lisp functions down in memory (so that they aren't moved by GC), then write an ELF object file to the indicated pathname. This typically takes a few seconds.

3. Generate a lisp heap image in which the ELF symbols generated in the previous step are prepended.

   The function CCL:SAVE-APPLICATION provides a :PREPEND-KERNEL argument, which is ordinarily used to save a standalone application in which the kernel and heap image occupy a single file. :PREPEND-KERNEL doesn't really care what it's prepending to the image, and we can just as easily ask it to prepend the ELF symbol file generated in the previous step.

       ? (save-application "somewhere/image-for-profiling"
           :prepend-kernel "home:elf-symbols")

   If you then run

       shell> ccl64 somewhare/image-for-profiling

   any lisp code sampled by oprofile in that image will be identified "symbolically" by `opreport`.

### Example

    ;;; Define some lisp functions that we want to profile and save
    ;;; a profiling-enabled image.  In this case, we just want to
    ;;; define the FACTORIAL funcion, to keep things simple.
    ? (defun fact (n) (if (zerop n) 1 (* n (fact (1- n)))))
    FACT
    ? (require "ELF")
    "ELF"
    ("ELF")
    ? (ccl::write-elf-symbols-to-file "home:elf-symbols")
    "home:elf-symbols"
    ? (save-application "home:profiled-ccl" :prepend-kernel "home:elf-symbols")

    ;;; Setup oprofile with (mostly) default arguments.  This example was
    ;;; run on a Fedora 8 system where an uncompressed 'vmlinux' kernel
    ;;; image isn't readily available.

    ;;; Note that use of 'opcontrol' generally requires root access, e.g.,
    ;;; 'sudo' or equivalent:

    [~] gb@rinpoche> sudo opcontrol --no-vmlinux --setup

    ;;; Start the profiler

    [~] gb@rinpoche> sudo opcontrol --start
    Using 2.6+ OProfile kernel interface.
    Using log file /var/lib/oprofile/samples/oprofiled.log
    Daemon started.
    Profiler running.

    ;;; Start CCL with the "profiled-ccl" image created above.
    ;;; Invoke "(FACT 10000)"

    [~] gb@rinpoche> ccl64 profiled-ccl
    Welcome to Clozure Common Lisp Version 1.2-r9198M-trunk  (LinuxX8664)!
    ? (null (fact 10000))
    NIL
    ? (quit)

    ;;; We could stop the profiler (opcontrol --stop) here; instead,
    ;;; we simply flush profiling data to disk, where 'opreport' can
    ;;; find it.

    [~] gb@rinpoche> sudo opcontrol --dump

    ;;; Ask opreport to show us where we were spending time in the
    ;;; 'profiled-ccl' image.

    [~] gb@rinpoche> opreport -l profiled-ccl | head
    CPU: Core 2, speed 1596 MHz (estimated)
    Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
    samples  %        symbol name
    6417     65.2466  <Compiled-function.(:INTERNAL.MULTIPLY-UNSIGNED-BIGNUM-AND-1-DIGIT-FIXNUM.MULTIPLY-BIGNUM-AND-FIXNUM).(Non-Global)..0x30004002453F>
    3211     32.6487  <Compiled-function.%MULTIPLY-AND-ADD4.0x300040000AAF>
    17        0.1729  <Compiled-function.%%ONE-ARG-DCODE.0x3000401740AF>
    11        0.1118  <Compiled-function.%UNLOCK-RECURSIVE-LOCK-OBJECT.0x30004007F7DF>
    10        0.1017  <Compiled-function.AUTO-FLUSH-INTERACTIVE-STREAMS.0x3000404ED6AF>
    7         0.0712  <Compiled-function.%NANOSLEEP.0x30004040385F>
    7         0.0712  <Compiled-function.%ZERO-TRAILING-SIGN-DIGITS.0x300040030F3F>

### Issues

CCL::WRITE-ELF-SYMBOLS-TO-FILE currently only works on x86-64; it certainly -could- be made to work on ppc32/ppc64 as well.

So far, no one has been able to make oprofile/opreport options that're supposed to generate call-stack info generate meaningful call-stack info.

As of a few months ago, there was an attempt to provide symbol info for oprofile/opreport "on the fly", e.g., for use in JIT compilation or other incremental compilation scenarios. That's obviously more nearly The Right Thing, but it might be awhile before that experimental code makes it into widespread use.

## Using Apple's CHUD metering tools

Apple's CHUD package provides libraries, kernel extensions, and a set of graphical and command-line programs that can be used to measure many aspects of application and system performance.

One of these programs is the Shark application (often installed in "/Developer/Applications/Performance Tools/Shark.app"), which provides a graphical user interface for exploring and analyzing profiling results and provides tools for creating "sampling configurations" (see below), among other things. Use of Shark isn't really documented here (a Shark manual is available at "Developer/Documentation/CHUD/Shark/ SharkUserGuide.pdf"); what is described is a way of providing information about Lisp function names and addresses so that Shark can meaningly identify those functions in its output.

### Prerequisites

Apple's CHUD tools have been distributed with the last several XCode releases. One way to determine whether or not the tools are installed is to run:

    $ /usr/bin/shark -v

in a terminal or Emacs shell buffer. If that returns output like

    shark 4.7.3 (365)

then the CHUD package is installed. Output like

    shark: Command not found.

strongly suggests that it isn't ...

### Generating a lisp image for use with Shark

Shark can only properly identify functions that're defined in a shared library that's loaded by the target application. (Any other functions will be identified by a hex address described as being in an "Unknown Library"; the hex address is generally somewhat near the actual function, but it's determined heuristically and isn't always accurate.)

For those reasons, it's desirable to load the code that you wish to profile in one lisp session, save a native (Mach-O library) image, and invoke Shark in a new session which uses that native image. (It may also be useful to load the CHUD-METERING module, which defines CHUD:METER and friends.

### Usage synopsis

    [src/ccl-dev] gb@antinomial> ccl64
    Welcome to Clozure Common Lisp Version 1.7-dev-r14624M-trunk  (DarwinX8664)!
    ? (defun fact(n) (if (zerop n) 1 (* n (fact (1- n)))))
    FACT
    ? (require "CHUD-METERING")
    "CHUD-METERING"
    ("CHUD-METERING")
    ? (save-application "ccl:dx86cl64.dylib" :native t)
    [src/ccl-dev] gb@antinomial> ccl64 -I dx86cl64.dylib
    Welcome to Clozure Common Lisp Version 1.7-dev-r14624M-trunk  (DarwinX8664)!
    ? (chud:meter (dotimes (i 1000) (fact 1000)))
    ;;; Waiting for shark to process samples ...done.
    NIL

and, a few seconds after the result is returned, a file whose name is of the form "session_nnn.mshark" will open in Shark.app.

The fist time that CHUD:METER is used in a lisp session, it'll do a few things to prepare subsequent profiling sessions. Those things include:

- creating a directory to store files that are related to using the CHUD tools in this lisp session. This directory is created in the user's home directory and has a name of the form:

      profiling-session-<lisp-kernel>-<pid>_<mm>-<dd>-<yyyy>_<h>.<m>.<s>

- run the shark program ("/usr/bin/shark") and wait until it's ready to receive signals that control its operation.

This startup activity typically takes a few seconds; after it's been completed, subsequent use of CHUD:METER doesn't involve that overhead. (See the discussion of :RESET below.)

After any startup activity is complete, CHUD:METER arranges to send a "start profiling" signal to the running shark program, executes the form, sends a "stop profiling" signal to the shark program, and reads its diagnostic output, looking for the name of the ".mshark" file it produces. If it's able to find this filename, it arranges for "Shark.app" to open it.

### Profiling "configurations"

By default, a shark profiling session will:

- use "time based" sampling, to periodically interrupt the lisp process and note the value of the program counter and at least a few levels of call history.

- do this sampling once every millisecond

- run for up to 30 seconds, unless told to stop earlier.

This is known as "the default configuration"; it's possible to use items on the "Config" menu in the Shark application to create alternate configurations which provide different kinds of profiling parameters and to save these configurations in files for subsequent reuse. (The set of things that CHUD knows how to monitor is large and interesting.)

You use alternate profiling configurations (created and "exported" via Shark.app) with CHUD:METER, but the interface is a little awkward.

### Reference

``CHUD:*SHARK-CONFIG-FILE*` [Variable]`

When non-null, this should be the pathname of an alternate profiling configuration file created by the "Config Editor" in Shark.app.

``CHUD:METER` form &key; (reset nil) (debug-output nil) [Macro]`

Executes FORM (an arbitrary lisp form) and returns whatever result(s) it returns, with CHUD profiling enabled during the form's execution. Tries to determine the name of the session file (*.mshark) to which the shark program wrote profiling data and opens this file in the Shark application.

Arguments:

`debug-output`

  when non-nil, causes output generated by the shark program to be echoed to *TERMINAL-IO*. For debugging.

`reset`

  when non-nil, terminates any running instance of the shark program created by previous invocations of CHUD:METER in this lisp session, generates a new .spatch file (describing the names and addresses of lisp functions), and starts a new instance of the shark program; if CHUD:*SHARK-CONFIG-FILE* is non-NIL when this new instance is started, that instance is told to use the specified config file for profiling (in lieu of the default profiling configuration.)

### Acknowledgement

Both Dan Knapp and Hamilton Link have posted similar CHUD interfaces to openmcl-devel in the past; Hamilton's also reported bugs in the spatch mechanism to CHUD developers (and gotten those bugs fixed.)