Rewrite timings, again. Better results this time...

Author: bensku

src/main/java/ch/njol/skript/SkriptEventHandler.java

@@ -47,6 +47,8 @@
 import ch.njol.skript.lang.SelfRegisteringSkriptEvent;
 import ch.njol.skript.lang.Trigger;
 import ch.njol.skript.lang.function.Functions;
+import ch.njol.skript.timings.Timing;
+import ch.njol.skript.timings.Timings;
 
 /**
  * @author Peter Güttinger
@@ -155,16 +157,24 @@ static void check(final Event e) {
 	}
 
 	private static long startEvent;
+	@Nullable
+	private static Timing timing;
 
 	public static void logEventStart(final Event e) {
+		if (Timings.enabled())
+			timing = Timings.of(e.getEventName());
+		
+		startEvent = System.nanoTime();
 		if (!Skript.logVeryHigh())
 			return;
-		startEvent = System.nanoTime();
 		Skript.info("");
 		Skript.info("== " + e.getClass().getName() + " ==");
 	}
 
 	public static void logEventEnd() {
+		if (timing != null)
+			timing.setEventTime(System.nanoTime() - startEvent);
+		
 		if (!Skript.logVeryHigh())
 			return;
 		Skript.info("== took " + 1. * (System.nanoTime() - startEvent) / 1000000. + " milliseconds ==");
@@ -173,13 +183,16 @@ public static void logEventEnd() {
 	static long startTrigger;
 
 	public static void logTriggerStart(final Trigger t) {
+		startTrigger = System.nanoTime();
 		if (!Skript.logVeryHigh())
 			return;
 		Skript.info("# " + t.getName());
-		startTrigger = System.nanoTime();
 	}
 
 	public static void logTriggerEnd(final Trigger t) {
+		if (timing != null)
+			timing.addTrigger(t, System.nanoTime() - startTrigger);
+		
 		if (!Skript.logVeryHigh())
 			return;
 		Skript.info("# " + t.getName() + " took " + 1. * (System.nanoTime() - startTrigger) / 1000000. + " milliseconds");

src/main/java/ch/njol/skript/lang/TriggerItem.java

@@ -88,11 +88,7 @@ protected TriggerItem walk(final Event e) {
 	public final static boolean walk(final TriggerItem start, final Event e) {
 		assert start != null && e != null;
 		TriggerItem i = start;
-		Timing timing = null;
 		try {
-			if (Timings.enabled())
-				timing = Timings.start(e);
-			
 			while (i != null)
 				i = i.walk(e);
 
@@ -106,11 +102,6 @@ public final static boolean walk(final TriggerItem start, final Event e) {
 		} catch (final Exception ex) {
 			if (ex.getStackTrace().length != 0) // empty exceptions have already been printed
 				Skript.exception(ex, i);
-		} finally {
-			if (Timings.enabled()) {
-				assert timing != null;
-				timing.stop(); // Whatever happened, end the timing
-			}
 		}
 		return false;
 	}

src/main/java/ch/njol/skript/timings/Timing.java

@@ -24,145 +24,47 @@
 import java.lang.ref.WeakReference;
 import java.util.ArrayList;
 import java.util.HashMap;
+import java.util.LinkedHashMap;
 import java.util.List;
 import java.util.Map;
 
-import ch.njol.skript.Skript;
+import org.bukkit.event.Event;
+
+import com.google.common.collect.ImmutableMap;
 
-import com.google.common.collect.Lists;
+import ch.njol.skript.Skript;
+import ch.njol.skript.lang.Trigger;
 
 /**
  * Timing for certain action.
  */
 public class Timing {
 
-	public class Capture {
-		
-		final String thread;
-		
-		long start;
-		long end;
-		
-		long paused; // Time while paused
-		long pauseBegin;
-		
-		protected Capture(final Thread thread) {
-			String name = thread.getName();
-			assert name != null;
-			this.thread = name;
-		}
-		
-		public void start() {
-			start = System.nanoTime();
-		}
-		
-		public void stop() {
-			end = System.nanoTime();
-		}
-		
-		public void pause() {
-			pauseBegin = System.nanoTime();
-		}
-		
-		public void unpause() {
-			long pauseTime = System.nanoTime() - pauseBegin;
-			paused += pauseTime;
-		}
-		
-		public long result() {
-			if (end == 0L)
-				end = System.nanoTime();
-			
-			return end - start - paused;
-		}
-		
-		public boolean isOf(Thread t) {
-			return (thread.equals(t.getName()));
-		}
-	}
-	
-	private List<Capture> captures = new ArrayList<Capture>();
-	private Map<Thread,Capture> inProgress;
+	private Map<Trigger,Long> triggerTimes;
+	private long eventTime;
 
 	/**
 	 * Creates a new timing. Only used by {@link Timings}
 	 */
 	protected Timing() {
-		captures = new ArrayList<Capture>();
-		inProgress = new HashMap<Thread,Capture>();
+		triggerTimes = new LinkedHashMap<Trigger,Long>();
+		eventTime = 0L;
 	}
 
-	/**
-	 * Starts timing measurement for caller thread.
-	 * @return Timing for chaining
-	 */
-	public Timing start() {
-		Thread current = Thread.currentThread();
-		assert current != null;
-		if (inProgress.containsKey(current)) {
-			inProgress.get(current).stop();
-			inProgress.remove(current);
-		}
-		
-		Capture c = new Capture(current);
-		c.start();
-		captures.add(c);
-		inProgress.put(current, c);
-		
-		return this;
+	public void addTrigger(Trigger t, long time) {
+		triggerTimes.put(t, time);
 	}
 
-	/**
-	 * Stops timing measurements for caller thread if it was in progress.
-	 */
-	public void stop() {
-		Thread current = Thread.currentThread();
-		assert current != null;
-		if (inProgress.containsKey(current)) {
-			inProgress.get(current).stop();
-			inProgress.remove(current);
-		}
+	public void setEventTime(long time) {
+		eventTime = time;
 	}
 
-	/**
-	 * Pauses timing measurement for caller thread until {@link #unpause()} is called.
-	 * @return Timing for chaining.
-	 */
-	public Timing pause() {
-		Thread current = Thread.currentThread();
-		assert current != null;
-		if (inProgress.containsKey(current)) {
-			inProgress.get(current).pause();
-		}
-		
-		return this;
-	}
-	
-	/**
-	 * Unpauses timing measurement for caller thread if it was paused.
-	 * @return Timing for chaining.
-	 */
-	public Timing unpause() {
-		Thread current = Thread.currentThread();
-		assert current != null;
-		if (inProgress.containsKey(current)) {
-			inProgress.get(current).unpause();
-		}
-		
-		return this;
+	@SuppressWarnings("null")
+	public Map<Trigger,Long> getTriggerTimes() {
+		return ImmutableMap.copyOf(triggerTimes);
 	}
 
-	/**
-	 * Gets list of captures for given thread. Very expensive to call.
-	 * @param thread
-	 * @return Captures for given thread
-	 */
-	public List<Capture> getCaptures(Thread thread) {
-		List<Capture> ret = new ArrayList<Capture>();
-		for (Capture c : captures)
-			if (c.isOf(thread))
-				ret.add(c);
-		
-		return ret;
+	public long getEventTime() {
+		return eventTime;
 	}
 }

src/main/java/ch/njol/skript/timings/TimingReporter.java

@@ -27,44 +27,54 @@
 import java.util.Map;
 import java.util.Map.Entry;
 
+import ch.njol.skript.lang.Trigger;
 import ch.njol.skript.localization.Language;
-import ch.njol.skript.timings.Timing.Capture;
 
 /**
  * Creates timing reports.
  */
 public class TimingReporter {
 
-	public static String generateReport() {
+	public static String getReport() {
 		Map<Object,Timing> timings = Timings.timings;
-		StringBuilder sb = new StringBuilder();
+		Map<String,Long> triggers = new HashMap<String,Long>();
+		Map<Object,Long> events = new HashMap<Object,Long>();
 
-		sb.append(String.format(Language.get("timings.start"), ((Timings.disableTime - Timings.enableTime)) / 1000000000));
-		Map<String,Long> results = parseTimings();
-		Iterator<Entry<String, Long>> it = results.entrySet().iterator();
-		while (it.hasNext()) {
-			Entry<String, Long> entry = it.next();
-			long time = entry.getValue();
-			sb.append(entry.getKey() + ": " + time + " (" + (time / 1000000000) + "ms)");
+		for (Entry<Object,Timing> entry : timings.entrySet()) {
+			Object key = entry.getKey();
+			Timing val = entry.getValue();
+			
+			for (Entry<Trigger,Long> trigger : val.getTriggerTimes().entrySet()) {
+				String name = trigger.getKey().getName();
+				long tt = 0L;
+				if (triggers.containsKey(name))
+					tt = triggers.get(name);
+				tt += trigger.getValue();
+				triggers.put(name, tt);
+			}
+			
+			long evtTime = 0L;
+			if (events.containsKey(key))
+				evtTime = events.get(key);
+			evtTime += val.getEventTime();
 		}
 
-		return sb.toString();
-	}
-	
-	@SuppressWarnings("null")
-	public static Map<String,Long> parseTimings() {
-		Map<String,Long> ret = new HashMap<String,Long>();
+		long length = Timings.disableTime - Timings.enableTime;
+		StringBuilder sb = new StringBuilder();
+		sb.append(String.format(Language.get("timings.start"), length / 1000000000));
+		
+		sb.append(Language.get("timings.triggers"));
+		for (Entry<String,Long> trigger : triggers.entrySet()) {
+			float percent = trigger.getValue() / length * 100;
+			sb.append(trigger.getKey() + ": " + (trigger.getValue() / 1000000) + "ms (" + percent + "%)");
+		}
 
-		Iterator<Entry<Object, Timing>> it = Timings.timings.entrySet().iterator();
-		while (it.hasNext()) {
-			Entry<Object, Timing> entry = it.next();
-			List<Capture> captures = entry.getValue().getCaptures(Thread.currentThread());
-			long time = 0;
-			for (Capture c : captures)
-				time += c.result();
-			ret.put(entry.toString(), time);
+		sb.append(Language.get("timings.events"));
+		for (Entry<Object,Long> event : events.entrySet()) {
+			float percent = event.getValue() / length * 100;
+			sb.append(event.getKey() + ": " + (event.getValue() / 1000000) + "ms (" + percent + "%)");
 		}
 
-		return ret;
+		return sb.toString();
 	}
 }

src/main/java/ch/njol/skript/timings/Timings.java

@@ -65,26 +65,8 @@ public static void disable() {
 		disableTime = System.nanoTime();
 	}
 
-	public static Timing start(Object ref) {
-		Timing timing = of(ref);
-		timing.start();
-		return timing;
-	}
-	
-	public static void stop(Object ref) {
-		Timing timing = of(ref);
-		timing.stop();
-	}
-	
-	public static Timing pause(Object ref) {
-		Timing timing = of(ref);
-		timing.pause();
-		return timing;
+	public static void clear() {
+		timings.clear();
 	}
 
-	public static Timing unpause(Object ref) {
-		Timing timing = of(ref);
-		timing.unpause();
-		return timing;
-	}
 }