Merge pull request #9 from vanilladb/develop

Update the interface of VanillaDb and timers for debugging

Author: SLMT

src/main/java/org/vanilladb/core/server/VanillaDb.java

@@ -47,20 +47,12 @@
  * be initialized by the method {@link #init(String) init} before use. The
  * methods {@link #initFileMgr(String) initFileMgr},
  * {@link #initFileAndLogMgr(String) initFileAndLogMgr},
- * {@link #initTaskMgr() initTaskMgr},
- * {@link #initTxMgr() initTxMgr},
- * {@link #initCatalogMgr(boolean, Transaction) initCatalogMgr},
- * {@link #initStatMgr(Transaction) initStatMgr},
- * {@link #initSPFactory() initSPFactory}, and
- * {@link #initCheckpointingTask() initCheckpointingTask} provide limited
+ * {@link #initFileLogAndBufferMgr(String) initFileLogAndBufferMgr}, and
+ * {@link #initCatalogMgr(boolean, Transaction) initCatalogMgr} provide limited
  * initialization, and are useful for debugging purposes.
  */
 public class VanillaDb {
 
-	public static enum BufferMgrType {
-		DefaultBufferMgr, DummyBufferMgr
-	};
-
 	// Logger
 	private static Logger logger = Logger.getLogger(VanillaDb.class.getName());
 
@@ -91,24 +83,27 @@ public static enum BufferMgrType {
 	 *            the name of the database directory
 	 */
 	public static void init(String dirName) {
-		init(dirName, BufferMgrType.DefaultBufferMgr);
+		init(dirName, new SampleStoredProcedureFactory());
 	}
 
 	/**
 	 * Initializes the system. This method is called during system startup.
 	 * 
 	 * @param dirName
 	 *            the name of the database directory
-	 * @param bufferType
-	 *            the type of the buffer manager for storage engine
+	 * @param factory
+	 *            the stored procedure factory for generating stored procedures
 	 */
-	public static void init(String dirName, BufferMgrType bufferType) {
+	public static void init(String dirName, StoredProcedureFactory factory) {
 
 		if (inited) {
 			if (logger.isLoggable(Level.WARNING))
 				logger.warning("discarding duplicated init request");
 			return;
 		}
+		
+		// Set the stored procedure factory
+		spFactory = factory;
 
 		/*
 		 * Note: We read properties file here before, but we moved it to a

src/main/java/org/vanilladb/core/util/TxComponentTimer.java renamed to src/main/java/org/vanilladb/core/util/Timer.java

@@ -20,9 +20,26 @@
 import java.util.List;
 import java.util.Map;
 
-public class TxComponentTimer {
+public class Timer {
 
-	private static final boolean PRINT_COUNTS = false;
+	private static final String EXE_TIME_KEY = "Execution Time";
+
+	private static final ThreadLocal<Timer> LOCAL_TIMER = 
+			new ThreadLocal<Timer>() {
+		@Override
+		protected Timer initialValue() {
+			return new Timer();
+		}
+	};
+
+	/**
+	 * Get the timer local to this thread.
+	 * 
+	 * @return
+	 */
+	public static Timer getLocalTimer() {
+		return LOCAL_TIMER.get();
+	}
 
 	private static class SubTimer {
 		private long start = 0, startTimes = 0, totalTime = 0, count = 0;
@@ -52,14 +69,13 @@ public long getCount() {
 	}
 
 	private Map<Object, SubTimer> subTimers = new HashMap<Object, SubTimer>();
+	// We want to preserve the order of creating timers so that
+	// we use a list to record the order.
 	private List<Object> componenents = new LinkedList<Object>();
-	private Object[] metadata;
-	private long executionStart, executionTime = 0;
 
-	private long txNum;
-
-	public TxComponentTimer(long txNum) {
-		this.txNum = txNum;
+	public void reset() {
+		subTimers.clear();
+		componenents.clear();
 	}
 
 	public void startComponentTimer(Object component) {
@@ -78,59 +94,49 @@ public void stopComponentTimer(Object component) {
 			timer.stopTimer();
 	}
 
-	public long getComponentCount(Object component) {
-		return subTimers.get(component).getCount();
-	}
-
-	public void startExecution() {
-		executionStart = System.nanoTime();
-	}
-
-	public void stopExecution() {
-		executionTime = (System.nanoTime() - executionStart) / 1000;
-	}
-
 	public long getComponentTime(Object component) {
 		SubTimer timer = subTimers.get(component);
 		if (timer == null)
 			return -1;
 		return timer.getTotalTime();
 	}
 
-	public long getExecutionTime() {
-		return executionTime;
+	public long getComponentCount(Object component) {
+		return subTimers.get(component).getCount();
 	}
 
-	public long getTransactionNumber() {
-		return txNum;
+	public List<Object> getComponents() {
+		return new LinkedList<Object>(componenents);
 	}
 
-	public Object getMetadata() {
-		return metadata;
+	public void startExecution() {
+		startComponentTimer(EXE_TIME_KEY);
 	}
 
-	public void setMetadata(Object[] m) {
-		this.metadata = m;
+	public void stopExecution() {
+		stopComponentTimer(EXE_TIME_KEY);
+	}
+
+	public long getExecutionTime() {
+		return getComponentTime(EXE_TIME_KEY);
+	}
+	
+	public void addToGlobalStatistics() {
+		TimerStatistics.add(this);
 	}
 
 	public String toString() {
 		StringBuilder sb = new StringBuilder();
 
-		if (!componenents.isEmpty()) {
-			sb.append("===== Profile for Tx." + txNum + " =====\n");
-			for (Object com : componenents) {
-				sb.append(String.format("%-40s: %d us", com, subTimers.get(com)
-						.getTotalTime()));
-				if (PRINT_COUNTS) {
-					sb.append(String.format(", with %d counts",
-							subTimers.get(com).getCount()));
-				}
-				sb.append("\n");
+		sb.append("==============================\n");
+		for (Object com : componenents) {
+			if (!com.equals("Execution Time")) {
+				sb.append(String.format("%-40s: %d us, with %d counts\n", com, subTimers.get(com).getTotalTime(),
+						subTimers.get(com).getCount()));
 			}
-			sb.append(String.format("%-40s: %d us\n", "Execution Time:",
-					executionTime));
-			sb.append("==============================\n");
 		}
+		sb.append(String.format("%-40s: %d us\n", EXE_TIME_KEY, subTimers.get(EXE_TIME_KEY).getTotalTime()));
+		sb.append("==============================\n");
 
 		return sb.toString();
 	}

src/main/java/org/vanilladb/core/util/TimerStatistics.java

@@ -0,0 +1,138 @@
+package org.vanilladb.core.util;
+
+import java.util.LinkedList;
+import java.util.List;
+import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.atomic.AtomicBoolean;
+
+public class TimerStatistics {
+	
+	private static final long REPORT_PERIOD = 3000;
+	private static final AtomicBoolean IS_REPORTING = new AtomicBoolean(false); 
+	
+	private static List<Object> components = new LinkedList<Object>();
+	private static Map<Object, ComponentStatistic> stats = new ConcurrentHashMap<Object, ComponentStatistic>();
+	private static Object[] anchors = new Object[1099];
+	
+	private static class ComponentStatistic {
+		long recordTime;
+		int lastCount, count;
+		
+		synchronized void addTime(long time) {
+			recordTime += time;
+			count++;
+		}
+		
+		synchronized double calAverage() {
+			double avg = 0;
+			if (count != 0) {
+				avg = ((double) recordTime) / ((double) count);
+			}
+			recordTime = 0;
+			lastCount = count;
+			count = 0;
+			return avg;
+		}
+		
+		synchronized int getLastCount() {
+			return lastCount;
+		}
+	}
+	
+	static {
+		for (int i = 0; i < anchors.length; i++)
+			anchors[i] = new Object();
+		
+		new Thread(new Runnable() {
+
+			@Override
+			public void run() {
+				long startTime = System.currentTimeMillis();
+				long lastTime = startTime;
+				
+				while (true) {
+					long currentTime = System.currentTimeMillis();
+					
+					if (currentTime - lastTime > REPORT_PERIOD) {
+						lastTime = currentTime;
+						
+						double t = (currentTime - startTime) / 1000;
+						StringBuilder sb = new StringBuilder();
+						
+						sb.append("===================================\n");
+						sb.append(String.format("At %.2f:\n", t));
+						
+						synchronized (components) {
+							for (Object key : components) {
+								ComponentStatistic stat = stats.get(key);
+								double avg = stat.calAverage();
+								int count = stat.getLastCount();
+								
+								if (count > 0) {
+									sb.append(String.format("%s: average %.2f us", key, avg));
+									sb.append(String.format(" with count %d\n", count));
+								}
+							}
+						}
+						
+						sb.append("===================================\n");
+						
+						if (IS_REPORTING.get())
+							System.out.println(sb.toString());
+					}
+					
+					try {
+						Thread.sleep(REPORT_PERIOD / 10);
+					} catch (InterruptedException e) {
+						e.printStackTrace();
+					}
+				}
+			}
+			
+		}).start();
+	}
+	
+	public static void startReporting() {
+		IS_REPORTING.set(true);
+	}
+	
+	public static void stopReporting() {
+		IS_REPORTING.set(false);
+	}
+	
+	static void add(Timer timer) {
+		if (IS_REPORTING.get()) {
+			for (Object com : timer.getComponents()) {
+				ComponentStatistic stat = stats.get(com);
+				if (stat == null)
+					stat = createNewStatistic(com);
+				stat.addTime(timer.getComponentTime(com));
+			}
+		}
+	}
+	
+	private static Object getAnchor(Object key) {
+		int code = key.hashCode();
+		code = Math.abs(code); // avoid negative value
+		return anchors[code % anchors.length];
+	}
+	
+	private static ComponentStatistic createNewStatistic(Object key) {
+		Object anchor = getAnchor(key);
+		synchronized (anchor) {
+			
+			ComponentStatistic stat = stats.get(key);
+			
+			if (stat == null) {
+				stat = new ComponentStatistic();
+				stats.put(key, new ComponentStatistic());
+				synchronized (components) {
+					components.add(key);
+				}
+			}
+			
+			return stat;
+		}
+	}
+}