Wednesday, March 30, 2011

Developing an Exception monitoring system for your cluster

Lot of times developers want to know
1) How many exceptions are happening in a 100 node cluster
2) When I do a new release are the no of exceptions growing or decreasing
3) What are my top 5 exceptions in the app that I need to focus on
4) overall are there any nodes where some exception is happening a lot of times compared to other nodes.

Getting all this statistics is tricky as you have to parse logs and aggregate what not so all this is messy and time consuming. Also when nodes are added/removed from cluster you have to change the script.

Solution I came up was very simple
1) 90% of the time the exceptions are logged using logger so I overrode the logger.error method and would get first 100 chars out of exception stacktrace keep a counter in a static in memory hashmap.
2) Some exceptions that are never logged so I wrote a servlet filter to catch them in a top level filter and log them to logger that way it would be counted.
3) I wrote a quartz job at the end of the day to print all this information in memory to scribe.
4) Scibe logs from all app nodes are sent to scribe server(We use it for other purposes but I piggy backed on it). The logs are rolled once a day.
5) Wrote a python program that listens to scribe log file rollover at the end of day and combines exception counters from all nodes and generates a sweet report and mails it to developers.
6) Next goal is to add these statistics counters to graphite dashboard so we can trend them and get the 4 requirements I highlighted above.

Side effect of using spring bean injection in your application

I realized that a good side effect of using spring in your application is that you are always creating public setter/getter(optional) for your dependencies and sometimes "init" and "destroy" methods.

Lot of times in production we had to change some settings like list of memcache servers(when you add/remove a one) or list of cassandra servers(when you move them around to better hardware). The problem is that we want to avoid as much tomcat restarts when this happens as some of these are global to all tomcats and we cant restart all of them(it has to be a rolling restart). With spring its easy, you can always write a jsp that can call the setter and change the setting on the live bean and you are done.

In traditional applications where you don't use spring its entirely up to developers to expose the setter method but with spring this nice side effect has save my ass a lot of time.

Thursday, March 10, 2011

Spring log query execution time for SimpleJdbcTemplate

Without going into too much depth here is the way to do it. The challenge faced were SimpleJdbcTemplate has a no-arg constructor. In future the intent of this interceptor is to detect N+1 query problem by using a light weight instrumentation framework plugged in instead of logging query times in log file.


 public void setDataSource(DataSource dataSource) {
  final SimpleJdbcTemplate simpleJdbcTemplate = new SimpleJdbcTemplate(
    dataSource);
  Enhancer enhancer = new Enhancer();
  enhancer.setSuperclass(SimpleJdbcTemplate.class);
  enhancer.setCallback(new MethodInterceptor() {
   @Override
   public Object intercept(Object obj, Method method,
     Object[] args, MethodProxy proxy) throws Throwable {
    try{
     String methodName = method.getName();
     if (methodName.startsWith("query")
       || methodName.startsWith("batchUpdate")
       || methodName.startsWith("update")) {
      String query = (String) args[0];
      String prefix = extractQueryName(query);
      long start = System.currentTimeMillis();
      Object result = method.invoke(simpleJdbcTemplate,
        args);
      logger.info("Query {} took {} msec", prefix,
        (System.currentTimeMillis() - start));
      return result;
     } else {
      return method.invoke(simpleJdbcTemplate, args);
     }
    } catch(InvocationTargetException e) {
     throw e.getTargetException();
    }
   }

   private String extractQueryName(String query) {
    //with xml based property files I am externalizing queries into a xml file and then when reading them back I am appending query name as a comment before qeury so a query look like below and I extract query name here.
    /*getPerson*/ select * from person
   }
  });
  this.jdbcTemplate = (SimpleJdbcTemplate) enhancer.create(new Class[]{DataSource.class}, new Object[]{dataSource});
 }