Debugging Without A Debugger: IndexOutOfBoundsException

The technique of putting yourself in the position of the computer is very valuable when you do not have the luxury of using a debugger to debug a problem. However, it is rare to be able to debug your problems in this way without the benefit of logging. Logging, in combination with logical thinking, can help to make this type of debugging much easier.

Here is another example with a different type of exception that shows how valuable logging is when debugging these types of problems.

package nodebugger;

import java.util.ArrayList;
import java.util.List;

public class DebugExample2 {
  private static final String JIM = "Jim";
  private static final String JAVA = "Java";

  public String removeComment(String line) {
    if (line.charAt(0) != '*') {
      return line;
    }
    // Return empty line
    return "";
  }

  private static String addHighlight(String line,
                                     String str,
                                     String hilite) {
    final int pos = line.indexOf(str);
    String newLine = line.substring(0, pos);
    newLine += "<" + hilite + ">" + str +
      "</" + hilite + ">";
    newLine += line.substring(pos + str.length());
    return newLine;
  }

  public static void main(String[] args) {
    DebugExample2 de = new DebugExample2();
    List<String> newLines = new ArrayList<String>();
    // Simplification - imagine that these lines
    // are being read from a file.
    for (String line : DebugExample.LINES) {
      String newLine = line;
      //
      if (line.contains(JIM)) {
        newLine = addHighlight(line, JIM, "B");
      }
      else if (line.contains(JAVA)) {
        newLine = addHighlight(line, JAVA, "I");
      }
      else if (line.startsWith("*")) {
        newLine = "";
      }
      newLines.add(de.removeComment(newLine));
    }
    System.out.println("newLines = " + newLines);
  }
}

The above example is highly simplified in order to focus on the key concepts that are interesting for debugging purposes. We have a main method that obtains a list of lines from an external source and then makes changes to those lines depending on the content. On line 18, you see a general purpose method that searches for a string in a line, and if it finds that string, it applies the specified HTML highlighting to it. At line 37, you see that if the line contains the string, "Jim", then it will highlight that string in bold. Similarly, on line 40, is the line contains the string, "Java", then it will highlight that string in italics. Finally, if the line starts with an asterisk, then it treats it as a comment and sets up to ignore it.

When you run the above program, you get the following exception:

Exception in thread "main"
java.lang.StringIndexOutOfBoundsException
 at java.lang.String.charAt(String.java:418)
 at 
nodebugger.DebugExample2.removeComment(DebugExample2.java:11)
 at nodebugger.DebugExample2.main(DebugExample2.java:46)

