source: release/1.2/source/library/oprofile.txt @ 9204

Using the Linux oprofile system-level profiler with CCL
=======================================================

'oprofile' (<http://oprofile.sourceforge.net>) 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 regiions.  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
-------------

1) oprofile itself, which is almost certainly available via your
distributions's package management system if not already preinstalled.
2) 'libelf', which provides utilities for reading and writing ELF
files (and is likewise likely preinstalled or readily installable.)

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) Generating 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>

I think that we can conclude that (FACT 10000) mostly involves multiplying
bignums by small fixnums.

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 compilations scenarios.  That's obviously more nearly
The Right Thing, but it might be awhile before that experimental code
makes it into widespread use.