From: Aron Roberts Date: Mon, 27 Sep 2010 07:05:54 +0000 (+0000) Subject: CSPACE-2950: Minor generalization of Profiler class. Temporary expedient in log4j... X-Git-Url: https://git.aero2k.de/?a=commitdiff_plain;h=4b4a7a19a3b8ea5ccf9a167bb02e4c71a75a450d;p=tmp%2Fjakarta-migration.git CSPACE-2950: Minor generalization of Profiler class. Temporary expedient in log4j config file and CSpace filter class to interleave CSV-style log messages with existing messages, to give Kasper a starting point. These CSV-style messages should instead be logged via a separate file appender. --- diff --git a/services/common/src/main/config/log/jboss-log4j.xml b/services/common/src/main/config/log/jboss-log4j.xml index f4bdca6c5..d5f0a0daa 100644 --- a/services/common/src/main/config/log/jboss-log4j.xml +++ b/services/common/src/main/config/log/jboss-log4j.xml @@ -154,12 +154,14 @@ - - - + + + - + + + - - - - - - - + + + + + + + - + + @@ -389,7 +392,11 @@ - + + + + + diff --git a/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java b/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java index 1d2e44b2d..72aa93411 100644 --- a/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java +++ b/services/common/src/main/java/org/collectionspace/services/common/profile/CSpaceFilter.java @@ -1,14 +1,4 @@ -/** - * CSpaceFilter.java - * - * {Purpose of This Class} - * - * {Other Notes Relating to This Class (Optional)} - * - * $LastChangedBy: $ - * $LastChangedRevision: $ - * $LastChangedDate: $ - * +/** * This document is a part of the source code and related artifacts * for CollectionSpace, an open source collections management system * for museums and related institutions: @@ -36,52 +26,92 @@ import javax.servlet.ServletResponse; import javax.servlet.http.HttpServletRequest; //import javax.servlet.ServletContext; +import org.collectionspace.services.common.ServletTools; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + /** - * The Class CSpaceFilter. + * CSpaceFilter.java + * + * A filter that performs specified actions at the time + * each new request is received by the servlet container. + * + * This filter is currently used for recording performance + * metrics for requests to the CollectionSpace services. + * + * $LastChangedRevision: $ + * $LastChangedDate: $ + * */ public class CSpaceFilter implements Filter { - - /** The filter config. */ - FilterConfig filterConfig = null; - /* (non-Javadoc) - * @see javax.servlet.Filter#destroy() - */ - @Override - public void destroy() { - // Empty method. - } + /** The filter config. */ + FilterConfig filterConfig = null; + + private final String CLASS_NAME = this.getClass().getSimpleName(); + private Logger csvPerfLogger = LoggerFactory.getLogger("perf.collectionspace.csv"); + + /* (non-Javadoc) + * @see javax.servlet.Filter#destroy() + */ + @Override + public void destroy() { + // Empty method. + } + + /* (non-Javadoc) + * @see javax.servlet.Filter#doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) + */ + @Override + public void doFilter(ServletRequest request, ServletResponse response, + FilterChain chain) throws IOException, ServletException { + if (request != null) { + HttpServletRequest httpRequest = (HttpServletRequest) request; + + // Instantiate the CollectionSpace services profiler. + StringBuffer uri = new StringBuffer(httpRequest.getRequestURI()); + uri.append(':'); + uri.append(httpRequest.getMethod()); + Profiler profiler = new Profiler(uri.toString(), 0); + + // Start timing. + profiler.start(); + + // Process the request. + chain.doFilter(request, response); + + // Stop timing and log performance-related metrics. + profiler.stop(); - /* (non-Javadoc) - * @see javax.servlet.Filter#doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) - */ - @Override - public void doFilter(ServletRequest request, ServletResponse response, - FilterChain chain) throws IOException, ServletException { - if (request != null) { - HttpServletRequest httpRequest = (HttpServletRequest)request; - StringBuffer uri = new StringBuffer(httpRequest.getRequestURI()); - uri.append(':'); - uri.append(httpRequest.getMethod()); - Profiler profiler = new Profiler(uri.toString(), - 0); - profiler.start(); - chain.doFilter(request, response); -// profiler.log(httpRequest.getRequestURI()); - profiler.stop(); - } - } + String csvMsg = + "," + System.currentTimeMillis() + + "," + Thread.currentThread().getName() + + "," + "app" + + "," + "svc" + + "," + CLASS_NAME + + "," + httpRequest.getMethod() + + "," + ServletTools.getURL(httpRequest) + + "," + profiler.getElapsedTime(); - /* (non-Javadoc) - * @see javax.servlet.Filter#init(javax.servlet.FilterConfig) - */ - @Override - public void init(FilterConfig theFilterConfig) throws ServletException { - filterConfig = theFilterConfig; - if (filterConfig != null) { - // We can initialize using the init-params here which we defined in - // web.xml) - } - } + // FIXME: Expedient change interleaves CSV-style log entries with entries + // in the original perf log. These should be written to their own log file, + // with their own patternLayout. + profiler.log(csvMsg); + profiler.reset(); + // csvPerfLogger.debug(csvMsg); + } + } + /* (non-Javadoc) + * @see javax.servlet.Filter#init(javax.servlet.FilterConfig) + */ + @Override + public void init(FilterConfig theFilterConfig) throws ServletException { + filterConfig = theFilterConfig; + if (filterConfig != null) { + // We can initialize using the init-params here which we defined in + // web.xml) + } + } } diff --git a/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java b/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java index 1a85859cd..d63c5300f 100644 --- a/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java +++ b/services/common/src/main/java/org/collectionspace/services/common/profile/Profiler.java @@ -1,14 +1,4 @@ -/** - * Profiler.java - * - * {Purpose of This Class} - * - * {Other Notes Relating to This Class (Optional)} - * - * $LastChangedBy: $ - * $LastChangedRevision: $ - * $LastChangedDate: $ - * +/** * This document is a part of the source code and related artifacts * for CollectionSpace, an open source collections management system * for museums and related institutions: @@ -29,137 +19,272 @@ package org.collectionspace.services.common.profile; import org.slf4j.Logger; import org.slf4j.LoggerFactory; - /** - * The Class Profiler. + * Profiler.java + * + * Simple utility to store and report performance metrics. + * + * Records start and stop times, and elapsed and cumulative timings; + * writes performance-related log times. + * + * $LastChangedRevision: $ + * $LastChangedDate: $ + * */ public class Profiler { - - private int messageIndent = 0; - - /** The start time. */ - private long startTime = 0; - - /** The stop time. */ - private long stopTime = 0; - - /** The final time. */ - private long finalTime = 0; - - /** The message prefix. */ - private String messagePrefix = "Default profiler prefix:"; + /** The level of indentation. */ + private int messageIndent = 0; + /** The indentation character(s) */ + private static String INDENT = "\t"; + /** The message prefix. */ + private String messagePrefix = ""; + /** The separator between the message prefix and the message. **/ + final static String PREFIX_SEPARATOR = ":"; + /** The start time. */ + private long startTime = 0; + /** The stop time. */ + private long stopTime = 0; + /** The segment time. */ + private long elapsedTime = 0; + /** The cumulative time. */ + private long cumulativeTime = 0; /** The profiler logger. */ - private static String LOG4J_CATEGORY = "perf.collectionspace"; - private static Logger profilerLogger = LoggerFactory.getLogger(LOG4J_CATEGORY); - + private static String DEFAULT_LOG4J_CATEGORY = "perf.collectionspace"; + private static Logger profileLogger = LoggerFactory.getLogger(DEFAULT_LOG4J_CATEGORY); + /** * private default constructor. */ private Profiler() { - //empty default constructor + //empty default constructor + } + + /** + * Instantiates a new profiler. + * + * @param theObject a class whose name is to be logged. + */ + public Profiler(Object theObject) { + this(theObject, 0); } - + /** - * Sets the message prefix. + * Instantiates a new profiler. * - * @param theMessagePrefix the new message prefix + * @param theObject a class whose name is to be logged. + * @param messageIndent the level of indentation for log messages. */ - protected void setMessagePrefix(String theMessagePrefix, int indent) { - StringBuffer stringBuffer = new StringBuffer(); - for (int i = 0; i < indent; i++) { - stringBuffer.append('\t'); - } - stringBuffer.append(theMessagePrefix); - stringBuffer.append(':'); - messagePrefix = stringBuffer.toString(); - } - - protected StringBuffer getMessagePrefix() { - return new StringBuffer(messagePrefix); - } - + public Profiler(Object theObject, int messageIndent) { + init(objectName(theObject), messageIndent); + } + /** * Instantiates a new profiler. - * @param theObject - * @param indent * - * @param theClass the the class + * @param messagePrefix the message prefix to appear in log messages. + * @param messageIndent the level of indentation for log messages. + */ + public Profiler(String messagePrefix, int messageIndent) { + init(messagePrefix, messageIndent); + } + + /* + * For some reason, we need to call this method "early" at startup time for our + * Logger instance to get created correctly. FIXME: REM - Can we figure this out and fix it? + */ + /** + * Setup. + */ + public static void setup() { + //do nothing + } + + private void init(String messagePrefix, int messageIndent) { + this.setMessagePrefix(messagePrefix); + this.setMessageIndent(messageIndent); + } + + /** + * Stores and logs the start time. + * + * Logs using a default message. + */ + public void start() { + start(defaultStartMessage()); + } + + /** + * Stores and logs the start time. + * + * @param msg the message to log. + */ + public void start(String msg) { + log(msg); + setStartTime(currentTime()); + } + + /** + * Stores and logs the stop time, and the elapsed and cumulative timings + * from one or more cycles of start and stop. + * + * Logs using a default message. + */ + public void stop() { + // FIXME: Need to store values before constructing default stop message, + // hence has some redundant code with stop(msg) below. Perhaps can be consolidated. + setStopTime(currentTime()); + setElapsedTime(elapsedTime()); + addToCumulativeTime(elapsedTime()); + stop(defaultStopMessage()); + } + + /** + * Stores and logs the stop time, and the elapsed and cumulative timings, + * from one or more cycles of start and stop. + * + * @param msg the message to log. + */ + public void stop(String msg) { + setStopTime(currentTime()); + setElapsedTime(elapsedTime()); + addToCumulativeTime(elapsedTime()); + log(msg); + } + + public long getStartTime() { + return this.startTime; + } + + public long getStopTime() { + return this.stopTime; + } + + public long getElapsedTime() { + return this.elapsedTime; + } + + public long getCumulativeTime() { + return this.cumulativeTime; + } + + /** + * Resets the start and stop time, and the elapsed and cumulative timings. + */ + public void reset() { + setStartTime(0); + setStopTime(0); + setElapsedTime(0); + setCumulativeTime(0); + } + + /** + * Writes a log entry. + * + * @param msg the message to log. + */ + public void log(String msg) { + if (getLogger().isDebugEnabled()) { + getLogger().debug(formatLogMessage(msg)); + } + } + + /** + * Gets the logger. + * + * @return the logger */ - public Profiler(Object theObject, int indent) { - if (theObject != null) { - this.setMessagePrefix(theObject.getClass().getSimpleName(), indent); - } - } - /** - * Instantiates a new profiler. - * - * @param theMessagePrefix the the message prefix - * @param indent - */ - public Profiler(String theMessagePrefix, int indent) { - this.setMessagePrefix(theMessagePrefix, indent); - } - - /* - * For some reason, we need to call this method "early" at startup time for our - * Logger instance to get created correctly. FIXME: REM - Can we figure this out and fix it? - */ - /** - * Setup. - */ - public static void setup() { - //do nothing - } - - /** - * Gets the logger. - * - * @return the logger - */ - protected Logger getLogger() { - return profilerLogger; - } - - /** - * Private log. - * - * @param inMessage the in message - */ - public void log(String inMessage) { - if (getLogger().isDebugEnabled() == true) { - StringBuffer finalMessage = getMessagePrefix(); - if (inMessage != null) { - finalMessage.append(inMessage); - } - getLogger().debug(finalMessage.toString()); - } - } - - /** - * Start - */ - public void start() { - if (getLogger().isDebugEnabled() == true) { - StringBuffer message = getMessagePrefix(); - message.append(">>>> Start >>>>"); - getLogger().debug(message.toString()); - } - startTime = System.currentTimeMillis(); - } - - /** - * Stop. - */ - public void stop() { - stopTime = System.currentTimeMillis(); - finalTime = finalTime + (stopTime - startTime); - if (getLogger().isDebugEnabled() == true) { - StringBuffer message = getMessagePrefix(); - message.append("<<<< Stopped <<<< ["); - message.append(finalTime); - message.append("ms]"); - getLogger().debug(message.toString()); - } - } + protected Logger getLogger() { + return this.profileLogger; + } + + private void setMessagePrefix(String prefix) { + this.messagePrefix = prefix; + } + + private String getMessagePrefix() { + return this.messagePrefix; + } + + private int getMessageIndent() { + return this.messageIndent; + } + + private void setMessageIndent(int indent) { + this.messageIndent = indent; + } + + private void setStartTime(long start) { + this.startTime = start; + } + + private void setStopTime(long stop) { + this.stopTime = stop; + } + + private void setElapsedTime(long segment) { + this.elapsedTime = segment; + } + + private void setCumulativeTime(long cumulative) { + this.cumulativeTime = cumulative; + } + + private void addToCumulativeTime(long cumulative) { + this.cumulativeTime += cumulative; + } + + private long currentTime() { + return System.currentTimeMillis(); + } + + private long elapsedTime() { + return (currentTime() - getStartTime()); + } + + private String objectName(Object theObject) { + if (theObject != null) { + return (theObject.getClass().getSimpleName()); + } else { + return ""; + } + } + + /** + * Returns a formatted log message, including indentation and prefix. + * + * @param msg the message to log. + * @return a constructed log message, including indentation and prefix, if any. + */ + private String formatLogMessage(String msg) { + StringBuffer logMsg = new StringBuffer(); + for (int i = 0; i < getMessageIndent(); i++) { + logMsg.append(INDENT); + } + String prefix = getMessagePrefix(); + if (prefix != null && !prefix.trim().isEmpty()) { + logMsg.append(prefix); + logMsg.append(PREFIX_SEPARATOR); + } + if (msg != null) { + logMsg.append(msg); + } + return logMsg.toString(); + } + + private String defaultStartMessage() { + StringBuffer defaultStartMessage = new StringBuffer(); + defaultStartMessage.append(">>>> Start >>>>"); + return defaultStartMessage.toString(); + } + + private String defaultStopMessage() { + StringBuffer defaultStopMessage = new StringBuffer(); + defaultStopMessage.append("<<<< Stopped <<<<"); + defaultStopMessage.append(" [" + getElapsedTime() + " ms]"); + if (getCumulativeTime() > getElapsedTime()) { + defaultStopMessage.append(" (cumulative [" + getCumulativeTime() + " ms])"); + } + return defaultStopMessage.toString(); + } }