Tuesday, April 19, 2011

Using Nimbits to log unit test performance metrics

Alternate title: Application, heal thy self.

This article will show you how to add a couple of lines of code to your Unit Tests to change them from simply telling you if your code passes or fails, to all singing all dancing integrations tests that log execution times, enforce SLAs, and even warn you if the test isn't running.

The reason for the alternate title above is that as I was writing the Nimbits source code, I realized that there was an incredible useful aspect to the Nimbits server: I could actually use the server to record how long my tests took to run, and see the history of this performance metric. Nimbits was actually using itself to improve performance. So I could see if changes I made to the code was improving performance or not.

Take, for example this test, which writes 10 random values to a data point called b1.


@Test
public void testLoadRandom() throws IOException {
Random r = new Random();
for (int i = 0; i < 10; i++) { Value v = nimbitsSDK.recordValue("b1", (r.nextDouble() * 100), new Date()); 

 Assert.assertNotNull(v); 
 Assert.assertTrue(v.getKey() > 0);
}
}


Good, this test will run once an hour on my Hudson server and fails if any of the 10 values do not get recorded into the b1 data point.   This of course, can be any test you are running on any project. In my example here i'm using Nimbits to test and tune Nimbits which I know is a little creepy.

You can add a couple of lines of code to this test to time how long it takes to write these 10 values - that is to make 10 round trips to Nimbits, waiting for each response.  We're then going to record how long the test took to run and save that time in another time series Data Point on a Nimbits Server. This way, we can better understand how our system is performing. What's more, there are many built in features we can take advantage of. Check this out.

Here is the same unit test with references to the Nimbits SDK, and some code to time the test. We then write the result to the data point



@Test
public void testLoadRandom() throws IOException {
Date start = new Date();
Random r = new Random();
for (int i = 0; i < 10; i++) { Value v = Common.client().recordValue("b1", (r.nextDouble() * 100), new Date()); Assert.assertNotNull(v); Assert.assertTrue(v.getKey() > 0);
}
Date end = new Date();
long time = (end.getTime() - start.getTime()) / 1000;
nimbitsSDK.recordValue("Time to record 10 values to b1", time, new Date());
}


I have a data point setup called "Time to record 10 values to b1" that holds the time each test took to run. Let's take a look at some of the value Nimbits brings to the table besides being able to see how our system performs.

Alerts:  A data point can be configured to send you an email, text message, twitter etc if a value exceeds a threshold. 


Why yes, I'd like to know if the time is over 20 seconds or below 0, both indicating something was wrong.


Idle Alarms: Nimbits can alert you if a data point is idle when it should have received a value.


Sure, the build can fail on an error, but what if the whole build server or Hudson is down? Nimbits can alert you if a point has not received a new value. Yes, i'd like to know if my hourly tests are not generating data.





See the impact of your code changes:


The test I wrote above has been humming away for several weeks. Here is a snapshot of the resulting times that spanned the upgrade of the Test Nimbits Server Instance to Nimbits 3.1, being released this week on www.nimbits.com.  Imagine going into your boss's office with a chart like this showing real improvement as a result of a code change. (Yes, Nimbits Server 3.1 is way faster)





Obvious improvement with the upgrade, one of the many uses of a Nimbits Server. You can use the live nimbits server, download your own, and get the Nimbits SDK for java and .net on www.nimbits.com