When you look at the exception, the first line of the stack trace is from the java.lang.String class. In virtually every situation, we can assume that there aren't any bugs in any code that comes from Java itself. So, we move down to the next line and we see line 11 of our source file.

      if (line.charAt(0) != '*') {

We consult the API documentation for the String class and find the following:

IndexOutOfBoundsException - if the index argument is negative or not less than the length of this string.

Since the index is a constant, it clearly cannot be negative, so it must not be less than the length of the string. Since the index is zero, the string must be of length zero, in other words an empty string.

How Did We Get Here?

So, we know that we must have had an empty string in order to have taken this exception. A naïve approach to solving this problem would be to go into the code at line 11 and change it to handle empty strings. However, when you are working with complex software, the naïve approach is usually the wrong approach. It may be the case that this method never should be called with an empty string, in which case the problem would not be at line 11. So, let's look at the next line in the stack trace:

    for (String line : DebugExample.LINES) {
      String newLine = line;
      //
      if (line.contains(JIM)) {
        newLine = addHighlight(line, JIM, "B");
      }
      else if (line.contains(JAVA)) {
        newLine = addHighlight(line, JAVA, "I");
      }
      else if (line.startsWith("*")) {
        newLine = "";
      }
      newLines.add(de.removeComment(newLine));
    }

The problem occurred at line 46, and sure enough, we see a call to the removeComment method on that line. The variable newLine, then, must be an empty string for us to have received this exception. But how could we have gotten to this point? If you look at the code closely, you'll see that there are two possibilities: either the incoming line was empty, or the incoming line began with an asterisk. But how do we know this?

Pretending to Be the Computer, a.k.a. Using Logic

On line 35, we see the declaration for the variable newLine. Since it is inside the for loop that begins on line 34, the scope of a variable is limited to the for loop. Therefore, we know that we only have to look at the lines within this for loop to determine what may be happening. In other words, we only care about lines 35 to 46 inclusive. So, let's examine all the places where this variable is modified to see where it is possible for us to get an empty string.

First of all, on line 35 itself, the variable is set to the current element in our list of lines. This happens unconditionally, so the value of the current element is a consideration.

Next, on line 38, we see that it is set to the result of the addHighlight method. The parameters to this method are the original line, the string, "Jim", and the string "B." So, let's examine that method on line 18.

This method appears somewhat complicated. There seems to be many possibilities where things may go wrong depending upon the parameters that are passed to this method. However, remember that we are not required to fully understand what this method does in order to debug this particular problem. We only care about situations where we will end up with an empty string in the calling method, which means that we only care about situations where this method can return an empty string.

So, working backwards, we see that the variable newLine is returned on line 26. We see this variable as the target of assignment statements on lines 22, 23, and 25. Notice, however, that after it is initially set on line 22, the following two assignments are "+=" assignments. Therefore, they are concatenations to the existing value. Specifically, on line 23, notice that several constants are being concatenated to the variable. Regardless of whatever else this routine may be doing, it is clear from this line that there is no way that this routine could ever return an empty string. In the worst possible case, the returned string would still contain at least four characters: "<><>". Since we only care about situations where we can get an empty string, this routine clearly cannot have been called in the path that leads to this particular exception. Therefore, this tells us that line 38 could not have been run when we received this exception.

Similarly, since line 41 calls the same method, it also cannot have been run in the path that leads to this exception.

The last-place where the newLine variable appears on the left side of an assignment statement is online 44. Here, we see that it is, in fact, being set to an empty string. Well, that certainly looks suspicious. We see, however, that line 44 is protected by the if statement online 43, which checks whether the original line starts with an asterisk. To be thorough, note that this test is the else clause for the previous tests on line 37 and 40. So, we know that the only way we could have gotten to line 44 is if the original line did not contain the string, "Jim", did not contain the string, "Java", but did start with an asterisk.

The End of Our Analysis

Our analysis has shown that there are two possibilities that could have led to this exception: either the original line was empty, or the original line started with an asterisk. But which is it? There is simply no way to tell without actually getting access to the system, making changes to the code, and then rerunning this test.

Performing Further Debugging

Of course, if this class was a part of an enterprise software product that was installed on a customer production system, it would be extremely difficult to make a change to the class, then send that change the customer and ask them to simply try it out. It would be much better to have built the class with the necessary pieces for doing this additional debugging without having to ask the customer to install patches. In a subsequent article, I will discuss techniques for doing this in a way that does not impact the customer normally. For now, though, simply note that if it were possible to see the contents of the newLine variable at line 36, then we would be able to determine exactly which path we were taking that led to this problem.

Simple Logging

The easiest thing to do would be to add a logging statement to line 36 that would log the contents of the newLine variable. So, let's change line 36 to the following:

      System.out.println("newLine = " + newLine);

Running with Simple Logging

When we run the new code, we see the following:

newLine = * Comment 1
Exception in thread "main" 
java.lang.StringIndexOutOfBoundsException
 at java.lang.String.charAt(String.java:418)
 at 
nodebugger.DebugExample2.removeComment(DebugExample2.java:11)
 at nodebugger.DebugExample2.main(DebugExample2.java:46)

This shows us that, in fact, the problem is we received a line that starts with an asterisk. We need to change the code to deal properly with these types of lines, or else we need to change other aspects of the system to ensure that we would never get such a line in the first place.

Conclusion

When trying to debug a problem without the benefit of a debugger, the task can at first appear quite daunting. However, with a little logic, you can often make great simplifying assumptions that will remove entire complex branches of code from consideration. The judicious use of logging statements can further augment the use of logic to make debugging much simpler.

Debugging Without a Debugger: NullPointerExceptions

We will now begin giving some examples of techniques you can use to debug without actually having access to the system where the problem occurred. This example shows techniques for dealing with a common type of problem: the NullPointerException.

Note that software engineers who have significant experience with diagnosing customer issues may find this posting a bit obvious, but I think it's still a good introduction to the concepts.

Example Code

Here's the example code:

public class DebugExample {
 public String doSomething(String s) {
     return s.replace('l', 'L');
 }

 public static final class C1 {

     private DebugExample _de;

     public DebugExample getDe() {
         return _de;
     }

     public void setDe(final DebugExample de) {
         _de = de;
     }

     public String save(DebugExample de) {
         return de.doSomething("Hello");
     }
 }

 public static final class C2 {
     public String x(C1 c1) {
         return c1.getDe().doSomething(null); /* Line 25 */
     }
 }

 public static void main(String[] args) {
     DebugExample de = new DebugExample();
     de.doSomething("Hello");
     C1 c1 = new C1();
     c1.save(de);
     C2 c2 = new C2();
     System.out.println(c2.x(c1));  /* Line 35 */
 }
}

Scenario

Imagine that you have a customer bug report, saying that when they run the above code, then get the following:

Exception in thread "main" java.lang.NullPointerException
 at DebugExample$C2.x(DebugExample.java:25)
 at DebugExample.main(DebugExample.java:35)

You don't have any other information. So, what do you do?

Become the Computer

The best way to approach NullPointerExceptions (NPEs) is to put yourself in the position of the computer. You want to try to look at the evidence you have, and then use logic to work backwards from the point of the exception to see how you could possibly have gotten to that point with a null variable.

In this case, the exception occurred at line 25. Line 25 looks like this:

return c1.getDe().doSomething(null); /* Line 25 */

So, how could this line produce a NPE? Working from the end of the line, your eye might be drawn to the null being passed to the “doSomething()” method. However, that could not be the problem. If it were, then the NPE would have occurred inside the “doSomething()” method. But it did not – it occurred on the line in the “x()” method. Even if the null could cause a problem (which it definitely would in this case), it was not the cause of this problem.

Causes for NullPointerExceptions

There are only two possible ways that line 25 could cause an NPE: If the “c1” variable was null, or if the “getDe()” method returned a null. Remember that an NPE means that Java tried to use an object reference to call a method on that object, but the object reference was null. So, the last method in any chain of method calls can not be the cause of a NPE that occurs directly on that line.

First Possibility

So, let’s look at those two possible causes. Could the “c1” variable be null? Well, “c1” is a parameter to the method:

public String x(C1 c1) {

There are no intervening lines that make any changes to “c1”, so if it is null, there had to be a null passed in the “x()” method call. So, let’s look at the previous line in the stack traceback. It says that the call to “x()” came from line 35:

C1 c1 = new C1();
c1.save(de);
C2 c2 = new C2();
System.out.println(c2.x(c1));  /* Line 35 */

As you can see, the parameter to the “x()” method is also called “c1”, and it is most definitely not null. The only assignment to it is where it is assigned to “new C1()”. There is no way that a constructor can return a null, so the “c1” variable is not null. Novices might be tempted to look into the “save()” method on the C1 class to see if there is anything that could be null there, but the internal state of the object that “c1” refers to does not matter. Remember, for Java to throw an NPE, the object reference itself must be null – if the reference itself is not null, then an NPE could not be thrown from that line.

Second Possibility

So, this means that the only way we could have gotten a NPE from line 25 is if the “getDe()” method returned a null. We have proven that there is no other way this could have happened. This is a key part of this kind of debugging – you have to not waste time chasing after issues that could not possibly have occurred.

So, let’s look at the “getDe() method:

public DebugExample getDe() {
 return _de;
}

So, “_de” is a member variable (a.k.a. “field”) of the C1 class. Let’s look at its declaration:

private DebugExample _de;

Now we’re getting somewhere. There’s no initializer for this variable, which means that its value starts out as null. So now we should look for assignments to that variable. Scanning the source, we find only one such assignment:

public void setDe(final DebugExample de) {
_de = de;
}

OK, so somebody must call this method before the call to “getDe()” takes place. Scanning the source, though, there are no callers to this method. That, then, is the reason for the NPE – the “getDe()” method is being called without a previous call to “setDe()”.

Aftermath

Finding the problem is the first part – now you need to determine how to fix the problem. After reading the code, you notice that the C1 class has a method called “save()” that takes an instance of a DebugExample object as a parameter. It calls a method on that object, but it does not do anything else with it. From the method name (“save”), you can reasonably guess that the original writer of this code was planning to save the reference to the DebugExample object parameter. After fixing that, you find that the null you originally looked at on line 25 is indeed a problem, and you fix that as well.

Conclusions

The art of debugging is especially challenging when you don’t have access to the system where the failure occurs. It is necessary to become the computer, using logic to look for take the actual symptoms and reverse-engineer what must have been true to cause those symptoms. In doing this kind of work, it is key to not waste time looking at things that you have already proven could not be true.

A Complex Debugging Scenario

Here’s an example of a complex situation that did not involve a customer, but required extensive debugging work.

Background

This was a complex J2EE-based product with several web applications and EARs, plus several JARs that were directly added to the J2EE container (WebSphere Application Server) in order to provide us with some functions that extended the container’s function. This was a new release of the product, under active development. There were many third-party components present in the product, and we did not have access to the source code for most of them. We were using the IBM 1.5 JVM and WebSphere Application Server (WAS) version 6.1.2 (which was also being developed at the same time).

The major difference here relative to the previous scenario was that there were no customers involved. This provided several advantages:

• We had some level of direct access to all the systems involved.
  
• We had the ability to ask for detailed reproduction steps.
  
• We could try out possible solutions within reason
  

The major drawback, though, is that the development team was split between India and the US. This meant that when we wanted further information, we often had to wait a day to get it.

Scenario

The situation first came to light when two system testers in India reported out of memory errors while running tests during development of the previous release of the product. The problem was only reproducible on two systems – it was never seen anywhere else. Also, there was no real pattern that could be discerned so that we could attempt to reproduce the problem anywhere else.

As time went on, since the problem was confined to those two systems and had never been seen anywhere else, it was decided that we could release the product. We did increase the JVM maximum memory recommendations (the –Xmx option) “just in case”, but we never had any customer reports of issues. So, we were ready to chalk it up to “gremlins”.

However, after release, even with the larger memory, the problem continued to be seen by those two testers. As we worked on testing of the new product release, the same problem was still seen by those two testers. Even a month before release, problem was still being seen by them, but it was still never seen on any other systems. Since the problem had gone on so long, we decided to take a serious look in order to prove that it was not a case of “gremlins.”

Reproducing the Problem

The key issue to be addressed, clearly, was reproducing the problem. Every previous attempt had failed, so we knew that if it was a real issue, there must be something on those two systems that was different from all other systems. Several people thought they knew what was necessary to reproduce the problem, but there previous attempts to communicate those steps to others had apparently failed (again, assuming it was a real problem).

So, we asked for *exact* reproduction steps in writing from the testers who saw the problem. Every single step, no matter how minor, was requested. We told them to not leave out anything – even if something seemed obvious to them, they should write it down. Once we had those steps, we were extremely pedantic about making sure that every single step was executed in order to maximize the chances for reproduction. The reproduction steps that were finally delivered took an hour to run through. We needed to uninstall, reinstall, then run many other steps without restarting any servers. This was the first clue that something was different – every one else “knew” that you could start the servers after about half the steps, but these testers were waiting until almost the very end. That was an apparent difference.

Eureka Number 1

Finally, we successfully reproduced the problem on another system. This happened only after executing every single step we were given, even those that should not have had anything to do with the problem. Suddenly, this problem that had been pooh-poohed as “not a real problem,” suddenly was a legitimate issue.

Diagnosing the Problem

Now, we needed to gather data. The stack traces that came with the OutOfMemoryExceptions showed that the problem occurred when the JVM was attempting to load a new class. Every time that problem occurred, the top 15 lines of the stack traceback were the same. Once the problem occurred, WAS itself stopped working for a while. We could not use any WAS features, even including the WAS Integrated Solutions Console. We could do nothing with it. However, after a few minutes, the problem would clear up.

Since this was a memory issue, we used a memory profiling tool to observe overall JVM heap size during problem reproduction. However, we soon ran into a problem: monitoring with the profiler showed that we never got close to running out of heap space. The maximum size allowed was 1GB, but the peak size we ever observed was 600MB. The heap was rapidly oscillating between 300MB and 600MB during active testing, but it never got to be more than 60% of the total JVM size allowed.

Theories?

So the question was, why were we running out of memory when there was plenty available? It could not be a case of memory fragmentation, because there was still 400MB of contiguous space for new allocations. One theory was that JVM memory garbage collection (GC) was getting overloaded by rapid expansion/contraction cycles. However, that didn’t make sense. When the heap is full, the JVM should wait until GC reclaims memory before continuing. It shouldn’t be throwing memory errors.

More Diagnosis

We then decided to turn on a JVM option that enabled verbose garbage collection (WAS provides a checkbox to enable this easily, but it is also available on any JVM with the “–verbosegc” option). This writes data to the JVM console whenever GC ran, giving details on what GC does.

Once we did that, we noticed an odd pattern to the GC output. The GC log showed that many finalizers were being run during each GC run. What’s more, the longer the time between GC runs, the more finalizers were being run. In other words, when there was less activity on the system, CG would run less often, but there would paradoxically be more finalizers run during the fewer GC runs. In one case, 5 minutes between GC runs resulted in over 20000 finalizers being run. This told us that the finalizers were being created on the basis of time, not on the basis of load. But why were there so many finalizers in the first place?

Analysis

The main reason to have a finalizer is to release native resources for objects that are no longer needed, since GC knows nothing about native resources. This includes cleaning up JNI allocations. When GC wants to free up an object that has a finalizer, it instead calls the finalizer, and then leaves the object on the heal for the next GC pass to collect. This sounded good, but we had no JNI code, and we certainly had no finalizers. So, we concocted a new theory – some third party code was running a thread that periodically created finalizers. But which third-party code was it (we had many different packages in our product)?

In any case, it was still unclear why this would cause memory failures. After all, plenty of memory was available. Then, while reading more about how GC worked, we came across a reference to a “non-Java JVM heap.” We read that this heap is used for allocations not directly related to Java objects. For example, JNI allocations, or those for internal JVM maintenance, come from this other heap. The key items for us, though, were these: this heap is not garbage collected, and it is limited in size.

Thus, we now knew how it was possible to run out of memory even though the main JVM heap had plenty of memory remaining. Moreover, since we had so many finalizers running, we knew that someone must be causing these allocations to occur, and the evidence also indicated that they must be occurring in some thread that runs periodically (as opposed to in direct response to input requests to the product).

Eureka Number 2

Now we had a theory, but we still didn’t have a culprit. Each time the system failed, the stack traceback pointed to our own product code, and we knew that we could not be at fault. So, since we at least had a reproduction scenario, we kept repeating tests. Finally, we hit the jackpot. We got a stack traceback that had those same 15 lines being invoked from a thread created by a third party UI framework called Wicket.

Further Analysis

Now we started looking at the Wicket documentation, and noticed that new Wicket “Application” objects could be configured in either “Deployment” or “Development” modes. Since we could get access to the Wicket source, we read it, and found that “Development” mode caused a maintenance thread to look for changes to files that were part of the UI (HTML, Java classes, etc.). By default, this thread would run once per second! That sounded like were looking in the right place. Since we knew that the problem was time-based rather than load-based, we were looking for a thread running on a frequent schedule.

As we looked we found that the Wicket code did not directly create finalizers. However, it did use java.io classes to look at the file system for updated files. It would open and close directories quickly to look at modification dates. As we did further research, we found that when a java.io class opens a file, it drops to native code (JNI), and certain items are allocated in that JNI code. Those items, of course, came from the “non-Java JVM heap.” The java.io class then creates a finalizer to ensure that, when the corresponding Java class is scheduled to be GCed, the native heap items are cleaned up first. Ah ha!

Eureka Number 3

So the final question was, why would development mode be used by our product? So, we looked at our code that created the Wicket application, and found that it looked at a system environment variable to determine whether to run in “Development” or “Deployment” mode. This “feature” had been added when we converted from Tapestry to Wicket by a developer who wanted to do faster development of Wicket pages.

The problem was that this same environment variable used for other purposes, including allowing a re-initialization of our product’s database in case the data got corrupted. These two testers had that environment variable set “just in case” they needed to do this re-initialization. This was one of the steps that everyone had skipped because “it should not have caused the problem.”

We changed the code to always specify “Deployment” mode, regardless of the setting of the environment variable, and the problem went away!

Lessons

The important lessons here were:

• Do not take anything for granted when trying to reproduce a problem. If a problem cannot be easily reproduced, be extremely pedantic about following every step, and take notes on every step that is run.
  
• As a corollary, once again, attention to detail is required. The “gun-slinging” approach to debugging that software engineers learn in school, in this case, led to developers pooh-poohing the bug report. The earlier haphazard attempts to debug the problem led to developers believing that this wasn’t a real problem.
  
• Be aware of the native heap. Watch for finalizers being run by garbage collection – many finalizers is an indication of possible significant usage of the native heap.
  
• Verbose GC is your friend when diagnosing memory problems.
  
• Do not use existing environment variables that control some aspect of your product for other purposes. People will not realize that when the variable is set in a certain way, that other things are happening besides the ones they expect. Use a different variable instead.
  

Conclusions

So far, we have seen that debugging hard problems requires diligence, patience, and persistence. The early emphasis on a “gun slinging” approach to debugging will fail when you are presented with a truly difficult problem. I strongly suggest that every developer gets used to taking extra care when doing their own debugging – that way you won’t revert to early training when pressure is on.

Communication is also a real key when working on a hard problem. This can be especially challenging when a customer is involved. Don’t take anything for granted. Make sure all the people involved in the problem communicate everything they are doing - the smallest detail could end up being significant. As a side benefit, you will find that in many cases, people will appreciate it if you truly listen to them, especially customers.

Finally, always suspect your own code, even when the evidence points to third parties (e.g. the JVM, Wicket, etc.). Look for all the ways that you interact with that component. It may be that someone else made a change that you are unaware of that causes the component to behave unpredictably.

A Customer Debugging Scenario

As promised, here’s an example of debugging in a customer situation.

Background

This was a very complex web application written in Java, whose main operational requirements were only encoded in the behavior of an older application written in an arcane language known by fewer than a dozen people. There were many third-party/open source projects included in the application (like Tapestry, OJB, the Byte Code Engineering Library, etc.). One major component of this application was written new by a separate third-party. The server environment was WebSphere Application Server version 5.1, running on the IBM JVM version 1.4.

Among the most challenging things about this customer were the political issues. There was an institutional lack of trust throughout the company, exacerbated by the fact that the IT group had been split recently, with one part outsourced. There was little history between the client and the application supplier, and many client employees believed that the supplier was only in the account due to the drive of one executive. Thus, many of the client employees still expected the project to fail, with some people actively looking for an excuse to kill it.

Scenario

The first report we received from the customer was that the memory usage seemed excessive. There had been several out of memory exceptions in the past. We had told the client to increase the JVM maximum heap size to 384 MB, but they did not like that. They suspected that we had a memory leak and were covering it up by telling them to increase the JVM heap size. In this specific situation, client monitoring of the JVM showed that after running for several days in production, the application was getting close to the 384 MB memory maximum. They were making this determination after turning on verbose garbage collection (GC), using the memory usage minima after each GC cycle. Since the client could not afford a failure during business hours, they would restart the server when memory usage got “close” in order to avoid unplanned outages. Note that they never actually ran out of memory.When the client performed more detailed monitoring (via verbose GC), it showed that the number of pinned objects on the JVM heap was climbing gradually. This was concerning because pinned object growth causes memory fragmentation. The client claimed that this was enough evidence that there must be a memory leak, and they insisted on a resolution. However, we didn’t believe there was a problem, because it appeared that the memory growth was leveling off as it approached the maximum. However, it didn’t matter what we thought – we had to prove it to client.

Initial Research

The key issue that we had to address was this: what was causing the pinned object count to climb? Well, there are two types of objects that would be pinned when running on the IBM JVM:

• JNI objects, because memory allocated by JNI code cannot be moved (since it needs to be accessed by non-Java code that is not tolerant of memory movement. This was not an issue for us because we had no JNI code.
  
• Class objects. The IBM JVM cannot relocate class objects. This is generally not a problem because classes are mostly loaded during startup, and the JVM has a separate heap for these objects. However, since this was the only type of object that could be pinned in our application, this was what we would look for. (for more details on pinned objects, see http://www.ibm.com/developerworks/forums/thread.jspa?messageID=13771069).

We had no access to the customer system where the problem was happening (see my previous article, “Debugging in Customer Situations”), so we could only get the basic diagnostic information that we already had. We needed to reproduce it on our own systems. This meant that we needed to develop a path through the application that would produce growth in pinned objects. Once we had been successful, this would help us to observe other data and behaviors that might lead to a diagnosis.

Reproducing The Problem

We enabled verbose GC, and then ran a manual series of steps through the application that simulated the typical usage we expected. Unfortunately, the symptoms were not obvious. The number of pinned objects would not grow consistently. From one run to the next, the pinned object number would stay the same, grow, or even shrink on a few occasions. GC further contributed to the unpredictability – we would watch the number climb steadily, even through multiple GC cycles, and then suddenly, the number would shrink by a lot.After a while, it became clear that we needed another way to verify that this path would cause the problem. So, we used a GUI scripting tool to run the same path over and over, and let it run overnight. This did show a slow overall growth trend, which told us that we had a path that would reproduce the issue.

Diagnosing The Problem

Once we had a path, we needed to start watching all the pinned objects on the heap between runs of the test script. We used a memory profiling tool (JProfiler) that allowed inspection of live objects on the heap. However, the first several attempts were fruitless – they produced no data that we could view. We then realized that the JProfiler defaults caused IBM and Sun classes to be excluded from the data view. Since class definitions used both IBM and Sun classes, no data for class definitions was visible. We changed the defaults, and suddenly much more data was available.

The technique we then used was, when the pinned object count climbed (as reported by verbose GC), we looked for new class objects on the heap. We saw many different objects, but most were eventually reclaimed during a future GC cycle. We then noticed a curious thing: a pair of objects (one from an IBM package, the other from a Sun package) were allocated during the invocation of methods by reflection, and would remain through multiple repeating runs of the test scenario. In fact, large growth in the pinned object count always seemed to correlate with creation of these new objects.

So it seemed that we had a culprit, and we just needed to look at the code. However, these class objects had names that made it clear they corresponded to generated code. Thus, there was no code to directly look at. We then used a debugger to try stop at last point we could before code that performed the allocation. Sun reflection code was actually doing the allocation, though, and we could not set breakpoints in Sun code.

Back To Square One

So we returned to a basic question: Where were we using reflection? It turns out that we were using a third-party framework (Tapestry) for UI management. In Tapestry, method names were kept in configuration files, rather than being directly called. This meant that the methods had to be invoked via reflection. The framework cached results of these methods for performance, so that it did not invoke these methods every time the results were needed. Periodically, the cache results would be purged. Then Tapestry would invoke the method the next time the results were needed.

Try, Try Again

The net of all this was that the invocation pattern was highly complex. Lots of different activity or a long period of execution were required before the Tapestry cache would need to be reloaded. Assuming that the reflection invocations were the problem, we just needed to step through one, see these problem pinned objects, and we would be done. However, that did not work. The first time through this code via reflection, no objects with these names were being created. With nothing else to do, and with no further ideas forthcoming, we kept running the tests using GUI scripting tool, stopping in the debugger every time the code we cared about was being invoked via reflection.

Eureka!

On the 15th invocation (which required us to run over 2000 application round trips), we noticed two things: several objects disappeared, and two new class objects were created with the generated names we were looking for!

Or Is it?

Now, however, we had another problem: we had no access to the source code that was creating these objects (since it was a Sun class). So, we opened a problem report with the IBM JVM team. We had to present all this evidence to the JVM team, including the names of the generated class objects and of the actual Sun class that was allocating these objects. After getting rebuffed several times, we had to persistently repeat requests for the involvement of people who actually understood reflection code.

Eureka! Really!

Finally, we talked to a person in JVM support who was familiar with the refection source code. This person told us that on 15th invocation of any method via reflection, an optimization took place: the JVM “compiled” the code that performed the reflection invocation into a new class. This created the pinned objects!

And It’s Not A Bug!

Better yet, there was a finite number of methods to be invoked via reflection. Only those methods that were listed in the Tapestry configuration files would be invoked via reflection. So eventually, all reflection method invocations would be “compiled”. This meant that the pinned object growth was bounded! We presented this entire chain of evidence to the client, and after much debate, they accepted it.

Lessons Learned

There were several important lessons from this exercise:

• Attention to detail is required. The “gun-slinging” approach to debugging that software engineers learn in school is inappropriate when dealing with a customer situation.
• Watch out for debugging tool defaults that exclude potentially valuable data.
• Be aware of the possibilities for optimizations that could cause sudden changes in operation.
  
• Keep extensive notes on every debugging step. First, you don’t know which steps will eventually produce valuable results, and those notes could end up being key when you say, “so how did I get here?” Second, if there isn’t an actual code fix, the client will need to be led through the same steps in order to reach the same conclusion, which will make the notes invaluable.
• The JVM is probably correct, but you may need help to understand what it’s doing. After all, any JVM gets tested far more than your own code.
• Don’t take anything for granted.
  

Next, I’ll talk about a different debugging scenario that did not involve a customer, but was very difficult, to show a bit more about actual debugging techniques.