From 5917b0f7e5cb0b1da78f90d3713b19ce82f6c217 Mon Sep 17 00:00:00 2001 From: James Brook Date: Tue, 20 Nov 2012 18:38:37 +0100 Subject: [PATCH] New feature branch to allow a custom listener to be created for ERXStatisticsStore. Such a listener can be used to notify an external monitoring system (e.g. StatsD/Graphite) if request handling is slow. --- .../statistics/ERXStatisticsStore.java | 143 +++++++++++------- .../store/DumbERXStatisticsStoreListener.java | 8 + .../store/ERXStatisticsStoreListener.java | 9 ++ .../store/EmptyRequestDescription.java | 34 +++++ .../store/NormalRequestDescription.java | 35 +++++ .../statistics/store/RequestDescription.java | 13 ++ .../store/RequestDescriptionType.java | 5 + 7 files changed, 190 insertions(+), 57 deletions(-) create mode 100644 Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/DumbERXStatisticsStoreListener.java create mode 100644 Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/ERXStatisticsStoreListener.java create mode 100644 Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/EmptyRequestDescription.java create mode 100644 Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/NormalRequestDescription.java create mode 100644 Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescription.java create mode 100644 Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescriptionType.java diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/ERXStatisticsStore.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/ERXStatisticsStore.java index d308c511fd9..cba36082fe3 100644 --- a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/ERXStatisticsStore.java +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/ERXStatisticsStore.java @@ -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 @@ -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. * @@ -101,36 +105,27 @@ protected void endTimer(WOContext aContext, String aString) { if (hasTimerStarted()) { requestTime = System.currentTimeMillis() - time(); } - Thread currentThread = Thread.currentThread(); - Map traces = _fatalTraces.remove(currentThread); - Map 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); } } @@ -140,7 +135,30 @@ else if (requestTime > _maximumRequestWarnTime) { } } - private String stringFromTraces(Map traces, Map names) { + private String stringFromTraces() { + String result; + Thread currentThread = Thread.currentThread(); + Map traces = _fatalTraces.remove(currentThread); + Map 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 traces, Map names) { String trace = null; if (traces != null) { String capturedThreadName = null; @@ -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; @@ -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(); @@ -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); } } diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/DumbERXStatisticsStoreListener.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/DumbERXStatisticsStoreListener.java new file mode 100644 index 00000000000..10f6affd2c8 --- /dev/null +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/DumbERXStatisticsStoreListener.java @@ -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) {} +} diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/ERXStatisticsStoreListener.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/ERXStatisticsStoreListener.java new file mode 100644 index 00000000000..f338ef17f1b --- /dev/null +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/ERXStatisticsStoreListener.java @@ -0,0 +1,9 @@ +package er.extensions.statistics.store; + +public interface ERXStatisticsStoreListener { + + public void log(long requestTime, RequestDescription description); + + public void deadlock(int deadlocksCount); + +} diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/EmptyRequestDescription.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/EmptyRequestDescription.java new file mode 100644 index 00000000000..21097c26efc --- /dev/null +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/EmptyRequestDescription.java @@ -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; + } +} diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/NormalRequestDescription.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/NormalRequestDescription.java new file mode 100644 index 00000000000..409740c86f6 --- /dev/null +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/NormalRequestDescription.java @@ -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; + } +} diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescription.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescription.java new file mode 100644 index 00000000000..ff51c5e9fd1 --- /dev/null +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescription.java @@ -0,0 +1,13 @@ +package er.extensions.statistics.store; + +public interface RequestDescription { + + public String getComponentName(); + + public String getRequestHandler(); + + public String getAdditionalInfo(); + + public RequestDescriptionType getType(); + +} diff --git a/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescriptionType.java b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescriptionType.java new file mode 100644 index 00000000000..8e8b09bbff6 --- /dev/null +++ b/Frameworks/Core/ERExtensions/Sources/er/extensions/statistics/store/RequestDescriptionType.java @@ -0,0 +1,5 @@ +package er.extensions.statistics.store; + +public enum RequestDescriptionType { + NORMAL, EMPTY, DEADLOCK +}