lberk

Thoughts of a open source hacker

Probing Java Methods With Systemtap

Hi,

Today we’ll be looking at systemtap’s latest native java probing capabilities.
These go beyond systemtap’s existing hotspot-based probe points to actual entry,
exit, and line number specific to the relevant java method.

How to install (if running Fedora 19)

# yum install systemtap byteman

Alternatively, you can get the latest systemtap source by

$ git clone git://sourceware.org/git/systemtap.git

and following the README instructions for installation.  Likewise, you can download the latest byteman version from;

http://www.jboss.org/byteman/downloads

Basic Usage

How do I use systemtap to probe a java method?

Below we have a simple threaded java program, which waits for our input on the command
line.  Given the input ‘int’ or ‘long’, the program will print out a predetermined
variable (that we would like to know the value).

package foo.bar;

import java.lang.*;
import java.io.DataInputStream;
import java.io.BufferedReader;
import java.io.InputStreamReader;

class ThreadedExample
{

    public static void printMessage(int message)
    {
    System.out.println("message: " + message);
    }

    public static void printMessage(long message)
    {
    System.out.println("message: " + message);
    }

    public static void main(String[] args)
    {
    try
        {
        BufferedReader in = new BufferedReader(new InputStreamReader(System.in));
        String next = in.readLine();
        while(next != null && next.length() > 0 && !next.contains("end"))
            {
            final String arg = next;
            final int i = 42;
            final long j = 987234864;
            Thread thread = new Thread(arg)
                {
                public void run()
                {
                    if(arg.equals("int"))
                        printMessage(i);
                    else if(arg.equals("long"))
                         printMessage(j);
                    else
                    System.out.println("Neither of the types");
                }
                };
            thread.start();
            try
                {
                thread.join();
                } catch (Exception e){}
            next = in.readLine();
            }
        } catch (Exception e){}
    }
}

compile and run the java program in the typical way;

lberk:]$ javac foo/bar/ThreadedExample.java
lberk:]$ java foo.bar.ThreadedExample
int
message: 42
test
Neither of the types
long
message: 987234864

Good, now to run a systemtap script which will probe both printMessage methods
and display the parameter passed.

Java probe points in systemtap follow the basic syntax of
probe java(“PNAME”).class(“CLASS”).method(“METHOD”) { handler }

where PNAME is either the string of the java program as listed by jps -l or the
specific PID of the java program.  It should be noted that the java program must
be already running at the time of script invocation.  The CLASS parameter is the
fully qualified class, and the METHOD parameter is the method name with parameter
types.

An example of a systemtap script written for ThreadedExample.java is below:

ThreadExample.stp

#!/usr/bin/env stap
probe java("foo.bar.ThreadedExample").class("ThreadedExample").method("printMessage(int)")
{
    printf("Hit printMessage(int): %d\n", $arg1)
}
probe java("foo.bar.ThreadedExample").class("ThreadedExample").method("printMessage(long)")
{
    printf("Hit printMessage(long): %d\n", $arg1)
}

Running the systemtap script in another terminal (and specifying “int”, “long” respectively);

lberk:]$ stap ThreadedExample.stp

Hit printMessage(int): 42                                           
Hit printMessage(long): 987234864

JBoss-AS Example

This example will use the Jboss Application Server, using the helloworld example
which can be obtained by running:

git clone git://github.com/jboss-jdf/jboss-as-quickstart.git --branch jdf-2.1.2.Final

In order to probe a standalone server, we need to ensure both the byteman and systemtap
packages are visible for the target’s class loaders.  We can do this by either editting
the configuration file directly, or by modifying the environment variable on server startup
to list org.jboss.byteman and org.systemtap.byteman.helper package in the
JBOSS_MODULES_SYSTEM_PKGS option.  For our example we’ve launched the startup server using the environment variable.

lberk:]$ JBOSS_MODULES_SYSTEM_PKGS="org.jboss.byteman,org.systemtap.byteman.helper" $HOME/jboss-as-user-instance/bin/standalone.sh

