[freenet-cvs] r20958 - branches/db4o/freenet/src/freenet/support

[toad at freenetproject.org]

Author: toad
Date: 2008-07-04 00:07:53 +0000 (Fri, 04 Jul 2008)
New Revision: 20958

Modified:
   branches/db4o/freenet/src/freenet/support/PrioritizedSerialExecutor.java
Log:
Logging, including calculation of the total millis used by each class.
Also add runningJobs().

Modified: branches/db4o/freenet/src/freenet/support/PrioritizedSerialExecutor.java
===================================================================
--- branches/db4o/freenet/src/freenet/support/PrioritizedSerialExecutor.java	2008-07-04 00:06:38 UTC (rev 20957)
+++ branches/db4o/freenet/src/freenet/support/PrioritizedSerialExecutor.java	2008-07-04 00:07:53 UTC (rev 20958)
@@ -1,6 +1,9 @@
 package freenet.support;
 
+import java.util.HashMap;
+import java.util.Iterator;
 import java.util.LinkedList;
+import java.util.Map;
 
 import freenet.node.PrioRunnable;
 import freenet.support.io.NativeThread;
@@ -12,6 +15,7 @@
 	private final int defaultPriority;
 	private boolean waiting;
 	private final boolean invertOrder;
+	private final Map timeByJobClasses = new HashMap();
 	
 	private String name;
 	private Executor realExecutor;
@@ -30,6 +34,7 @@
 		}
 
 		public void run() {
+			long lastDumped = System.currentTimeMillis();
 			current = Thread.currentThread();
 			while(true) {
 				Runnable job = null;
@@ -54,7 +59,34 @@
 				try {
 					if(Logger.shouldLog(Logger.MINOR, this))
 						Logger.minor(this, "Running job "+job);
+					long start = System.currentTimeMillis();
 					job.run();
+					long end = System.currentTimeMillis();
+					if(Logger.shouldLog(Logger.MINOR, this))
+						Logger.minor(this, "Job "+job+" took "+(end-start)+"ms");
+					synchronized(timeByJobClasses) {
+						String name = job.toString();
+						if(name.indexOf('@') > 0)
+							name = name.substring(0, name.indexOf('@'));
+						Long l = (Long) timeByJobClasses.get(name);
+						if(l != null) {
+							l = new Long(l.longValue() + (end-start));
+						} else {
+							l = new Long(end-start);
+						}
+						timeByJobClasses.put(name, l);
+						if(Logger.shouldLog(Logger.MINOR, this)) {
+							Logger.minor(this, "Total for class "+name+" : "+l);
+							if(System.currentTimeMillis() > (lastDumped + 60*1000)) {
+								Iterator i = timeByJobClasses.entrySet().iterator();
+								while(i.hasNext()) {
+									Map.Entry e = (Map.Entry) i.next();
+									Logger.minor(this, "Class "+e.getKey()+" : total time "+e.getValue());
+								}
+								lastDumped = System.currentTimeMillis();
+							}
+						}
+					}
 				} catch (Throwable t) {
 					Logger.error(this, "Caught "+t, t);
 					Logger.error(this, "While running "+job+" on "+this);
@@ -66,12 +98,16 @@
 			if(!invertOrder) {
 				for(int i=0;i<jobs.length;i++) {
 					if(!jobs[i].isEmpty()) {
+						if(Logger.shouldLog(Logger.MINOR, this))
+							Logger.minor(this, "Chosen job at priority "+i);
 						return (Runnable) jobs[i].removeFirst();
 					}
 				}
 			} else {
 				for(int i=jobs.length-1;i>=0;i--) {
 					if(!jobs[i].isEmpty()) {
+						if(Logger.shouldLog(Logger.MINOR, this))
+							Logger.minor(this, "Chosen job at priority "+i);
 						return (Runnable) jobs[i].removeFirst();
 					}
 				}
@@ -185,4 +221,13 @@
 		}
 	}
 
+	public int[] runningJobs() {
+		int[] retval = new int[jobs.length];
+		synchronized(jobs) {
+			for(int i=0;i<retval.length;i++)
+				retval[i] = jobs[i].size();
+		}
+		return retval;
+	}
+
 }