histogram tracker now nanoTime based; lombok itself can be histogrammed now with -Dlombok.histogram

3 files changed, 72 insertions, 22 deletions

diff --git a/src/core/lombok/core/AST.java b/src/core/lombok/core/AST.java
index 7bddbada..e6efe058 100644
--- a/src/core/lombok/core/AST.java
+++ b/src/core/lombok/core/AST.java
@@ -61,7 +61,7 @@ public abstract class AST<A extends AST<A, L, N>, L extends LombokNode<A, L, N>,
 	Map<N, N> identityDetector = new IdentityHashMap<N, N>();
 	private Map<N, L> nodeMap = new IdentityHashMap<N, L>();
 	private boolean changed = false;
-	private static final HistogramTracker histogramTracker = System.getProperty("lombok.timeConfig") == null ? null : new HistogramTracker("lombok.config");
+	private static final HistogramTracker configTracker = System.getProperty("lombok.timeConfig") == null ? null : new HistogramTracker("lombok.config");
 	
 	protected AST(String fileName, String packageDeclaration, ImportList imports) {
 		this.fileName = fileName == null ? "(unknown).java" : fileName;
@@ -421,11 +421,11 @@ public abstract class AST<A extends AST<A, L, N>, L extends LombokNode<A, L, N>,
 	}
 	
 	public final <T> T readConfiguration(ConfigurationKey<T> key) {
-		long start = System.currentTimeMillis();
+		long start = configTracker == null ? 0L : configTracker.start();
 		try {
 			return LombokConfiguration.read(key, this);
 		} finally {
-			if (histogramTracker != null) histogramTracker.report(start);
+			if (configTracker != null) configTracker.end(start);
 		}
 	}
 }
diff --git a/src/core/lombok/core/debug/HistogramTracker.java b/src/core/lombok/core/debug/HistogramTracker.java
index 3ae8a58b..5471540f 100644
--- a/src/core/lombok/core/debug/HistogramTracker.java
+++ b/src/core/lombok/core/debug/HistogramTracker.java
@@ -1,5 +1,6 @@
 package lombok.core.debug;
 
+import java.io.PrintStream;
 import java.util.Calendar;
 import java.util.GregorianCalendar;
 import java.util.concurrent.atomic.AtomicBoolean;