We then deploy the helloworld example by running the following command in the
jboss-as-quickstart/helloworld directory:

lberk:]$ mvn clean package jboss-as:deploy

At this point, we have a running hello world example that displays a “Hello World!” at

http://localhost:8080/jboss-as-helloworld/HelloWorld

We can tell when this web page is requested, and how many times by writing a simple
systemtap script that targets the “doGet” method.

stap jboss-example.stp
———————-

#!/usr/bin/env stap
global counter

probe

java("/usr/share/jboss-as/jboss-modules.jar").class("org.jboss.as.quickstarts.helloworld.HelloWorldServlet").method("doGet")
{
    counter++
    printf("%s, %d\n", ctime(gettimeofday_s()), counter)
}

This will provide output similar to the following for each webpage request:

Mon Jun 17 02:37:05 2013, 1
Mon Jun 17 02:37:06 2013, 2
Mon Jun 17 02:37:07 2013, 3
Mon Jun 17 02:37:08 2013, 4
Mon Jun 17 02:37:08 2013, 5
Mon Jun 17 02:37:09 2013, 6
Mon Jun 17 02:37:09 2013, 7

Thermostat Example

Note: This example requires further OSGi class loading work, please refer to
the OSGi section in the tutorial.

Thermostat is an Open Source Java Tooling project aimed to improve monitoring
and instrumentation tooling.  More information about the project can be found at

http://icedtea.classpath.org/thermostat/

In order to make the necessary OSGi class visibility changes, we’re going clone
thermostat and checkout the 0.9-branchpoint

lberk:]$ hg clone http://icedtea.classpath.org/hg/thermostat
lberk:]$ hg checkout 0.9-branchpoint
lberk:]$ mvn clean install

In this example we’re interested in Thermostat’s ability to inspect java threads
and their current state (ie, blocked, waiting, runnable, etc), and the effect
it has (if any) on recording information to storage.  To do this we need to identify
the method used to write to the mongoDB, as well as the mechanism used to
trigger/enable the thread recording.  In this case, it means placing method entry
and return probe points on addImpl and replaceImp, as well as recording the time
spent in both recording thread state and ‘normal’ operation by
placing a probe point on the GUI’s getToggleButton method in the ThreadMainPanel class.

We launch thermostat by executing

lberk:]$ distribution/target/bin/thermostat service

and in a seperate terminal running

lberk:]$ distribution/target/bin/thermostat gui

Once the two thermostat services are running, we can run our script in a third terminal
and toggle the thread recording switch in the Thermostat gui, and exit the script
with a ctrl-C

stap thermostat.stp
——

#!/usr/bin/env stap
global mongo, mongoreturn
global recording = 0
global timeinaddimpl, timeinreplace, t1, t2, threadtimestart = 0, threadtimeend = 0, nothreadstart = 0, nothreadend = 0

probe java("Thermostat").class("com.redhat.thermostat.storage.mongodb.internal.MongoStorage").method("addImpl")
{
  t1 = gettimeofday_us()
  if(recording==0)
    mongo["non-threading"]<<<1
  else
  mongo["threading"]<<<1
}
probe java("Thermostat").class("com.redhat.thermostat.storage.mongodb.internal.MongoStorage").method("addImpl").return
{
  timeinaddimpl<<<(gettimeofday_us() - t1)
  if(recording==0)
    mongoreturn["non-threading"]<<<1
  else
    mongoreturn["threading"]<<<1
}
probe java("Thermostat").class("com.redhat.thermostat.storage.mongodb.internal.MongoStorage").method("replaceImpl")
{
  t2 = gettimeofday_us()
  if(recording==0)
    mongo["non-threading"]<<<1
  else
    mongo["threading"]<<<1
}
probe java("Thermostat").class("com.redhat.thermostat.storage.mongodb.internal.MongoStorage").method("replaceImpl").return
{
  timeinreplace<<<(gettimeofday_us() - t2)
  if(recording==0)
    mongoreturn["non-threading"]<<<1
  else
    mongoreturn["threading"]<<<1
}

