Fix negative response times in case of exceptions.

extension/src/main/java/perfmodel/wildfly/interceptors/EJBIncomingCallInterceptor.java

@@ -46,25 +46,27 @@ public class EJBIncomingCallInterceptor extends AbstractEJBInterceptor {
 		threadCallStack.push(orec);
 		
 		long startTime = System.nanoTime();
-		Object ret = ctx.proceed();
-		long endTime = System.nanoTime();
-		
-		long executionTime = (endTime - startTime) / Constants.NANOS_IN_MILLIS;
-		if (caller != null) {
-			// this is a local call in the same thread
-			// also add a outgoing call to the callee component
+		try {
+			return ctx.proceed();
+		} finally {
+			long endTime = System.nanoTime();
+			
+			long executionTime = (endTime - startTime) / Constants.NANOS_IN_MILLIS;
+			if (caller != null) {
+				// this is a local call in the same thread
+				// also add a outgoing call to the callee component
+				if (log.isTraceEnabled()) {
+					log.info("Outgoing invocation (" + caller.getInterface().getInterfaceName() + ", " + caller.getOperationName() + ") -> (" + interf + ", " + operation + ", " + executionTime + "ms)");
+				}
+				OperationRecord callerOrec = caller.requireComponent(component).requireInterface(interf).requireOperation(operation);
+				callerOrec.addInvocation(executionTime);
+			}
 			if (log.isTraceEnabled()) {
-				log.info("Outgoing invocation (" + caller.getInterface().getInterfaceName() + ", " + caller.getOperationName() + ") -> (" + interf + ", " + operation + ", " + executionTime + "ms)");
+				log.info("Incoming invocation (" + component + ", " + operation + ", " + executionTime + "ms)");
 			}
-			OperationRecord callerOrec = caller.requireComponent(component).requireInterface(interf).requireOperation(operation);
-			callerOrec.addInvocation(executionTime);
-		}
-		if (log.isTraceEnabled()) {
-			log.info("Incoming invocation (" + component + ", " + operation + ", " + executionTime + "ms)");
+			orec.addInvocation(executionTime);		
+			threadCallStack.pop();
 		}
-		orec.addInvocation(executionTime);		
-		threadCallStack.pop();
-		return ret;
 	}
 	
 }

extension/src/main/java/perfmodel/wildfly/interceptors/EJBOutgoingCallInterceptor.java

@@ -45,20 +45,23 @@ public class EJBOutgoingCallInterceptor implements EJBClientInterceptor {
 
 	@Override
 	public Object handleInvocationResult(EJBClientInvocationContext ctx) throws Exception {
-		long endTime = System.nanoTime();
-		Deque<OperationRecord> threadCallStack = ThreadCallStack.get();
-		if (!threadCallStack.isEmpty()) {
-			long executionTime = (endTime - invocationTime.get().longValue()) / Constants.NANOS_IN_MILLIS;
-			OperationRecord orec = threadCallStack.pop();			
-			orec.addInvocation(executionTime);		
-			
-			if (log.isTraceEnabled()) {
-				OperationRecord caller = threadCallStack.peek();
-				log.trace("Outgoing invocation (" + caller.getInterface().getInterfaceName() + ", " + caller.getOperationName() 
-						+ ") -> (" + orec.getInterface().getInterfaceName() + ", " + orec.getOperationName() + ", " + executionTime + "ms)");				
+		try {
+			return ctx.getResult();
+		} finally {
+			long endTime = System.nanoTime();
+			Deque<OperationRecord> threadCallStack = ThreadCallStack.get();
+			if (!threadCallStack.isEmpty()) {
+				long executionTime = (endTime - invocationTime.get().longValue()) / Constants.NANOS_IN_MILLIS;
+				OperationRecord orec = threadCallStack.pop();			
+				orec.addInvocation(executionTime);		
+				
+				if (log.isTraceEnabled()) {
+					OperationRecord caller = threadCallStack.peek();
+					log.trace("Outgoing invocation (" + caller.getInterface().getInterfaceName() + ", " + caller.getOperationName() 
+							+ ") -> (" + orec.getInterface().getInterfaceName() + ", " + orec.getOperationName() + ", " + executionTime + "ms)");				
+				}
 			}
-		}
-		return ctx.getResult();
+		}		
 	}
 
 }