|
How can you measure Java code performance? Karl examines techniques for instrumenting Java code at run time.
October 01, 2000
URL:http://www.drdobbs.com/jvm/java-qa/184404293
Karl is a principal software developer at Allaire Corp. where he works on the JRun Application Server. Karl is also the author of Java Servlets (McGraw-Hill, 1999) and Java Database Programming with JDBC (Coriolis, 1997). He can be contacted at [email protected].
To find out how long a Java method is taking to execute, you inevitably resort to modifying the source code to capture the start time, then print the elapsed time once the method has completed. But there's an easier way. Instead of inserting the same code over and over into your source code, why not modify the compiled class directly? In this article, I'll examine techniques for instrumenting Java code at run time, letting you add bytecode instructions directly to compiled classes without having to modify (or even require) the source code. This is the methodology we used in the JRun Application Server from Allaire (the company I work for) to provide simple, easy-to-use profiling.
To instrument Java class files, you have to understand the structure of a Java class. The Java Virtual Machine Specification (http://java.sun.com/docs/books/vmspec/ index.html) describes a class file as "a stream of 8-bit bytes. All 16-bit, 32-bit, and 64-bit quantities are constructed by reading in two, four, and eight consecutive 8-bit bytes, respectively. Multibyte data items are always stored in Big-endian order, where the high-order bytes come first."
Table 1 shows the general structure of a Java class file. Once you understand how the class structure is tied together, it becomes easier to grasp how to insert bytecodes to perform instrumentation.
In addition to the Virtual Machine Specification, you may also find it useful to have a good hexadecimal editor so that you can read and examine existing class files. I found it beneficial to create small Java classes, compile them, and read them with a hex editor. I also like to print the hex representation and mark up the various parts of the raw class file. Being able to visualize how the constant pool entries tie together with the other pieces of the raw class file (in particular the method table) is vitally important.
To illustrate the class file format, I created the small "Hello, world!" application in Listing One. Table 2 lists the hexadecimal representation of the compiled class file. I've split the various parts of the class file and annotated them so you can see what a typical class file will contain, and how the constant pool is utilized.
Reading the class is not difficult. I've used both a custom class loader and a stand-alone application to read and modify the class. In the case of the custom class loader, you need to modify the loaded class stream before it is resolved by the Virtual Machine; for standalone applications, you simply need to read the class file, modify it, then write it back out. The latter approach would be beneficial if you have a closed system where you do not have the option of using a custom class loader. This takes away some of the "coolness" of being able to instrument on-the-fly (a postcompilation step is necessary), but the net effect is the same.
Once the class is read, it's time to parse. The class file structure lends itself well to breaking each part down into objects. Listing Two shows the function that is responsible for reading the main class file structure. As you can see, most of the work is delegated to other objects, which each have a read() method to handle the reading of the input stream. In this way, the format and type of the data is completely encapsulated. Each of these objects is also responsible for writing data back out as well.
Listing Three is code that reads the constant pool, which is the heart and soul of the Java class file. Again, the real work is delegated to supporting objects, one for each type of constant pool entry. Listing Four shows the simple read() and write() methods of the ConstantUtf8 class, which simply reads a string value from the input stream, and writes the value back out (along with the constant pool tag value). The write() method will be used later, when the modified class file is reconstructed.
Many constant pool entries refer to other pool entries (see Table 2). Using a separate object for each entry lets you hide these complexities as well. The String constant, for example, holds a constant pool index which points to a Utf8 constant, which ultimately holds the value of the string. It is quite simple to add a getString() method for the String constant class to perform this lookup, thus further insulating the details of the constant pool from the consumer.
Reading the class methods is handled in the same manner. An object exists for each type of method attribute (either Code or Exceptions), with subsequent objects for handling the code, code attributes, and so on.
Now that the class has been loaded and split into the proper object representation, how do you go about inserting an opcode into a method? On the surface it seems simple enough: Insert a byte into the code array of the Code attribute of a given method, and then increment the code_ length value by 1. In some limited cases -- depending upon the opcode you are inserting and where it is being inserted -- this may indeed work (although I sincerely doubt it). Unfortunately, the method code is much more complex. Inserting a new opcode causes any following opcodes to change their offset, which is dangerous because branching instructions and offset-based tables may need to be adjusted as well.
For branch instructions, offsets are stored as a positive or negative number, indicating how many bytes away (forward or back) the next instruction can be found from the current position. There are 20 different opcodes for branching, including goto, ifeq, iflt, ifgt, ifnonnull, and ifnull, to name a few. Each of these branch opcodes are followed by either a 2-byte or 4-byte relative offset. This introduces the notion of "wide" instructions that are followed by 4 bytes of data instead of the default 2 bytes. This allows smaller offsets, for example, to be stored more efficiently, while still accounting for larger offsets. When inserting an opcode into the code array, you will need to scan forward through the code, interpreting each opcode. When a branch instruction is found, and the branch offset is negative (meaning to branch backwards), it will need to be adjusted if branching occurs prior to the newly inserted opcode. You will also need to scan the opcodes before the insertion point (starting at the first opcode) looking for branch instructions with positive branch offsets; if it branches after the newly inserted opcode it will also need to be adjusted. An exceedingly difficult adjustment may also need to be made to the code generated from the switch statement, which can generate either a lookupswitch or tableswitch opcode. You'll get one or the other, depending upon the range of the case statement values used in the switch. Not only will you have to adjust the offsets stored in the table, but the beginning of the tables must be aligned on a 4-byte boundary. This is accomplished by inserting pad bytes before the table. Doesn't sound too bad, but if you insert a new opcode you may have to change the number of pad bytes in order to maintain the proper alignment.
The exception_table is part of the method Code attribute and is used to map exception handlers to areas of code. The offsets used in the table are relative to the beginning of the code array, so it's a simple matter when inserting an opcode to rip through the table and increment any offsets found after the insertion point.
The LineNumberTable is an optional attribute for the method Code and contains a mapping of code offsets to source-line numbers. Just like the exception_table, the offsets here are relative to the beginning of the code array and need to be updated in the same manner.
Of course, adding the ability to time methods is a little more difficult than adding a single opcode. Two approaches can be taken for inserting method timers:
I'll be timing the current method, although you could also opt to do both.
The first step is to capture the current system time. If you were writing Java code, it would look like this:
long starting_timer =
System.currentTimeMillis();
You'll have to manually create a new long local variable and call System.currentTimeMillis() to save the current clock time using opcodes. The number of local variables is part of the method code attribute. Local variables are referenced by index values. You will need to save the current max_locals as your starting timer index, and then increment the max_locals so that the Virtual Machine will allocate the proper space. Each local variable consumes 2 bytes, so you'll have to increment the max_locals by 2 since a long needs 4 bytes of storage. Next, you'll need to add some entries to the constant pool so that we can make the static method call to System.currentTimeMillis(). What you end up needing is a Methodref entry, but this will cause you to also insert a Class entry, NameAndType entry, and (potentially) three Utf8 entries. I say potentially, because you will also need to scan the constant pool to make sure you are not going to insert an exact duplicate of the Utf8 entry that you need. You will want to keep the constant pool as small as possible, and excluding duplicates is one way to do this. (I did not run into any problems inserting duplicates, but it's a good idea to avoid them.) Again referring to Table 2, Table 3 shows the new constant pool entries that need to be added to make a static method call to System.currentTimeMillis(). The Methodref entry references the existing Class entry for "java/lang/System." Once the constant pool has been updated we can insert the opcodes necessary to invoke a static method and store the results (which will be on the stack after the method call) in the new local variable:
invokestatic (0xB8) <System.currentTime Millis Methodref index>
lstore (0x37) <local variable index>
You may need to use lstore_w if the local variable index is greater than Short.MAX_VALUE (32767). Also be aware that you may be creating a deeper stack than was previously used; if this is the case you'll have to update the max_stack attribute as well.
Now that you've captured the start time of the method, you need to calculate the elapsed time and store it as well. The Java code would look like this:
long elapsed = System.currentTimeMillis() - starting_timer;
To cut down on the local variables, you can reuse the starting_timer variable to store the elapsed time. Since you have already updated the constant pool for the call to System.currentTimeMillis(), you just need to insert the proper opcodes to invoke System.currentTimeMillis() (which will put the current time on the stack), push the starting_timer on the stack, subtract the two, and then store the results back into starting_timer:
invokestatic (0xB8) <System.currentTime- Millis Methodref index>
lload (0x16) <local variable index>
lsub (0x65)
lstore (0x37) <local variable index>
You will need to insert the new opcodes before the return takes place from the method.
Now that the elapsed time for the method has been calculated and stored, what do you do with it? It certainly doesn't do any good just to calculate it, you've got to log it somewhere. I suggest calling a static method that accepts the class name, method name, and elapsed time. Making a static method call is simple (as with System.currentTimeMillis), plus you don't need to worry about instantiating an object. You will need to update the constant pool to include a Methodref entry for the logging method class, method name, and method signature. Assuming the static method has the definition:
public static void logTime(String class, String method, long elapsed);
You will need to push the class name, method name, and elapsed time on the stack and then invoke the static method:
ldc (0x12) <class name index>
ldc (0x12) <method name index>
lload (0x16) <local variable index>
invokestatic (0xB8) <logTime Methodref index>
To further illustrate what we have just done, Listing 5 shows the source code for a method to be timed, Listing 6 shows the static log method which will receive method timings, and Listing 7 shows what the modified method would look like in source form. The log method simply prints the results to stdout, but you could very easily log the statistics to a database for easy data mining. Instead of logging the results directly, it would be less performance impacting to the calling code if you posted the log results in a queue (and return immediately), letting another thread actually write the results. You may also want to consider changing the log method signature (and the corresponding opcodes for the method call) to include the current thread ID if you are performing method timings in a multithreaded environment so that you can easily identify separate processes.
There are many details that I have not presented, but you should be able to see how powerful this technique can be. Although I focused on how to instrument Java code, the possible uses of modifying compiled classes is broad. Couple that with using a custom class loader to modify code on-the-fly, and it's not too hard to envision:
DDJ
public class hello
{
public static void main(String[] args)
{
System.out.println("Hello, world!");
}
}
/** Constructs class elements from the raw byte stream
* @param name The class file name
* @param bytes The class file format
*/
public void read(String name, byte[] b) throws IOException
{
// Create a new input stream for reading the bytes
ByteArrayInputStream bais = new ByteArrayInputStream(b);
DataInputStream in = new DataInputStream(bais);
// Read the magic number
magic = in.readInt();
if (magic != 0xcafebabe) {
throw new IOException("Bad Magic Number");
}
// Read the minor version and major version. Do not worry about validation
minor_version = in.readUnsignedShort();
major_version = in.readUnsignedShort();
// Read the constant pool count
constant_pool_count = in.readUnsignedShort();
// Read the constant pool. If a problem exists the results will be null,
// in which case we'll just exit and let the class verifier catch the
// problem. The input stream will be positioned just after the constant
// pool when complete (on the access_flags attribute)
constantPool = readConstantPool(name, in, constant_pool_count);
if (constantPool == null) {
throw new IOException("Invalid Constant Pool");
}
// Get the access flags
access_flags = in.readUnsignedShort();
// This class
this_class = in.readUnsignedShort();
// Super class
super_class = in.readUnsignedShort();
// The number of interfaces
interface_count = in.readUnsignedShort();
// Read the interfaces
interfaces = new Vector();
for (int i = 0; i < interface_count; i++) {
ClassInterface iface = new ClassInterface(constantPool);
iface.read(in);
interfaces.addElement(iface);
}
// The number of fields
field_count = in.readUnsignedShort();
// Read the fields
fields = new Vector();
for (int i = 0; i < field_count; i++) {
ClassField field = new ClassField();
field.read(in);
fields.addElement(field);
}
// The number of methods
method_count = in.readUnsignedShort();
// Get the methods
methods = new Vector();
for (int i = 0; i < method_count; i++) {
ClassMethod method = new ClassMethod(constantPool);
method.read(in);
methods.addElement(method);
}
// Get the number of attributes
attribute_count = in.readUnsignedShort();
// Get the attributes
attributes = new Vector();
for (int i = 0; i < attribute_count; i++) {
ClassAttribute attr = new ClassAttribute(constantPool);
attr.read(in);
attributes.addElement(attr);
}
}
/** Reads the constant pool into a Vector. If some error occurs a null will
* be returned. The input stream should be positioned at the first byte in
* the constant pool
* @param name The class name
* @param in The input stream containing the class file
* @param count The constant pool count
* @return A vector containing each entry in the constant pool
*/
protected Vector readConstantPool(String name, DataInputStream in,
int constantPoolCount) throws IOException
{
// Loop through the constant pool and build a vector containing
// all of the entries
Vector entries = new Vector();
for (int entry = 1; entry < constantPoolCount; entry++) {
// Read the next constant pool tag
byte tag = in.readByte();
ConstantInterface constant;
// Create the proper type of constant object
switch(tag) {
case Tags.CONSTANT_Utf8:
constant = new ConstantUtf8();
break;
case Tags.CONSTANT_Integer:
constant = new ConstantInteger();
break;
case Tags.CONSTANT_Float:
constant = new ConstantFloat();
break;
case Tags.CONSTANT_Long:
constant = new ConstantLong();
break;
case Tags.CONSTANT_Double:
constant = new ConstantDouble();
break;
case Tags.CONSTANT_Class:
constant = new ConstantClass();
break;
case Tags.CONSTANT_String:
constant = new ConstantString();
break;
case Tags.CONSTANT_Fieldref:
constant = new ConstantFieldref();
break;
case Tags.CONSTANT_Methodref:
constant = new ConstantMethodref();
break;
case Tags.CONSTANT_InterfaceMethodref:
constant = new ConstantInterfaceMethodref();
break;
case Tags.CONSTANT_NameAndType:
constant = new ConstantNameAndType();
break;
default:
System.out.println("Unknown Tag " + tag);
return null;
}
// Read the constant entry
constant.read(in);
// Add the constant to the pool
entries.addElement(constant);
// Now adjust for long and double. For obscure reasons, when an entry
// is tagged CONSTANT_Long or CONSTANT_Double the JVM
// considers this a taking up two entries.
if ((tag == Tags.CONSTANT_Long) ||
(tag == Tags.CONSTANT_Double)) {
entry++;
entries.addElement(new BaseConstant());
}
}
return entries;
}
/** Reads the entry from the input stream
* @param in The input stream
*/
public void read(DataInputStream in) throws IOException
{
value = in.readUTF();
}
/** Writes the entry to the output stream
* @param out The output stream
*/
public void write(DataOutputStream out) throws IOException
{
// Write the tag byte
out.writeByte(getTag());
// Write the string
out.writeUTF(getString());
}
public Connection getConnection(String url, String user, String password)
throws SQLException
{
Connection connection = DriverManager.getConnection(url, user, password);
return connection;
}
/** Contains static logging methods */
public class StaticLogger
{
/** Logs the elapsed time for a method
* @param className The class name
* @param methodName The method name
* @param elapsed The elapsed time for the method
*/
public static void logTime(String className, String methodName, long elapsed)
{
System.out.println("Method "+className+"."+methodName+" took "+elapsed+"ms");
}
}
public Connection getConnection(String url, String user, String password)
throws SQLException
{
long starting_timer = System.currentTimeMillis();
Connection connection = DriverManager.getConnection(url, user, password);
long elapsed = System.currentTimeMillis() - starting_timer;
StaticLogger.logTime("myclass", "getConnection", elapsed);
return connection;
}
Terms of Service | Privacy Statement | Copyright © 2024 UBM Tech, All rights reserved.