Skip to content

Commit

Permalink
New feature branch to allow a custom listener to be created for ERXSt…
Browse files Browse the repository at this point in the history 
…atisticsStore. Such a listener can be used to notify an external monitoring system (e.g. StatsD/Graphite) if request handling is slow.
  • Loading branch information
@jbrook @darkv
jbrook authored and darkv committed Nov 23, 2012
1 parent 496d108 commit 5917b0f
Show file tree
Hide file tree
Showing 7 changed files with 190 additions and 57 deletions.
143 changes: 86 additions & 57 deletions Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/ERXStatisticsStore.java
View file
Original file line number Diff line number Diff line change
@@ -1,30 +1,18 @@
package er.extensions.statistics;

import java.util.ArrayList;
import java.util.Collections;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.Iterator;
import java.util.Map;
import java.util.Set;
import java.util.WeakHashMap;

import org.apache.log4j.Logger;

import com.webobjects.appserver.WOComponent;
import com.webobjects.appserver.WOContext;
import com.webobjects.appserver.WORequest;
import com.webobjects.appserver.WOSession;
import com.webobjects.appserver.WOStatisticsStore;
import com.webobjects.appserver.*;
import com.webobjects.foundation.NSArray;
import com.webobjects.foundation.NSDictionary;
import com.webobjects.foundation.NSMutableArray;
import com.webobjects.foundation.NSMutableDictionary;

import er.extensions.appserver.ERXApplication;
import er.extensions.eof.ERXEC;
import er.extensions.eof.ERXObjectStoreCoordinator;
import er.extensions.foundation.ERXProperties;
import er.extensions.statistics.store.*;
import org.apache.log4j.Logger;

import java.util.*;

/**
* Enhances the normal stats store with a bunch of useful things which get
Expand Down Expand Up @@ -57,7 +45,23 @@ private StopWatchTimer timer() {
return _timer;
}

/**
private final ERXStatisticsStoreListener listener;

public ERXStatisticsStore() {
listener = new DumbERXStatisticsStoreListener();
}

/**
* Create a statistics store with a custom listener. For example this listener might
* notify an external system when a response is very slow in coming.
*
* @param listener a customer listener to do something 'special' when requests are slow
*/
public ERXStatisticsStore(ERXStatisticsStoreListener listener) {
this.listener = listener;
}

