Bert's Blog

Posts tagged java

Jul 15

Profiling Production

I work a lot in Java and one thing it does well is profiling. IDEs like Netbeans have profiling options, that are also available as plugins to VisualVM which comes with the JDK. This is great for development, but I think its main use is to settle technical arguments.

Things are a little different in production where hundreds of processes are running with all manner of dependencies. By far the most common problem that occurs is that something has “slowed down”. So without a profiler how would you find out what’s happening? 

First you need to find out what’s going on in the JVM and unless you have an amazing logging framework, it will require some digging. If you’ve ever done this sort of thing before then you’ll know all about thread dumps. Taking a thread dump is as easy as:

jstack pid > threaddump.txt

or on Solaris you can get a JVM to output a thread dump to its stdout via

kill -3 pid

This will output the stack of every thread running on a particular JVM. If you have an application server that’s running 1000+ threads, then it’ll output a lot of information to wade through. However this can be to your advantage, simply because slow code “hangs around”, and if it’s being noticed then it’s probably holding up multiple threads. It’s then time to try one of my favourite commands: 

threaddump.txt sort | uniq -c | sort -n

This simply says:

  1. sort all lines in the file in alphabetical order. 
  2. count the occurrences of each line.
  3. sort by the number of occurrences.

This will give you a hit count for every method call on your system. Slow calls will tend to stack up, and if you have a sensible naming convention then multiple calls to methods named “send”, “read” or ”write” will jump out at you to suggest an external dependency is to blame. Another thing that sticks out will be recursive calls that might be on their way to a Stack Overflow.

If this doesn’t give you something to go on, and things are still slow, then you might have a deadlock. To verify this you’ll need to take a second thread dump and compare it to the first. Every thread in java is given a unique name, so you can see which threads are common as follows 

cat threaddump.txt threaddump2.txt | grep prefix | sort | uniq -d

Hopefully this’ll return only a handful of matches giving you a good chance at finding out what’s going wrong.

Happy Hunting!


Jul 12

Mockito Magic

I like unit tests, for one simple reason. I don’t trust myself! Tell me your name and I’ll forget it. Give me something to look after, and I’ll lose it. Put something down for a minute and I’ll step on it. 

Of course I’m exaggerating, I’m not that bad … or am I?

Tell me your name, and I’ll probably use a mnemonic to remember it. Give me something to look after and I’ll include it in my three-pocket-pat. Put something down and I’ll demand that you pick it up immediately or make some excuse to leave. I use unit tests in the same way, to avoid tripping over my own feet.

Anyway, I’d like to share a really neat feature of Mockito. Consider the following contrived example:

public class Example {
  private static final Logger LOG = Logger.getLogger("");
  public void cleanUp(InputStream is) {
    try {
      is.close();
    } catch(IOException e) {
      LOG.log(Level.FINEST,"IOE handled",e);
    } catch(NullPointerException e) {
      LOG.log(Level.WARNING,"NPE handled",e);
    }
  }
}

If you really wanted it to be bullet proof, you’d probably write a unit test like this:

public class ExampleTest {
  private final Example example = new Example();

  @Test
  public void testCleanUpInputStream() 
  throws IOException {
    InputStream is = mock(InputStream.class);
    example.cleanUp(is);
    verify(is).close();
  }

  @Test
  public void testCleanUpNullPointerException() 
  throws IOException {
    InputStream is = mock(InputStream.class);
    NullPointerException e = new NullPointerException();
    doThrow(e).when(is).close();
    example.cleanUp(is);
    verify(is).close();
  }

  @Test
  public void testCleanUpIOException() 
  throws IOException {
    InputStream is = mock(InputStream.class);
    IOException e = new IOException();
    doThrow(e).when(is).close();
    example.cleanUp(is);
    verify(is).close();
  }
}

It’s a good attempt, but there is a snag. There is nothing to verify that there was any real difference between testCleanUpNPE() and testCleanUpIOE(). But how to test it, after all Logger is static so doesn’t that make verifying behaviour problematic? The answer requires a minor refactor to create a new log() method:

public class Example {
  private static final Logger LOG = Logger.getLogger("");
  public void cleanUp(InputStream is){
    try {
      is.close();
    } catch(IOException e) {
      log(Level.FINEST,"IOE handled",e);
    } catch(NullPointerException e) {
      log(Level.WARNING,"NPE handled",e);
    }
  }
  protected void log(Level l, String m, Throwable e){
    LOG.log(l,m,e);
  }
}

And now enter Mockito.spy(). Similar to mock(), this returns an object stub of your original object, where all calls still invoke the same methods, only it’s also a mock. Now you can verify the behaviour as you would do with a mock. For example:

public class ExampleTest {
  private Example example = new Example();

