Commit a6844cd7 authored by Christian Wulf's avatar Christian Wulf

merged Adrian's performance counter

parent 8834f785
......@@ -108,12 +108,22 @@ public abstract class AbstractStage implements StateLoggable {
// used only for performance measuring
private long beforeExecuteTime;
private long lastTimeAfterExecute;
protected final void executeStage() {
if (performanceLoggingEnabled) {
beforeExecuteTime = System.nanoTime();
executeWithCatchedExceptions();
if (lastState.getExecutionState() == ExecutionState.ACTIVE) {
this.addActiveWaitingTime(beforeExecuteTime - lastTimeAfterExecute);
}
lastTimeAfterExecute = System.nanoTime();
} else {
executeWithCatchedExceptions();
}
}
private void executeWithCatchedExceptions() {
try {
this.execute();
} catch (NotEnoughInputException e) {
......@@ -136,8 +146,7 @@ public abstract class AbstractStage implements StateLoggable {
// after being active the according time stamp is saved so that one can gather
// information about the time the stage was in one state uninterrupted.
if (newStateRequired(ExecutionState.BLOCKED)) {
StateChange newState = new StateChange(ExecutionState.BLOCKED, beforeExecuteTime, StateChange.PULLING_FAILED);
this.addState(newState);
this.addState(ExecutionState.BLOCKED, beforeExecuteTime);
}
throw NOT_ENOUGH_INPUT_EXCEPTION;
}
......@@ -330,7 +339,9 @@ public abstract class AbstractStage implements StateLoggable {
@SuppressWarnings("PMD.SignatureDeclareThrowsException")
public void onTerminating() throws Exception {
this.addState(ExecutionState.TERMINATED);
if (newStateRequired(ExecutionState.TERMINATED)) {
this.addState(ExecutionState.TERMINATED, System.nanoTime());
}
changeState(StageState.TERMINATED);
calledOnTerminating = true;
}
......@@ -530,24 +541,21 @@ public abstract class AbstractStage implements StateLoggable {
*/
private final List<StateChange> states = new ArrayList<StateChange>();
private StateChange lastState = new StateChange(ExecutionState.INITIALIZED);
private StateChange lastState = new StateChange(ExecutionState.INITIALIZED, System.nanoTime());
/**
* Deactivated if performance logging does not reduce the performance. must be measured first. (28.10.2016)
*/
private final boolean performanceLoggingEnabled = false;
private long activeWaitingTime;
@Override
public List<StateChange> getStates() {
return states;
}
protected void addState(final ExecutionState stateCode) {
StateChange state = new StateChange(stateCode);
addState(state);
}
protected void addState(final StateChange state) {
protected void addState(final ExecutionState stateCode, final long timestamp) {
StateChange state = new StateChange(stateCode, timestamp);
this.states.add(state);
this.lastState = state;
}
......@@ -562,22 +570,24 @@ public abstract class AbstractStage implements StateLoggable {
@Override
public void sendingFailed() {
if (newStateRequired(ExecutionState.BLOCKED)) {
this.addState(new StateChange(ExecutionState.BLOCKED, StateChange.SENDING_FAILED));
this.addState(ExecutionState.BLOCKED, System.nanoTime());
}
}
@Override
public void sendingSucceeded() {
if (newStateRequired(ExecutionState.ACTIVE_WAITING)) {
this.addState(ExecutionState.ACTIVE_WAITING);
if (newStateRequired(ExecutionState.ACTIVE)) {
this.addState(ExecutionState.ACTIVE, System.nanoTime());
}
}
@Override
public void sendingReturned() {
if (newStateRequired(ExecutionState.ACTIVE)) {
this.addState(ExecutionState.ACTIVE);
}
public long getActiveWaitingTime() {
return this.activeWaitingTime;
}
public void addActiveWaitingTime(final long time) {
activeWaitingTime += time;
}
}
......@@ -28,6 +28,8 @@ import java.util.Calendar;
import java.util.LinkedHashSet;
import java.util.Set;
import teetime.framework.performancelogging.formatstrategy.CumulativeActivePassivTime;
/**
* This class serves as storage for information about active and inactive times of objects.
*
......@@ -49,7 +51,7 @@ public class ActivationStateLogger {
*/
private int longestName = 0;
private IFormatingStrategy formatingStrategy = new CumulativeActivePassivTime(this);
private IFormatingStrategy formatingStrategy = new CumulativeActivePassivTime(stages);
private ActivationStateLogger() {
// singleton
......@@ -70,17 +72,6 @@ public class ActivationStateLogger {
stages.add(stage);
}
/**
* Will return the simple name of the given stage and added enough spaces to match the longest name.
*
* @param stage
* Stage which name should be formated.
* @return Simple name of the given stage plus spaces to match the longest name.
*/
String formateName(final StateLoggable stage) {
return stage.getClass().getSimpleName() + ";";
}
public void logToFile() throws UnsupportedEncodingException, FileNotFoundException {
this.logToFile("StateLogs/");
}
......
/**
* Copyright © 2015 Christian Wulf, Nelson Tavares de Sousa (http://teetime-framework.github.io)
*
* Licensed 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 teetime.framework.performancelogging;
class CumulativeActivePassivTime implements ActivationStateLogger.IFormatingStrategy {
/**
*
*/
private final ActivationStateLogger stateLogger;
/**
* @param stateLogger
*/
CumulativeActivePassivTime(final ActivationStateLogger stateLogger) {
this.stateLogger = stateLogger;
}
@Override
public String formatData() {
String result = "\n Formating to analyse differences in runtime:\n\n";
result += "name;cumulative active time;cumulative active waiting time;cumulative blocked time; total time\n";
// go through all the stages
for (StateLoggable stage : this.stateLogger.getStages()) {
// first add a formated version of their names to the line.
result += this.stateLogger.formateName(stage);
long earliestTimeStamp = stage.getStates().get(0).getTimeStamp();
long latestTimeStamp = earliestTimeStamp;
long lastTimeStamp = earliestTimeStamp;
long cumulativeActiveTime = 0;
long cumulativeActiveWaitingTime = 0;
long cumulativeBlockedTime = 0;
// go through all states of this stage and sum up the active times while counting the number of active times
for (StateChange state : stage.getStates()) {
long actualTimeStamp = state.getTimeStamp();
if (actualTimeStamp < earliestTimeStamp) {
earliestTimeStamp = actualTimeStamp;
System.err.println("Some later State has a lower timestamp value!");
} else if (actualTimeStamp > latestTimeStamp) {
latestTimeStamp = actualTimeStamp;
}
long elapsedTime = actualTimeStamp - lastTimeStamp;
switch (state.getExecutionState()) {
case ACTIVE:
cumulativeActiveTime += elapsedTime;
break;
case ACTIVE_WAITING:
cumulativeActiveWaitingTime += elapsedTime;
break;
case BLOCKED:
cumulativeBlockedTime += elapsedTime;
break;
default:
break;
}
lastTimeStamp = actualTimeStamp;
}
result += cumulativeActiveTime + ";" + cumulativeActiveWaitingTime + ";" + cumulativeBlockedTime + ";" + (latestTimeStamp - earliestTimeStamp);
result += "\n";
}
return result.replace("\n", String.format("%n"));
}
}
/**
* Copyright © 2015 Christian Wulf, Nelson Tavares de Sousa (http://teetime-framework.github.io)
*
* Licensed 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 teetime.framework.performancelogging;
class PercentageOfActiveTime implements ActivationStateLogger.IFormatingStrategy {
/**
*
*/
private final ActivationStateLogger stateLogger;
/**
* @param stateLogger
*/
PercentageOfActiveTime(final ActivationStateLogger stateLogger) {
this.stateLogger = stateLogger;
}
@Override
public String formatData() {
String result = "\n Formating of the data to get Percentage of active time:\n\n";
for (StateLoggable stage : this.stateLogger.getStages()) {
result += this.stateLogger.formateName(stage);
long firstTimeStamp = stage.getStates().get(0).getTimeStamp();
long lastTimeStamp = Long.MIN_VALUE;
long commulativeActiveTime = 0;
long lastActiveTimeStamp = 0;
boolean lastActive = false;
for (StateChange state : stage.getStates()) {
long currentTimeStamp = state.getTimeStamp();
if (state.getCause() == StateChange.NOTHING_FAILED) {
if (!lastActive) {
lastActiveTimeStamp = currentTimeStamp;
}
lastActive = true;
} else {
if (lastActive && lastActiveTimeStamp != 0) {
commulativeActiveTime += (currentTimeStamp - lastActiveTimeStamp);
}
lastActive = false;
}
if (currentTimeStamp > lastTimeStamp) {
lastTimeStamp = currentTimeStamp;
}
if (currentTimeStamp < firstTimeStamp) {
firstTimeStamp = currentTimeStamp;
}
}
long totalTime = (lastActiveTimeStamp - firstTimeStamp);
// Add formated data to the line
result += " Percentage of ActiveTime: "
// I differentiate between stages that were active the whole time and the ones that were interrupted in between.
// this will help to keep track of the necessary information.
+ ((totalTime != 0) ? (commulativeActiveTime / (lastActiveTimeStamp - firstTimeStamp)) : "100") + "%";
result += "\n";
}
return result.replace("\n", String.format("%n"));
}
}
......@@ -33,47 +33,27 @@ public class StateChange {
/** Represents the state where the stage is being executed. */
ACTIVE,
/** Represents the state where the stage is waiting for its passive successor stage to return. */
ACTIVE_WAITING,
// ACTIVE_WAITING,
/** Represents the state where the stage is waiting for its active successor stage to consume the elements within the interconnected pipe. */
BLOCKED,
/** Represents the stage where the stage has been terminated. */
TERMINATED,
}
// TODO vielleicht überflüssig
public final static int SENDING_FAILED = -1;
public final static int PULLING_FAILED = -2;
public final static int GENERAL_EXCEPTION = -3;
public final static int NOTHING_FAILED = 0;
private final ExecutionState executionState;
private final long timeStamp;
private final int cause;
public StateChange(final ExecutionState state) {
this(state, System.nanoTime(), 0);
}
public StateChange(final ExecutionState state, final int cause) {
this(state, System.nanoTime(), cause);
}
public StateChange(final ExecutionState state, final long timeStamp, final int cause) {
public StateChange(final ExecutionState state, final long timeStamp) {
this.executionState = state;
this.timeStamp = timeStamp;
this.cause = cause;
}
public long getTimeStamp() {
return timeStamp;
}
public int getCause() {
return cause;
}
public ExecutionState getExecutionState() {
return executionState;
}
public long getTimeStamp() {
return timeStamp;
}
}
......@@ -39,6 +39,8 @@ public interface StateLoggable {
/**
* This method is called when the Thread returns to a Stage that send an element before.
*/
public void sendingReturned();
// public void sendingReturned();
public long getActiveWaitingTime();
}
package teetime.framework.performancelogging.formatstrategy;
import java.util.Collection;
import teetime.framework.performancelogging.ActivationStateLogger.IFormatingStrategy;
import teetime.framework.performancelogging.StateChange;
import teetime.framework.performancelogging.StateChange.ExecutionState;
import teetime.framework.performancelogging.StateLoggable;
public class CumulativeActivePassivTime implements IFormatingStrategy {
private final Collection<StateLoggable> stages;
public CumulativeActivePassivTime(final Collection<StateLoggable> stages) {
this.stages = stages;
}
/**
* Will return the simple name of the given stage and added enough spaces to match the longest name.
*
* @param stage
* Stage which name should be formated.
* @return Simple name of the given stage plus spaces to match the longest name.
*/
String formateName(final StateLoggable stage) {
return stage.getClass().getSimpleName() + ";";
}
@Override
public String formatData() {
String result = "\n Formating to analyse differences in runtime:\n\n";
result += "name;total time;cumulative blocked time;cumulative active waiting time time;active time\n";
// go through all the stages
for (StateLoggable stage : stages) {
// first add a formated version of their names to the line.
result += formateName(stage);
long earliestTimeStamp = Long.MAX_VALUE;
long latestTimeStamp = Long.MIN_VALUE;
long lastTimeStamp = 0;
ExecutionState lastState = ExecutionState.INITIALIZED;
long cumulativeActiveTime = 0;
long cumulativeActiveWaitingTime = stage.getActiveWaitingTime();
long cumulativeBlockedTime = 0;
// go through all states of this stage and sum up the active times while counting the number of active timestamp
for (StateChange state : stage.getStates()) {
long actualTimeStamp = state.getTimeStamp();
// update earliest and latest timeStamp if necessary
if (actualTimeStamp < earliestTimeStamp) {
earliestTimeStamp = actualTimeStamp;
} else if (actualTimeStamp > latestTimeStamp) {
latestTimeStamp = actualTimeStamp;
}
// In the first loop neither lastTimeStamp nor lastState are set. So the next part wouldn't calculate correct.
if (lastState != ExecutionState.INITIALIZED) {
long elapsedTime = actualTimeStamp - lastTimeStamp;
switch (lastState) {
case ACTIVE:
cumulativeActiveTime += elapsedTime;
break;
case BLOCKED:
cumulativeBlockedTime += elapsedTime;
break;
case TERMINATED:
break;
default:
break;
}
}
lastTimeStamp = actualTimeStamp;
lastState = state.getExecutionState();
}
// The ActiveWaiting time was counted into active time till now. So it it subtracted now.
cumulativeActiveTime -= cumulativeActiveWaitingTime;
result += (latestTimeStamp - earliestTimeStamp) + ";" + cumulativeBlockedTime + ";" + cumulativeActiveWaitingTime + ";" + cumulativeActiveTime;
result += "\n";
}
return result.replace("\n", String.format("%n"));
}
}
package teetime.framework.performancelogging.formatstrategy;
import java.util.Collection;
import teetime.framework.performancelogging.ActivationStateLogger.IFormatingStrategy;
import teetime.framework.performancelogging.StateChange;
import teetime.framework.performancelogging.StateChange.ExecutionState;
import teetime.framework.performancelogging.StateLoggable;
/**
* Formating strategy to apply for percentage of active time.
*
* @author Adrian
*
*/
public class PercentageOfActiveTime implements IFormatingStrategy {
private final Collection<StateLoggable> stages;
public PercentageOfActiveTime(final Collection<StateLoggable> stages) {
this.stages = stages;
}
/**
* Will return the simple name of the given stage and added enough spaces to match the longest name.
*
* @param stage
* Stage which name should be formated.
* @return Simple name of the given stage plus spaces to match the longest name.
*/
String formateName(final StateLoggable stage) {
return stage.getClass().getSimpleName() + ";";
}
@Override
public String formatData() {
String result = "\n Formating of the data to get percentage of active time:\n\n";
result += "name;% active time\n";
for (StateLoggable stage : stages) {
result += formateName(stage);
boolean lastActive = false;
long lastActiveTimestamp = Long.MAX_VALUE;
long cumulativeActiveTime = 0;
long firstTimestamp = Long.MAX_VALUE;
long lastTimestamp = Long.MIN_VALUE;
for (StateChange state : stage.getStates()) {
if (state.getTimeStamp() < firstTimestamp) {
firstTimestamp = state.getTimeStamp();
}
if (state.getTimeStamp() > lastTimestamp) {
lastTimestamp = state.getTimeStamp();
}
if (!lastActive && state.getExecutionState() == ExecutionState.ACTIVE) {
lastActive = true;
lastActiveTimestamp = state.getTimeStamp();
}
if (lastActive && state.getExecutionState() != ExecutionState.ACTIVE && lastActiveTimestamp != Long.MAX_VALUE) {
lastActive = false;
cumulativeActiveTime += (state.getTimeStamp() - lastActiveTimestamp);
}
}
result += ((double) cumulativeActiveTime / (double) (lastTimestamp - firstTimestamp)) * 100 + "\n";
}
return result.replace("\n", String.format("%n"));
}
}
/**
* Copyright © 2015 Christian Wulf, Nelson Tavares de Sousa (http://teetime-framework.github.io)
*
* Licensed 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 teetime.framework.performancelogging;
package teetime.framework.performancelogging.formatstrategy;
import java.util.Collection;
import teetime.framework.performancelogging.ActivationStateLogger.IFormatingStrategy;
import teetime.framework.performancelogging.StateChange;
import teetime.framework.performancelogging.StateChange.ExecutionState;
import teetime.framework.performancelogging.StateLoggable;
/**
* Formating Strategy to apply the data to the Bottleneck Detection Approach of Roser, Nakano and Tanaka.
*
* @author Adrian
*
*/
class RNTFormating implements IFormatingStrategy {
/**
*
*/
private final ActivationStateLogger stateLogger;
public class RNTFormating implements IFormatingStrategy {
private final Collection<StateLoggable> stages;
public RNTFormating(final Collection<StateLoggable> stages) {
this.stages = stages;
}
/**
* @param stateLogger
* Will return the simple name of the given stage and added enough spaces to match the longest name.
*
* @param stage
* Stage which name should be formated.
* @return Simple name of the given stage plus spaces to match the longest name.
*/
RNTFormating(final ActivationStateLogger stateLogger) {
this.stateLogger = stateLogger;
String formateName(final StateLoggable stage) {
return stage.getClass().getSimpleName() + ";";
}
@Override
public String formatData() {
String result = "\n Formating of the data to fit Approach of Roser, Nakano and Tanak:\n\n";
result += "name;Average ActiveTime (ns)\n";
// go through all the stages
for (StateLoggable stage : this.stateLogger.getStages()) {
for (StateLoggable stage : stages) {
// first add a formated version of their names to the line.
result += this.stateLogger.formateName(stage);
result += formateName(stage);
// will count the number of activeTimes
double counter = 0;
// stores the sum of active time
long commulativeActiveTime = 0;
long cummulativeActiveTime = 0;
// stores the last relevant active time stamp
long lastActiveTimeStamp = 0;
// boolean to remember last state that was processed
......@@ -53,14 +54,12 @@ class RNTFormating implements IFormatingStrategy {
// go through all states of this stage and sum up the active times while counting the number of active times
for (StateChange state : stage.getStates()) {
if (state.getCause() == StateChange.NOTHING_FAILED) {
if (!lastActive) {
lastActiveTimeStamp = state.getTimeStamp();
}
if (state.getExecutionState() == ExecutionState.ACTIVE && !lastActive) {
lastActiveTimeStamp = state.getTimeStamp();
lastActive = true;
} else {
if (lastActive && lastActiveTimeStamp != 0) {
commulativeActiveTime += (state.getTimeStamp() - lastActiveTimeStamp);
cummulativeActiveTime += (state.getTimeStamp() - lastActiveTimeStamp);
counter++;
}
lastActive = false;
......@@ -68,14 +67,14 @@ class RNTFormating implements IFormatingStrategy {
}
// Add formated data to the line
result += " Average ActiveTime in seconds: "
result +=
// I differentiate between stages that were active the whole time and the ones that were interrupted in between.
// this will help to keep track of the necessary information.
+ ((counter != 0) ? (((commulativeActiveTime) / counter) / 1000000) : "whole time");
((counter != 0) ? ((long) ((cummulativeActiveTime) / counter)) : cummulativeActiveTime);
result += "\n";
}
return result.replace("\n", String.format("%n"));
}
}
};
......@@ -22,7 +22,7 @@ import teetime.framework.StageState;
import teetime.framework.exceptionHandling.TerminateException;
import teetime.util.framework.concurrent.queue.ObservableSpScArrayQueue;
public class BoundedSynchedPipe<T> extends AbstractSynchedPipe<T>implements IMonitorablePipe {
public class BoundedSynchedPipe<T> extends AbstractSynchedPipe<T> implements IMonitorablePipe {
// private static final Logger LOGGER = LoggerFactory.getLogger(SpScPipe.class);
......@@ -43,6 +43,8 @@ public class BoundedSynchedPipe<T> extends AbstractSynchedPipe<T>implements IMon
@Override
public boolean add(final Object element) {
while (!addNonBlocking(element)) {
// the following sending*-related lines are commented out since they are computationally too expensive
// this.getSourcePort().getOwningStage().sendingFailed();
// Thread.yield();
if (this.cachedTargetStage.getCurrentState() == StageState.TERMINATED ||
Thread.currentThread().isInterrupted()) {
......@@ -55,6 +57,7 @@ public class BoundedSynchedPipe<T> extends AbstractSynchedPipe<T>implements IMon
throw TerminateException.INSTANCE;
}
}
// this.getSourcePort().getOwningStage().sendingSucceeded();
// this.reportNewElement();
return true;
}
......
......@@ -21,6 +21,7 @@ import teetime.framework.OutputPort;
public final class UnsynchedPipe<T> extends AbstractUnsynchedPipe<T> {
// private final StopWatch stopWatch = new StopWatch();
private Object element;
public UnsynchedPipe(final OutputPort<? extends T> sourcePort, final InputPort<T> targetPort) {
......@@ -33,7 +34,11 @@ public final class UnsynchedPipe<T> extends AbstractUnsynchedPipe<T> {
throw new IllegalArgumentException("Parameter 'element' is null, but must be non-null.");