probe java("Thermostat").class("com.redhat.thermostat.thread.client.swing.impl.ThreadMainPanel").method("getToggleButton")
{
  if( recording == 0){
    threadtimestart = gettimeofday_s()
    if (nothreadstart == 0){
      nothreadend = 0}
    else{
      nothreadend = nothreadend + (gettimeofday_s() - nothreadstart)
    }
    printf("Thread recording has been enabled.\n")
    recording = 1
  }
  else{
    nothreadstart = gettimeofday_s()
    threadtimeend = threadtimeend + (gettimeofday_s() - threadtimestart)
    printf("Thread recording has been disabled.\n")
    recording = 0 //recording is already 1, set to 0
  }
}
probe end
{
  printf("\n")
  printf("Time in AddImpl (uS)\n")
  print(@hist_log(timeinaddimpl))
  printf("Time in ReplaceImpl (uS)\n")
  print(@hist_log(timeinreplace))
}

While toggling the ‘Monitor Thread’ option a few times, the script output should look something similar to;

Thread recording has been enabled.
Thread recording has been disabled.
Thread recording has been enabled.
Thread recording has been disabled.
Thread recording has been enabled.
Thread recording has been disabled.
^C
Time in AddImpl (uS)
value |-------------------------------------------------- count
   16 |                                                     0
   32 |                                                     0
   64 |@@@@@@@@@@@@@@@@@@@@@@@@@                          305
  128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@              452
  256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    575
  512 |@@@@@@@@@@@                                        135
 1024 |@                                                   13
 2048 |                                                     2
 4096 |                                                     2
 8192 |                                                     2
16384 |                                                     0
32768 |                                                     0

Time in ReplaceImpl (uS)
value |-------------------------------------------------- count
   16 |                                                    0
   32 |                                                    0
   64 |@@@@@                                              10
  128 |@@                                                  5
  256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@              75
  512 |@@                                                  4
 1024 |                                                    1
 2048 |                                                    1
 4096 |                                                    0
 8192 |                                                    0

mongo["threading"] @count=1419 @min=1 @max=1 @sum=1419 @avg=1
mongo["non-threading"] @count=163 @min=1 @max=1 @sum=163 @avg=1
mongoreturn["threading"] @count=1419 @min=1 @max=1 @sum=1419 @avg=1
mongoreturn["non-threading"] @count=163 @min=1 @max=1 @sum=163 @avg=1

OSGI Note

Due to module class loaders and class visibility restrictions under OSGI,
a few further steps must be taken to properly probe java methods.  The
specific instructions can vary widely from application to application,
however this overview should give the knowledge to make educated decisions
to implement class loading visibility to the bundles systemtap requires.

There are two aspects to address in working with OSGi applications, importing
the helper jars to each specific bundle, and making the OSGi application aware of our
helper jar’s existence (ie, adding the required changes to the framework classpath).

First, to add the bundles to the framework classpath, we must create a new
framework instance and list the classes we’d like tomake available to the
program, the basic functionality of this class must include;

Map<String, String> jarsWereAdding = new HashMap<String, String>();
jarsWereAdding.put(Constants.FRAMEWORK_SYSTEMPACKAGES_EXTRA, jarList);
factories.next().newFramework(jarsWereAdding);

Where jarList is a file containing the following bundles

org.jboss.byteman.rule
org.jboss.byteman.rule.exception
org.jboss.byteman.rule.exception.EarlyReturnException
org.jboss.byteman.rule.helper
org.systemtap.byteman.helper.HelperSDT

The second portion is adding the import clause to the specific MANIFEST.MF of the
class you’re looking to probe.  This is a standard import clause which should resemble

Import Package: org.jboss.byteman.rule, org.jboss.byteman.rule.exception, org.jboss.byteman.rule.helper

This may also be added to the respective pom.xml if you’re using a build system such as maven:

<Import-Package>
org.jboss.byteman.rule,org.jboss.byteman.rule.exception,org.jboss.byteman.rule.helper,org.systemtap.byteman.helper,*
</Import-Package>