  @Test
  public void testCleanUpInputStream() 
  throws IOException {
    Example spyExample = spy(example);
    InputStream is = mock(InputStream.class);
    spyExample.cleanUp(is);
    verify(is).close();
    verify(spyExample,never()).log(any(Level.class),anyString(),any(Throwable.class));
  }

  @Test
  public void testCleanUpNullPointerException() 
  throws IOException {
    Example spyExample = spy(example);
    InputStream is = mock(InputStream.class);
    NullPointerException e = new NullPointerException();
    doThrow(e).when(is).close();
    spyExample.cleanUp(is);
    verify(is).close();
    verify(spyExample).log(Level.WARNING,"NPE handled",e);
  }

  @Test
  public void testCleanUpIOException() 
  throws IOException {
    Example spyExample = spy(example);
    InputStream is = mock(InputStream.class);
    IOException e = new IOException();
    doThrow(e).when(is).close();
    spyExample.cleanUp(is);
    verify(is).close();
    verify(spyExample).log(Level.FINEST,"IOE handled",e);
  }
}

Mockito is awesome, and spy() is a very powerful tool as it allows you to verify interactions within the class itself. Because spy() essentially returns a mock, you can do “Partial Mocking”. However this I will save for another time. Now where did I put my keys?


Apr 3

Despicable Dates

A long time ago, I had the unpleasant task of writing a library for “intuitively” parsing Dates. As with most mental trauma, I cannot recall what happened, but I still fly into a blind rage when I see one written m/d/y.

The other day I came across this neat piece of code for calculating a countdown broken down into days, hours, minutes and seconds:

public void Countdown(long lo, long hi) {
  int diff = (int) (hi - lo)/1000;
  days = diff/(24*60*60);
  hours = diff/(60*60) - days*24;
  mins = diff/60 - days*24*60 - hours*60;
  secs = diff - days*24*60*60 - hours*60*60 - mins*60;
}

Of course these is absolutely nothing wrong with this code … if you happen live in a sane country. Unfortunately I live in England and we do things slightly differently. Yes I’m referring to “British Summer Time” which decides that one day a year will have 23 hours, and another 25! This means we have to do stupid things like this:

public Countdown(Calendar lo, Calendar hi) {
  int loOffset = lo.getTimeZone()
    .getOffset(lo.getTimeInMillis());
  int hiOffset = hi.getTimeZone()
    .getOffset(hi.getTimeInMillis());
  int offset = loOffset - hiOffset;

  Calendar temp = (Calendar)hi.clone();
  temp.add(MILLISECOND, offset);
		
  secs = temp.get(SECOND) - lo.get(SECOND);
  mins = temp.get(MINUTE) - lo.get(MINUTE);
  hours = temp.get(HOUR_OF_DAY) - lo.get(HOUR_OF_DAY);
  days = temp.get(DAY_OF_YEAR) - lo.get(DAY_OF_YEAR);		

  if(secs < 0) {
    secs += temp.getActualMaximum(SECOND)+1;
    mins--;
  }
  if(mins < 0) {
    mins += temp.getActualMaximum(MINUTE)+1;
    hours--;
  }
  if(hours < 0) {
    hours += temp.getActualMaximum(HOUR_OF_DAY)+1;
    days--;
  }
}

Perhaps I should move to a country where daylight isn’t in such short supply!


Jan 16

Troublesome Timestamps

A few years ago I was working for a company who would distribute a simple data file to it’s client app. The client app would scan the data file and construct an index of keywords together with the offset into the file for quick searching. As the data file grew, the time taken to index also grew and so it made sense to index the file and distribute both files together in a zip file. I wrote and unit tested a short routine to do this, and second to unpack and verify the files at the client side.

All was fine until we shipped the new software, and then complaints started coming in that the new functionality ‘wasn’t working’. Very baffled, I turn to the code - no more than a few lines - and the tests - again no more than a few lines and couldn’t see the error. Being unable to replicate I asked for some sample zip files, which all worked fine!

It wasn’t until I spoke to an engineer looking at a different problem that he mentioned the client app had begun to index a large file and was taking ages. I immediately directed him to where the zip file is kept, so he could get me a copy to replicate. After a lot of digging I discovered this little gem in the java ZipEntry source code. 

private static long javaToDosTime(long time) {
  Date d = new Date(time);
  int year = d.getYear() + 1900;
  if (year < 1980) {
    return (1 << 21) | (1 << 16);
  }
  return (year - 1980) << 25 | 
    ( d.getMonth() + 1) << 21 |
    d.getDate() << 16 |
    d.getHours() << 11 | 
    d.getMinutes() << 5 |
    d.getSeconds() >> 1;
}

The index file was storing the timestamp of the data file - so it would know to re-index. However, when you zip a file in Java, it’ll loose precision when storing seconds, as it only stores them in 5 bits (2^5=32 which explains the »1).

My solution was to force all data file timestamps to be even before they’re indexed and zipped!