Wednesday, December 9, 2009

The Dreadful JMX Tunneling Problem

JMX is notoriously difficult to access remotely. It relies on RMI which means that you need a connection to an RMI registry and a separate connection to an RMI server. The port (and host name) to be used for the second connection are assigned by the RMI registry, and can thus not be "guessed" in advanced.  This makes it almost impossible to setup the necessary port forwarding or ssh tunnels to access JMX on a server which is not directly in your network.

We used to use JBoss, which provides a html wrapper around the MBean server ("jmx-console"), thus allowing easy access to our MBeans. It's not as nice and graphical as JConsole, but at least http is easy enough to tunnel through ssh or firewalls.

After switching to tomcat (for various other reasons), I was looking for a solution to this "access our MBeans through ssh tunnels"-problem. There are all kinds of workarounds available to make RMI "tunnelable', but everything I tried came with its own set of problems (for example having to append stuff on the class path of JConsole).

So if tunneling turned out not to be a viable option, I started looking for html based alternatives like the "jmx-console" from JBoss. I found a couple of them:
JManage looks very nice and feature complete but it has the downside of being a standalone application running an embedded jetty rather than something I can simply deploy in tomcat.
• On some mailing list I found somebody who once created an application called "jmx-console" which does what I want. I tried it and it seemed to work OK, but it's an old and unmaintained project.
Coldbeans has an application written entirely in JSP. When testing it, it found it somewhat cumbersome to work with though, and I couldn't seem to access all my MBean operations (as if some of them where "read only").