/**
* Thread that checks each second for running requests and makes a snapshot
* after a certain amount of time has expired.
*
Expand Down Expand Up @@ -101,36 +105,27 @@ protected void endTimer(WOContext aContext, String aString) {
if (hasTimerStarted()) {
requestTime = System.currentTimeMillis() - time();
}
Thread currentThread = Thread.currentThread();
Map<Thread, StackTraceElement[]> traces = _fatalTraces.remove(currentThread);
Map<Thread, String> names = _fatalTracesNames.remove(currentThread);
if (traces == null) {
traces = _errorTraces.remove(currentThread);
names = _errorTracesNames.remove(currentThread);
}
if (traces == null) {
traces = _warnTraces.remove(currentThread);
names = _warnTracesNames.remove(currentThread);
}
String trace = stringFromTraces(traces, names);
synchronized (_requestThreads) {
_requestThreads.remove(Thread.currentThread());
}

// Don't get the traces string if we have already logged all
// of the stacks within the last 10s. All of this logging
// could just makes it worse for an application that is
// already struggling.
String trace = " - (skipped stack traces)";
long currentTime = System.currentTimeMillis();
if(currentTime - _lastLog < 10000) {
return;
if (currentTime - _lastLog > 10000) {
trace = stringFromTraces();
_lastLog = currentTime;
}
_lastLog = currentTime;

RequestDescription requestDescription = descriptionObjectForContext(aContext, aString);
listener.log(requestTime, requestDescription);
if (requestTime > _maximumRequestFatalTime) {
String requestDescription = aContext == null ? aString : descriptionForContext(aContext);
log.fatal("Request did take too long : " + requestTime + "ms request was: " + requestDescription + trace);
}
else if (requestTime > _maximumRequestErrorTime) {
String requestDescription = aContext == null ? aString : descriptionForContext(aContext);
log.error("Request did take too long : " + requestTime + "ms request was: " + requestDescription + trace);
}
else if (requestTime > _maximumRequestWarnTime) {
String requestDescription = aContext == null ? aString : descriptionForContext(aContext);
log.warn("Request did take too long : " + requestTime + "ms request was: " + requestDescription + trace);
}
}
Expand All @@ -140,7 +135,30 @@ else if (requestTime > _maximumRequestWarnTime) {
}
}

private String stringFromTraces(Map<Thread, StackTraceElement[]> traces, Map<Thread, String> names) {
private String stringFromTraces() {
String result;
Thread currentThread = Thread.currentThread();
Map<Thread, StackTraceElement[]> traces = _fatalTraces.remove(currentThread);
Map<Thread, String> names = _fatalTracesNames.remove(currentThread);
if (traces == null) {
traces = _errorTraces.remove(currentThread);
names = _errorTracesNames.remove(currentThread);
}
if (traces == null) {
traces = _warnTraces.remove(currentThread);
names = _warnTracesNames.remove(currentThread);
}

result = stringFromTracesAndNames(traces, names);

synchronized (_requestThreads) {
_requestThreads.remove(Thread.currentThread());
}

return result;
}

private String stringFromTracesAndNames(Map<Thread, StackTraceElement[]> traces, Map<Thread, String> names) {
String trace = null;
if (traces != null) {
String capturedThreadName = null;
Expand Down Expand Up @@ -199,24 +217,32 @@ protected void startTimer() {
}
}

public String descriptionForContext(WOContext aContext) {
try {
WOComponent component = aContext.page();
String componentName = component != null ? component.name() : "NoNameComponent";
String additionalInfo = "(no additional Info)";
WORequest request = aContext.request();
String requestHandler = request != null ? request.requestHandlerKey() : "NoRequestHandler";
if (!requestHandler.equals("wo")) {
additionalInfo = additionalInfo + aContext.request().uri();
}
return componentName + "-" + requestHandler + additionalInfo;
}
catch (RuntimeException e) {
log.error("Cannot get context description since received exception " + e, e);
}
return "Error-during-context-description";
public String descriptionForContext(WOContext aContext, String string) {
return descriptionObjectForContext(aContext, string).toString();
}

public RequestDescription descriptionObjectForContext(WOContext aContext, String string) {
if (aContext != null) {
try {
WOComponent component = aContext.page();
String componentName = component != null ? component.name() : "NoNameComponent";
String additionalInfo = "(no additional Info)";
WORequest request = aContext.request();
String requestHandler = request != null ? request.requestHandlerKey() : "NoRequestHandler";
if (!requestHandler.equals("wo")) {
additionalInfo = additionalInfo + aContext.request().uri();
}
return new NormalRequestDescription(componentName, requestHandler, additionalInfo);
}
catch (RuntimeException e) {
log.error("Cannot get context description since received exception " + e, e);
}
}
return new EmptyRequestDescription(string);
}



public void run() {
Thread.currentThread().setName("ERXStopWatchTimer");
boolean done = false;
Expand All @@ -237,6 +263,7 @@ private void checkThreads() {
requestThreads.putAll(_requestThreads);
}
if (!requestThreads.isEmpty()) {
int deadlocksCount = 0;
Map traces = null;
for (Iterator iterator = requestThreads.keySet().iterator(); iterator.hasNext();) {
Thread thread = (Thread) iterator.next();
Expand Down Expand Up @@ -266,13 +293,15 @@ private void checkThreads() {
_fatalTraces.put(thread, traces);
_fatalTracesNames.put(thread, names);
String message = "Request is taking too long, possible deadlock: " + time + " ms ";
message += stringFromTraces(traces, names);
message += stringFromTracesAndNames(traces, names);
message += "EC info:\n" + ERXEC.outstandingLockDescription();
message += "OSC info:\n" + ERXObjectStoreCoordinator.outstandingLockDescription();
log.fatal(message);
deadlocksCount++;
}
}
}
listener.deadlock(deadlocksCount);
}
}

Expand Down
8 changes: 8 additions & 0 deletions ...e/ERExtensions/Sources/er/extensions/statistics/store/DumbERXStatisticsStoreListener.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
package er.extensions.statistics.store;

public class DumbERXStatisticsStoreListener implements ERXStatisticsStoreListener {

public void log(long requestTime, RequestDescription description) {}

public void deadlock(int deadlocksCount) {}
}
9 changes: 9 additions & 0 deletions .../Core/ERExtensions/Sources/er/extensions/statistics/store/ERXStatisticsStoreListener.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
package er.extensions.statistics.store;

public interface ERXStatisticsStoreListener {

public void log(long requestTime, RequestDescription description);

public void deadlock(int deadlocksCount);

}
34 changes: 34 additions & 0 deletions ...rks/Core/ERExtensions/Sources/er/extensions/statistics/store/EmptyRequestDescription.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
package er.extensions.statistics.store;

public class EmptyRequestDescription implements RequestDescription {

public static final String ERROR_STRING = "Error-during-context-description";
private String descriptionString = ERROR_STRING;

public EmptyRequestDescription(String descriptionString) {
if (descriptionString != null) {
this.descriptionString = descriptionString;
}
}

public String getComponentName() {
throw new IllegalStateException("field was not set use toString method instead!");
}

public String getRequestHandler() {
throw new IllegalStateException("field was not set use toString method instead!");
}

public String getAdditionalInfo() {
throw new IllegalStateException("field was not set use toString method instead!");
}

public RequestDescriptionType getType() {
return RequestDescriptionType.EMPTY;
}

@Override
public String toString() {
return descriptionString;
}
}
35 changes: 35 additions & 0 deletions ...ks/Core/ERExtensions/Sources/er/extensions/statistics/store/NormalRequestDescription.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,35 @@
package er.extensions.statistics.store;

public class NormalRequestDescription implements RequestDescription {

private final String componentName;
private final String requestHandler;
private final String additionalInfo;

public NormalRequestDescription(String componentName, String requestHandler, String additionalInfo) {
this.componentName = componentName;
this.requestHandler = requestHandler;
this.additionalInfo = additionalInfo;
}

public String getComponentName() {
return componentName;
}

public String getRequestHandler() {
return requestHandler;
}

public String getAdditionalInfo() {
return additionalInfo;
}

public RequestDescriptionType getType() {
return RequestDescriptionType.NORMAL;
}

@Override
public String toString() {
return componentName + "-" + requestHandler + additionalInfo;
}
}
13 changes: 13 additions & 0 deletions Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescription.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
package er.extensions.statistics.store;

public interface RequestDescription {

public String getComponentName();

public String getRequestHandler();

public String getAdditionalInfo();

public RequestDescriptionType getType();

}
5 changes: 5 additions & 0 deletions ...orks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescriptionType.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
package er.extensions.statistics.store;

public enum RequestDescriptionType {
NORMAL, EMPTY, DEADLOCK
}

0 comments on commit 5917b0f

Please sign in to comment.