Have you ever been in the position where you have to look after a legacy app that has insufficient logging and non-deterministic problems? Whatsmore, it's running in production and that rare non-deterministic bug has just occurred. How do you diagnose it?
This task faced me last week. Looking at the code on my machine, I just couldn't see how the problem could manifest itself. "Afterall, there is only one instance of this object in the entire system, right?" I found myself saying. "It must be a bizarre and rare threading issue!"
So, I ran this on the production Linux box (where PID is the Java process ID):
$JAVA_HOME/jmap -histo:live PID | grep OUR_CLASS
and saw something like this (I've added the column headings for clarity):
num #instances #bytes class name
----------------------------------------------
9030: 2 200 OUR_CLASS
So, there were 2 instances of our class! All my recent investigation of odd threading issues was for naught!
This is one reason why the factory pattern is so nice - you know exactly where the objects are being instantiated (tip: make the class's constructor package protected and put the factory in the same package with no other classes in that package). As an added benefit, it makes writing test code easier.
Still, this isn't going to help you if some smart alec decides to introspectively instantiate an object of this class. But such a practice should be strongly discouraged.
Saturday, October 30, 2010
Testing and embracing change
My client can only be described as "Agile curious" rather than gung-ho disciples of our lord, Kent Beck. So, it was nice to see an email circulated on the company-wide technical mailing lists asking for help in writing automated regression tests. The author asked about the wisdom of serializing the output of all tests into XML and comparing them between runs.
I almost choked on my coffee. I worked on a project that did this last year and it was not pretty. So, I emailed him how using serialized objects in tests had worked for us:
I almost choked on my coffee. I worked on a project that did this last year and it was not pretty. So, I emailed him how using serialized objects in tests had worked for us:
1. It was fragile. Even minor refactoring of the Java objects would break the tests.
2. It didn’t scale. As the number of XML files that needed to be maintained increased, productivity declined. (At one point, we were maintaining about 20 megs of serialization XML.)
3. Java developers tend not to like maintaining large XML files as their Java code changes - so some refactoring of the XML was, shall we say, less than diligent...
4. Serializing Sets (or any other collection where the order in which the elements were serialized was non-deterministic) could break the tests. For a time, some developers were hacking the problem domain classes to make the order deterministic just so the tests would pass.
More volatility
Wondering why one of our legacy apps seems to be having thread issue, I continued digging into the recesses of the Java Memory Model.
Volatile is a fascinating keyword since many excellent Java programmers don't appreciate its finer points. An engineer I much admire told me that he only used it for boolean primitives when telling threads to stop running. Fair enough, but there is more to it than that. Here are some:
1. What if we're not using volatile primitives? What if we're using, say, an array? Can I be sure that setting an element of the array is volatile too and will be seen by other threads? Apparently not, according to Google's Jeremy Manson in this tutorial (about 40' into the video) where he says: "there is no way to make the elements of an array volatile... the reference to the array is volatile not the elements of the array itself".
2. Furthermore, the performance of volatile is generally pretty good. "On an x86 there is no cost in reading a volatile variable. There is a cost to writing to a volatile variable but not reading... as of 2007".
3. On some hardware, 64-bit read/writes are not atomic but "writes and reads of volatile long and double values are always atomic" (Java Language Specification 17.7).
4. The order of the lines of your code that a JVM executes can also be changed by volatile (you did know the order of execution may differ to how you wrote your code, right?). Brian Goetz explains:
"Under the old memory model, accesses to volatile variables could not be reordered with each other, but they could be reordered with nonvolatile variable accesses. [...]
Incidentally, this does mean that if you write code that is fine in JDK 1.5+, it might not be fine running on older machines. If you really want to write-once-run-anywhere Java, you should assume you're writing for the old JMM and make all variables volatile for whom the order of execution of read/write operations is important.
So, did all of this help me to fix the buggy legacy app? No. Every time I have cast a suspicious eye at the finer points of the JMM, it has actually been a much more mundane bug that was the culprit. In this case, it turns out that somebody, somewhere was introspectively calling one of our methods that starts threads - a call that is very hard to find with most IDEs.
Evil.
Volatile is a fascinating keyword since many excellent Java programmers don't appreciate its finer points. An engineer I much admire told me that he only used it for boolean primitives when telling threads to stop running. Fair enough, but there is more to it than that. Here are some:
1. What if we're not using volatile primitives? What if we're using, say, an array? Can I be sure that setting an element of the array is volatile too and will be seen by other threads? Apparently not, according to Google's Jeremy Manson in this tutorial (about 40' into the video) where he says: "there is no way to make the elements of an array volatile... the reference to the array is volatile not the elements of the array itself".
2. Furthermore, the performance of volatile is generally pretty good. "On an x86 there is no cost in reading a volatile variable. There is a cost to writing to a volatile variable but not reading... as of 2007".
3. On some hardware, 64-bit read/writes are not atomic but "writes and reads of volatile long and double values are always atomic" (Java Language Specification 17.7).
4. The order of the lines of your code that a JVM executes can also be changed by volatile (you did know the order of execution may differ to how you wrote your code, right?). Brian Goetz explains:
"There is no guarantee that operations in one thread will be performed in the order given by the program, as long as the reordering is not detectable within that thread - even if the reordering is apparent to other threads"
(Java Concurrency in Practise, p34).
However, when we introduce volatile :"Under the old memory model, accesses to volatile variables could not be reordered with each other, but they could be reordered with nonvolatile variable accesses. [...]
Under the new memory model, it is still true that volatile variables cannot be reordered with each other. The difference is that it is now no longer so easy to reorder normal field accesses around them... In effect, because the new memory model places stricter constraints on reordering of volatile field accesses with other field accesses, volatile or not, anything that was visible to thread A when it writes to volatile field f becomes visible to thread B when it reads f."
Incidentally, this does mean that if you write code that is fine in JDK 1.5+, it might not be fine running on older machines. If you really want to write-once-run-anywhere Java, you should assume you're writing for the old JMM and make all variables volatile for whom the order of execution of read/write operations is important.
So, did all of this help me to fix the buggy legacy app? No. Every time I have cast a suspicious eye at the finer points of the JMM, it has actually been a much more mundane bug that was the culprit. In this case, it turns out that somebody, somewhere was introspectively calling one of our methods that starts threads - a call that is very hard to find with most IDEs.
Evil.
Wednesday, October 27, 2010
A little volatile
Time to refresh my memory: what is the volatile modifier for?
The answer given by most Java programmers I've interviewed recently is that it makes the value the reference points to visible to all threads. This is true but not the whole story.
When I first came to appreciate the Java Memory Model I was surprised like almost everybody else to see that the value of a single field may be different for two different threads. This is not something peculiar to Java. Any hardware that conforms to a Von Neumann architecture (which is pretty much every common processor) can run faster if it uses its CPU's registers to store references rather than main memory (RAM).
Making a reference volatile means that it will be published to main memory (accessible by all threads) rather than being stored in a CPU's register (accessible by only that thread). But it also means:
1. Its published state is safe
If a field of an object is being instantiated, potentially other threads have access to it. However, they may reference it before the instantiating thread has left the constructor. If the object is not immutable, this can lead to inconsistent data. Using volatile is one way to eliminate this.
To ensure safe publication, Java code needs to do at least one of the following:
2. All other variables are flushed to main memory
"When thread A writes to a volatile variable and subsequently thread B reads that same variable, the value of all variables that were visible to A prior to writing to the volatile variable become visible to B after reading the volatile variable."
(Java Concurrency in Practise, p38)
The reason I am re-reading Mr Goetz's excellent book is that I have been asked to diagnose a threading issue in some legacy code where I came across the Double Checked Locking idiom (see this link for what it is and why it's pathological). It's been a long time since I saw DCL code or even the Singleton pattern (singletons are hard to test and, in this day of dependency injection, largely redundant). But something I read that I had forgotten was:
"To ensure that all threads see the most up-to-date values of shared mutable variables, the reading and writing threads must synchronize on a common lock"
(ibid, p37, emphasis mine).
DCL is fixed if one uses volatile, according to Jeremy Manson, co-author of the JSR-133 and JLS that deals with threads and synchronization. Since the old code does not use volatile, I suspect this may be the cause of our problem. However, now I need to prove it - not easy when you're dealing with Heisenbugs.
The answer given by most Java programmers I've interviewed recently is that it makes the value the reference points to visible to all threads. This is true but not the whole story.
When I first came to appreciate the Java Memory Model I was surprised like almost everybody else to see that the value of a single field may be different for two different threads. This is not something peculiar to Java. Any hardware that conforms to a Von Neumann architecture (which is pretty much every common processor) can run faster if it uses its CPU's registers to store references rather than main memory (RAM).
Making a reference volatile means that it will be published to main memory (accessible by all threads) rather than being stored in a CPU's register (accessible by only that thread). But it also means:
1. Its published state is safe
If a field of an object is being instantiated, potentially other threads have access to it. However, they may reference it before the instantiating thread has left the constructor. If the object is not immutable, this can lead to inconsistent data. Using volatile is one way to eliminate this.
To ensure safe publication, Java code needs to do at least one of the following:
- initialize the object from a static initializer
- store the reference in a final field
- store the reference in a volatile field
- store the reference in a java.util.concurrent.atomic.AtomicReference
- guard the reference in an appropriate lock
2. All other variables are flushed to main memory
"When thread A writes to a volatile variable and subsequently thread B reads that same variable, the value of all variables that were visible to A prior to writing to the volatile variable become visible to B after reading the volatile variable."
(Java Concurrency in Practise, p38)
The reason I am re-reading Mr Goetz's excellent book is that I have been asked to diagnose a threading issue in some legacy code where I came across the Double Checked Locking idiom (see this link for what it is and why it's pathological). It's been a long time since I saw DCL code or even the Singleton pattern (singletons are hard to test and, in this day of dependency injection, largely redundant). But something I read that I had forgotten was:
"To ensure that all threads see the most up-to-date values of shared mutable variables, the reading and writing threads must synchronize on a common lock"
(ibid, p37, emphasis mine).
DCL is fixed if one uses volatile, according to Jeremy Manson, co-author of the JSR-133 and JLS that deals with threads and synchronization. Since the old code does not use volatile, I suspect this may be the cause of our problem. However, now I need to prove it - not easy when you're dealing with Heisenbugs.
Sunday, August 15, 2010
Emergent (Mis)behavior
I've been puzzling for a while over why our bond allocation program would suddenly hang when under stress.
Fortunately for us, we have a good test harness and I could attach a profiler and watch and wait for it to happen. Eventually, it did:
Emergent behaviour as all threads spontaneously start contending for a resource
All the threads found themselves in the same logjam - but for no discernible reason. It was like a spontaneous "phantom jam" on a motorway (there is an interesting computer simulation of exactly this in a video here).
It was clear where the threads were choking (mentioned here).
But why did an innocent - if not particularly efficient - piece of code cause the system to grind to a halt?
Well, it's all down to something called emergent behaviour - or Emergent (Mis)behavior as Jeffrey C. Mogul calls it in his excellent paper here. One (of many) definitions is:
Emergent behavior is that which cannot be predicted through analysis at any level simpler than that of the system as a whole.
Mogul's paper does not address the question of whether emergent behaviour is a property of the system or a function of our ignorance. But he does give many examples of where it has occurred in software systems and gives a warning to the architects of SOA systems. Service Oriented Architecture emphasises a separation of concerns:
The fundamental benefit to solving problems this way is that a number of the solution logic units can be designed to solve immediate concerns while still remaining agnostic to the greater problem.
(SOA, Principles of Service Design, p70 - Thomas Erl)
Although it's a good design principle that helps minimize maintenance costs, it can lead the unwary into a false sense of security. To avoid this, one can only watch a system's behaviour in a test environment for a long period of time - time that most projects don't have. Most projects fix these problems once they have gone live.
There is very little literature in this area but Mogul attempts to build a taxonomy of emergent misbehaviour with the hope that one day we'll be better equipped to say what a particular system may be prone to it.
Emergent behaviour also occurs in non-computer systems. As examples: it was not obvious from the constitution of the Weimar Republic that it could allow the rise of a tyrant like Hitler; the book Freakonomics describes many examples where unexpected behaviour arises in otherwise well-understood systems; the designers of the Millennium Bridge in London understood footbridges and understood how crowds behave on them but did not predict how the crowds response to the bridge would feed back into how the bridge behaved under load.
Regarding this last example, Dr Mogul points out that although this phenomena was know, no quantitive analysis existed. The same problem still afflicts IT community.
Monday, August 9, 2010
Hash brown-outs
How do you tell if a production server has a memory leak? Simply run:
$JAVA_HOME/jmap -dump:file=/tmp/dump_file PID
and then load the file into your profiler of choice and see where all the memory is being used.
I had to do this last week. As it happened, there wasn't a memory leak but a ConcurrentHashMap that was being populated faster than its elements could be consumed.
The interesting thing was that the memory profile looked all wrong. To see what I mean, we have to look closer at ConcurrentHashMap.
What is a ConcurrentHashMap?
ConcurrentHashMap is a map that more than one thread can read and update without any fear of ConcurrentModificationExceptions being thrown.
How does it do this?
ConcurrentHashMap is basically a hash table of hash tables. These inner hash tables are called "segments". Threads that insert elements only lock one of these segments. This is one way that ConcurrentHashMap improves throughput.
Threads that wish to read do not use locking. Instead, you see in the code, snippets like this:
transient volatile HashEntry[] table;
.
.
.
HashEntry getFirst(int hash) {
HashEntry[] tab = table;
return (HashEntry) tab[hash & (tab.length - 1)];
}
Without the method-scoped pointer (tab) pointing to the object-scoped pointer (table) on the first line of the method, the second line would have a race condition. That is: the table may change size as the array index was being calculated. This would return the wrong element.
Of course, this means that between the first and the second line, tab may have become stale. The danger is that this method could return an element that another thread had already removed from the "real" table.
[Aside: pointing a reference (tab) to another reference (table) is, of course, atomic ("Writes to and reads of references are always atomic, regardless of whether they are implemented as 32 or 64 bit values." - Java Language Spec 17.7, 3rd Edition).]
The JavaDocs do warn you about this potential "staleness" when it says:
"Retrievals reflect the results of the most recently completed update operations holding upon their onset."
A bug in ConcurrentHashMap
Back to my memory dump. The problem seen in the ourput from jmap was that all of the objects we wanted to store in the ConcurrentHashMap were in just one segment rather than being evenly distributed. The code of ConcurrentHashMap that determines which segment into which an object is to be inserted looks like this:
final Segment segmentFor(int hash) {
return segments[(hash >>> segmentShift) & segmentMask];
}
Where hash is the hashCode of our object and segmentShift is 28 for the default constructor of ConcurrentHashMap. Reducing this significantly means gobbling huge amounts of memory.
Shifting an Integer to the right 28 times means only a very small range of numbers that can be stored in a 32-bit Integer are useful - those greated than 2 e 29 and less than -2 e 29.
This bug is mentioned here but Sun/Oracle appear to say it is fixed in my version of Java when it definitely isn’t (as the source code shows).
This leaves us with the choice of hacking our hashCode() method to achieve these extreme numbers or grin and bear it until we upgrade our Java to a version that has fixed this problem.
It's not a major issue so it looks like the latter.
$JAVA_HOME/jmap -dump:file=/tmp/dump_file PID
and then load the file into your profiler of choice and see where all the memory is being used.
I had to do this last week. As it happened, there wasn't a memory leak but a ConcurrentHashMap that was being populated faster than its elements could be consumed.
The interesting thing was that the memory profile looked all wrong. To see what I mean, we have to look closer at ConcurrentHashMap.
What is a ConcurrentHashMap?
ConcurrentHashMap is a map that more than one thread can read and update without any fear of ConcurrentModificationExceptions being thrown.
How does it do this?
ConcurrentHashMap is basically a hash table of hash tables. These inner hash tables are called "segments". Threads that insert elements only lock one of these segments. This is one way that ConcurrentHashMap improves throughput.
Threads that wish to read do not use locking. Instead, you see in the code, snippets like this:
transient volatile HashEntry[] table;
.
.
.
HashEntry
return (HashEntry
}
Without the method-scoped pointer (tab) pointing to the object-scoped pointer (table) on the first line of the method, the second line would have a race condition. That is: the table may change size as the array index was being calculated. This would return the wrong element.
Of course, this means that between the first and the second line, tab may have become stale. The danger is that this method could return an element that another thread had already removed from the "real" table.
[Aside: pointing a reference (tab) to another reference (table) is, of course, atomic ("Writes to and reads of references are always atomic, regardless of whether they are implemented as 32 or 64 bit values." - Java Language Spec 17.7, 3rd Edition).]
The JavaDocs do warn you about this potential "staleness" when it says:
"Retrievals reflect the results of the most recently completed update operations holding upon their onset."
A bug in ConcurrentHashMap
Back to my memory dump. The problem seen in the ourput from jmap was that all of the objects we wanted to store in the ConcurrentHashMap were in just one segment rather than being evenly distributed. The code of ConcurrentHashMap that determines which segment into which an object is to be inserted looks like this:
final Segment
return segments[(hash >>> segmentShift) & segmentMask];
}
Where hash is the hashCode of our object and segmentShift is 28 for the default constructor of ConcurrentHashMap. Reducing this significantly means gobbling huge amounts of memory.
Shifting an Integer to the right 28 times means only a very small range of numbers that can be stored in a 32-bit Integer are useful - those greated than 2 e 29 and less than -2 e 29.
This bug is mentioned here but Sun/Oracle appear to say it is fixed in my version of Java when it definitely isn’t (as the source code shows).
This leaves us with the choice of hacking our hashCode() method to achieve these extreme numbers or grin and bear it until we upgrade our Java to a version that has fixed this problem.
It's not a major issue so it looks like the latter.
Sunday, August 1, 2010
Go test, young man
Since I've had a week of testing, I thought I'd share some thoughts on an area much neglected by most Agile methodologies: non-functional testing. Everybody knows it's important but most books only make a passing reference to it.
Stress Tests
Since I have my copy of Pressman sitting next to me, I'll use his definition:
Stress tests are designed to confront programs with abnormal situations. In essence, the tester who performs stress testing asks: "How high can we crank this up before it fails?"
(Software Engineering: A Practitioners Approach - Roger S Pressman)
The trouble is: what defines "fails"? For a web application, it might be when the time it takes to service a request exceeds a predefined limit. But which metric and at which point in time? The average time? And which average - mean or median? Or maybe the 90% line? And what if it just spikes momentarily then settles down? Has the test failed at this point? I don't have the answers.
Sufficient for us was when our system started throwing (ie, the first one) non-deterministic ConcurrentModificationExceptions after the code naively tries 5 times to change a data structure other threads are changing (this poor design is fixed in the next release).
Look out for deadlocks in your code during these tests. The annoying thing about deadlocks is that they tend to happen when your system is most under stress so now is a chance to catch them rather than when a production release has gone live and is getting hammered. The JConsole that comes with JDK6 can do this detection automatically for you.
Soak Tests
For want of a better reference, Wikipedia defines Soak Tests as "testing a system with a significant load extended over a significant period of time".
For most practical purposes, this boils down to memory leaks. My advice is to attach JConsole and look and look at the memory of the JVM. Then start the stress tests and go home. The following morning, look at the pretty graph JConsole has produced. It should be a nice saw-tooth shape with the average remaining pretty much constant.
Test Harnesses
Apache's JMeter should be good enough for most of your needs. But the question of "who watches the watchmen?" [quis custodiet ipsos custodes?] has never been more important. Two gotchas that got me were:
Performance Testing
Put together a test with typical usage metrics. I once worked for a company that had outsourced a lot of it's coding. The legal draft contract stated that access to page X would take place in no more than 2 seconds. The vendor must have been rubbing its hands with glee as that should have been easy to achieve with just one person using the system. The draft never specified the number of concurrent users. If the system didn't scale, it was legally no longer the vendor's problem. They had met their contractual obligation.
"Performance tests ... often require both hardware and software instrumentation" says Pressman. On Linux, it should be sufficient to run the top command to get a good idea of CPU usage (vmstat is also useful if you want to monitor IO). The stat that is the most interesting is the load average. If this number is greater than your number of CPUs, work is starting to backlog. Or, to put it another way:
“If there are four CPUs on a machine and the reported one-minute load average is 4.00, the machine has been utilizing its processors perfectly for the last 60 seconds”
Linux Journal Dec 1 2006
Profiling
You can use your performance tests to drive your system while you profile the JVM. There are (as ever) some caveats:
java.net.SocketInputStream.read(byte[], int, int)
java.io.BufferedInputStream.fill()
java.io.BufferedInputStream.read()
java.io.DataInputStream.readInt()
Stress Tests
Since I have my copy of Pressman sitting next to me, I'll use his definition:
Stress tests are designed to confront programs with abnormal situations. In essence, the tester who performs stress testing asks: "How high can we crank this up before it fails?"
(Software Engineering: A Practitioners Approach - Roger S Pressman)
The trouble is: what defines "fails"? For a web application, it might be when the time it takes to service a request exceeds a predefined limit. But which metric and at which point in time? The average time? And which average - mean or median? Or maybe the 90% line? And what if it just spikes momentarily then settles down? Has the test failed at this point? I don't have the answers.
Sufficient for us was when our system started throwing (ie, the first one) non-deterministic ConcurrentModificationExceptions after the code naively tries 5 times to change a data structure other threads are changing (this poor design is fixed in the next release).
Look out for deadlocks in your code during these tests. The annoying thing about deadlocks is that they tend to happen when your system is most under stress so now is a chance to catch them rather than when a production release has gone live and is getting hammered. The JConsole that comes with JDK6 can do this detection automatically for you.
Soak Tests
For want of a better reference, Wikipedia defines Soak Tests as "testing a system with a significant load extended over a significant period of time".
For most practical purposes, this boils down to memory leaks. My advice is to attach JConsole and look and look at the memory of the JVM. Then start the stress tests and go home. The following morning, look at the pretty graph JConsole has produced. It should be a nice saw-tooth shape with the average remaining pretty much constant.
Test Harnesses
Apache's JMeter should be good enough for most of your needs. But the question of "who watches the watchmen?" [quis custodiet ipsos custodes?] has never been more important. Two gotchas that got me were:
- too much monitoring in JMeter causes it to use a lot of memory and start performing poorly thus giving false data.
- my test code had a memory leak. I had to connect to the system I was testing using in-house code. This code tries to connect to a messaging system to send audits for each request to the system. If it cannot, it quietly stores the messages in memory for sending later. And so, it is the test harness that slowly runs out of memory not the system under test. This is generally not your first thought. I fixed this problem by getting the source code of the client JAR and commenting out this call before redeploying the test harness.
Performance Testing
Put together a test with typical usage metrics. I once worked for a company that had outsourced a lot of it's coding. The legal draft contract stated that access to page X would take place in no more than 2 seconds. The vendor must have been rubbing its hands with glee as that should have been easy to achieve with just one person using the system. The draft never specified the number of concurrent users. If the system didn't scale, it was legally no longer the vendor's problem. They had met their contractual obligation.
"Performance tests ... often require both hardware and software instrumentation" says Pressman. On Linux, it should be sufficient to run the top command to get a good idea of CPU usage (vmstat is also useful if you want to monitor IO). The stat that is the most interesting is the load average. If this number is greater than your number of CPUs, work is starting to backlog. Or, to put it another way:
“If there are four CPUs on a machine and the reported one-minute load average is 4.00, the machine has been utilizing its processors perfectly for the last 60 seconds”
Linux Journal Dec 1 2006
Profiling
You can use your performance tests to drive your system while you profile the JVM. There are (as ever) some caveats:
- There's a testing version of the Heisenberg Uncertainty Principle: the act of observation affects the system. Profiling adds an overhead so do this as well as your non-profiling performance tests.
- Just because your profiler shows that a particular method takes a long time it doesn't mean it did a lot of work. Message driven systems will typically spend a lot of time waiting for something to happen. This shows up in the profiler as a method that is "hogging" CPU time. This is a false interpretation. Another common time "hog" is waiting IO code - typically this is an order of magnitude greater than your code in a server. So don't be surprised if you see a lot of time spent here:
java.net.SocketInputStream.read(byte[], int, int)
java.io.BufferedInputStream.fill()
java.io.BufferedInputStream.read()
java.io.DataInputStream.readInt()
Subscribe to:
Posts (Atom)
