[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.

5 files changed, 155 insertions, 6 deletions

diff --git a/doc/changelog.markdown b/doc/changelog.markdown
index d6c1b380..40a8e312 100644
--- a/doc/changelog.markdown
+++ b/doc/changelog.markdown
@@ -4,6 +4,14 @@ Lombok Changelog
 ### v1.14.5 "Edgy Guinea Pig"
 
 * WORK-IN-PROGRESS: A bunch of errors in the error log about 'Path must include project and resource name' seem to be related to slowdowns. This fix removes the errors, but does it remove the slowdowns? [Issue #682](https://code.google.com/p/projectlombok/issues/detail?id=682).
+    This edge release contains some special flags:
+
+    1. `-Dlombok.timeConfig`: Adding this switch adds profiling to config lookups. Every minute a histogram is printed to the error log (eclipse) or syserr (javac and others).
+        The 10 numbers printed list calls in exponential increasing millisecond durations (first number is 0 millis, second is 1, third is 2 to 4, etc). If the numbers seem
+        excessive to you, help us out and report your findings on our [newsgroup](https://groups.google.com/forum/#!topic/project-lombok/UNCvLSEGWik).
+    2. `-Dlombok.disableConfig`: Disables the config system (notably including all attempts to look up the location of, and read, `lombok.config` files) entirely.
+
+    Both flags can be used simultaneously. Add either or both of these switches in your `eclipse.ini`, directly under `-javaagent:lombok.jar`.
 
 ### v1.14.4 (July 1st, 2014)
 * BUGFIX: GWT produces errors in handlers on line 1 in any source files that use lombok; this has been fixed. [Issue #699](https://code.google.com/p/projectlombok/issues/detail?id=699)
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;