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.
