The Java Virtual Machine Profiler Interface

Low-level performance measurements for Java apps

Christof is IT Architect at IBM Business Consulting Services in Germany. He can be contacted at cschmalede.ibm.com. Christian is a consultant and can be contacted at http://www.harung.de/.

Java is often considered the technology of choice for highly distributed intranet and Internet applications. One reason for this is that complex issues such as security, transaction control, and data persistence are encapsulated by standardized APIs within the J2EE specification. Moreover, these issues are addressed and implemented through Java-based application servers such as IBM's WebSphere Application Server, BEA's WebLogic Server, and the open-source Jboss.

But successful e-business applications do not just provide infrastructures for development and runtime systems. They also define, monitor, and guarantee quality-of-service standards. Just as developers are supported by sophisticated IDEs, standardized monitoring APIs, and protocols support system management to meet service-level agreements.

Since 1998 and Java SDK 1.2, Sun has offered a standardized monitoring API—the Java Virtual Machine Profiler Interface (JVMPI)—for low-level performance measurements involving memory consumption, bytecode of classes being loaded, parameters of methods, and the like. Performance requirements may differ significantly between applications, but with JVMPI, there is a broad range of values to select from. A CPU-bound application (an XML parser, for instance) may best be analyzed by looking at time usage of methods or even single lines of code. JVMPI offers the getCurrentThreadCpuTime() function for analysis such as this. Meanwhile, database-driven web applications have other analysis needs. Application servers, for instance, often act as mediators between web servers and database back ends, and performance analysis must focus on time consumption of transactions—specifically SQL statements with long response times. In such cases, you can use JVMPI to patch (or instrument) the database JDBC driver class and extract SQL statements information on the fly.

Although intended originally for tool vendors, JVMPI can be a great tool for developers because it gives you a free view of what is going on under the hood.

Performance measuring in heavily distributed systems is complex. Often, several physical machines and application services are involved, all acting together to provide, for example, web-based transaction processing. When end users complain about an application's bad response times, low throughput, or rejected requests, getting to the cause of the problem may be difficult. Analysis must take into account all the layers between users and servers, where the business logic executes. Items to look at include web server load, J2EE server connection pools, and database index organization; or coding problems at the web layer, business layer, or in utilities, libraries, and helper classes.

Consider a typical J2EE example such as a travel agency where users request bookings. A service chain starts from the http server to a servlet, delegating to a Session Bean, activating one or more Entity Beans, and finally communicating with the database. With the exception of the web server to the application server channel, all services are directly under the control of Java processes and can be looked at with Java monitoring tools.

As an ad hoc solution, Java developers often start measuring via logging statements, putting them around code that does something interesting (like the crossing of a transaction layer). For example, a database statement call may be surrounded by timestamp information and domain-specific parameters.

Measuring performance this way has several drawbacks. You can slow down your application by including too many measuring points and spending too much time writing to log files, distorting the values you are getting. Another disadvantage of this approach is that you may end up constantly adding/removing logging statements to/from your code, cluttering it and creating extra efforts for code management and deployment. A better solution is monitoring using JVMPI.

JVMPI

