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.

Debugging In Customer Situations

When you are learning the art of software development in school, you learn to debug your programs in your own little cocoon. You are the customer, and your only goal is to make the program work. You can use a debugger to look at the program as is runs. You can run your code multiple times, each time with additional tweaks to try to solve the problem. You can use all your available tools at your discretion.

However, when you are providing software service in a professional environment, you are not the customer. You have to deal with someone else’s reality, which is much more constrained than what you experienced as you were learning. Customers have the concept of “production” systems, on which their day-to-day business runs. Since the customer is betting their business on these systems, changes to them are highly controlled. Any changes have to be demonstrated to work before they are deployed. There is no way any customer will agree to just “trying out” a fix on a production system.

Instead, customers have "working," "test," or "development" systems. These are the places where fixes and new applications are tried out before they get to production. If you have a fix for a customer to try, these types of systems will be the place. However, there are going to be many restrictions:

• Without production workloads, it may be difficult to reproduce the problem you are trying to solve.
  
• You are not going to have direct access to the system. In particular, you are not going to get the ability to use a debugger.
  
• Reproducing the problem will require involving the customer. That means working on their schedule, among other things.
  
• The fix must be packaged in such a way that the same fix can be applied to a production system reliably.
  
• You will have to deal with the politics of the customer relationship. In particular, you need to be careful to avoid the appearance of wasting the customer’s time, and you need to make sure they see constant progress towards a solution.
  

To net it out, remember that the customer is not your partner in the debugging process. They are looking to you to fix their problem, and they want a minimum of interaction other than status updates. So, this requires a different style of debugging than you learned in school.

Next, I'll give a real world example to show how this really happens. I'll also talk about techniques you can use in these situations.

Introduction

I'm Jim Babka, and have been a software engineer for 24 years. Over the course of my career, I have often been called upon to debug some very difficult problems, both in the office and at customer sites. This has given me a good perspective on designing code in the first place to make debugging easier. However, as I reflect upon my career, and as I have talked to many other highly skilled software engineers, I have realized that there is a wide disparity in practical debugging skills, even when people are otherwise equally skilled at writing code.

The reason for this is that many software developers have been left to their own devices to learn debugging. So, they have learned to use a “gunslinger” approach to debugging. This approach works well for class projects. However, it is unsuitable for professional development. The professional developer needs to put aside their early training (or lack thereof), instead incorporating a more disciplined and thorough approach to debugging that starts with good serviceability development techniques and ends up with deliberate methodology for debugging hard problems. While this may cause debugging to take longer in some cases, it will pay huge dividends when difficult problems get much scrutiny.

So, I decided to start this blog to discuss the serviceability and debugging techniques that are required for any enterprise software developer to be truly successful. It is my hope that some of the ideas here may eventually lead to improvements in the education and training of software engineers.