Please take note of the additional ‘*’ appended to the clause.  This explicit import is required
as previously ‘*’ was considered implied.
NOTE: If you’d like to modify the root pom.xml with a <Import-Package> statement, be sure to place it under
the maven-plugin-bundle artifactId

About these ads

5 responses to “Probing Java Methods With Systemtap

  1. noodlesfs August 28, 2013 at 12:49 pm

    I’m newer for systemtap. I follow your example in Basic Usage, but I hava get an error log cause by systemtap. what should I do?

    semantic error: probe point mismatch at position 0 (alternatives: __nfs __scheduler __signal __tcpmib __vm _linuxmib _signal _sunrpc _syscall _vfs begin begin(number) end end(number) error error(number) generic glib gobject hotspot ioblock ioblock_trace ioscheduler ioscheduler_trace ipmib irq_handler kernel kprobe kprocess linuxmib module(string) nd_syscall netdev never nfs nfsd perf perl process process(number) process(string) procfs procfs(string) python scheduler scsi signal socket softirq stap staprun sunrpc syscall tcp tcpmib timer tty udp vfs vm workqueue): identifier ‘java’ at ThreadExample.stp:3:7 while resolving probe point java(“ThreadedExample”).class(“ThreadedExample”).method(“printMessage(int)”)
    source: probe java(“ThreadedExample”).class(“ThreadedExample”).method(“printMessage(int)”){
    ^
    semantic error: probe point mismatch at position 0 (alternatives: __nfs __scheduler __signal __tcpmib __vm _linuxmib _signal _sunrpc _syscall _vfs begin begin(number) end end(number) error error(number) generic glib gobject hotspot ioblock ioblock_trace ioscheduler ioscheduler_trace ipmib irq_handler kernel kprobe kprocess linuxmib module(string) nd_syscall netdev never nfs nfsd perf perl process process(number) process(string) procfs procfs(string) python scheduler scsi signal socket softirq stap staprun sunrpc syscall tcp tcpmib timer tty udp vfs vm workqueue): identifier ‘java’ at :7:7 while resolving probe point java(“ThreadedExample”).class(“ThreadedExample”).method(“printMessage(long)”)
    source: probe java(“ThreadedExample”).class(“ThreadedExample”).method(“printMessage(long)”){
    ^
    Pass 2: analyzed script: 0 probe(s), 0 function(s), 0 embed(s), 0 global(s) using 29780virt/16888res/2596shr kb, in 10usr/0sys/5real ms.
    Pass 2: analysis failed. Try again with another ‘–vp 01′ option.

    PS: I use this java env:
    ===================

    java version “1.6.0_22″
    OpenJDK Runtime Environment (IcedTea6 1.10.4) (fedora-60.1.10.4.fc15-i386)
    OpenJDK Server VM (build 20.0-b11, mixed mode)

    • lukasberk October 29, 2013 at 7:02 pm

      Hey noodlesfs, unfortunately fedora 15 is rather old, and while byteman does work with java 1.6, I suspect the packaged versions of byteman/systemtap may be too old. My immediate recommendation would be (if possible) to upgrade fedora to fedora 19.

      Could you provide the versions of systemtap and byteman installed? Have you installed either outside of yum?

  2. Kapileshwar Singh October 28, 2013 at 5:59 pm

    This is indeed great work! Was trying this out, had a rather basic question, we cannot inject code into methods that are implemented as “native”??

    eg.

    public native void someNativeMethod();

    On trying to probe this, we don’t get any hits.

    • lukasberk October 29, 2013 at 7:08 pm

      Hey Kapileshwar,

      Thanks for the kind words. While I haven’t explicitly tested methods marked as “native” with this methodology, systemtap also has jni specific probe points in hotspot itself. Assuming a yum installed systemtap and java-1.7.0-openjdk-devel are present (on fedora at least), you should be able to list these probe points via a `$stap -L ‘hotspot.jni.*’ ` command.

      Hope that helps!

  3. Pingback: Support for Java Probing in SystemTap | rgrunber

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: