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.