JVMPI is a two-way API between the JVMPI and profiler agent (http://java.sun.com/ products/j2se/1.3/docs/guide/jvmpi/jvmpi.html). With JVMPI, your profiling agent has a way to specify to the JVM what kind of events you are interested in. The JVM, in turn, can tell you (the agent) that interesting events occurred.

The agent code is a platform-specific native library that runs in the same process as the JVM. The agent code can initially (or at any later time) register with the JVM its interest in events. When the event comes along, the JVM calls a handler function that the agent supplies. Within that handler, it is possible to show interest for new event types or indicate loss of interest in other ones. The handler code typically aggregates the information coming from the JVM and prints or displays it in some form of GUI.

The JVMPI specifications lists 37 events and additionally defines 26 interface functions. While the events are the bread and butter of monitoring, the interface functions mainly help you report without interfering. For example, they let you switch garbage collection off while your handler is examining and reporting on event objects, or provide locking to synchronize the writing of collected data.

Simpleprof

While JVMPI comes with its own profiling agent (called HPROF), we present Simpleprof, a minimal agent that runs on Windows or UNIX. (The complete source code and related files are available electronically; see "Resource Center," page 3.) To use Simpleprof, you need:

• The test class to be monitored, jvmpi4ddj.samples.MemConsumer.java.
• JDK 1.2 (or higher) to compile the MemConsumer.java into a MemConsumer .class.
• The agent source, simpleprof.c, that compiles into a shared library (Linux) or DLL (Windows).
• The compile instructions to make the library or DLL.
• The command line to run the profiled example.

MemConsumer (Figure 1) is a Swing tool that allocates objects of different sizes. Additionally, it lets you free the objects and run the garbage collector explicitly.

Listing One is simpleprof.c, the profiler code. This minimal profiler is only interested in two events—class load and object allocation events—and uses one function, EnableEvent()interface. Simpleprof looks for memory allocations that exceed a predefined limit of 5000 bytes, then prints a statement.

The profiler agent's first task is to define the JVM_Onload() function, the entry point for the JVM:

JNIEXPORT jint JNICALL JVM_OnLoad (JavaVM *jvm,
char *options, void *reserved) {

When the JVM starts up, it calls JVM_Onload() before running your application. In this example, JVM_Onload registers first registers interest in the JVM_INIT_DONE event, then sets up the notifyEvent() function. When the JVM is sufficiently initialized more interest is shown in CLASS_LOAD and OBJEC_ALLOC events.

jvmpi_interface->EnableEvent(JVMPI _EVENT_OBJECT_ALLOC, NULL);
jvmpi_interface->EnableEvent(JVMPI _EVENT_CLASS_LOAD, NULL);
// initialize jvmpi interface
jvmpi_interface->NotifyEvent = notifyEvent;

NotifyEvent() is called whenever registered events happen. After checking what type of event happened, it prints information that comes with the event and returns control.

Returning control to the JVM quickly is crucial in real applications. The profiler agent is running in the same process as the JVM, and time-consuming analysis of event information can significantly slow down the application. This can be bad if your application is an application server that runs into transaction timeouts.

The profiler code is compiled into a shared library (Linux) or DLL (Windows). Under Linux with gcc, the compile statement is: gcc -I . -I/usr/lib/java/include -I/ usr/lib/java/include/linux simpleprofiler.c -shared -o libsimpleprofiler.so.1.0. The library needs to be placed into the library path, typically into /usr/local/lib or the LD_LIBRARY_PATH variable must be set. Under Windows, a DLL named simpleprof.c is created and put into the DLL search path.

The MemConsumer.java class, available electronically, is compiled into MemConsumer.class with javac MemConsumer.java. To start profiling the MemConsumer, Java is called with the -Xrun option. This option is identical for Linux and Windows: java -Xrunsimpleprof jvmpi4ddj.samples.MemConsumer. When you allocate objects of various sizes, you see the profiler agent print allocation information on your standard output.

JVMPI & Class Instrumentation

The example we just presented was motivated by our work on a large, batch-oriented J2EE project. In highly distributed environments, transactions are processed using IBM's MQ Series, IBM's WebSphere application server, and Oracle databases. Our goal was to enable online performance monitoring and bottleneck analysis at transaction boundaries so that we could track MQ message read/writes and SQL execution. After first implementing a simple performance-measuring package (classes that write to log files and offer simple timestamp and timerange information), the issue of avoiding code changes and providing more flexibility to select profiling classes prompted the next step.

One possible solution was the implementation of a classloader, which modifies classes on the fly. Methods of interest should be encapsulated by time measurements—the original class is modified or instrumented. But two problems come with that solution:

• Class instrumentation requires a deep understanding of the classfile format. The classloader must be able to transform the binary class stream without violating the JVM contract.
• There are strong limitations for plugging in your own classloading mechanisms into a J2EE environment. For instance, the IBM WebSphere Application Server servlet and EJB containers are not explicitly invoked, but are implicitly invoked through the WebSphere AdminServer. There is no obvious spot to plug in a customized classloader because WebSphere and other application servers generally use complex chains of bootclass and class loaders, and hooking in seems nearly impossible.

The first problem can be solved with the BCEL package, part of the Apache Jakarta project (http://www.apache.org/ dist/jakarta/bcel). BCEL offers an object-oriented layer above the binary classfile structure and allows instrumentation without knowledge of the underlying details.

The second problem can be solved with JVMPI and the JVMPI_EVENT_CLASS _LOAD_HOOK event. This event is sent when the JVM obtains a classfile data but just before constructing the in-memory representation for that class.

Thus, a possible profiling solution is:

• Use of JVMPI.
• In the JVM_OnLoad method, only enable JVMPI_EVENT_JVM_INIT_DONE.
• After the JVMPI_EVENT_JVM_INIT _DONE event, load a BCEL-based instrumentation class.
• After the successful load of the instrumentation class, register the JVMPI _EVENT_CLASS_LOAD_HOOK event.
• When handling JVMPI_EVENT_CLASS _LOAD_HOOK, delegate the decision whether to instrument to the instrumentation class.
• Select classes to monitor with a property file.

This way, coding the native C/C++ library is minimized. The instrumentation class is pure Java, with easy access to available APIs like BCEL.

Listing Two is a snippet of the profiler code that shows how to prepare the instrumentation class (Listing Three is the complete code). Using JNI, instrumentClass looks up the mandatory instrumentClass method within the instrumentation class (in this case, TimeInstrumentation). The instrumentation class is not hard coded, but passed together with the -Xrun command-line token: java -Xrunjvmpi4ddj:jvmpi4ddj/TimeInstrumentation.

The instrumentation class has to implement the method public static byte[] instrumentClass(byte[] buf), which is invoked during the JVMPI_EVENT_CLASS _LOAD_HOOK event handling. Instrumentation occurs within this method. When the method returns, it gives back the instrumented class as a byte array. The profiler passes it back to JVM and continues handling new events.

The helper class, jvmpi4ddj.PerfMeasure, reduces the effort for instrumentation: BCEL API calls are used to wrap the original method in the time taking and time usage printing code from PerfMeasure. For example, suppose the class Cfoo (Listing Four) has gone through our profiler and was instrumented (you can dump the instrumented bytecode easily from within the TimeInstrumentation code). Listing Five is the resulting instrumented class. A new method appears, jvmpi4ddj_mfoo, which represents the original mfoo() method. The call to mfoo() is wrapped by the PerfMeasure method call, providing timing information before and after the mfoo call.

Patching classes and methods indirectly by wrapping them nicely avoids the complexity of injecting code into classes with several methods or into methods with try/catch blocks.

We tested the profiler in the real world, applying it to a WebSphere 4.0 application server clone. Instrumenting several low-level methods (EJB container, database driver, CORBA) worked without problems.

Figure 2 illustrates how the profiler can be enabled through the WebSphere administration client. The command-line arguments show the -Xrun... configuration and the boot classpath (append), setting all the necessary bootclass path extensions (bcel lib and so on).

What's Not So Great About JVMPI ?

JVMPI isn't without its shortcomings. Say, for instance, you want to monitor events with a fine granularity—all events for a particular class. With JVMPI, you can turn an event type on/off—that's it. Of course, you are free not to handle the specific event depending on some conditions, but the event and overhead that goes with it is created.

Also, there's only one agent per virtual machine. There is no concept of chaining agents. If you want to replace your agent, you have to code a different library and restart the virtual machine.

Furthermore, there is no matching of JVMPI events to host-specific events. Your Java program runs in a virtual machine, but the virtual machine itself runs in a host environment where events of its own type occur. It would be helpful to be able to see and handle both types of events in a single piece of code.

The native interface makes it harder to use Java-specific solutions; for example, Java APIs already available to instrument classfiles while they are being loaded.

The profiling of Java code is only one part of a successful performance management. Profiling must harmonize with general solutions for system management. For example, IBM Tivoli Monitoring for Transaction Performance (see http://www-306.ibm.com/software/tivoli/products/monitor-transaction/) integrates JVMPI-based profiling techniques into a wider range of solutions.

Finally, JVMPI doesn't scale well with large applications because events may arrive faster than they can be handled. With serious JVMPI use, you may find yourself caught up in threading and locking problems that aren't easy to debug or solve.

Conclusion

Experience shows that the implementation of a sophisticated profiler based on JVMPI is not a weekend job. But as part of a business application development project, JVMPI profiling can play an important role in successful performance management.

DDJ

Listing One

// simpleprof.c - simple library, profiling agent JVMPI
// #include <string.h>
#include <jvmpi.h>
#include <jni.h>
#define ALLOC_LIMIT 2000    // object size for notification
void notifyEvent(JVMPI_Event *event);
static JVMPI_Interface *jvmpi_interface;

// profiler agent entry point
JNIEXPORT jint JNICALL JVM_OnLoad(JavaVM *jvm,char *options,void *reserved) {
    // get jvmpi interface pointer
    int res = (*jvm)->GetEnv(jvm,(void **)&jvmpi_interface,JVMPI_VERSION_1);
    if (res < 0) {
      printf("Error obtaining jvmpi interface pointer\n");
      return JNI_ERR;
    }
    // enable minimum event notification, rest from notifyEvent()
    if (jvmpi_interface->EnableEvent(JVMPI_EVENT_JVM_INIT_DONE, NULL)
            != JVMPI_SUCCESS) {;
      printf("Failed to enable JVM_INIT_DONE.\n");
      return JNI_ERR;
    }
    // initialize jvmpi interface
    jvmpi_interface->NotifyEvent = notifyEvent;
    return JNI_OK;
}
// function for handling event notification - our own function
void notifyEvent(JVMPI_Event *event) {
   switch(event->event_type) {
        case JVMPI_EVENT_JVM_INIT_DONE:
            printf("\nSIMPLEPROF: INIT_DONE\n");
            jvmpi_interface->EnableEvent(JVMPI_EVENT_OBJECT_ALLOC, NULL);
            return;
        case JVMPI_EVENT_OBJECT_ALLOC:
        if (event->u.obj_alloc.size >= ALLOC_LIMIT) {
             printf("\nSIMPLEPROF: Large object size %d (>= %d) allocated\n",
                        event->u.obj_alloc.size,ALLOC_LIMIT);
                return;
        }
       return;
    }
}

/*
*  loadInstrumentationClass instantiate our BCEL based Instrumentation Class
*  Note : this class is determined at run time
*  with
*  -Xrunjvmpi4ddj:<package_and_classname>
*  However, the instrumentation class have to provide a method:
*  public static byte[] instrumentClass(byte[] buf)
*/
int loadInstrumentationClass(JNIEnv *env)
{
   /*
    * instrumentation class and the method may already have been located,
    * no need to do it more than once. To remember, we need a GLOBAL reference,
    * not a local one ! Otherwise, reference may have been garbage collected.
    * Will create a global one with NewGlobalRef().
    * See java.sun.com/docs/books/tutorial/native1.1/implementing/refs.html
    * or http://java.sun.com/docs/books/jni/html/refs.html
   */

   jclass localref_instrumentationClass = 0;

   if ( instrumentationClass != 0 ) {
      fprintf(stderr,"native:instrumentationClass is 0\n");
      return 1;
   }
   /*
    * Use the JNI Function FindClass
    * see http://java.sun.com/j2se/1.4.2/docs/guide/jni/spec/functions.html
    * load a locally defined class
    * "name: a fully-qualified class name (that is, a package name,
    * delimited by "/", followed by the class name).
    * If the name begins with "[" (the array signature character),
    * it returns an array class.
   */

   localref_instrumentationClass = env->FindClass(ppatchclass);
   if ( localref_instrumentationClass == NULL ) {
      fprintf(stderr,"native:loadInstrumentationClass:INFO:could not FindClass(%s)\n",
         ppatchclass);
      return 0;
   }
   instrumentationClass = 
     (jclass)env->NewGlobalRef(localref_instrumentationClass);   // now cached
   if (instrumentationClass == NULL) {
      fprintf(stderr,
"native:loadInstrumentationClass:INFO:could not create global ref to (%s)\n",
         ppatchclass);
      return 0;
   }
    /* The local reference is no longer useful */
    env->DeleteLocalRef(localref_instrumentationClass);

   /*
    * this may throw Java exceptions:
    * NoSuchMethodError
    * ExceptionInInitializerError
    * OutOfMemoryError
   */
instrumentClassMethodID = env->GetStaticMethodID(instrumentationClass, 
                                               "instrumentClass","([B)[B");
   if ( instrumentClassMethodID == NULL ) {
      fprintf(stderr,
"native:loadInstrumentationClass:INFO:could not get static method instrumentClass in %s\n",
         ppatchclass);
      return 0;
   }
   return 1;
}

/**
 * jvmpi4ddj.cc
 * The one and only module
 * For our BCEL based C profiler
 * The sense of this C-code is the minimization of C-code for JVMPI :-)
 * project : jvmpi profiler; article for ddj 2004
 * version 1.00 02/02/04
 * author Chr. Hoefig / Chr. Schmalenbach
 */

#include <jvmpi.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>

/*
Enable this precompilerflag if the first instrumented
class should be written to the file system for debugging purposes
*/
//#define WRITEFIRSTHOOKEDCLASSTOFILE 1

#ifdef WRITEFIRSTHOOKEDCLASSTOFILE
FILE *fp = 0;
int filewritten = 0;
#endif // #ifdef WRITEFIRSTHOOKEDCLASSTOFILE

// global jvmpi interface pointer
static JVMPI_Interface *jvmpi_interface;

// pointer to the JVM
JavaVM *jvm;

// instrumentation class and Method
jclass instrumentationClass = 0;
jmethodID instrumentClassMethodID = 0;

/*
*   it seems that our instrumentaion strategy has reentrance
*   problems, if we instrument two classes at the same time.
*   So we avoid this through instrumentation_active flag
*/
int instrumentation_active = 0;

/*
*   We use the opions field to allow dynamic configuration
*   of the instrumentation class.
*/
char* ppatchclass;

/*
*   loadInstrumentationClass instantiate our BCEL based Instrumentation Class
*   Note : this class is determined at run time
*   with
*   -Xrunjvmpi4ddj:<package_and_classname>
*   However, the instrumentation class have to provide a method:
*   public static byte[] instrumentClass(byte[] buf)
*/
int loadInstrumentationClass(JNIEnv *env)
{
   /*
    * instrumentation class and the method may already have been located,
    * no need to do it more than once. To remember, we need a GLOBAL reference,
    * not a local one ! Otherwise, reference may have been garbage collected.
    * Will create a global one with NewGlobalRef().
    * See java.sun.com/docs/books/tutorial/native1.1/implementing/refs.html
    * or http://java.sun.com/docs/books/jni/html/refs.html
   */

   jclass localref_instrumentationClass = 0;

   if ( instrumentationClass != 0 ) {
      fprintf(stderr,"native:instrumentationClass is 0\n");
      return 1;
   }
   /*
    * Use the JNI Function FindClass
    * see http://java.sun.com/j2se/1.4.2/docs/guide/jni/spec/functions.html
    * load a locally defined class
    * "name: a fully-qualified class name (that is, a package name,
    * delimited by "/", followed by the class name).
    * If the name begins with "[" (the array signature character),
    * it returns an array class.
   */

   localref_instrumentationClass = env->FindClass(ppatchclass);
   if ( localref_instrumentationClass == NULL ) {
      fprintf(stderr,"native:loadInstrumentationClass:INFO:could not FindClass(%s)\n",
         ppatchclass);
      return 0;
   }
   instrumentationClass = (jclass)env->NewGlobalRef(localref_instrumentationClass);   // now cached
   if (instrumentationClass == NULL) {
      fprintf(stderr,
"native:loadInstrumentationClass:INFO:could not create global ref to (%s)\n",
         ppatchclass);
      return 0;
   }
    /* The local reference is no longer useful */
    env->DeleteLocalRef(localref_instrumentationClass);

   /*
    * this may throw Java exceptions:
    * NoSuchMethodError
    * ExceptionInInitializerError
    * OutOfMemoryError
   */
   instrumentClassMethodID = env->GetStaticMethodID(instrumentationClass, 
                                                "instrumentClass","([B)[B");
   if ( instrumentClassMethodID == NULL ) {
      fprintf(stderr,
"native:loadInstrumentationClass:INFO:could not get static method instrumentClass in %s\n",
         ppatchclass);
      return 0;
   }
   return 1;
}


// function for handling event notification
void notifyEvent(JVMPI_Event *event) {

JNIEnv *jni_interface;
switch(event->event_type) {
  case JVMPI_EVENT_CLASS_LOAD_HOOK:
  {
    jint class_data_length = event->u.class_load_hook.class_data_len;
    /*
      in most cases we aren't interested in instrumentation.
      that's why we use the class as read by the jvm
    */
    event->u.class_load_hook.new_class_data = event->u.class_load_hook.class_data;
    event->u.class_load_hook.new_class_data_len = event->u.class_load_hook.class_data_len;

    jvm->GetEnv((void **)&jni_interface, JNI_VERSION_1_2);

    if ( instrumentation_active == 1 )
      return;

    instrumentation_active = 1;
    jbyteArray buf = jni_interface->NewByteArray(event->u.class_load_hook.class_data_len);
    jni_interface->SetByteArrayRegion(
                  buf,
                  0,
                  event->u.class_load_hook.class_data_len,
                  (jbyte *)event->u.class_load_hook.class_data
                );
    jbyteArray buf_new;
    buf_new = (jbyteArray)jni_interface->CallStaticObjectMethod(
                    instrumentationClass,
                    instrumentClassMethodID,
                    buf
                  );
    // contract between this shared library and the instrumentation class:
    // return buf_new != 0 iff instrumented
    if( buf_new != 0 )
    {
      int new_len = jni_interface->GetArrayLength(buf_new);
      event->u.class_load_hook.new_class_data_len = new_len;
      event->u.class_load_hook.new_class_data =
         (unsigned char*)event->u.class_load_hook.malloc_f(new_len);
      jni_interface->GetByteArrayRegion(buf_new, 0, new_len, 
         (jbyte*)event->u.class_load_hook.new_class_data);

#ifdef WRITEFIRSTHOOKEDCLASSTOFILE

      fp = fopen("jvmpi4ddj_dump", "wb");
        if( !filewritten )
        {
          fwrite( event->u.class_load_hook.new_class_data,
                sizeof(char),
                event->u.class_load_hook.new_class_data_len,
                fp );
          fclose(fp);
          filewritten = 1;
        }
#endif //#ifdef WRITEFIRSTHOOKEDCLASSTOFILE
        }
        instrumentation_active = 0;

        break;
      }
      case JVMPI_EVENT_JVM_INIT_DONE:
      {
        jvm->GetEnv((void **)&jni_interface, JNI_VERSION_1_2);
        // try to load our BCEL based instrumentation class
        if ( loadInstrumentationClass( jni_interface ) == 0 ) {
            return;
        }
        else
        {
            // class and method successfully estimated, so we can use it in
            // event JVMPI_EVENT_CLASS_LOAD_HOOK
            jvmpi_interface->EnableEvent(JVMPI_EVENT_CLASS_LOAD_HOOK, NULL);
        }
        break;
      }
}
return;
}

// profiler agent entry point
extern "C" {
  JNIEXPORT jint JNICALL JVM_OnLoad(JavaVM *_jvm, char *options, void *reserved) {

    ppatchclass = (char *)malloc( sizeof(char)*strlen(options) + 1 );
    strcpy( ppatchclass,options );
    jvm = _jvm;

    if ((jvm->GetEnv((void **)&jvmpi_interface, JVMPI_VERSION_1_1)) < 0) {
      return JNI_ERR;
    }


    jvmpi_interface->NotifyEvent = notifyEvent;
    /*
                initially we are only interested in notification
                of successful VM start
    */
            jvmpi_interface->EnableEvent(JVMPI_EVENT_JVM_INIT_DONE, NULL);

    return JNI_OK;
  }
}

public class CFoo
{
    public Long mfoo(long l)
    {
        return new Long(l);
    }
}

import jvmpi4ddj.PerfMeasure;
public class CFoo
{
    public CFoo()
    {
    }
    private Long jvmpi4ddj_mfoo(long l)
    {
        return new Long(l);
    }
    public Long mfoo(long arg0)
    {
        String s = "mfoo";
        Object obj = ";";
        Object obj1 = "CFoo";
        obj = new PerfMeasure(obj1 + obj + s + obj + arg0 + obj);
        obj1 = jvmpi4ddj_mfoo(arg0);
        ((PerfMeasure) (obj)).closeMeasure();
        return ((Long) (obj1));
    }
}