During my search, I learned that the original reference implementation for JMX (or now in http://opendmk.dev.java.net/) contains a class named HtmlAdaptorServer, which didn't make it into JDK 5 when JMX was first introduced. The reference implementation is still usable in itself though (in maven2 repository as com.sun.jdmk:jmxtools:1.2.1). This HtmlAdaptorServer does exactly what I need: expose MBeans in a straightforward html view. I simply instantiate it in a ServletContextListener like this:

final HtmlAdaptorServer adapter = new HtmlAdaptorServer(port);
ManagementFactory.getPlatformMBeanServer().registerMBean(adapter, new ObjectName("my.domain:name=htmladapter,port=8000"));
adapter.start();

Although this is a good enough solution for me right now, I still think some configuration options to make JMX/RMI easily 'tunnelable' (being able to fix the port and host name would probably be enough) are something we should consider adding to the JDK...

Thursday, October 29, 2009

A performance tuning story

Recently at work, we were performance testing a few use cases of an application which are completely bottlenecked by the database. Actually, we were trying to figure out how much data we could input in the system, while sustaining the required response times. The "input into system" use cases obviously involves a few "insert" operations on the database, but also a few "select" queries on what is already in the database for verification of the inserted data etc. Initially we simply wanted to see how the performance of this "input into system" use case degrades when the database gets filled more and more.

A colleague of mine performed the tests (thanks Bart, if you are reading this), and created some nice graphs of the results. One of these graphs looks like this:

On the vertical axis you can see the response times. On the horizontal axis the number of "input into system" operations that have already been performed.

You notice that, as expected, the performance degrades as the database is filled with more data. But something strange is visible: the response times bounce up and down between some kind of minimum and maximum. Response times for individual requests seem to be either "slow", either "fast". We were convinced that if we could find the cause of the response times sometimes being slow, we could fix it, and all response times would be on the lowest line in the graph.

This is where the discussion started to diverge. We started thinking about all kinds of possible explanations as to why this could be the case. Many graphs where produced and many tests conducted, to try and figure out what the underlying cause could be.

Although this kind of reasoning is highly enjoyable, and watching all these graphs is very intriguing indeed, I proposed a more pragmatic approach: lets just find the slowest query in the system and try to improve that one... without bothering about trying to explain the strange graphs. Or as Kirk Pepperdine would say: "big gains first".

A quick check with vmstat confirmed our initial idea that the database was indeed the bottleneck. The MySQL process was using all of the CPU (user time). This also meant that I/O was not the problem. MySQL probably had all the data cached in memory, but some query (or queries) demanded lots of CPU time to be executed.

Next we added logging of the database queries being executed using P6Spy. We let the test run for a few minutes and then opened the log in IroneEye. This gives a nice overview of all the queries that have been executed, with their execution times. One query came out as being about 5 times slower as the other ones. We had a look at the actual query, and it turned out not only to be slow but also incorrect. The corrected version of the query had to do less joins, and was much faster. Running the test again resulted in a constant linear degradation of the response times, as expected.

Actually, when running the test for a longer time, the bouncing up and down pattern came back. This time it was much less severe though, and it happened only when much more data was already in the system. We'll probably have to hunt down the next slowest query now, in order to try and improve the situation even more.

Taken all together, it took us only 30 minutes or so to perform the test with P6Spy, analyze the logs with IroneEye, find the slowest query, fix the query and run the test again. Compared to endless discussions about possible explanations for the strange behaviour, the pragmatic approach clearly won in this case. Agreed, the pragmatic approach didn't help us to explain why the response times are sometimes slow, sometimes fast... but who cares, it's much faster now anyway, and we fixed an incorrect query in the process.

On a side note... P6Spy and IroneEye seem both rather dead. IroneEye can not even be downloaded anymore. Does anybody know a more alive (and free) alternative? I could probably look into the tools of the database vendors (MySQL in our case) themselves, but they are typically not free and maybe also not so easy to setup?

Tuesday, August 11, 2009

Mysterious JVM crashes explained

We've recently suffered from mysterious crashes of the JVM running our application server. The JVM (Sun JDK 1.5.0_06 but it was later reproduced with JDK 1.6.0_14 as well) simply crashed with all sorts of memory related errors. A few examples:

java.lang.OutOfMemoryError: requested 8388608 bytes for uint64_t in /BUILD_AREA/jdk1.5.0_06/hotspot/src/share/vm/utilities/growableArray.cpp. Out of swap space?
java.lang.OutOfMemoryError: requested 157286476 bytes for JvmtiTagHashmapEntry* in /BUILD_AREA/jdk1.5.0_06/hotspot/src/share/vm/prims/jvmtiTagMap.cpp. Out of swap space?
java.lang.OutOfMemoryError: requested 16 bytes for CHeapObj-new. Out of swap space?

The server was not out of swap space and it had plenty of free memory left, so that was not the problem.

I started googling around and found lots of different mentions of these kinds of problems, but there turned out to be many possible causes.

In our case, the problem turned out to be that we allowed the JVM to use too much memory... The JVM was configured with a 2GB heap (and 256MB of perm size), and was running on a 32bit machine with 4GB of memory (linux 2.6.x kernel without hugemem or anything like that). As it turns out, in this kind of configuration, linux allows each process to allocate at most a little over 3GB. When our application was requiring a lot of memory, the JVM was trying to (perhaps temporary, to perform garbage collection) allocate more memory than it is allowed to by the linux kernel, resulting in one of the above types of crashes.

Configuring the JVM with a smaller heap (1.5GB) caused our application to simple go out of memory with a regular "java.lang.OutOfMemoryError: Java heap space". But now at least, it didn't just crash, and after a few hours with a memory profiler (YourKit), the cause of the excessive memory usage in our application was found as well.

I still wonder if the JVM or the linux kernel could arrage for a more meaningful error message though.


Saturday, June 27, 2009

Consistent SVN branch and tag names for maven projects

When using maven together with subversion (SVN), it is good to have a naming strategy for your branches and tags which is consistent with the maven versions of your projects (in the pom.xml files). A consistent naming strategy makes it trivial to know which version of a maven project can be found where in the SVN repository (and vice versa), and it prevents possible version conflicts between maven projects when for example branching twice from the same starting point.

We designed a simple scheme at work which suits us well. I thought I might as well share it, you might find it useful.
  • In principle, we have a X.Y.Z numbering scheme for all our maven projects (but having only one or two numbers would be possible as well); for example someproject-3.4.4.
  • All main development happens on trunk (for the "current" release). A maven project on trunk thus has a version number X.Y.Z-SNAPSHOT; for example someproject-3.4.5-SNAPSHOT.
  • When releasing a maven project, the word "SNAPSHOT" is removed from the version; for example someproject-3.4.5. On trunk, development continues with the next SNAPSHOT version; for example someproject-3.4.6-SNAPSHOT (or perhaps 3.5.0-SNAPSHOT or even 4.0.0-SNAPSHOT).
  • A released project is tagged in SVN as ${artifactId}-${version}; for example http://svnserver/svnrepo/tags/someproject-3.4.5.
  • A branch (for fixes in "old" releases) is always taken starting from a tag. Branching a project tagged with version X.Y.Z results in a branch SVN directory called X.Y.Z.1.x; for example http://svnserver/svnrepo/branches/someproject-3.4.5.1.x (the 1 means "first branch", the x indicates that that is the only part of the version which changes in this branch during the lifetime of the branched project).
  • If another branch is taken from the same tag, it becomes X.Y.Z.2.x etc (This actually corresponds to how CVS does it: branching introduces two extra numbers); for example http://svnserver/svnrepo/branches/someproject-3.4.5.2.x.
  • The version of the maven project in a branch follows this naming strategy; for example the maven version of the project in .../branches/someproject-3.4.5.1.x is initially 3.4.5.1.0-SNAPSHOT.
  • Releasing from a branch results in a tag with 5 numbers; for example the first release would be someproject-3.4.5.1.0 and the branch would continue with 3.4.5.1.1-SNAPSHOT.
  • Branching on a branch is also possible, just add another two numbers; for example X.Y.Z.1.2.1.x (first branch of the second release from that first branch of project with version X.Y.Z). In our case, this has been necessary only once though.
I guess we aren't the first team to invent this, but I have never seen it written down for the SVN/maven combination like this.

Tuesday, June 23, 2009

How to provide hibernate persistence support along with class libraries

Suppose you want to encapsulate some kind of functionality in a class library, and you want to provide an easy way for the clients of your library to persist certain entities from your library with hibernate. I think the most straight forward way to do this, is to provide hibernate UserType implementations along with the entities in the class library that the client might want to persist. Joda Time for example, uses this approach. Joda Time is a class library to work with dates and times, and the Joda Time Hibernate Support project provides hibernate UserType implementations for many of the entities from Joda Time.

This approach works perfectly well, but it is limited to what one can express in a hibernate UserType. One of those limitations is that you can not (or almost not) use a single UserType to persist an entity that has a one2many relationship with something else (probably a value type). I encountered this problem when writing a class library to manage IP address pools (an IP address pool is a continuous range of IP addresses of which some are "free" and some are "allocated"). I represent an IP address pool as a class (IpAddressPool) which contains a sorted set of free sub-ranges in the pool. Persisting this would naturally result in a one2many mapping (using hibernate to map the SortedSet). Writing a single UserType which is capable of persisting IpAddressPool instances (including the one2many mapping) is (almost) not possible. I say almost, because it might be possible to access the JDBC connection directly and do everything by hand, but obviously I would like hibernate to manage the one2many relation.

So, when UserType implementations are not an option, what other options do we have?

  • we can simply do nothing and leave it up to the client to create the necessary hibernate mappings;
  • we can provide a mapping and a perhaps even a DAO and let the client use that by "injecting" its session factory into it;
  • we can do the same with annotations;
  • we can prevent the one2many mapping by serializing the sorted set into a single string representation or something like that, and use a simple UserType after all;
  • ... ?

The first solution is not really a solution at all. Apart from not helping the client of your library with the persistence aspect, it also means that we need to expose the internals of our classes such that clients can write correct hibernate mapping files for them.

The second solution is a bit better, but still not as good as the UserType approach. It typically results in having two mapping files (one from the class library, one from the client application) and thus complicates things like schema generation. It also makes it more cumbersome to integrate it with your client application. The provided DAO for example, might not be aligned with the DAO style of the client application, or the DAO might not provide certain queries the user wants to perform. Also, the client application might use annotations to express the hibernate mappings, while the class library uses an XML mapping file. Querying on properties of the entity in the class library is possible, but it means the internal representation has to be exposed. The UserType (and more specifically CompositeUserType) API has a nicer way to expose properties on which HQL queries can be performed without having to expose the internals of the entities in your class library, which can unfortunately not be used in this solution. It also becomes a bit problematic if you have multiple entities in your class library of which a client might only use a few.

The third solution is basically the same concept as the previous, except we could use annotations in stead of mapping files in the class library. It has all the typical advantages of annotations, but also means that the class library now needs a dependency on hibernate, even if the client doesn't care about persistence.

The fourth solution is more a workaround than a real solution. I think it might be appropriate in some situations though. In the IP address pool example this actually works very well, although it could become a problem for very large pools with lots of fragmentation (many entries in the sorted set of free sub-ranges) and it also complicates manual SQL database queries.
 
If anybody has better suggestions, or if anybody can prove me wrong on the claim that this is not feasible with a UserType, I'd be happy to hear about it.
 

Monday, June 8, 2009

Modernizing MultithreadedTC: JUnit 4 integration

MultithreadedTC is a nice library to help writing tests for multi threaded applications (go check out their website for some examples, I can 't explain it better). Writing and testing multi threaded applications is not an easy task, so having a decent test suite for to help with that task is no luxury at all. I think MultithreadedTC does a nice job, it certainly helped me to write better and more elegant tests than I would have been able to without the library.

One thing I find it a bit frustrating though, is that it doesn't integrate with JUnit (4) very nicely. Basically, with MultithreadedTC, you have to write a class which extends MultithreadedTestCase, with some methods that start with "thread" (a naming convention for MultithreadedTC to know what to run in which threads)
class MyMultithreadedTest extends MultithreadedTestCase {
  public void threadFoo() {
    ...
  }
}
To execute this "multi threaded test case", you have to instantiate it and pass it on to one of the static methods in the TestFramework
TestFramework.runOnce(new MyMultithreadedTest());
Although the name MultithreadedTestCase suggests it is a JUnit test, it is not. To get it all bootstrapped in a JUnit test, you typically end up with an inner class (extending MultithreadedTestCase) inside a JUnit test, and a single JUnit test method to call the TestFramework.runOnce() method
public class SomeTest {
  class MyMultithreadedTest extends MultithreadedTestCase {
    public void threadFoo() {
      ...
    }

    ...
  }
  
  @Test
  public void test() {
    TestFramework.runOnce(new MyMultithreadedTest());
  }
}
This obviously works, but I think we can do better.

I updated the MultithreadedTC library such that multi threaded tests are real JUnit tests (including all the benefits that has, such as using the @After and @Before annotations), in stead of merely something which can be bootstrapped from within JUnit. I also added some annotations for the "thread" methods, in stead of the naming conventions.

The above now looks like this
public class SomeTest {

  @Thread("Foo")
  public void threadFoo() {
    ...
  }
  
  @Test
  public void test() {
    ...
  }
}
Consider the first example on the authors website for a more complete example. This can now be written like this:
public class MTCCompareAndSetTest extends MultithreadedTestCase
{

    AtomicInteger ai;

    @Before
    public void initialize()
    {
        ai = new AtomicInteger(1);
    }

    @Threaded
    public void getTwoSetThree()
    {
        while (!ai.compareAndSet(2, 3)) Thread.yield();
    }

    @Threaded
    public void getOneSetTwo()
    {
        assertTrue(ai.compareAndSet(1, 2));
    }

    @Test
    public void resultShouldBeThree()
    {
        assertEquals(ai.get(), 3);
    }
}
Advantages of this approach include: no inner classes, no explicit TestFramework.runOnce() method calls, usage of standard JUnit annotations, test class is a JUnit class, annotations in stead of naming conventions, ...

Let me know if you are interested in a tgz file which contains the code of this modified MultithreadedTC library. It also contains all the tests of the original sourcecode, adapted to the more modern version.

I have tried to contact the authors of MultithreadedTC, asking them if they are interested. I am willing to share my modifications with them to get them included in the MultithreadedTC library, but I'm still awaiting their reply. Maybe they are deadlocked ;-)

Friday, April 10, 2009

High frequency task scheduling with inaccurate system clock in Java

Java has two general purpose scheduling implementations: java.util.Timer (further referenced as "Timer") and java.util.concurrent.ScheduledThreadPoolExecutor (further referenced as "STPE"). STPE is generally concieved as the successor of Timer and their should normally not be a reason to use Timer any longer. However, both Timer and STPE rely on the underlying system clock, and can thus not be more accurate then the accuracy of that clock.

I happen to have access to a machine where the accuracy of the clock is 20 milliseconds. This means that when you try to make a thread sleep for a single millisecond
public class SleepTest
{
    public static void main(String[] args) throws InterruptedException
    {
        while (true)
        {
            long start = System.nanoTime();
            Thread.sleep(1);
            System.out.println((System.nanoTime() - start) / 1000000);
        }
    }
}
the thread will actually sleep for about 20 milliseconds every time
20
19
19
19
20
20
19
19
...
This also has an impact on the scheduling behaviour with Timer and STPE. Note that the Timer javadoc explicitely mentions this, while the STPE javadoc doesn't.

For example timing a task to execute every 10ms "with fixed delays" using Timer or STPE results in the task being executed every 20ms in stead:
running task [elapsed nanos since previous = 20157000]
running task [elapsed nanos since previous = 19999000]
running task [elapsed nanos since previous = 19895000]
running task [elapsed nanos since previous = 19940000]
running task [elapsed nanos since previous = 19987000]
running task [elapsed nanos since previous = 19991000]
running task [elapsed nanos since previous = 20013000]
running task [elapsed nanos since previous = 20011000]
running task [elapsed nanos since previous = 19980000]
...
When using Timer or STPE to schedule "at fixed rate", two tasks are being executed in immidiate succession every 20ms. This is also consistent with the documentation: it tries to "catch up".
running task [elapsed nanos since previous = 19808000]
running task [elapsed nanos since previous = 187000]
running task [elapsed nanos since previous = 19813000]
running task [elapsed nanos since previous = 185000]
running task [elapsed nanos since previous = 19842000]
running task [elapsed nanos since previous = 185000]
running task [elapsed nanos since previous = 19803000]
running task [elapsed nanos since previous = 214000]
...
Note that the "fixed delay" of Timer doesn't take the execution time of the task itself into account, while the STPE "fixed delay" does, but that is not something I was trying to measure here. The task I am executing is just an empty Runnable.run() method.

Now imagine you are in a situation where you actually need to schedule something at a higher frequency then what the underlying system clock can handle (sending out a UDP stream at a fixed rate for example). Scheduling with "fixed delay" clearly is no option; both Timer and STPE will only give you a frequency equal to the accuracy of the underlying clock, nothing higher. The only option is to schedule "at fixed rate". Both Timer and STPE will "catch up" in this mode, so the average throughput corresponds to the requested frequency to execute the tasks with. The tasks will be executed in bursts though: one burst with a few tasks every time the underlying clock reports a new time value (every 20ms in my example). The problem with "fixed rate" scheduling is that you don't really have a way to control these bursts. If for example your application is blocked for a longer time for some reasons (garbage collection for example), there will be a gap in the task execution, and then a "big" burst to catch up all the tasks it missed.

This is where Timer offers an advantage over STPE. With STPE you schedule runnables, so inside the task there is not really an API to find out information about the scheduling of the task. With Timer, you schedule TimerTask instances. TimerTask has a method scheduledExecutionTime which returns the time the task "should have run". By comparing this to the actual time, you can discover "big bursts" and for example decide not to execute the task. I haven't found a practical way to do that with STPE.

I discovered this when trying to send out a UDP data stream at a fixed rate. The requirement was that a few missed packets were not so bad (a little drop in the speed), but big bursts with many packets (more then about 10 in a row) caused a problematically high peak in the data rate (because then the stream was "clipped" further down the path resulting in dropped packets) and should thus never happen.

Note that in my tests I used System.nanoTime() to measure the time between task executions. This gives me a higher accuracy then the System.currentTimeMillis() which makes me wonder why there is no scheduler with the same accuracy in Java. Something I should look into...