[config] added histogram tracker option (-Dlombok.timeConfig) and disable-entirely option (-Dlombok.disableConfig) to debug continuing speed issues with the config system, for an edge release.

4 files changed, 147 insertions, 6 deletions

diff --git a/src/core/lombok/core/AST.java b/src/core/lombok/core/AST.java
index 18bae175..7bddbada 100644
--- a/src/core/lombok/core/AST.java
+++ b/src/core/lombok/core/AST.java
@@ -37,6 +37,7 @@ import java.util.List;
 import java.util.Map;
 
 import lombok.core.configuration.ConfigurationKey;
+import lombok.core.debug.HistogramTracker;
 
 /**
  * Lombok wraps the AST produced by a target platform into its own AST system, mostly because both Eclipse and javac
@@ -60,6 +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");
 	
 	protected AST(String fileName, String packageDeclaration, ImportList imports) {
 		this.fileName = fileName == null ? "(unknown).java" : fileName;
@@ -419,6 +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) {
-		return LombokConfiguration.read(key, this);
+		long start = System.currentTimeMillis();
+		try {
+			return LombokConfiguration.read(key, this);
+		} finally {
+			if (histogramTracker != null) histogramTracker.report(start);
+		}
 	}
 }
diff --git a/src/core/lombok/core/LombokConfiguration.java b/src/core/lombok/core/LombokConfiguration.java
index 137a8a83..c53da35f 100644
--- a/src/core/lombok/core/LombokConfiguration.java
+++ b/src/core/lombok/core/LombokConfiguration.java
@@ -29,8 +29,27 @@ import lombok.core.configuration.ConfigurationResolverFactory;
 import lombok.core.configuration.FileSystemSourceCache;
 
 public class LombokConfiguration {
+	private static final ConfigurationResolver NULL_RESOLVER = new ConfigurationResolver() {
+		@Override public <T> T resolve(ConfigurationKey<T> key) {
+			return null;
+		}
+	};
+	
 	private static FileSystemSourceCache cache = new FileSystemSourceCache();
-	private static ConfigurationResolverFactory configurationResolverFactory = createFileSystemBubblingResolverFactory();
+	private static ConfigurationResolverFactory configurationResolverFactory;
+	
+	static {
+		if (System.getProperty("lombok.disableConfig") != null) {
+			configurationResolverFactory = new ConfigurationResolverFactory() {
+				@Override public ConfigurationResolver createResolver(AST<?, ?, ?> ast) {
+					return NULL_RESOLVER;
+				}
+			};
+		}
+		else {
+			configurationResolverFactory = createFileSystemBubblingResolverFactory();
+		}
+	}
 	
 	private LombokConfiguration() {
 		// prevent instantiation
diff --git a/src/core/lombok/core/debug/HistogramTracker.java b/src/core/lombok/core/debug/HistogramTracker.java
new file mode 100644
index 00000000..3ae8a58b
--- /dev/null
+++ b/src/core/lombok/core/debug/HistogramTracker.java
@@ -0,0 +1,93 @@
+package lombok.core.debug;
+
+import java.util.Calendar;
+import java.util.GregorianCalendar;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicStampedReference;
+
+/**
+ * Create one of these and call .report() on it a lot to emit histogram data about the times taken by some process.
+ * Currently the results are broken down into 10 buckets, from 0 millis to a quarter of a second, and a report is emitted
+ * to the ProblemReporter every minute. If there are 0 entries for a given minute, it is not reported. Reports aren't
+ * 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 final String category;
+	private final AtomicStampedReference<int[]> bars = new AtomicStampedReference<int[]>(new int[RANGES.length + 2], 0);
+	private final AtomicBoolean addedSysHook = new AtomicBoolean(false);
+	
+	public HistogramTracker(String category) {
+		this.category = category;
+		if (category == null) {
+			ProblemReporter.info("Initialized histogram", null);
+		} else {
+			ProblemReporter.info(String.format("Initialized histogram tracker for '%s'",  category), null);
+		}
+	}
+	
+	public void report(long start) {
+		if (!addedSysHook.getAndSet(true)) Runtime.getRuntime().addShutdownHook(new Thread("Histogram Printer") {
+			@Override public void run() {
+				int[] currentInterval = {0};
+				int[] b = bars.get(currentInterval);
+				printReport(currentInterval[0], b);
+			}
+		});
+		
+		long end = System.currentTimeMillis();
+		long delta = end - start;
+		int interval = (int) (end / REPORT_TIME);
+		int[] currentInterval = {0};
+		int[] bars = this.bars.get(currentInterval);
+		int[] newBars;
+		
+		if (currentInterval[0] != interval) {
+			printReport(currentInterval[0], bars);
+			newBars = new int[RANGES.length + 2];
+			if (!this.bars.compareAndSet(bars, newBars, currentInterval[0], interval)) {
+				newBars = this.bars.get(currentInterval);
+			}
+		} else {
+			newBars = bars;
+		}
+		
+		newBars[RANGES.length + 1] += delta;
+		for (int i = 0; i < RANGES.length; i++) {
+			if (delta < RANGES[i]) {
+				newBars[i]++;
+				return;
+			}
+		}
+		
+		newBars[RANGES.length]++;
+	}
+	
+	private void printReport(int interval, int[] bars) {
+		StringBuilder sb = new StringBuilder();
+		if (category != null) sb.append(category).append(" ");
+		sb.append("[");
+		GregorianCalendar gc = new GregorianCalendar();
+		gc.setTimeInMillis(interval * REPORT_TIME);
+		int hour = gc.get(Calendar.HOUR_OF_DAY);
+		int minute = gc.get(Calendar.MINUTE);
+		if (hour < 10) sb.append('0');
+		sb.append(hour).append(":");
+		if (minute < 10) sb.append('0');
+		sb.append(minute).append("] {");
+		
+		int sum = bars[RANGES.length];
+		for (int i = 0; i < RANGES.length; i++) {
+			sum += bars[i];
+			sb.append(bars[i]).append(" ");
+		}
+		
+		if (sum == 0) return;
+		
+		sb.append(bars[RANGES.length]).append("} total calls: ").append(sum).append(" total time: ").append(bars[RANGES.length + 1]);
+		
+		ProblemReporter.info(sb.toString(), null);
+	}
+}
diff --git a/src/core/lombok/core/debug/ProblemReporter.java b/src/core/lombok/core/debug/ProblemReporter.java
index 489bdfea..ce30496b 100644
--- a/src/core/lombok/core/debug/ProblemReporter.java
+++ b/src/core/lombok/core/debug/ProblemReporter.java
@@ -31,6 +31,16 @@ import org.eclipse.core.runtime.Status;
 import org.osgi.framework.Bundle;
 
 public class ProblemReporter {
+	public static void info(String msg, Throwable ex) {
+		init();
+		try {
+			logger.info(msg, ex);
+		} catch (Throwable t) {
+			logger = new TerminalLogger();
+			logger.info(msg, ex);
+		}
+	}
+	
 	public static void warning(String msg, Throwable ex) {
 		init();
 		try {
@@ -63,13 +73,14 @@ public class ProblemReporter {
 	private static ErrorLogger logger;
 	
 	private interface ErrorLogger {
-		void error(String message, Throwable ex);
+		void info(String message, Throwable ex);
 		void warning(String message, Throwable ex);
+		void error(String message, Throwable ex);
 	}
 	
 	private static class TerminalLogger implements ErrorLogger {
 		@Override
-		public void error(String message, Throwable ex) {
+		public void info(String message, Throwable ex) {
 			System.err.println(message);
 			if (ex != null) ex.printStackTrace();
 		}
@@ -79,6 +90,12 @@ public class ProblemReporter {
 			System.err.println(message);
 			if (ex != null) ex.printStackTrace();
 		}
+		
+		@Override
+		public void error(String message, Throwable ex) {
+			System.err.println(message);
+			if (ex != null) ex.printStackTrace();
+		}
 	}
 	
 	private static class EclipseWorkspaceLogger implements ErrorLogger {
@@ -96,8 +113,8 @@ public class ProblemReporter {
 		}
 		
 		@Override
-		public void error(String message, Throwable error) {
-			msg(IStatus.ERROR, message, error);
+		public void info(String message, Throwable error) {
+			msg(IStatus.INFO, message, error);
 		}
 		
 		@Override
@@ -105,6 +122,11 @@ public class ProblemReporter {
 			msg(IStatus.WARNING, message, error);
 		}
 		
+		@Override
+		public void error(String message, Throwable error) {
+			msg(IStatus.ERROR, message, error);
+		}
+		
 		private void msg(int msgType, String message, Throwable error) {
 			int ct = squelchTimeout != 0L ? 0 : counter.incrementAndGet();
 			boolean printSquelchWarning = false;