Tuesday, May 24, 2011

Java count open file handles

Encountered an issue in production where JVM ran out of file handles due to code bug. It took five minutes for file handles to build up but had there been any trending of open file handles we would have caught it as soon as release was pushed as on some nodes it didnt exhausted the file handles but the number was high enough to have caught suspicion. Now I can do lsof and put it in cron but I am not fond of crons as you have to configure it manually and if a box has 4 tomcats then you have to configure for each one of them on 20-30 nodes. So I wanted to get count of open file handles every five minutes and push it to graphite for trending. Here is a sample code to do it

 public long getOpenFileDescriptorCount() {
  OperatingSystemMXBean osStats = ManagementFactory.getOperatingSystemMXBean();
  if(osStats instanceof UnixOperatingSystemMXBean) {
   return ((UnixOperatingSystemMXBean)osStats).getOpenFileDescriptorCount();
  }
  return 0;
 }

Friday, May 20, 2011

RateLimiting based on load on nodes

We are a cloud based file storage company and we allow many access point to the cloud. One of the access point is Webdav api and people can use any webdav client to access the cloud. But some of the webdav client especially on mac OS are really abusive. Though the user is not doing any abusive action, the webdav client does aggressive caching so even when you are navigating at a top directory it does PROPFINDs for depth at 5 or 6 level to make the user experience seamless as if he is navigating local drive. This makes life miserable on the server because from some clients we get more than 1000 requests in a minute. If there are 5-10 clients do the webdav activity then it causes 100 or more propfinds per sec. Luckily the server is able to process these but it hurts other activities. So we needed to rate limit this. Now as the user is really not doing any abusive action it would be bad to slow down on penalize the user in normal circumstance, however if the server is under load then it would be worth while to throttle the user for some time.

Luckily Jdk1.6 has a light weight api to get system load average.

 public double getSystemLoadAverage() {
  OperatingSystemMXBean osStats = ManagementFactory.getOperatingSystemMXBean();
  double loadAverage = osStats.getSystemLoadAverage();
  return loadAverage;
 }


And now I can write code like

  if(throttlePropFinds(req, user)) {
   logger.info("Throttling due to excessive webdav requests from user {}", user.getId());
   if(throttlingHelper.isBlockUsers()) {
    double loadAverage = SpringBeanLocator.getJvmStatsLogger().getSystemLoadAverage();
    if (loadAverage > 4) {
     logger.info("Sending 503 as loadAverage>4 and excessive webdav requests from user {}", user.getId());
           resp.sendError(WebdavStatus.SC_SERVICE_UNAVAILABLE);
           return;
    }
   }
  }


The logic I used for propfind rate limiting is simple where I keep track of all users who made>1000 requests in last 5 min and only if loadAvg is >4, I send 503. For brevity I am not putting the code to count no of request made by users in last 5 min but I am using memcache to maintain the counters in one minute buckets.

Sunday, May 15, 2011

ubuntu 11.04 natty upgrade hangs

It hung there for more than one hour. It was trying to upgrade cups. I have no idea but then I tried doing "sudo stop cups" and that let the upgrade resume.

Friday, May 13, 2011

Quartz stop a job

Quartz did a good job on implementing this concept. It was very easy to add this feature by implementing a base class that abstract the details of interrupt and have every job extend this class. If you can rely on thread.interrupt() then its the best way to interrupt a job that is blocked on some I/O or native call. However if its a normal job then a simple boolean flag would do the work.

You would need to use scheduler.interrupt(jobName, groupName); to interrupt a running Quartz job.


public abstract class BaseInterruptableJob implements InterruptableJob {
 private static final AppLogger logger = AppLogger.getLogger(BaseInterruptableJob.class); 
 private Thread thread;
 @Override
 public void interrupt() throws UnableToInterruptJobException {
  logger.info("Interrupting job " + getClass().getName());
  if (thread != null) {
   thread.interrupt();
  }
 }

 @Override
 final public void execute(JobExecutionContext context) throws JobExecutionException {
  try {
   thread = Thread.currentThread();
   interruptableExecute(context);
  } finally {
   thread = null;
  }
 }
 
 protected abstract void interruptableExecute(JobExecutionContext context) throws JobExecutionException;

}

Sunday, May 8, 2011

Pitfalls of defensive programming

We programmers some times add too much defensive code in order to protect ourselves from the caller not asserting preconditions before making the call. So for e.g. if we have to save a file in some directory, we would first go and check if the directory exists and if it exists then create the file. Now NFS is not designed to work at cloud scale and we saw lots of calls just stuck in file.exists call in threaddumps. The solution was simple, some of these directories could be created at tomcat startup or app node installer can create them. Also some code can assume that directory exists and if if gets a FileNotFoundExcpetion then create it and retry the operation. Removing these defensive coding practices reduced a lot of unnecessary stat calls on filers and improved performance. This is just an example but similar pattern can be observed in other areas of the code and fixed. Defensive programming is good but too much of it is bad and can be improved by making some assumptions or providing better documentation of the api.

Contextual Thread dumps

Due to some business policy changes we recently started seeing some changes in usage pattern of our application leading to unexplained app node spikes. These spikes were temporary and by the time we go and try to take jstacks it might have disappeared. So we configured a quartz job to take jstack every 5 min(wrote a quartz instead of cron because cron needs to be manually configured on each node and we have tons of nodes to ops was always missing or misconfiguring it) and dump it in to a folder and we keep last 500 copies. That way I can go and correlate what was going on in the tomcat during the time of the spike (I had to get lucky for spike to happen when quartz job was running but I was lucky as most spikes spanned 3-5 mins). Now from those thread dumps I can figure out what was going on like how many thread are doing "searches" v/s how many thread are coming from Webdav or how many threads are doing add file. But one question that keep on coming was who are the customers who are doing them. For e.g. if we saw 50 threads doing webdav propfinds, it would be good to know if most of these requests are coming from same customer or diff customer. So I went and added customer domain name to each thread in a servlet filter for each incoming request. This helped me find issues at a much faster rate as I no longer need to go and correlate it in the logs as to what thread was doing at that time. I found lots of patterns by just adding contextual information to threads. Below is how the information is in the thread name.

Thread[http-6280-Processor169|D-avlapp05,5,main]
RUNNABLE

      
   at java.lang.Thread.dumpThreads(Native Method)
   at java.lang.Thread.getAllStackTraces(Thread.java:1487)
   at com.sslinc.infrastructure.perf.ThreadDumpBean.(ThreadDumpBean.java:17)
   at org.apache.jsp.static_.admin.threadDump_jsp._jspService(threadDump_jsp.java:58)
   at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
   at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
   at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
   at java.lang.Thread.run(Thread.java:619)
      

Thread[multi-file-upload-commit-a5611a5a-3e5a-44ee-a005-8042ee732d9d-13900185618|D-krisgsc1,5,main]
WAITING

      
   at sun.misc.Unsafe.park(Native Method)
   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
   at com.sslinc.ui.web.servlet.UploadProcessThread.run(UploadProcessThread.java:120)