How slow is Java reflection?

I use Java reflection for trace analysis, as a way to call hooks when specific events are encountered. I wanted to know the overheard related to using such dynamic invocation. First, here is a small example of a trace event handler.

public class FooTraceEventHandler extends TraceEventHandlerBase {

  public FooTraceEventHandler() {
    super();
    this.hooks.add(new TraceHook("sched_switch"));
  }

  public void handle_sched_switch(TraceReader reader,
                                  CtfTmfEvent event) {
    // Process event
  }
}

By convention, the function "handle_sched_switch" is called only with an instance of "sched_switch" event as argument. The magic happens by first getting a reference the method by it's name (done once), and then call it dynamically later in the processing path, similar to the following small example.

method = dummy.getClass().getMethod("foo", (Class[]) null);
...
method.invoke(dummy);

To compare dynamic invocation to compile-time method call, I did a trivial benchmark program. Here are the results for 10 billion calls.

StaticMethodBenchmark     9,653000
DynamicMethodBenchmark    47,625000

This experiment shows that dynamic invocation is roughly 5x slower than compile-time method call. Dynamic invocations is also weaker, because a missing method for the corresponding hook will be detected only at runtime.

There are benefits to using hooks. The test for the event type is done only once for all handlers. It avoid quite a lot of repetition. Also, it allows to list events required for a specific analysis, and then enable only this subset in the tracing session, reducing the runtime overhead and the trace size compared to enabling all events. So, we need to preserve these properties, but with compile-time invocations.

How-to setup LTTng on Fedora 19

Here is how to install lttng including kernel and userspace tracing on Fedora 19 beta.

Instructions uses sudo. To configure sudo on your fedora system, use this command as root, and replace  [username] with your username, then logout and login again:

usermod [username] -a -G wheel

1 Build and install kernel modules

1.1 Perform any pending updates:

sudo yum update

If the kernel is updated, reboot the machine.

1.2 Install development tools:

sudo yum group install "Development tools"

1.3 Fix kernel headers location

At the time of writing this How-to, the version of the kernel-devel package doesn't exactly matches the running kernel (uname -r). We worked around this issue by copying headers in the directory matching the version of the running kernel. The version numbers are likely to change (and this issue may be solved), so adapt it your situation.

First, check if this applies to your system:

rpm -qa | grep kernel-devel

kernel-devel-3.9.4-300.fc19.x86_64

uname -r
3.9.4-301.fc19.x86_64

If versions do not match, you can fix (hack) it like this:

sudo su -
cd /usr/src/kernels
cp -a 3.9.4-300.fc19.x86_64 3.9.4-301.fc19.x86_64

1.4 Download lttng-modules

We need to install lttng-modules 2.2.0-rc2 (or later) for compatibility with linux 3.9.4.

wget http://lttng.org/files/lttng-modules/lttng-modules-2.2.0-rc2.tar.bz2
tar -xjvf lttng-modules-2.2.0-rc2.tar.bz2
cd lttng-modules-2.2.0-rc2/
KERNELDIR=/usr/src/kernels/$(uname -r) make
sudo KERNELDIR=/usr/src/kernels/$(uname -r) make modules_install
sudo depmod -a
sudo modprobe lttng-tracer

The module lttng_tracer should be loaded and visible with lsmod. 

Step 2: Install lttng packages

sudo yum install lttng-tools lttng-ust babeltrace lttng-ust-devel

Now, reboot the machine. The service lttng-sessiond should be started automatically, and all required modules should be loaded. Here is some checks that can be done:

$ lsmod | grep lttng_tracer
lttng_tracer          558145  24 lttng_ring_buffer_client_discard,lttng_probe_jbd2,lttng_probe_kmem,lttng_probe_napi,lttng_probe_scsi,lttng_probe_sock,lttng_ring_buffer_client_mmap_overwrite,lttng_probe_statedump,lttng_ring_buffer_metadata_client,lttng_ring_buffer_client_mmap_discard,lttng_probe_irq,lttng_probe_kvm,lttng_probe_net,lttng_probe_skb,lttng_probe_udp,lttng_ring_buffer_metadata_mmap_client,lttng_probe_module,lttng_probe_signal,lttng_probe_vmscan,lttng_probe_block,lttng_ring_buffer_client_overwrite,lttng_probe_power,lttng_probe_sched,lttng_probe_timer
lttng_lib_ring_buffer    50443  7 lttng_ring_buffer_client_discard,lttng_ring_buffer_client_mmap_overwrite,lttng_ring_buffer_metadata_client,lttng_ring_buffer_client_mmap_discard,lttng_tracer,lttng_ring_buffer_metadata_mmap_client,lttng_ring_buffer_client_overwrite
lttng_statedump        30537  1 lttng_tracer
lttng_ftrace           13097  1 lttng_tracer
lttng_kprobes          12911  1 lttng_tracer
lttng_kretprobes       13224  1 lttng_tracer

$ sudo service lttng-sessiond status
Redirecting to /bin/systemctl status  lttng-sessiond.service
lttng-sessiond.service - LTTng 2.x central tracing registry session daemon
   Loaded: loaded (/usr/lib/systemd/system/lttng-sessiond.service; enabled)
   Active: active (running) since Tue 2013-06-04 14:48:53 EDT; 1min 8s ago
  Process: 385 ExecStart=/usr/bin/lttng-sessiond -d (code=exited, status=0/SUCCESS)
 Main PID: 418 (lttng-sessiond)
   CGroup: name=systemd:/system/lttng-sessiond.service
           └─418 /usr/bin/lttng-sessiond -d

Step 3: Make traces with workload-kit

One way to make traces is to use workload-kit. Here is how to install it from sources.

wget http://secretaire.dorsal.polymtl.ca/~fgiraldeau/workload-kit/workload-kit-0.1.13.tar.bz2
tar -xjvf workload-kit-0.1.13.tar.bz2 
cd workload-kit-0.1.13/
./configure --disable-cputemp
make -j12 
sudo make install

Then, the tool lttng-simple can be used to generate a UST trace or a kernel trace for instance:

lttng-simple -k -s -- sleep 1
babeltrace sleep-k/

lttng-simple -u -- /usr/local/share/workload-kit/scripts/ust/wk-heartbeat
babeltrace wk-heartbeat-u/

Happy tracing!