You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@uima.apache.org by de...@apache.org on 2014/02/27 22:18:40 UTC

svn commit: r1572741 - in /uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator: ./ maintenance/ utilities/

Author: degenaro
Date: Thu Feb 27 21:18:40 2014
New Revision: 1572741

URL: http://svn.apache.org/r1572741
Log:
UIMA-3657 DUCC Orchestrator (OR) improved synchronization tracking

Added:
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/WorkMapHelper.java   (with props)
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/utilities/TrackSync.java   (with props)
Modified:
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/JobDriverHostManager.java
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCheckpoint.java
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCommonArea.java
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorComponent.java
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/ProcessAccounting.java
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/StateManager.java
    uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/maintenance/HealthMonitor.java

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/JobDriverHostManager.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/JobDriverHostManager.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/JobDriverHostManager.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/JobDriverHostManager.java Thu Feb 27 21:18:40 2014
@@ -156,7 +156,7 @@ public class JobDriverHostManager {
 		reservationRequestProperties.put(ReservationSpecificationProperties.key_user, jdHostUser);
 		duccWorkReservation = ReservationFactory.getInstance().create(commonConfiguration, reservationRequestProperties);
 		DuccWorkMap workMap = orchestratorCommonArea.getWorkMap();
-		workMap.addDuccWork(duccWorkReservation);
+		WorkMapHelper.addDuccWork(workMap, duccWorkReservation, this, methodName);
 		// state: Received
 		duccWorkReservation.stateChange(ReservationState.Received);
 		OrchestratorCheckpoint.getInstance().saveState();

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCheckpoint.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCheckpoint.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCheckpoint.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCheckpoint.java Thu Feb 27 21:18:40 2014
@@ -30,6 +30,7 @@ import org.apache.uima.ducc.common.utils
 import org.apache.uima.ducc.common.utils.DuccLoggerComponents;
 import org.apache.uima.ducc.common.utils.IOHelper;
 import org.apache.uima.ducc.orchestrator.utilities.Checkpointable;
+import org.apache.uima.ducc.orchestrator.utilities.TrackSync;
 import org.apache.uima.ducc.transport.event.common.DuccWorkMap;
 
 
@@ -146,8 +147,9 @@ public class OrchestratorCheckpoint {
 		boolean retVal = false;
 		if(saveEnabled) {
 			DuccWorkMap workMap = orchestratorCommonArea.getWorkMap();
-			long t0 = System.currentTimeMillis();
+			TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 			synchronized(workMap) {
+				ts.using();
 				try
 				{
 					logger.info(methodName, null, messages.fetchLabel("saving to")+fileName);
@@ -166,11 +168,7 @@ public class OrchestratorCheckpoint {
 					logger.error(methodName, null, e);
 				}
 			}
-			long t1 = System.currentTimeMillis();
-			long elapsed = t1 - t0;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-			}
+			ts.ended();
 		}
 		else {
 			logger.debug(methodName, null, messages.fetchLabel("bypass saving to")+fileName);
@@ -185,8 +183,9 @@ public class OrchestratorCheckpoint {
 		boolean retVal = false;
 		if(saveEnabled) {
 			DuccWorkMap workMap = orchestratorCommonArea.getWorkMap();
-			long t0 = System.currentTimeMillis();
+			TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 			synchronized(workMap) {
+				ts.using();
 				try
 				{
 					logger.info(methodName, null, messages.fetchLabel("restoring from")+fileName);
@@ -209,11 +208,7 @@ public class OrchestratorCheckpoint {
 					logger.error(methodName, null, e);
 				}
 			}
-			long t1 = System.currentTimeMillis();
-			long elapsed = t1 - t0;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-			}
+			ts.ended();
 		}
 		else {
 			logger.info(methodName, null, messages.fetchLabel("bypass restoring from")+fileName);

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCommonArea.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCommonArea.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCommonArea.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorCommonArea.java Thu Feb 27 21:18:40 2014
@@ -36,6 +36,7 @@ import org.apache.uima.ducc.common.utils
 import org.apache.uima.ducc.common.utils.id.DuccIdFactory;
 import org.apache.uima.ducc.common.utils.id.IDuccIdFactory;
 import org.apache.uima.ducc.orchestrator.utilities.Checkpointable;
+import org.apache.uima.ducc.orchestrator.utilities.TrackSync;
 import org.apache.uima.ducc.transport.event.common.DuccWorkMap;
 import org.apache.uima.ducc.transport.event.common.history.HistoryPersistenceManager;
 import org.apache.uima.ducc.transport.event.jd.DriverStatusReport;
@@ -180,24 +181,25 @@ public class OrchestratorCommonArea {
 		String methodName = "getCheckpointable";
 		DuccWorkMap ckptWorkMap;
 		ConcurrentHashMap<DuccId,DuccId> ckptProcessToJobMap;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			ckptWorkMap = (DuccWorkMap)SerializationUtils.clone(workMap);
 			ckptProcessToJobMap = (ConcurrentHashMap<DuccId,DuccId>)SerializationUtils.clone(processAccounting.getProcessToJobMap());
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}
+		ts.ended();
 		return new Checkpointable(ckptWorkMap,ckptProcessToJobMap);
 	}
 	
 	public void setCheckpointable(Checkpointable checkpointable) {
+		String methodName = "setCheckpointable";
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			workMap = checkpointable.getWorkMap();
 			processAccounting = new ProcessAccounting(checkpointable.getProcessToJobMap());
 		}
+		ts.ended();
 	}
 	
 	// **********

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorComponent.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorComponent.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorComponent.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/OrchestratorComponent.java Thu Feb 27 21:18:40 2014
@@ -47,6 +47,7 @@ import org.apache.uima.ducc.orchestrator
 import org.apache.uima.ducc.orchestrator.authentication.DuccWebAdministrators;
 import org.apache.uima.ducc.orchestrator.maintenance.MaintenanceThread;
 import org.apache.uima.ducc.orchestrator.maintenance.NodeAccounting;
+import org.apache.uima.ducc.orchestrator.utilities.TrackSync;
 import org.apache.uima.ducc.transport.event.CancelJobDuccEvent;
 import org.apache.uima.ducc.transport.event.CancelReservationDuccEvent;
 import org.apache.uima.ducc.transport.event.CancelServiceDuccEvent;
@@ -275,8 +276,9 @@ implements Orchestrator {
 			boolean saveState = false;
 			DuccPropertiesResolver dpr = DuccPropertiesResolver.getInstance();
 			String jdHostClass = dpr.getCachedProperty(DuccPropertiesResolver.ducc_jd_host_class);
-			long t0 = System.currentTimeMillis();
+			TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 			synchronized(workMap) {
+				ts.using();
 				Iterator<IDuccWork> iterator = workMap.values().iterator();
 				while(iterator.hasNext()) {
 					IDuccWork duccWork = iterator.next();
@@ -326,11 +328,7 @@ implements Orchestrator {
 					}
 				}
 			}
-			long t1 = System.currentTimeMillis();
-			long elapsed = t1 - t0;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-			}
+			ts.ended();
 			if(saveState) {
 				OrchestratorCheckpoint.getInstance().saveState();
 			}
@@ -423,13 +421,7 @@ implements Orchestrator {
 		logger.trace(methodName, null, messages.fetch("enter"));
 		OrchestratorStateDuccEvent orchestratorStateDuccEvent = new OrchestratorStateDuccEvent();
 		try {
-			long t0 = System.currentTimeMillis();
-			DuccWorkMap workMapCopy = workMap.deepCopy();
-			long t1 = System.currentTimeMillis();
-			long elapsed = t1 - t0;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-			}
+			DuccWorkMap workMapCopy = WorkMapHelper.deepCopy(workMap, this, methodName);
 			int activeJobs = workMapCopy.getJobCount();
 			int activeReservations = workMapCopy.getReservationCount();
 			int activeServices = workMapCopy.getServiceCount();
@@ -462,13 +454,7 @@ implements Orchestrator {
 		logger.trace(methodName, null, messages.fetch("enter"));
 		OrchestratorAbbreviatedStateDuccEvent orchestratorAbbreviatedStateDuccEvent = new OrchestratorAbbreviatedStateDuccEvent();
 		try {
-			long t0 = System.currentTimeMillis();
-			DuccWorkMap workMapCopy = workMap.deepCopy();
-			long t1 = System.currentTimeMillis();
-			long elapsed = t1 - t0;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-			}
+			DuccWorkMap workMapCopy = WorkMapHelper.deepCopy(workMap, this, methodName);
 			int activeJobs = workMapCopy.getJobCount();
 			int activeReservations = workMapCopy.getReservationCount();
 			int activeServices = workMapCopy.getServiceCount();
@@ -481,13 +467,7 @@ implements Orchestrator {
 											);
 			int jobDriverNodeCount = hostManager.nodes();
 			workMapCopy.setJobDriverNodeCount(jobDriverNodeCount);
-			long t2 = System.currentTimeMillis();
 			orchestratorAbbreviatedStateDuccEvent.setWorkMap(workMapCopy);
-			long t3 = System.currentTimeMillis();
-			long elapsed2 = t3 - t2;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed2);
-			}
 			//stateManager.prune(workMapCopy);
 			//healthMonitor.cancelNonViableJobs();
 			//mqReaper.removeUnusedJdQueues(workMapCopy);
@@ -611,13 +591,7 @@ implements Orchestrator {
 			else {
 				if(Validate.request(duccEvent)) {
 					DuccWorkJob duccWorkJob = jobFactory.create(common,properties);
-					long t0 = System.currentTimeMillis();
-					workMap.addDuccWork(duccWorkJob);
-					long t1 = System.currentTimeMillis();
-					long elapsed = t1 - t0;
-					if(elapsed > Constants.SYNC_LIMIT) {
-						logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-					}
+					WorkMapHelper.addDuccWork(workMap, duccWorkJob, this, methodName);
 					// state: Received
 					stateJobAccounting.stateChange(duccWorkJob, JobState.Received);
 					OrchestratorCheckpoint.getInstance().saveState();
@@ -658,7 +632,7 @@ implements Orchestrator {
 		else if(Validate.request(duccEvent)) {
 			String jobId = properties.getProperty(JobRequestProperties.key_id);
 			long t0 = System.currentTimeMillis();
-			DuccWorkJob duccWorkJob = (DuccWorkJob) workMap.findDuccWork(DuccType.Job,jobId);
+			DuccWorkJob duccWorkJob = (DuccWorkJob) WorkMapHelper.findDuccWork(workMap, DuccType.Job, jobId, this, methodName);
 			long t1 = System.currentTimeMillis();
 			long elapsed = t1 - t0;
 			if(elapsed > Constants.SYNC_LIMIT) {
@@ -726,7 +700,7 @@ implements Orchestrator {
 		else if(Validate.request(duccEvent)) {
 			String dpid = null;
 			String jobId = properties.getProperty(JobRequestProperties.key_id);
-			DuccWorkJob duccWorkJob = (DuccWorkJob) workMap.findDuccWork(DuccType.Job,jobId);
+			DuccWorkJob duccWorkJob = (DuccWorkJob) WorkMapHelper.findDuccWork(workMap, DuccType.Job, jobId, this, methodName);
 			if(duccWorkJob != null) {
 				dwid = duccWorkJob.getDuccId();
 				String reqUser = properties.getProperty(JobRequestProperties.key_user).trim();
@@ -825,13 +799,7 @@ implements Orchestrator {
 			}
 			else if(Validate.request(duccEvent)) {
 				DuccWorkReservation duccWorkReservation = reservationFactory.create(common,(ReservationRequestProperties)properties);
-				long t0 = System.currentTimeMillis();
-				workMap.addDuccWork(duccWorkReservation);
-				long t1 = System.currentTimeMillis();
-				long elapsed = t1 - t0;
-				if(elapsed > Constants.SYNC_LIMIT) {
-					logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-				}
+				WorkMapHelper.addDuccWork(workMap, duccWorkReservation, this, methodName);
 				// state: Received
 				duccWorkReservation.stateChange(ReservationState.Received);
 				OrchestratorCheckpoint.getInstance().saveState();
@@ -898,7 +866,7 @@ implements Orchestrator {
 		else {
 			String id = properties.getProperty(ReservationRequestProperties.key_id);
 			long t0 = System.currentTimeMillis();
-			DuccWorkReservation duccWorkReservation = (DuccWorkReservation) workMap.findDuccWork(DuccType.Reservation,id);
+			DuccWorkReservation duccWorkReservation = (DuccWorkReservation) WorkMapHelper.findDuccWork(workMap, DuccType.Reservation, id, this, methodName);
 			long t1 = System.currentTimeMillis();
 			long elapsed = t1 - t0;
 			if(elapsed > Constants.SYNC_LIMIT) {
@@ -985,13 +953,7 @@ implements Orchestrator {
 				logger.debug(methodName, null, messages.fetch("job driver host")+" "+messages.fetchLabel("IP")+nodeIdentity.getIp()+" "+messages.fetchLabel("name")+nodeIdentity.getName());
 				if(Validate.request(duccEvent)) {
 					DuccWorkJob duccWorkJob = jobFactory.create(common,properties);
-					long t0 = System.currentTimeMillis();
-					workMap.addDuccWork(duccWorkJob);
-					long t1 = System.currentTimeMillis();
-					long elapsed = t1 - t0;
-					if(elapsed > Constants.SYNC_LIMIT) {
-						logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-					}
+					WorkMapHelper.addDuccWork(workMap, duccWorkJob, this, methodName);
 					// state: Received
 					stateJobAccounting.stateChange(duccWorkJob, JobState.Received);
 					OrchestratorCheckpoint.getInstance().saveState();
@@ -1040,7 +1002,7 @@ implements Orchestrator {
 			// update state
 			String jobId = properties.getProperty(JobRequestProperties.key_id);
 			long t0 = System.currentTimeMillis();
-			DuccWorkJob duccWorkJob = (DuccWorkJob) workMap.findDuccWork(DuccType.Service,jobId);
+			DuccWorkJob duccWorkJob = (DuccWorkJob) WorkMapHelper.findDuccWork(workMap, DuccType.Service, jobId, this, methodName);
 			long t1 = System.currentTimeMillis();
 			long elapsed = t1 - t0;
 			if(elapsed > Constants.SYNC_LIMIT) {

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/ProcessAccounting.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/ProcessAccounting.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/ProcessAccounting.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/ProcessAccounting.java Thu Feb 27 21:18:40 2014
@@ -29,6 +29,7 @@ import org.apache.uima.ducc.common.utils
 import org.apache.uima.ducc.common.utils.DuccLoggerComponents;
 import org.apache.uima.ducc.common.utils.TimeStamp;
 import org.apache.uima.ducc.common.utils.id.DuccId;
+import org.apache.uima.ducc.orchestrator.utilities.TrackSync;
 import org.apache.uima.ducc.transport.agent.IUimaPipelineAEComponent;
 import org.apache.uima.ducc.transport.event.common.DuccWorkJob;
 import org.apache.uima.ducc.transport.event.common.DuccWorkMap;
@@ -76,30 +77,24 @@ public class ProcessAccounting {
 	public DuccId getJobId(DuccId processId) {
 		String methodName = "getJobId";
 		DuccId retVal;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			retVal = processToJobMap.get(processId);
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}
+		ts.ended();
 		return retVal;
 	}
 	
 	public int processCount() {
 		String methodName = "processCount";
 		int retVal;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			retVal = processToJobMap.size();
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}
+		ts.ended();
 		return retVal;
 	}
 	
@@ -107,8 +102,9 @@ public class ProcessAccounting {
 		String methodName = "addProcess";
 		logger.trace(methodName, null, messages.fetch("enter"));
 		boolean retVal = false;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			if(!processToJobMap.containsKey(processId)) {
 				processToJobMap.put(processId, jobId);
 				retVal = true;
@@ -118,11 +114,7 @@ public class ProcessAccounting {
 				logger.warn(methodName, jobId, processId, messages.fetch("exists"));
 			}
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}
+		ts.ended();
 		logger.trace(methodName, null, messages.fetch("exit"));
 		return retVal;
 	}
@@ -131,8 +123,9 @@ public class ProcessAccounting {
 		String methodName = "removeProcess";
 		logger.trace(methodName, null, messages.fetch("enter"));
 		boolean retVal = false;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			if(processToJobMap.containsKey(processId)) {
 				DuccId jobId = processToJobMap.remove(processId);
 				retVal = true;
@@ -142,11 +135,7 @@ public class ProcessAccounting {
 				logger.warn(methodName, null, processId, messages.fetch("not found"));
 			}
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}
+		ts.ended();
 		logger.trace(methodName, null, messages.fetch("exit"));
 		return retVal;
 	}
@@ -653,11 +642,12 @@ public class ProcessAccounting {
 		try {
 			DuccId processId = inventoryProcess.getDuccId();
 			logger.debug(methodName, null, processId, messages.fetchLabel("node")+inventoryProcess.getNodeIdentity().getName()+" "+messages.fetchLabel("PID")+inventoryProcess.getPID());
-			long t0 = System.currentTimeMillis();
+			TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 			synchronized(workMap) {
+				ts.using();
 				if(processToJobMap.containsKey(processId)) {
 					DuccId jobId = getJobId(processId);
-					IDuccWork duccWork = workMap.findDuccWork(jobId);
+					IDuccWork duccWork = WorkMapHelper.findDuccWork(workMap, jobId, this, methodName);
 					if(duccWork != null) {
 						if(duccWork instanceof IDuccWorkExecutable) {
 							IDuccWorkExecutable duccWorkExecutable = (IDuccWorkExecutable) duccWork;
@@ -730,11 +720,7 @@ public class ProcessAccounting {
 					logger.warn(methodName, null, processId, messages.fetch("ID not found in process map"));
 				}
 			}
-			long t1 = System.currentTimeMillis();
-			long elapsed = t1 - t0;
-			if(elapsed > Constants.SYNC_LIMIT) {
-				logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-			}
+			ts.ended();
 		}
 		catch(Throwable t) {
 			logger.error(methodName, null, t);

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/StateManager.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/StateManager.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/StateManager.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/StateManager.java Thu Feb 27 21:18:40 2014
@@ -37,6 +37,7 @@ import org.apache.uima.ducc.common.utils
 import org.apache.uima.ducc.common.utils.TimeStamp;
 import org.apache.uima.ducc.common.utils.id.DuccId;
 import org.apache.uima.ducc.orchestrator.user.UserLogging;
+import org.apache.uima.ducc.orchestrator.utilities.TrackSync;
 import org.apache.uima.ducc.transport.agent.IUimaPipelineAEComponent;
 import org.apache.uima.ducc.transport.event.common.DuccProcess;
 import org.apache.uima.ducc.transport.event.common.DuccReservation;
@@ -241,7 +242,7 @@ public class StateManager {
 		Iterator<DuccId> workMapIterator = workMap.keySet().iterator();
 		while(workMapIterator.hasNext()) {
 			DuccId duccId = workMapIterator.next();
-			IDuccWork duccWork = workMap.findDuccWork(duccId);
+			IDuccWork duccWork = WorkMapHelper.findDuccWork(workMap, duccId, this, methodName);
 			switch(duccWork.getDuccType()) {
 			case Job:
 			case Service:
@@ -251,7 +252,7 @@ public class StateManager {
 						stateJobAccounting.stateChange(duccWorkJob, JobState.Completed);
 					}
 					if(duccWorkJob.isCompleted() && allProcessesTerminated(duccWorkJob) && isSaved(duccWorkJob) && isAgedOut(duccWorkJob)) {
-						workMap.removeDuccWork(duccId);
+						WorkMapHelper.removeDuccWork(workMap, duccWorkJob, this, methodName);
 						driverStatusReportMap.remove(duccId);
 						logger.info(methodName, duccId, messages.fetch("removed job"));
 						changes ++;
@@ -274,7 +275,7 @@ public class StateManager {
 				DuccWorkReservation duccWorkReservation = (DuccWorkReservation)duccWork;
 				if(duccWorkReservation != null) {
 					if(duccWorkReservation.isCompleted() && isSaved(duccWorkReservation) && isAgedOut(duccWorkReservation)) {
-						workMap.removeDuccWork(duccId);
+						WorkMapHelper.removeDuccWork(workMap, duccWorkReservation, this, methodName);
 						logger.info(methodName, duccId, messages.fetch("removed reservation"));
 						changes ++;
 					}
@@ -416,10 +417,11 @@ public class StateManager {
 		String methodName = "reconcileState (JD)";
 		logger.trace(methodName, null, messages.fetch("enter"));
 		int changes = 0;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			DuccId duccId = jdStatusReport.getDuccId();
-			DuccWorkJob duccWorkJob = (DuccWorkJob) workMap.findDuccWork(duccId);
+			DuccWorkJob duccWorkJob = (DuccWorkJob) WorkMapHelper.findDuccWork(workMap, duccId, this, methodName);
 			if(duccWorkJob != null) {
 				String jdJmxUrl = jdStatusReport.getJdJmxUrl();
 				setJdJmxUrl(duccWorkJob, jdJmxUrl);
@@ -556,11 +558,7 @@ public class StateManager {
 				logger.warn(methodName, duccId, messages.fetch("not found"));
 			}
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}		
+		ts.ended();
 		if(changes > 0) {
 			OrchestratorCheckpoint.getInstance().saveState();
 		}
@@ -678,8 +676,9 @@ public class StateManager {
 		logger.trace(methodName, null, messages.fetch("enter"));
 		logger.debug(methodName, null, messages.fetchLabel("size")+rmResourceStateMap.size());
 		int changes = 0;
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			Iterator<DuccId> rmResourceStateIterator = rmResourceStateMap.keySet().iterator();
 			while(rmResourceStateIterator.hasNext()) {
 				DuccId duccId = rmResourceStateIterator.next();
@@ -690,7 +689,7 @@ public class StateManager {
 				if(rmResourceState.getPendingRemovals() != null) {
 					logger.debug(methodName, duccId, messages.fetchLabel("pending removals")+rmResourceState.getPendingRemovals().size());
 				}
-				IDuccWork duccWork = workMap.findDuccWork(duccId);
+				IDuccWork duccWork = WorkMapHelper.findDuccWork(workMap, duccId, this, methodName);
 				if(duccWork== null) {
 					logger.debug(methodName, duccId, messages.fetch("not found"));
 				}
@@ -881,11 +880,8 @@ public class StateManager {
 				OrchestratorCheckpoint.getInstance().saveState();
 			}
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}		logger.trace(methodName, null, messages.fetch("exit"));
+		ts.ended();	
+		logger.trace(methodName, null, messages.fetch("exit"));
 	}
 	
 	private int processPurger(DuccWorkJob job,Map<DuccId, IResource> map) {
@@ -1132,12 +1128,13 @@ public class StateManager {
 		logger.trace(methodName, null, messages.fetch("enter"));
 		int changes = 0;
 		Iterator<DuccId> serviceMapIterator = serviceMap.keySet().iterator();
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			while(serviceMapIterator.hasNext()) {
 				DuccId duccId = serviceMapIterator.next();
 				ServiceDependency services = serviceMap.get(duccId);
-				DuccWorkJob duccWorkJob = (DuccWorkJob) workMap.findDuccWork(duccId);
+				DuccWorkJob duccWorkJob = (DuccWorkJob) WorkMapHelper.findDuccWork(workMap, duccId, this, methodName);
 				if(duccWorkJob != null) {
 					JobState jobState = duccWorkJob.getJobState();
 					ServiceState serviceState = services.getState();
@@ -1201,11 +1198,7 @@ public class StateManager {
 				OrchestratorCheckpoint.getInstance().saveState();
 			}
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}		
+		ts.ended();	
 		logger.trace(methodName, null, messages.fetch("exit"));
 	}
 	
@@ -1216,8 +1209,9 @@ public class StateManager {
 		String methodName = "reconcileState (Node Inventory)";
 		logger.trace(methodName, null, messages.fetch("enter"));
 		Iterator<DuccId> iterator = inventoryProcessMap.keySet().iterator();
-		long t0 = System.currentTimeMillis();
+		TrackSync ts = TrackSync.await(workMap, this.getClass(), methodName);
 		synchronized(workMap) {
+			ts.using();
 			while(iterator.hasNext()) {
 				DuccId processId = iterator.next();
 				IDuccProcess inventoryProcess = inventoryProcessMap.get(processId);
@@ -1233,7 +1227,7 @@ public class StateManager {
 				if(processType != null) {
 					DuccId jobId = OrchestratorCommonArea.getInstance().getProcessAccounting().getJobId(processId);
 					if(jobId != null) {
-						IDuccWork duccWork = workMap.findDuccWork(jobId);
+						IDuccWork duccWork = WorkMapHelper.findDuccWork(workMap, jobId, this, methodName);
 						if(duccWork != null) {
 							DuccType jobType = duccWork.getDuccType();
 							switch(jobType) {
@@ -1347,11 +1341,7 @@ public class StateManager {
 				}
 			}
 		}
-		long t1 = System.currentTimeMillis();
-		long elapsed = t1 - t0;
-		if(elapsed > Constants.SYNC_LIMIT) {
-			logger.debug(methodName, null, "elapsed msecs: "+elapsed);
-		}		
+		ts.ended();
 		logger.trace(methodName, null, messages.fetch("exit"));
 	}
 	

Added: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/WorkMapHelper.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/WorkMapHelper.java?rev=1572741&view=auto
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/WorkMapHelper.java (added)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/WorkMapHelper.java Thu Feb 27 21:18:40 2014
@@ -0,0 +1,85 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ * 
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+*/
+package org.apache.uima.ducc.orchestrator;
+
+import org.apache.uima.ducc.common.utils.id.DuccId;
+import org.apache.uima.ducc.orchestrator.utilities.TrackSync;
+import org.apache.uima.ducc.transport.event.common.DuccWorkMap;
+import org.apache.uima.ducc.transport.event.common.IDuccWork;
+import org.apache.uima.ducc.transport.event.common.IDuccTypes.DuccType;
+
+/**
+ * Wrapper calls to DuccWorkMap to perform synchronization accounting and logging into or.log.
+ * Introduced by Jira UIMA-3657.
+ */
+public class WorkMapHelper {
+
+	public static void addDuccWork(DuccWorkMap workMap, IDuccWork dw, Object object, String methodName) {
+		TrackSync ts = TrackSync.await(workMap, object.getClass(), methodName);
+		synchronized(workMap) {
+			ts.using();
+			workMap.addDuccWork(dw);
+		}
+		ts.ended();
+	}
+	
+	public static void removeDuccWork(DuccWorkMap workMap, IDuccWork dw, Object object, String methodName) {
+		TrackSync ts = TrackSync.await(workMap, object.getClass(), methodName);
+		DuccId duccId = dw.getDuccId();
+		synchronized(workMap) {
+			ts.using();
+			workMap.removeDuccWork(duccId);
+		}
+		ts.ended();
+	}
+	
+	public static IDuccWork findDuccWork(DuccWorkMap workMap, DuccId duccId, Object object, String methodName) {
+		IDuccWork dw = null;
+		TrackSync ts = TrackSync.await(workMap, object.getClass(), methodName);
+		synchronized(workMap) {
+			ts.using();
+			dw = workMap.findDuccWork(duccId);
+		}
+		ts.ended();
+		return dw;
+	}
+	
+	public static IDuccWork findDuccWork(DuccWorkMap workMap, DuccType duccType, String id, Object object, String methodName) {
+		IDuccWork dw = null;
+		TrackSync ts = TrackSync.await(workMap, object.getClass(), methodName);
+		synchronized(workMap) {
+			ts.using();
+			dw = workMap.findDuccWork(duccType, id);
+		}
+		ts.ended();
+		return dw;
+	}
+	
+	public static DuccWorkMap deepCopy(DuccWorkMap workMap, Object object, String methodName) {
+		DuccWorkMap workMapCopy = null;
+		TrackSync ts = TrackSync.await(workMap, object.getClass(), methodName);
+		synchronized(workMap) {
+			ts.using();
+			workMapCopy = workMap.deepCopy();
+		}
+		ts.ended();
+		return workMapCopy;
+	}
+	
+}

Propchange: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/WorkMapHelper.java
------------------------------------------------------------------------------
    svn:eol-style = native

Modified: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/maintenance/HealthMonitor.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/maintenance/HealthMonitor.java?rev=1572741&r1=1572740&r2=1572741&view=diff
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/maintenance/HealthMonitor.java (original)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/maintenance/HealthMonitor.java Thu Feb 27 21:18:40 2014
@@ -30,6 +30,7 @@ import org.apache.uima.ducc.orchestrator
 import org.apache.uima.ducc.orchestrator.OrchestratorCheckpoint;
 import org.apache.uima.ducc.orchestrator.OrchestratorCommonArea;
 import org.apache.uima.ducc.orchestrator.StateManager;
+import org.apache.uima.ducc.orchestrator.WorkMapHelper;
 import org.apache.uima.ducc.transport.event.common.DuccWorkMap;
 import org.apache.uima.ducc.transport.event.common.DuccWorkPopDriver;
 import org.apache.uima.ducc.transport.event.common.IDuccProcess;
@@ -201,7 +202,7 @@ public class HealthMonitor {
 			boolean ckpt = false;
 			for(DuccId jobId : jobKeySet) {
 				try {
-					IDuccWorkJob job = (IDuccWorkJob) workMap.findDuccWork(jobId);
+					IDuccWorkJob job = (IDuccWorkJob) WorkMapHelper.findDuccWork(workMap, jobId, this, methodName);
 					if(isDriverCompleted(job)) {
 						ckpt = true;
 					}
@@ -254,7 +255,7 @@ public class HealthMonitor {
 			boolean ckpt = false;
 			for(DuccId serviceId : serviceKeySet) {
 				try {
-					IDuccWorkJob service = (IDuccWorkJob) workMap.findDuccWork(serviceId);
+					IDuccWorkJob service = (IDuccWorkJob) WorkMapHelper.findDuccWork(workMap, serviceId, this, methodName);
 					if(isCancelJobExcessiveProcessFailures(service)) {
 						ckpt = true;
 					}

Added: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/utilities/TrackSync.java
URL: http://svn.apache.org/viewvc/uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/utilities/TrackSync.java?rev=1572741&view=auto
==============================================================================
--- uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/utilities/TrackSync.java (added)
+++ uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/utilities/TrackSync.java Thu Feb 27 21:18:40 2014
@@ -0,0 +1,277 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ * 
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+*/
+package org.apache.uima.ducc.orchestrator.utilities;
+
+import java.util.Map.Entry;
+import java.util.concurrent.ConcurrentSkipListMap;
+import java.util.concurrent.atomic.AtomicLong;
+
+import org.apache.uima.ducc.common.utils.DuccLogger;
+import org.apache.uima.ducc.common.utils.DuccLoggerComponents;
+import org.apache.uima.ducc.common.utils.id.DuccId;
+
+/**
+ * Helper class to account for synchronization time (usually on DuccWorkMap) in or.log.
+ * Introduced by Jira UIMA-3657.
+ */
+
+public class TrackSync {
+	
+	private static DuccLogger logger = DuccLoggerComponents.getOrLogger(TrackSync.class.getName());
+	private static DuccId jobid = null;
+	
+	private static String sep = ".";
+	
+	private static ConcurrentSkipListMap<String,ConcurrentSkipListMap<String,AtomicLong>> map = new ConcurrentSkipListMap<String,ConcurrentSkipListMap<String,AtomicLong>>();
+	
+	private static ConcurrentSkipListMap<String,TrackSync> mapHeldBy = new ConcurrentSkipListMap<String,TrackSync>();
+	
+	private static long msPerSecond = 1000;
+	private static long timeLimit = 10*msPerSecond;
+	
+	private String target = null;
+	private String requester = null;
+	
+	private AtomicLong t0 = new AtomicLong(0);
+	private AtomicLong t1 = new AtomicLong(0);
+	private AtomicLong t2 = new AtomicLong(0);
+	
+	private static void addPending(String target, String requester) {
+		String location = "addPending";
+		try {
+			ConcurrentSkipListMap<String,AtomicLong> tMap = new ConcurrentSkipListMap<String,AtomicLong>();
+			map.putIfAbsent(target, tMap);
+			tMap = map.get(target);
+			AtomicLong rCount = new AtomicLong(0);
+			tMap.putIfAbsent(requester, rCount);
+			rCount = tMap.get(requester);
+			rCount.getAndIncrement();
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	private static void delPending(String target, String requester) {
+		String location = "delPending";
+		try {
+			ConcurrentSkipListMap<String,AtomicLong> tMap = new ConcurrentSkipListMap<String,AtomicLong>();
+			map.putIfAbsent(target, tMap);
+			tMap = map.get(target);
+			AtomicLong rCount = new AtomicLong(1);
+			tMap.putIfAbsent(requester, rCount);
+			rCount = tMap.get(requester);
+			rCount.getAndDecrement();
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	private static long getPending(String target) {
+		String location = "getPending";
+		long retVal = 0;
+		try {
+			ConcurrentSkipListMap<String, AtomicLong> oMap = map.get(target);
+			if(oMap != null) {
+				for(Entry<String, AtomicLong> entry : oMap.entrySet()) {
+					retVal += entry.getValue().get();
+				}
+			}
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+		return retVal;
+	}
+	
+	private static void report(String target) {
+		String location = "report";
+		try {
+			ConcurrentSkipListMap<String, AtomicLong> oMap = map.get(target);
+			if(oMap != null) {
+				for(Entry<String, AtomicLong> entry : oMap.entrySet()) {
+					String requester = entry.getKey();
+					long pending = entry.getValue().longValue();
+					if(pending > 0) {
+						logger.info(location, jobid, "target: "+target+" "+"requester: "+requester+" "+" pending: "+pending);
+					}
+				}
+			}
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	private static void overtime(TrackSync ts, String target) {
+		String location = "overtime";
+		try {
+			if(ts != null) {
+				long timeHeld = ts.getTimeHeld();
+				if(timeHeld > timeLimit) {
+					logger.info(location, jobid, "target: "+ts.target+" "+"requester: "+ts.requester+" "+"wait: "+ts.getTimeWait()+" "+"held: "+ts.getTimeHeld());
+					report(target);
+				}
+			}
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	private static void blocked(TrackSync ts, String target, String requester) {
+		String location = "blocked";
+		try {
+			if(ts != null) {
+				long timeHeld = ts.getTimeHeld();
+				if(timeHeld > timeLimit) {
+					logger.info(location, jobid, "target: "+ts.target+" "+"requester: "+ts.requester+" "+"time: "+ts.getTimeHeld()+" "+"blocking: "+requester);
+				}
+			}
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	public static TrackSync await(Object targetObject, Class<?> requesterClass, String requesterLocation) {
+		String location = "await";
+		TrackSync ts = new TrackSync();
+		try {
+			ts.target = targetObject.getClass().getSimpleName();
+			ts.requester = requesterClass.getSimpleName()+sep+requesterLocation;
+			TrackSync tsHolder = mapHeldBy.get(ts.target);
+			addPending(ts.target, ts.requester);
+			blocked(tsHolder, ts.target, ts.requester);
+			logger.trace(location, jobid, "target: "+ts.target+" "+"requester: "+ts.requester);
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+		return ts;
+	}
+	
+	public TrackSync() {
+		setT0(this);
+	}
+	
+	private void setT0(TrackSync ts) {
+		if(ts != null) {
+			if(ts.t0.get() == 0) {
+				ts.t0.compareAndSet(0, System.currentTimeMillis());
+			}
+		}
+	}
+	
+	private void setT1(TrackSync ts) {
+		if(ts != null) {
+			if(ts.t1.get() == 0) {
+				ts.t1.compareAndSet(0, System.currentTimeMillis());
+			}
+		}
+	}
+	
+	private void setT2(TrackSync ts) {
+		if(ts != null) {
+			if(ts.t2.get() == 0) {
+				ts.t2.compareAndSet(0, System.currentTimeMillis());
+			}
+		}
+	}
+	
+	public long getT0() {
+		long value = t0.get();
+		if(value == 0) {
+			value = System.currentTimeMillis();
+		}
+		return value;
+	}
+	
+	public long getT1() {
+		long value = t1.get();
+		if(value == 0) {
+			value = System.currentTimeMillis();
+		}
+		return value;
+	}
+	
+	public long getT2() {
+		long value = t2.get();
+		if(value == 0) {
+			value = System.currentTimeMillis();
+		}
+		return value;
+	}
+	
+	private String target() {
+		return "target: "+target;
+	}
+	
+	private String requester() {
+		return "requester: "+requester;
+	}
+	
+	private String timeWait() {
+		return "wait: "+getTimeWait();
+	}
+	
+	private String timeHeld() {
+		return "held: "+getTimeHeld();
+	}
+	
+	private String pending() {
+		return "pending: "+getPending(target);
+	}
+	
+	public void using() {
+		String location = "using";
+		try {
+			TrackSync tsHolder = TrackSync.mapHeldBy.get(target); 
+			setT2(tsHolder);
+			overtime(tsHolder, target);
+			setT1(this);
+			TrackSync.delPending(target, requester);
+			TrackSync.mapHeldBy.put(target, this);
+			logger.trace(location, jobid, target()+" "+requester()+" "+timeWait());
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	public void ended() {
+		String location = "ended";
+		try {
+			setT2(this);
+			logger.trace(location, jobid, target()+" "+requester()+" "+timeWait()+" "+timeHeld()+" "+pending());
+		}
+		catch(Exception e) {
+			logger.error(location, jobid, e);
+		}
+	}
+	
+	public long getTimeWait() {
+		return getT1() - getT0();
+	}
+	
+	public long getTimeHeld() {
+		return getT2() - getT1();
+	}
+}

Propchange: uima/sandbox/uima-ducc/trunk/uima-ducc-orchestrator/src/main/java/org/apache/uima/ducc/orchestrator/utilities/TrackSync.java
------------------------------------------------------------------------------
    svn:eol-style = native