<!-- collectionspace performance appender -->
<appender name="CSLOG_PERF" class="org.jboss.logging.appender.DailyRollingFileAppender">
- <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
- <param name="Append" value="false"/>
- <param name="DatePattern" value="'.'yyyy-MM-dd"/>
+ <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
+
<param name="Append" value="false"/>
+
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<param name="File" value="${jboss.server.log.dir}/collectionspace-perf.log"/>
<layout class="org.apache.log4j.PatternLayout">
- <param name="ConversionPattern" value="%d [%t] %m%n"/>
+ <!-- FIXME: Temporary change to accommodate interleaved CSV log entries -->
+ <!-- param name="ConversionPattern" value="%d [%t] %m%n"/ -->
+ <param name="ConversionPattern" value=""%d",%m%n"/>
</layout>
<!--filter class="org.jboss.logging.filter.TCLFilter">
<param name="AcceptOnMatch" value="true"/>
<filter class="org.apache.log4j.varia.DenyAllFilter"></filter-->
</appender>
- <!-- collectionspace performance appender, generating a format -->
- <!-- common to the services and app layers -->
- <appender name="CSLOG_PERF_COMMON" class="org.jboss.logging.appender.DailyRollingFileAppender">
- <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
- <param name="Append" value="false"/>
- <param name="DatePattern" value="'.'yyyy-MM-dd"/> <!-- Roll over at midnight daily -->
- <param name="File" value="${jboss.server.log.dir}/collectionspace-perf-common.log"/>
+ <!-- collectionspace performance appender, generating a comma-separated value (CSV) -->
+ <!-- format common to (at least) the services and app layers -->
+ <appender name="CSLOG_PERF_CSV" class="org.jboss.logging.appender.DailyRollingFileAppender">
+ <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
+
<param name="Append" value="false"/>
+
<param name="DatePattern" value="'.'yyyy-MM-dd"/> <!-- Roll over at midnight daily -->
+ <param name="File" value="${jboss.server.log.dir}/collectionspace-perf-csv.log"/>
<layout class="org.apache.log4j.PatternLayout">
- <param name="ConversionPattern" value=""%d",%r,%t,app,svc,%C{2},%M,method_get_uri_placeholder,svc%n"/>
+ <!-- param name="ConversionPattern" value=""%d",%r,%t,app,svc,%C{2},%M,method_get_uri_placeholder,svc%n"/ -->
+ <param name="ConversionPattern" value=""%d",%m%n"/>
</layout>
</appender>
<category name="perf.collectionspace">
<priority value="DEBUG" />
<appender-ref ref="CSLOG_PERF"/>
- <appender-ref ref="CSLOG_PERF_COMMON"/>
+ </category>
+
+ <category name="perf.collectionspace.csv">
+ <priority value="DEBUG" />
+ <appender-ref ref="CSLOG_PERF_CSV"/>
</category>
<!-- ======================= -->
-/** \r
- * CSpaceFilter.java\r
- *\r
- * {Purpose of This Class}\r
- *\r
- * {Other Notes Relating to This Class (Optional)}\r
- *\r
- * $LastChangedBy: $\r
- * $LastChangedRevision: $\r
- * $LastChangedDate: $\r
- *\r
+/**\r
* This document is a part of the source code and related artifacts\r
* for CollectionSpace, an open source collections management system\r
* for museums and related institutions:\r
import javax.servlet.http.HttpServletRequest;\r
//import javax.servlet.ServletContext;\r
\r
+import org.collectionspace.services.common.ServletTools;\r
+\r
+import org.slf4j.Logger;\r
+import org.slf4j.LoggerFactory;\r
+\r
/**\r
- * The Class CSpaceFilter.\r
+ * CSpaceFilter.java\r
+ *\r
+ * A filter that performs specified actions at the time\r
+ * each new request is received by the servlet container.\r
+ *\r
+ * This filter is currently used for recording performance\r
+ * metrics for requests to the CollectionSpace services.\r
+ *\r
+ * $LastChangedRevision: $\r
+ * $LastChangedDate: $\r
+ *\r
*/\r
public class CSpaceFilter implements Filter {\r
- \r
- /** The filter config. */\r
- FilterConfig filterConfig = null;\r
\r
- /* (non-Javadoc)\r
- * @see javax.servlet.Filter#destroy()\r
- */\r
- @Override\r
- public void destroy() {\r
- // Empty method.\r
- }\r
+ /** The filter config. */\r
+ FilterConfig filterConfig = null;\r
+\r
+ private final String CLASS_NAME = this.getClass().getSimpleName();\r
+ private Logger csvPerfLogger = LoggerFactory.getLogger("perf.collectionspace.csv");\r
+\r
+ /* (non-Javadoc)\r
+ * @see javax.servlet.Filter#destroy()\r
+ */\r
+ @Override\r
+ public void destroy() {\r
+ // Empty method.\r
+ }\r
+\r
+ /* (non-Javadoc)\r
+ * @see javax.servlet.Filter#doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain)\r
+ */\r
+ @Override\r
+ public void doFilter(ServletRequest request, ServletResponse response,\r
+ FilterChain chain) throws IOException, ServletException {\r
+ if (request != null) {\r
+ HttpServletRequest httpRequest = (HttpServletRequest) request;\r
+\r
+ // Instantiate the CollectionSpace services profiler.\r
+ StringBuffer uri = new StringBuffer(httpRequest.getRequestURI());\r
+ uri.append(':');\r
+ uri.append(httpRequest.getMethod());\r
+ Profiler profiler = new Profiler(uri.toString(), 0);\r
+\r
+ // Start timing.\r
+ profiler.start();\r
+\r
+ // Process the request.\r
+ chain.doFilter(request, response);\r
+\r
+ // Stop timing and log performance-related metrics.\r
+ profiler.stop();\r
\r
- /* (non-Javadoc)\r
- * @see javax.servlet.Filter#doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain)\r
- */\r
- @Override\r
- public void doFilter(ServletRequest request, ServletResponse response,\r
- FilterChain chain) throws IOException, ServletException { \r
- if (request != null) {\r
- HttpServletRequest httpRequest = (HttpServletRequest)request;\r
- StringBuffer uri = new StringBuffer(httpRequest.getRequestURI());\r
- uri.append(':');\r
- uri.append(httpRequest.getMethod());\r
- Profiler profiler = new Profiler(uri.toString(),\r
- 0);\r
- profiler.start();\r
- chain.doFilter(request, response);\r
-// profiler.log(httpRequest.getRequestURI());\r
- profiler.stop();\r
- }\r
- }\r
+ String csvMsg =\r
+ "," + System.currentTimeMillis()\r
+ + "," + Thread.currentThread().getName()\r
+ + "," + "app"\r
+ + "," + "svc"\r
+ + "," + CLASS_NAME\r
+ + "," + httpRequest.getMethod()\r
+ + "," + ServletTools.getURL(httpRequest)\r
+ + "," + profiler.getElapsedTime();\r
\r
- /* (non-Javadoc)\r
- * @see javax.servlet.Filter#init(javax.servlet.FilterConfig)\r
- */\r
- @Override\r
- public void init(FilterConfig theFilterConfig) throws ServletException {\r
- filterConfig = theFilterConfig;\r
- if (filterConfig != null) {\r
- // We can initialize using the init-params here which we defined in\r
- // web.xml)\r
- }\r
- }\r
+ // FIXME: Expedient change interleaves CSV-style log entries with entries\r
+ // in the original perf log. These should be written to their own log file,\r
+ // with their own patternLayout.\r
+ profiler.log(csvMsg);\r
+ profiler.reset();\r
+ // csvPerfLogger.debug(csvMsg);\r
+ }\r
+ }\r
\r
+ /* (non-Javadoc)\r
+ * @see javax.servlet.Filter#init(javax.servlet.FilterConfig)\r
+ */\r
+ @Override\r
+ public void init(FilterConfig theFilterConfig) throws ServletException {\r
+ filterConfig = theFilterConfig;\r
+ if (filterConfig != null) {\r
+ // We can initialize using the init-params here which we defined in\r
+ // web.xml)\r
+ }\r
+ }\r
}\r
-/** \r
- * Profiler.java\r
- *\r
- * {Purpose of This Class}\r
- *\r
- * {Other Notes Relating to This Class (Optional)}\r
- *\r
- * $LastChangedBy: $\r
- * $LastChangedRevision: $\r
- * $LastChangedDate: $\r
- *\r
+/**\r
* This document is a part of the source code and related artifacts\r
* for CollectionSpace, an open source collections management system\r
* for museums and related institutions:\r
import org.slf4j.Logger;\r
import org.slf4j.LoggerFactory;\r
\r
-\r
/**\r
- * The Class Profiler.\r
+ * Profiler.java\r
+ *\r
+ * Simple utility to store and report performance metrics.\r
+ *\r
+ * Records start and stop times, and elapsed and cumulative timings;\r
+ * writes performance-related log times.\r
+ *\r
+ * $LastChangedRevision: $\r
+ * $LastChangedDate: $\r
+ *\r
*/\r
public class Profiler {\r
- \r
- private int messageIndent = 0;\r
- \r
- /** The start time. */\r
- private long startTime = 0;\r
- \r
- /** The stop time. */\r
- private long stopTime = 0;\r
- \r
- /** The final time. */\r
- private long finalTime = 0;\r
- \r
- /** The message prefix. */\r
- private String messagePrefix = "Default profiler prefix:";\r
\r
+ /** The level of indentation. */\r
+ private int messageIndent = 0;\r
+ /** The indentation character(s) */\r
+ private static String INDENT = "\t";\r
+ /** The message prefix. */\r
+ private String messagePrefix = "";\r
+ /** The separator between the message prefix and the message. **/\r
+ final static String PREFIX_SEPARATOR = ":";\r
+ /** The start time. */\r
+ private long startTime = 0;\r
+ /** The stop time. */\r
+ private long stopTime = 0;\r
+ /** The segment time. */\r
+ private long elapsedTime = 0;\r
+ /** The cumulative time. */\r
+ private long cumulativeTime = 0;\r
/** The profiler logger. */\r
- private static String LOG4J_CATEGORY = "perf.collectionspace";\r
- private static Logger profilerLogger = LoggerFactory.getLogger(LOG4J_CATEGORY);\r
- \r
+ private static String DEFAULT_LOG4J_CATEGORY = "perf.collectionspace";\r
+ private static Logger profileLogger = LoggerFactory.getLogger(DEFAULT_LOG4J_CATEGORY);\r
+\r
/**\r
* private default constructor.\r
*/\r
private Profiler() {\r
- //empty default constructor\r
+ //empty default constructor\r
+ }\r
+\r
+ /**\r
+ * Instantiates a new profiler.\r
+ *\r
+ * @param theObject a class whose name is to be logged.\r
+ */\r
+ public Profiler(Object theObject) {\r
+ this(theObject, 0);\r
}\r
- \r
+\r
/**\r
- * Sets the message prefix.\r
+ * Instantiates a new profiler.\r
*\r
- * @param theMessagePrefix the new message prefix\r
+ * @param theObject a class whose name is to be logged.\r
+ * @param messageIndent the level of indentation for log messages.\r
*/\r
- protected void setMessagePrefix(String theMessagePrefix, int indent) {\r
- StringBuffer stringBuffer = new StringBuffer();\r
- for (int i = 0; i < indent; i++) {\r
- stringBuffer.append('\t');\r
- }\r
- stringBuffer.append(theMessagePrefix);\r
- stringBuffer.append(':');\r
- messagePrefix = stringBuffer.toString();\r
- }\r
- \r
- protected StringBuffer getMessagePrefix() {\r
- return new StringBuffer(messagePrefix);\r
- }\r
- \r
+ public Profiler(Object theObject, int messageIndent) {\r
+ init(objectName(theObject), messageIndent);\r
+ }\r
+\r
/**\r
* Instantiates a new profiler.\r
- * @param theObject \r
- * @param indent \r
*\r
- * @param theClass the the class\r
+ * @param messagePrefix the message prefix to appear in log messages.\r
+ * @param messageIndent the level of indentation for log messages.\r
+ */\r
+ public Profiler(String messagePrefix, int messageIndent) {\r
+ init(messagePrefix, messageIndent);\r
+ }\r
+\r
+ /*\r
+ * For some reason, we need to call this method "early" at startup time for our\r
+ * Logger instance to get created correctly. FIXME: REM - Can we figure this out and fix it?\r
+ */\r
+ /**\r
+ * Setup.\r
+ */\r
+ public static void setup() {\r
+ //do nothing\r
+ }\r
+\r
+ private void init(String messagePrefix, int messageIndent) {\r
+ this.setMessagePrefix(messagePrefix);\r
+ this.setMessageIndent(messageIndent);\r
+ }\r
+\r
+ /**\r
+ * Stores and logs the start time.\r
+ *\r
+ * Logs using a default message.\r
+ */\r
+ public void start() {\r
+ start(defaultStartMessage());\r
+ }\r
+\r
+ /**\r
+ * Stores and logs the start time.\r
+ *\r
+ * @param msg the message to log.\r
+ */\r
+ public void start(String msg) {\r
+ log(msg);\r
+ setStartTime(currentTime());\r
+ }\r
+\r
+ /**\r
+ * Stores and logs the stop time, and the elapsed and cumulative timings\r
+ * from one or more cycles of start and stop.\r
+ *\r
+ * Logs using a default message.\r
+ */\r
+ public void stop() {\r
+ // FIXME: Need to store values before constructing default stop message,\r
+ // hence has some redundant code with stop(msg) below. Perhaps can be consolidated.\r
+ setStopTime(currentTime());\r
+ setElapsedTime(elapsedTime());\r
+ addToCumulativeTime(elapsedTime());\r
+ stop(defaultStopMessage());\r
+ }\r
+\r
+ /**\r
+ * Stores and logs the stop time, and the elapsed and cumulative timings,\r
+ * from one or more cycles of start and stop.\r
+ *\r
+ * @param msg the message to log.\r
+ */\r
+ public void stop(String msg) {\r
+ setStopTime(currentTime());\r
+ setElapsedTime(elapsedTime());\r
+ addToCumulativeTime(elapsedTime());\r
+ log(msg);\r
+ }\r
+\r
+ public long getStartTime() {\r
+ return this.startTime;\r
+ }\r
+\r
+ public long getStopTime() {\r
+ return this.stopTime;\r
+ }\r
+\r
+ public long getElapsedTime() {\r
+ return this.elapsedTime;\r
+ }\r
+\r
+ public long getCumulativeTime() {\r
+ return this.cumulativeTime;\r
+ }\r
+\r
+ /**\r
+ * Resets the start and stop time, and the elapsed and cumulative timings.\r
+ */\r
+ public void reset() {\r
+ setStartTime(0);\r
+ setStopTime(0);\r
+ setElapsedTime(0);\r
+ setCumulativeTime(0);\r
+ }\r
+\r
+ /**\r
+ * Writes a log entry.\r
+ *\r
+ * @param msg the message to log.\r
+ */\r
+ public void log(String msg) {\r
+ if (getLogger().isDebugEnabled()) {\r
+ getLogger().debug(formatLogMessage(msg));\r
+ }\r
+ }\r
+\r
+ /**\r
+ * Gets the logger.\r
+ *\r
+ * @return the logger\r
*/\r
- public Profiler(Object theObject, int indent) {\r
- if (theObject != null) {\r
- this.setMessagePrefix(theObject.getClass().getSimpleName(), indent);\r
- }\r
- }\r
- /**\r
- * Instantiates a new profiler.\r
- *\r
- * @param theMessagePrefix the the message prefix\r
- * @param indent \r
- */\r
- public Profiler(String theMessagePrefix, int indent) {\r
- this.setMessagePrefix(theMessagePrefix, indent);\r
- }\r
- \r
- /*\r
- * For some reason, we need to call this method "early" at startup time for our\r
- * Logger instance to get created correctly. FIXME: REM - Can we figure this out and fix it?\r
- */\r
- /**\r
- * Setup.\r
- */\r
- public static void setup() {\r
- //do nothing\r
- }\r
- \r
- /**\r
- * Gets the logger.\r
- *\r
- * @return the logger\r
- */\r
- protected Logger getLogger() {\r
- return profilerLogger;\r
- }\r
- \r
- /**\r
- * Private log.\r
- *\r
- * @param inMessage the in message\r
- */\r
- public void log(String inMessage) {\r
- if (getLogger().isDebugEnabled() == true) {\r
- StringBuffer finalMessage = getMessagePrefix();\r
- if (inMessage != null) {\r
- finalMessage.append(inMessage);\r
- }\r
- getLogger().debug(finalMessage.toString());\r
- }\r
- }\r
- \r
- /**\r
- * Start\r
- */\r
- public void start() {\r
- if (getLogger().isDebugEnabled() == true) {\r
- StringBuffer message = getMessagePrefix();\r
- message.append(">>>> Start >>>>");\r
- getLogger().debug(message.toString());\r
- }\r
- startTime = System.currentTimeMillis();\r
- }\r
- \r
- /**\r
- * Stop.\r
- */\r
- public void stop() {\r
- stopTime = System.currentTimeMillis();\r
- finalTime = finalTime + (stopTime - startTime);\r
- if (getLogger().isDebugEnabled() == true) {\r
- StringBuffer message = getMessagePrefix();\r
- message.append("<<<< Stopped <<<< [");\r
- message.append(finalTime);\r
- message.append("ms]");\r
- getLogger().debug(message.toString());\r
- } \r
- }\r
+ protected Logger getLogger() {\r
+ return this.profileLogger;\r
+ }\r
+\r
+ private void setMessagePrefix(String prefix) {\r
+ this.messagePrefix = prefix;\r
+ }\r
+\r
+ private String getMessagePrefix() {\r
+ return this.messagePrefix;\r
+ }\r
+\r
+ private int getMessageIndent() {\r
+ return this.messageIndent;\r
+ }\r
+\r
+ private void setMessageIndent(int indent) {\r
+ this.messageIndent = indent;\r
+ }\r
+\r
+ private void setStartTime(long start) {\r
+ this.startTime = start;\r
+ }\r
+\r
+ private void setStopTime(long stop) {\r
+ this.stopTime = stop;\r
+ }\r
+\r
+ private void setElapsedTime(long segment) {\r
+ this.elapsedTime = segment;\r
+ }\r
+\r
+ private void setCumulativeTime(long cumulative) {\r
+ this.cumulativeTime = cumulative;\r
+ }\r
+\r
+ private void addToCumulativeTime(long cumulative) {\r
+ this.cumulativeTime += cumulative;\r
+ }\r
+\r
+ private long currentTime() {\r
+ return System.currentTimeMillis();\r
+ }\r
+\r
+ private long elapsedTime() {\r
+ return (currentTime() - getStartTime());\r
+ }\r
+\r
+ private String objectName(Object theObject) {\r
+ if (theObject != null) {\r
+ return (theObject.getClass().getSimpleName());\r
+ } else {\r
+ return "";\r
+ }\r
+ }\r
+\r
+ /**\r
+ * Returns a formatted log message, including indentation and prefix.\r
+ *\r
+ * @param msg the message to log.\r
+ * @return a constructed log message, including indentation and prefix, if any.\r
+ */\r
+ private String formatLogMessage(String msg) {\r
+ StringBuffer logMsg = new StringBuffer();\r
+ for (int i = 0; i < getMessageIndent(); i++) {\r
+ logMsg.append(INDENT);\r
+ }\r
+ String prefix = getMessagePrefix();\r
+ if (prefix != null && !prefix.trim().isEmpty()) {\r
+ logMsg.append(prefix);\r
+ logMsg.append(PREFIX_SEPARATOR);\r
+ }\r
+ if (msg != null) {\r
+ logMsg.append(msg);\r
+ }\r
+ return logMsg.toString();\r
+ }\r
+\r
+ private String defaultStartMessage() {\r
+ StringBuffer defaultStartMessage = new StringBuffer();\r
+ defaultStartMessage.append(">>>> Start >>>>");\r
+ return defaultStartMessage.toString();\r
+ }\r
+\r
+ private String defaultStopMessage() {\r
+ StringBuffer defaultStopMessage = new StringBuffer();\r
+ defaultStopMessage.append("<<<< Stopped <<<<");\r
+ defaultStopMessage.append(" [" + getElapsedTime() + " ms]");\r
+ if (getCumulativeTime() > getElapsedTime()) {\r
+ defaultStopMessage.append(" (cumulative [" + getCumulativeTime() + " ms])");\r
+ }\r
+ return defaultStopMessage.toString();\r
+ }\r
}\r
projects / tmp / jakarta-migration.git / commitdiff