Commit f43e5c48 authored by Christian Wulf's avatar Christian Wulf

integrated Adrian Pegler's performance logging (deactivated so far)

parent 136ec28d
......@@ -8,15 +8,15 @@
<property name="checkstyle.cache.file" value="${project_loc}/target/checkstyle-cachefile"/>
<property name="checkstyle.header.file" value="C:\Users\chw\Repositories\teetime\target\checkstyle-header-default.txt"/>
</local-check-config>
<local-check-config name="maven-checkstyle-plugin validate" location="file:/C:/Users/chw/git/teetime/conf/quality-config/cs-conf.xml" type="remote" description="maven-checkstyle-plugin configuration validate">
<local-check-config name="maven-checkstyle-plugin validate" location="file:/I:/Repositories/teetime-master/conf/quality-config/cs-conf.xml" type="remote" description="maven-checkstyle-plugin configuration validate">
<property name="checkstyle.cache.file" value="${project_loc}/target/checkstyle-cachefile"/>
<property name="checkstyle.header.file" value="C:\Users\chw\workspace\.metadata\.plugins\org.eclipse.core.resources\.projects\teetime\com.basistech.m2e.code.quality.checkstyleConfigurator\checkstyle-header-validate.txt"/>
<property name="checkstyle.header.file" value="C:\Users\Nogge\workspace-phd\.metadata\.plugins\org.eclipse.core.resources\.projects\teetime\com.basistech.m2e.code.quality.checkstyleConfigurator\checkstyle-header-validate.txt"/>
</local-check-config>
<fileset name="java-sources-validate" enabled="true" check-config-name="maven-checkstyle-plugin validate" local="true">
<file-match-pattern match-pattern="src/test/java/.*\.java" include-pattern="true"/>
<file-match-pattern match-pattern="src/main/java/.*\.java" include-pattern="true"/>
<file-match-pattern match-pattern="src/main/resources/.*\.properties" include-pattern="true"/>
<file-match-pattern match-pattern="src/test/resources/.*\.properties" include-pattern="true"/>
<file-match-pattern match-pattern="^src/main/java/.*\.java" include-pattern="true"/>
<file-match-pattern match-pattern="^src/test/java/.*\.java" include-pattern="true"/>
<file-match-pattern match-pattern="^src/main/resources/.*\.properties" include-pattern="true"/>
<file-match-pattern match-pattern="^src/test/resources/.*\.properties" include-pattern="true"/>
</fileset>
<filter name="WriteProtectedFiles" enabled="true"/>
<filter name="DerivedFiles" enabled="true"/>
......
......@@ -15,6 +15,7 @@
*/
package teetime.framework;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.HashSet;
import java.util.List;
......@@ -29,6 +30,8 @@ import org.slf4j.LoggerFactory;
import teetime.framework.exceptionHandling.AbstractExceptionListener;
import teetime.framework.exceptionHandling.AbstractExceptionListener.FurtherExecution;
import teetime.framework.exceptionHandling.TerminateException;
import teetime.framework.performancelogging.ActivationState;
import teetime.framework.performancelogging.StateLoggable;
import teetime.framework.signal.ISignal;
import teetime.framework.signal.StartingSignal;
import teetime.framework.signal.TerminatingSignal;
......@@ -40,7 +43,7 @@ import teetime.util.framework.port.PortRemovedListener;
* Represents a minimal Stage, with some pre-defined methods.
* Implemented stages need to adapt all abstract methods with own implementations.
*/
public abstract class AbstractStage {
public abstract class AbstractStage implements StateLoggable {
private static final ConcurrentMap<String, Integer> INSTANCES_COUNTER = new ConcurrentHashMap<String, Integer>();
private static final NotEnoughInputException NOT_ENOUGH_INPUT_EXCEPTION = new NotEnoughInputException();
......@@ -104,10 +107,18 @@ public abstract class AbstractStage {
}
protected final void returnNoElement() {
// If the stage get null-element it can't be active. If it's the first time
// 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(ActivationState.BLOCKED)) {
ActivationState newState = new ActivationState(ActivationState.BLOCKED, this.getActualTimeStamp(), ActivationState.PULLING_FAILED);
this.addState(newState);
}
throw NOT_ENOUGH_INPUT_EXCEPTION;
}
protected final void executeStage() {
// this.setActualTimeStamp(System.nanoTime());
try {
this.execute();
} catch (NotEnoughInputException e) {
......@@ -309,6 +320,7 @@ public abstract class AbstractStage {
@SuppressWarnings("PMD.SignatureDeclareThrowsException")
public void onTerminating() throws Exception {
this.addState(ActivationState.TERMINATED);
changeState(StageState.TERMINATED);
calledOnTerminating = true;
}
......@@ -518,4 +530,105 @@ public abstract class AbstractStage {
// */
// public abstract void validateOutputPorts(List<InvalidPortConnection> invalidPortConnections);
/**
* A list which save a timestamp and an associated state (active or inactive). This Information can be used for Bottleneck analysis.
*
* @author Adrian Pegler
*/
private final List<ActivationState> states = new ArrayList<ActivationState>();
/**
* @author Adrian Pegler
*/
private ActivationState lastState;
/**
* @author Adrian Pegler
*/
private long actualTimeStamp;
/**
* Deactivated if performance logging does not reduce the performance. must be measured first. (28.10.2016)
*
* @author Christian Wulf (chw)
*/
private final boolean performanceLoggingEnabled = false;
/**
* @author Adrian Pegler
*/
@Override
public List<ActivationState> getStates() {
return states;
}
/**
* @author Adrian Pegler
*/
protected void addState(final int stateCode) {
ActivationState state = new ActivationState(stateCode);
this.states.add(state);
}
/**
* @author Adrian Pegler
*/
protected void addState(final ActivationState state) {
this.states.add(state);
}
/**
* @author Adrian Pegler
*/
protected boolean newStateRequired(final int state) {
if (!performanceLoggingEnabled) {
return false;
}
return ((this.lastState == null) || (this.lastState.getState() != state));
}
/**
* @author Adrian Pegler
*/
@Override
public void sendingFailed() {
if (newStateRequired(ActivationState.BLOCKED)) {
this.addState(new ActivationState(ActivationState.BLOCKED, ActivationState.SENDING_FAILED));
}
}
/**
* @author Adrian Pegler
*/
@Override
public void sendingSucceeded() {
if (newStateRequired(ActivationState.ACTIV_WAITING)) {
this.addState(ActivationState.ACTIV_WAITING);
}
}
/**
* @author Adrian Pegler
*/
@Override
public void sendingReturned() {
if (newStateRequired(ActivationState.ACTIV)) {
this.addState(ActivationState.ACTIV);
}
}
/**
* @author Adrian Pegler
*/
public long getActualTimeStamp() {
return actualTimeStamp;
}
/**
* @author Adrian Pegler
*/
public void setActualTimeStamp(final long actualTimeStamp) {
this.actualTimeStamp = actualTimeStamp;
}
}
package teetime.framework.performancelogging;
/**
* This class stores an active/inactive flag at a given time.
*
* @author Adrian
*
*/
public class ActivationState {
// 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;
public final static int ACTIV = 1;
public final static int ACTIV_WAITING = 0;
public final static int BLOCKED = -1;
public final static int TERMINATED = -2;
private final int state;
private final long timeStamp;
private final int cause;
public ActivationState(final int state) {
this(state, System.nanoTime(), 0);
}
public ActivationState(final int state, final int cause) {
this(state, System.nanoTime(), cause);
}
public ActivationState(final int state, final long timeStamp, final int cause) {
this.state = state;
this.timeStamp = timeStamp;
this.cause = cause;
}
public long getTimeStamp() {
return timeStamp;
}
public int getCause() {
return cause;
}
public int getState() {
return state;
}
}
package teetime.framework.performancelogging;
import java.io.BufferedOutputStream;
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.PrintStream;
import java.io.UnsupportedEncodingException;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Calendar;
import java.util.LinkedHashSet;
import java.util.Set;
/**
* This class serves as storage for information about active and inactive times of objects.
*
* @author Adrian
*
*/
public class ActivationStateLogger {
/**
* Singleton Instance Holder
*/
private final static ActivationStateLogger INSTANCE = new ActivationStateLogger();
/**
* Set of registered Stages
*/
private final Set<StateLoggable> stages = new LinkedHashSet<StateLoggable>();
/**
* A Integer trhat holds the longest of all registered simple Stage names.
*/
private int longestName = 0;
private IFormatingStrategy formatingStrategy = new CumulativeActivePassivTime(this);
private ActivationStateLogger() {
// singleton
}
public static ActivationStateLogger getInstance() {
return ActivationStateLogger.INSTANCE;
}
/**
* Any stage can register itself here. It will be stored with an empty List of States.
*
* @param stage
* Stage to be registered.
*/
public void register(final StateLoggable stage) {
this.setLongestName(stage.getClass().getSimpleName().length());
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/");
}
public void logToFile(final String path) throws UnsupportedEncodingException, FileNotFoundException {
Calendar now = Calendar.getInstance();
DateFormat formatter = new SimpleDateFormat();
String date = formatter.format(now.getTime()).replace('.', '-').replace(':', '.').replace(' ', '_');
String filename = "StateLog_" + date + ".txt";
this.logToFile(path, filename);
}
public void logToFile(final String path, final String filename) throws UnsupportedEncodingException, FileNotFoundException {
this.logToFile(new File(path + filename));
}
public void logToFile(final File file) throws UnsupportedEncodingException, FileNotFoundException {
try {
this.printToFile(file);
} catch (FileNotFoundException e) {
try {
if (file.createNewFile()) {
this.printToFile(file);
} else {
System.err.println("File wasn't created!");
}
} catch (IOException ioe) {
System.err.println("Error creating " + file.toString());
}
}
}
private void printToFile(final File file) throws UnsupportedEncodingException, FileNotFoundException {
PrintStream ps = new PrintStream(new BufferedOutputStream(new FileOutputStream(file, true), 8192 * 8), false, "UTF-8");
ps.print(this);
ps.close();
System.out.println("Log saved to File: " + file.getAbsolutePath());
}
// getter and setter:
public Set<StateLoggable> getStages() {
return stages;
}
public int getLongestName() {
return longestName;
}
public void setLongestName(final int longestName) {
if (longestName > this.longestName) {
this.longestName = longestName;
}
}
public IFormatingStrategy getFormatingStrategy() {
return formatingStrategy;
}
public void setFormatingStrategy(final IFormatingStrategy formatingStrategy) {
this.formatingStrategy = formatingStrategy;
}
// toString and inner classes
@Override
public String toString() {
String result = "";
result += this.formatingStrategy.formatData();
return result;
}
public interface IFormatingStrategy {
public String formatData();
}
}
package teetime.framework.performancelogging;
public interface CompositeStateLoggable {
public void registerStatebles();
}
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 (ActivationState 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.getState()) {
case ActivationState.ACTIV:
cumulativeActiveTime += elapsedTime;
break;
case ActivationState.ACTIV_WAITING:
cumulativeActiveWaitingTime += elapsedTime;
break;
case ActivationState.BLOCKED:
cumulativeBlockedTime += elapsedTime;
break;
default:
break;
}
lastTimeStamp = actualTimeStamp;
}
result += cumulativeActiveTime + ";" + cumulativeActiveWaitingTime + ";" + cumulativeBlockedTime + ";" + (latestTimeStamp - earliestTimeStamp);
result += "\n";
}
return result.replace("\n", String.format("%n"));
}
}
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 (ActivationState state : stage.getStates()) {
long currentTimeStamp = state.getTimeStamp();
if (state.getCause() == ActivationState.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"));
}
}
package teetime.framework.performancelogging;
import teetime.framework.performancelogging.ActivationStateLogger.IFormatingStrategy;
/**
* Formating Strategy to apply the data to the Bottleneck Detection Approach of Roser, Nakano and Tanaka.
*/
class RNTFormating implements IFormatingStrategy {
/**
*
*/
private final ActivationStateLogger stateLogger;
/**
* @param stateLogger
*/
RNTFormating(final ActivationStateLogger stateLogger) {
this.stateLogger = stateLogger;
}
@Override
public String formatData() {
String result = "\n Formating of the data to fit Approach of Roser, Nakano and Tanak:\n\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);
// will count the number of activeTimes
double counter = 0;
// stores the sum of active time
long commulativeActiveTime = 0;
// stores the last relevant active time stamp
long lastActiveTimeStamp = 0;
// boolean to remember last state that was processed
boolean lastActive = false;
// go through all states of this stage and sum up the active times while counting the number of active times
for (ActivationState state : stage.getStates()) {
if (state.getCause() == ActivationState.NOTHING_FAILED) {
if (!lastActive) {
lastActiveTimeStamp = state.getTimeStamp();
}
lastActive = true;
} else {
if (lastActive && lastActiveTimeStamp != 0) {
commulativeActiveTime += (state.getTimeStamp() - lastActiveTimeStamp);
counter++;
}
lastActive = false;
}
}
// Add formated data to the line
result += " Average ActiveTime in seconds: "
// 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");
result += "\n";
}
return result.replace("\n", String.format("%n"));
}
}
package teetime.framework.performancelogging;
import java.util.List;
public interface StateLoggable {
/**
* This method is used to collect the List of States
*
* @return List of states this stage saved during its run.
*/
public List<ActivationState> getStates();
/**
* This method is called by Pipes if the sending of the next element needs to be delayed because of full Queue.
*/
public void sendingFailed();
/**
* This method is called when the element is successfully added to the Pipe.
*/
public void sendingSucceeded();
/**
* This method is called when the Thread returns to a Stage that send an element before.
*/
public void sendingReturned();
}
......@@ -18,6 +18,8 @@ package teetime.stage.string;
import teetime.framework.CompositeStage;
import teetime.framework.InputPort;
import teetime.framework.OutputPort;
import teetime.framework.performancelogging.CompositeStateLoggable;
import teetime.framework.performancelogging.ActivationStateLogger;
import teetime.stage.MappingCounter;
import teetime.stage.taskfarm.ITaskFarmDuplicable;
import teetime.stage.util.CountingMap;
......@@ -31,7 +33,7 @@ import teetime.stage.util.CountingMap;
* @author Nelson Tavares de Sousa
*
*/
public final class WordCounter extends CompositeStage implements ITaskFarmDuplicable<String, CountingMap<String>> {
public class WordCounter extends CompositeStage implements ITaskFarmDuplicable<String, CountingMap<String>>, CompositeStateLoggable {
private final Tokenizer tokenizer;
private final MappingCounter<String> mapCounter;
......@@ -60,4 +62,10 @@ public final class WordCounter extends CompositeStage implements ITaskFarmDuplic
return new WordCounter();
}
@Override
public void registerStatebles() {
ActivationStateLogger.getInstance().register(tokenizer);
ActivationStateLogger.getInstance().register(tokenizer.getOutputPort().getPipe().getTargetPort().getOwningStage());
ActivationStateLogger.getInstance().register(mapCounter);
}
}
/**
* Copyright (C) 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.examples.wordcounter;
import java.io.File;
import java.util.ArrayList;
import java.util.List;
import teetime.framework.AbstractPort;
import teetime.framework.Configuration;
import teetime.framework.MonitoringThread;
import teetime.framework.performancelogging.ActivationStateLogger;
import teetime.stage.CountingMapMerger;
import teetime.stage.InitialElementProducer;
import teetime.stage.basic.distributor.Distributor;
import teetime.stage.basic.distributor.strategy.NonBlockingRoundRobinStrategy;
import teetime.stage.basic.merger.Merger;
import teetime.stage.io.File2SeqOfWords;
import teetime.stage.string.WordCounter;
import teetime.stage.util.CountingMap;
/**
* A simple configuration, which counts the words of a set of files.
* The execution of this configuration is demonstrated in {@link WordCountingTest}.
*
* This configuration is divided into three parts. The first part reads files and distributes them to different {@link WordCounter} instances.
* The second part are a certain number of WordCounter instances. On construction of this class the number of concurrent WordCounter instances is specified with the
* threads parameter.
* The third and last part collects the results from all WordCounter instances and merges them. This final result can be read afterwards.
*
*
* @author Nelson Tavares de Sousa