測量執行時間的小工具

我想每個人程式寫久了都會有些小工具，例如StringUtils、DateTimeUtils等，這可能是整個Team所累積的，如果能分享下應該也不錯吧。

這裡提供個測量執行時間的小API，雖說AOP可以測量每個Method所花的時間，但比較耗時，而且偶爾也有AOP不方便的時候。我常用的是下面這種方法。

TrackingStack.enable();
TrackingStack.push("Execution");
TrackingStack.push("Step1");
//Does something
TrackingStack.pop("Step1");
  
TrackingStack.push("Step2");
//Does something
TrackingStack.pop("Step2");
TrackingStack.pop("Execution");

跑出來的結果大概會長得像下面這樣

[Execution]:243 ms
 [Step1]:102 ms
 [Step2]:104 ms

用的程式如下

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class TrackingStack {
 private static final Logger logger = LoggerFactory.getLogger(TrackingStack.class);
 private static ThreadLocal current = new ThreadLocal();
 private static boolean ENABLE = false;

 public static final void push(String execution) {
  if (!ENABLE) {
   return;
  }

  ProfilingBean newPb = new ProfilingBean(execution);
  newPb.start();
  if (null == current.get()) {
   current.set(newPb);
  } else {
   current.get().addChild(newPb);
  }

  current.set(newPb);
 }

 public static final void pop(String execution) {
  if (!ENABLE) {
   return;
  }
  ProfilingBean currentPb = current.get();

  if (null == currentPb) {
   return;
  }

  if (currentPb.getExecution().equals(execution)) {
   currentPb.end();

   if (null != currentPb.getParent()) {
    current.set(currentPb.getParent());
   } else {
    logger.info(currentPb.getProfilingMessage());
    current.set(null);
   }
  } else {
   logger.info("Current execution sould be [{}], not [{}]", currentPb.getExecution(), execution);
  }
 }

 public static final void enable() {
  ENABLE = true;
 }

 public static final void disable() {
  ENABLE = false;
 }
}

import java.util.ArrayList;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ProfilingBean {
 private static final Logger logger = LoggerFactory.getLogger(ProfilingBean.class);
 private ArrayList children = new ArrayList();
 private ProfilingBean parent = null;

 private String execution;

 private long startTime;
 private long endTime;

 public ProfilingBean(String execution) {
  this.execution = execution;
 }

 public String getExecution() {
  return this.execution;
 }

 public void start() {
  this.startTime = System.currentTimeMillis();
 }

 public long getStartTime() {
  return this.startTime;
 }

 public void end() {
  this.endTime = System.currentTimeMillis();
 }

 public long getEndTime() {
  return this.endTime;
 }

 public long getTotalTime() {
  return this.endTime - this.startTime;
 }

 public void setParent(ProfilingBean parent) {
  this.parent = parent;
 }

 public ProfilingBean getParent() {
  return this.parent;
 }

 public void addChild(ProfilingBean child) {
  if (null == child) {
   logger.warn("Child should't be null");
   return;
  }
  this.children.add(child);
  child.setParent(this);
 }

 public String getProfilingMessage() {
  return this.getProfilingMessage("");
 }

 private String getProfilingMessage(String indent) {
  StringBuilder sb = new StringBuilder();
  sb.append("\n" + indent + "[" + this.execution + "]:" + (this.endTime - this.startTime) + " ms");
  for (ProfilingBean pb : this.children) {
   sb.append(pb.getProfilingMessage(indent + "\t"));
  }
  return sb.toString();
 }
}