@@ -12,41 +13,63 @@ import java.util.concurrent.atomic.AtomicStampedReference;
  * emitted until you call report().
  */
 public class HistogramTracker {
-	private static final int[] RANGES = {1, 2, 5, 9, 17, 33, 65, 129, 257};
-	private static final long REPORT_TIME = 1000 * 60;
+	private static final long[] RANGES = {
+		250001L, 500001L, 1000001L, 2000001L, 4000001L, 8000001L, 16000001L, 32000001L,
+		64000001L, 128000001L, 256000001L, 512000001L, 1024000001L, 2048000001L, 10000000001L};
+	private static final long REPORT_WINDOW = 1000 * 60;
 	
 	private final String category;
-	private final AtomicStampedReference<int[]> bars = new AtomicStampedReference<int[]>(new int[RANGES.length + 2], 0);
+	private final AtomicStampedReference<long[]> bars = new AtomicStampedReference<long[]>(new long[RANGES.length + 2], 0);
 	private final AtomicBoolean addedSysHook = new AtomicBoolean(false);
+	private final PrintStream out;
 	
 	public HistogramTracker(String category) {
 		this.category = category;
+		this.out = null;
+		printInit();
+	}
+	
+	public HistogramTracker(String category, PrintStream out) {
+		this.category = category;
+		this.out = out;
+		printInit();
+	}
+	
+	private void printInit() {
 		if (category == null) {
-			ProblemReporter.info("Initialized histogram", null);
+			if (out == null) ProblemReporter.info("Initialized histogram", null);
+			else out.println("Initialized histogram");
 		} else {
-			ProblemReporter.info(String.format("Initialized histogram tracker for '%s'",  category), null);
+			if (out == null) ProblemReporter.info(String.format("Initialized histogram tracker for '%s'",  category), null);
+			else out.printf("Initialized histogram tracker for '%s'%n", category);
 		}
 	}
 	
-	public void report(long start) {
+	public long start() {
+		return System.nanoTime();
+	}
+	
+	public void end(long startToken) {
 		if (!addedSysHook.getAndSet(true)) Runtime.getRuntime().addShutdownHook(new Thread("Histogram Printer") {
 			@Override public void run() {
 				int[] currentInterval = {0};
-				int[] b = bars.get(currentInterval);
+				long[] b = bars.get(currentInterval);
 				printReport(currentInterval[0], b);
 			}
 		});
 		
-		long end = System.currentTimeMillis();
-		long delta = end - start;
-		int interval = (int) (end / REPORT_TIME);
+		long end = System.nanoTime();
+		long now = System.currentTimeMillis();
+		long delta = end - startToken;
+		if (delta < 0L) delta = 0L;
+		int interval = (int) (now / REPORT_WINDOW);
 		int[] currentInterval = {0};
-		int[] bars = this.bars.get(currentInterval);
-		int[] newBars;
+		long[] bars = this.bars.get(currentInterval);
+		long[] newBars;
 		
 		if (currentInterval[0] != interval) {
 			printReport(currentInterval[0], bars);
-			newBars = new int[RANGES.length + 2];
+			newBars = new long[RANGES.length + 2];
 			if (!this.bars.compareAndSet(bars, newBars, currentInterval[0], interval)) {
 				newBars = this.bars.get(currentInterval);
 			}
@@ -65,12 +88,12 @@ public class HistogramTracker {
 		newBars[RANGES.length]++;
 	}
 	
-	private void printReport(int interval, int[] bars) {
+	private void printReport(int interval, long[] bars) {
 		StringBuilder sb = new StringBuilder();
 		if (category != null) sb.append(category).append(" ");
 		sb.append("[");
 		GregorianCalendar gc = new GregorianCalendar();
-		gc.setTimeInMillis(interval * REPORT_TIME);
+		gc.setTimeInMillis(interval * REPORT_WINDOW);
 		int hour = gc.get(Calendar.HOUR_OF_DAY);
 		int minute = gc.get(Calendar.MINUTE);
 		if (hour < 10) sb.append('0');
@@ -78,16 +101,32 @@ public class HistogramTracker {
 		if (minute < 10) sb.append('0');
 		sb.append(minute).append("] {");
 		
-		int sum = bars[RANGES.length];
+		long sum = bars[RANGES.length];
+		int count = 0;
+		int lastZeroPos = sb.length();
 		for (int i = 0; i < RANGES.length; i++) {
 			sum += bars[i];
-			sb.append(bars[i]).append(" ");
+			sb.append(bars[i]);
+			if (bars[i] != 0) lastZeroPos = sb.length();
+			sb.append(" ");
+			count++;
+			if (count == 3) sb.append("-- ");
+			if (count == 9) sb.append("-- ");
 		}
 		
+		
 		if (sum == 0) return;
+		sb.setLength(lastZeroPos);
 		
-		sb.append(bars[RANGES.length]).append("} total calls: ").append(sum).append(" total time: ").append(bars[RANGES.length + 1]);
+		double millis = bars[RANGES.length + 1] / 1000000.0;
+		
+		long over = bars[RANGES.length];
+		if (over > 0L) {
+				sb.append(" -- ").append(bars[RANGES.length]);
+		}
+		sb.append("} total calls: ").append(sum).append(" total time (millis): ").append((int)(millis + 0.5));
 		
-		ProblemReporter.info(sb.toString(), null);
+		if (out == null) ProblemReporter.info(sb.toString(), null);
+		else out.println(sb.toString());
 	}
 }
diff --git a/src/core/lombok/eclipse/TransformEclipseAST.java b/src/core/lombok/eclipse/TransformEclipseAST.java
index 11caf5c2..e6528178 100644
--- a/src/core/lombok/eclipse/TransformEclipseAST.java
+++ b/src/core/lombok/eclipse/TransformEclipseAST.java
@@ -26,6 +26,7 @@ import static lombok.eclipse.handlers.EclipseHandlerUtil.*;
 import java.lang.reflect.Field;
 
 import lombok.core.debug.DebugSnapshotStore;
+import lombok.core.debug.HistogramTracker;
 import lombok.patcher.Symbols;
 
 import org.eclipse.jdt.internal.compiler.ast.AbstractMethodDeclaration;
@@ -57,6 +58,14 @@ public class TransformEclipseAST {
 	private static final HandlerLibrary handlers;
 	
 	public static boolean disableLombok = false;
+	private static final HistogramTracker lombokTracker;
+	
+	static {
+		String v = System.getProperty("lombok.histogram");
+		if (v == null) lombokTracker = null;
+		else if (v.toLowerCase().equals("sysout")) lombokTracker = new HistogramTracker("lombok.histogram", System.out);
+		else lombokTracker = new HistogramTracker("lombok.histogram");
+	}
 	
 	static {
 		Field f = null;
@@ -136,8 +145,10 @@ public class TransformEclipseAST {
 		
 		try {
 			DebugSnapshotStore.INSTANCE.snapshot(ast, "transform entry");
+			long histoToken = lombokTracker == null ? 0L : lombokTracker.start();
 			EclipseAST existing = getAST(ast, false);
 			new TransformEclipseAST(existing).go();
+			if (lombokTracker != null) lombokTracker.end(histoToken);
 			DebugSnapshotStore.INSTANCE.snapshot(ast, "transform exit");
 		} catch (Throwable t) {
 			DebugSnapshotStore.INSTANCE.snapshot(ast, "transform error: %s", t.getClass().getSimpleName());