You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@uima.apache.org by bu...@apache.org on 2015/04/21 00:03:34 UTC
svn commit: r1674995 - in /uima/sandbox/uima-ducc/trunk:
uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/
uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/classload/
uima-ducc-container/src/main/java/or...
Author: burn
Date: Mon Apr 20 22:03:33 2015
New Revision: 1674995
URL: http://svn.apache.org/r1674995
Log:
UIMA-4354 Add debug logging to report summary of elapsed times of JD's msg processing. Increased Jetty server threads to 100
Modified:
uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/ILogger.java
uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/Logger.java
uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/classload/ProxyJobDriverCollectionReader.java
uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/mh/MessageHandler.java
uima/sandbox/uima-ducc/trunk/uima-ducc-transport/src/main/java/org/apache/uima/ducc/transport/configuration/jd/JobDriverConfiguration.java
Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/ILogger.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/ILogger.java?rev=1674995&r1=1674994&r2=1674995&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/ILogger.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/ILogger.java Mon Apr 20 22:03:33 2015
@@ -53,5 +53,7 @@ public interface ILogger {
public void warn(String location, Id jobId, Throwable t, Object ... args);
public void warn(String location, Id jobId, Id processId, Object ... args);
public void warn(String location, Id jobId, Id processId, Throwable t, Object ... args);
+
+ boolean isDebug();
}
Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/Logger.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/Logger.java?rev=1674995&r1=1674994&r2=1674995&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/Logger.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/common/logger/Logger.java Mon Apr 20 22:03:33 2015
@@ -169,4 +169,8 @@ public class Logger implements ILogger {
duccLogger.warn(location, toDuccId(jobId), toDuccId(processId), t, args);
}
+ @Override
+ public boolean isDebug() {
+ return duccLogger.isDebug();
+ }
}
Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/classload/ProxyJobDriverCollectionReader.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/classload/ProxyJobDriverCollectionReader.java?rev=1674995&r1=1674994&r2=1674995&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/classload/ProxyJobDriverCollectionReader.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/classload/ProxyJobDriverCollectionReader.java Mon Apr 20 22:03:33 2015
@@ -32,6 +32,7 @@ import org.apache.uima.ducc.container.co
import org.apache.uima.ducc.container.common.logger.IComponent;
import org.apache.uima.ducc.container.common.logger.ILogger;
import org.apache.uima.ducc.container.common.logger.Logger;
+import org.apache.uima.ducc.container.jd.mh.MessageHandler;
import org.apache.uima.ducc.container.net.impl.MetaCas;
public class ProxyJobDriverCollectionReader {
@@ -107,7 +108,9 @@ public class ProxyJobDriverCollectionRea
MetaCas retVal = null;
try {
method_getJdUserMetaCas = class_JdUserCollectionReader.getMethod(name_getJdUserMetaCas, nullClassArray);
+ long stime = System.nanoTime();
Object instance_metaCas = method_getJdUserMetaCas.invoke(instance_JdUserCollectionReader, nullObjectArray);
+ MessageHandler.accumulateTimes("CR", stime); // When debugging accumulate elapsed time spent in CR
if(instance_metaCas != null) {
Method method_getSeqNo = class_JdUserMetaCas.getMethod(name_getSeqNo, nullClassArray);
Integer integer = (Integer)method_getSeqNo.invoke(instance_metaCas, nullObjectArray);
Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/mh/MessageHandler.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/mh/MessageHandler.java?rev=1674995&r1=1674994&r2=1674995&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/mh/MessageHandler.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-container/src/main/java/org/apache/uima/ducc/container/jd/mh/MessageHandler.java Mon Apr 20 22:03:33 2015
@@ -20,6 +20,7 @@ package org.apache.uima.ducc.container.j
import java.io.File;
import java.util.ArrayList;
+import java.util.HashMap;
import java.util.Map.Entry;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.atomic.AtomicBoolean;
@@ -67,6 +68,8 @@ public class MessageHandler implements I
private static ILogger logger = Logger.getLogger(MessageHandler.class, IComponent.Id.JD.name());
+ private static final boolean reportTimes = logger.isDebug(); // Must be set for whole of job
+
private AtomicInteger gets = new AtomicInteger(0);
private AtomicInteger acks = new AtomicInteger(0);
private AtomicInteger investmentResets = new AtomicInteger(0);
@@ -186,6 +189,7 @@ public class MessageHandler implements I
mb.append(Standardize.Label.todMostRecentStart.get()+oi.getWorkItemTodMostRecentStart());
logger.debug(location, jobid, mb.toString());
retVal = oi;
+ totalWorkItems = cms.getCrTotal(); // Used by accumlateTimes
}
catch(Exception e) {
logger.error(location, jobid, e);
@@ -449,6 +453,7 @@ public class MessageHandler implements I
mb.append(Standardize.Label.type.get()+trans.getType());
logger.debug(location, ILogger.null_id, mb.toString());
Type type = trans.getType();
+ long stime = System.nanoTime(); // Used when log level == debug
switch(type) {
case Get:
handleMetaCasTransationGet(trans, rwt);
@@ -465,6 +470,7 @@ public class MessageHandler implements I
default:
break;
}
+ accumulateTimes(type.name(), stime);
JdState jdState = JobDriver.getInstance().getJdState();
trans.setJdState(jdState);
IMetaCas metaCas = trans.getMetaCas();
@@ -565,4 +571,42 @@ public class MessageHandler implements I
}
}
+ /*
+ * When debugging report elapsed times for JD's handling of requests
+ * Check the initial value of the logging level ... cannot change mid-stream as are collecting statistics
+ */
+ private static int totalWorkItems = -1;
+ private static HashMap<String,long[]> timeMap = new HashMap<String,long[]>();
+
+ public static void accumulateTimes(String name, long stime) {
+
+ if (!reportTimes) return;
+
+ long elapsed = System.nanoTime() - stime;
+
+ synchronized (timeMap) {
+ long[] nums = timeMap.get(name);
+ if (nums == null) {
+ nums = new long[]{0, 0, 10000000000L, 0}; // count total min max
+ timeMap.put(name, nums);
+ }
+ ++nums[0];
+ nums[1] += elapsed;
+ if (elapsed < nums[2])
+ nums[2] = elapsed;
+ else if (elapsed > nums[3])
+ nums[3] = elapsed;
+
+ // When processed last 'Get' log all times since winding down with empty Gets may distort avgs
+ if (nums[0] == totalWorkItems && name.equals("Get")) {
+ for (String nam : timeMap.keySet()) {
+ nums = timeMap.get(nam);
+ logger.debug("accumulateTimes", ILogger.null_id, "Elapsed times at last Get: " + nam + ": " + nums[0]
+ + " avg: " + 1E-6 * nums[1] / nums[0]
+ + " min: " + nums[2] * 1E-6
+ + " max: " + nums[3] * 1E-6 + " msec");
+ }
+ }
+ }
+ }
}
Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-transport/src/main/java/org/apache/uima/ducc/transport/configuration/jd/JobDriverConfiguration.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-transport/src/main/java/org/apache/uima/ducc/transport/configuration/jd/JobDriverConfiguration.java?rev=1674995&r1=1674994&r2=1674995&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-transport/src/main/java/org/apache/uima/ducc/transport/configuration/jd/JobDriverConfiguration.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-transport/src/main/java/org/apache/uima/ducc/transport/configuration/jd/JobDriverConfiguration.java Mon Apr 20 22:03:33 2015
@@ -36,6 +36,7 @@ import org.apache.uima.ducc.common.utils
import org.apache.uima.ducc.common.utils.Utils;
import org.apache.uima.ducc.common.utils.XStreamUtils;
import org.apache.uima.ducc.common.utils.id.DuccId;
+import org.apache.uima.ducc.container.jd.mh.MessageHandler;
import org.apache.uima.ducc.container.net.iface.IMetaCasTransaction;
import org.apache.uima.ducc.container.net.iface.IMetaCasTransaction.Direction;
import org.apache.uima.ducc.container.net.impl.MetaCasTransaction;
@@ -140,10 +141,10 @@ import org.springframework.context.annot
};
}
*/
- public Server createServer(int port, String app, IJobDriverComponent jdc) throws Exception {
+ public Server createServer(int port, int maxThreads, String app, IJobDriverComponent jdc) throws Exception {
Server server = new Server(port);
QueuedThreadPool threadPool = new QueuedThreadPool();
- threadPool.setMaxThreads(10);
+ threadPool.setMaxThreads(maxThreads);
server.setThreadPool(threadPool);
ServletContextHandler context = new ServletContextHandler(ServletContextHandler.SESSIONS);
@@ -224,11 +225,12 @@ import org.springframework.context.annot
}
port = Utils.findFreePort();
jdc.setPort(port);
+ int maxThreads = 100; // Could be specified in ducc.properties
String jdUniqueId = "/jdApp";
// jdc.getContext().addRoutes(this.routeBuilderForJpIncomingRequests(jdc, port, jdUniqueId));
- Server server = createServer(port, jdUniqueId, jdc);
+ Server server = createServer(port, maxThreads, jdUniqueId, jdc);
server.start();
- logger.info(location,jobid,"Jetty Running - Port:"+port);
+ logger.info(location,jobid,"Jetty Running - Port: "+port+" Max threads: "+maxThreads);
logger.info(location, jobid, "port: "+port+" "+"endpoint: "+common.jdStateUpdateEndpoint+" "+"rate: "+common.jdStatePublishRate);
jdc.getContext().addRoutes(this.routeBuilderForJdStatePost(jdc, common.jdStateUpdateEndpoint, Integer.parseInt(common.jdStatePublishRate)));
@@ -253,6 +255,7 @@ import org.springframework.context.annot
throws ServletException, IOException
{
try {
+ long post_stime = System.nanoTime();
StringBuilder sb = new StringBuilder();
BufferedReader reader = request.getReader();
String line;
@@ -274,10 +277,12 @@ import org.springframework.context.annot
// .unmarshall(t.trim());
imt = (IMetaCasTransaction) XStreamUtils
.unmarshall(content);
+ MessageHandler.accumulateTimes("Unmarshall", post_stime);
// process JP's request
jdc.handleJpRequest(imt);
+ long marshall_stime = System.nanoTime();
// setup reply
imt.setDirection(Direction.Response);
@@ -287,10 +292,16 @@ import org.springframework.context.annot
String body = XStreamUtils.marshall(imt);
response.getWriter().write(body);
-
+
+ // When debugging accumulate times taken by each stage of the message processing
+ MessageHandler.accumulateTimes("Marshall", marshall_stime);
+ MessageHandler.accumulateTimes("Post", post_stime);
} catch (Throwable e) {
throw new ServletException(e);
}
}
+
+
}
+
}