Author: dashorst Date: Wed Jul 6 09:05:18 2011 New Revision: 1143300 URL: http://svn.apache.org/viewvc?rev=1143300&view=rev Log: The getRequests() method of the request logger doesn't work at all. It returns a synchronized list which is wrapped in a unmodifiable list. The contents of the list is linked list, so whenever you are iterating over the unmodifiable list, the request logger is updating the underlying linked list—causing ConcurrentModificationExceptions.
Worked around this by using a rounded buffer in the request logger instead of the linked list. This implementation brings improved statistics to the request logger, such as average request times across the monitored interval. Issue: WICKET-3874 Modified: wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/IRequestLogger.java wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/RequestLogger.java Modified: wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/IRequestLogger.java URL: http://svn.apache.org/viewvc/wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/IRequestLogger.java?rev=1143300&r1=1143299&r2=1143300&view=diff ============================================================================== --- wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/IRequestLogger.java (original) +++ wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/IRequestLogger.java Wed Jul 6 09:05:18 2011 @@ -54,17 +54,27 @@ public interface IRequestLogger /** * @return Collection of live Sessions Data */ - public SessionData[] getLiveSessions(); + SessionData[] getLiveSessions(); /** * @return The current active requests */ - public int getCurrentActiveRequestCount(); + int getCurrentActiveRequestCount(); /** * @return The peak active requests */ - public int getPeakActiveRequestCount(); + int getPeakActiveRequestCount(); + + /** + * @return The number of requests per minute. + */ + long getRequestsPerMinute(); + + /** + * @return The average request time. + */ + long getAverageRequestTime(); /** * called when the session is created and has an id. (for http it means that the http session is @@ -226,19 +236,34 @@ public interface IRequestLogger return sessionId; } - void addTimeTaken(long time) + /** + * Adds {@code time} to the total server time. + * + * @param time + */ + public void addTimeTaken(long time) { lastActive = System.currentTimeMillis(); numberOfRequests++; totalTimeTaken += time; } - void setSessionInfo(Object sessionInfo) + /** + * Sets additional session info (e.g. logged in user). + * + * @param sessionInfo + */ + public void setSessionInfo(Object sessionInfo) { this.sessionInfo = sessionInfo; } - void setSessionSize(long size) + /** + * Sets the recorded session size. + * + * @param size + */ + public void setSessionSize(long size) { sessionSize = size; } Modified: wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/RequestLogger.java URL: http://svn.apache.org/viewvc/wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/RequestLogger.java?rev=1143300&r1=1143299&r2=1143300&view=diff ============================================================================== --- wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/RequestLogger.java (original) +++ wicket/trunk/wicket-core/src/main/java/org/apache/wicket/protocol/http/RequestLogger.java Wed Jul 6 09:05:18 2011 @@ -16,9 +16,10 @@ */ package org.apache.wicket.protocol.http; +import static java.lang.System.arraycopy; + import java.util.Arrays; -import java.util.Collections; -import java.util.LinkedList; +import java.util.Date; import java.util.List; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; @@ -28,16 +29,19 @@ import org.apache.wicket.Application; import org.apache.wicket.MetaDataKey; import org.apache.wicket.Page; import org.apache.wicket.Session; +import org.apache.wicket.ajax.AjaxRequestTarget; import org.apache.wicket.request.IRequestHandler; import org.apache.wicket.request.IRequestHandlerDelegate; import org.apache.wicket.request.cycle.RequestCycle; import org.apache.wicket.request.handler.BookmarkablePageRequestHandler; import org.apache.wicket.request.handler.BufferedResponseRequestHandler; -import org.apache.wicket.request.handler.IPageRequestHandler; +import org.apache.wicket.request.handler.IPageProvider; import org.apache.wicket.request.handler.ListenerInterfaceRequestHandler; +import org.apache.wicket.request.handler.RenderPageRequestHandler; import org.apache.wicket.request.handler.resource.ResourceReferenceRequestHandler; +import org.apache.wicket.request.resource.ResourceReference; import org.apache.wicket.settings.IRequestLoggerSettings; -import org.apache.wicket.util.lang.Classes; +import org.apache.wicket.util.lang.Args; import org.apache.wicket.util.string.AppendingStringBuffer; import org.apache.wicket.util.string.Strings; import org.slf4j.Logger; @@ -53,28 +57,40 @@ import org.slf4j.LoggerFactory; * session data was touched for this and how long the request did take. * * To view this information live see the {@link InspectorBug} that shows the {@link InspectorPage} - * with the {@link LiveSessionsPage} + * with the {@link LiveSessionsPage}. * - * @author jcompagner + * This implementation uses a rounded buffer for storing the request data, and strives to minimize + * contention on accessing the rounded buffer. At the beginning of your application start, the + * buffer is empty and fills up during the lifetime of the application until the window size has + * been reached, and new requests are written to the position containing the oldest request. * * @since 1.2 */ public class RequestLogger implements IRequestLogger { - /** log. */ + /** log, don't change this as it is often used to direct request logging to a different file. */ protected static Logger log = LoggerFactory.getLogger(RequestLogger.class); + /** + * Key for storing request data in the request cycle's meta data. + */ private static MetaDataKey<RequestData> REQUEST_DATA = new MetaDataKey<RequestData>() { private static final long serialVersionUID = 1L; }; + /** + * Key for storing session data in the request cycle's meta data. + */ + private static MetaDataKey<SessionData> SESSION_DATA = new MetaDataKey<SessionData>() + { + private static final long serialVersionUID = 1L; + }; + private final AtomicInteger totalCreatedSessions = new AtomicInteger(); private final AtomicInteger peakSessions = new AtomicInteger(); - private final List<RequestData> requests; - private final Map<String, SessionData> liveSessions; private final AtomicInteger activeRequests = new AtomicInteger(); @@ -82,31 +98,37 @@ public class RequestLogger implements IR private final AtomicInteger peakActiveRequests = new AtomicInteger(); /** + * Rounded request buffer that keeps the request data for the last N requests in the buffer. + */ + private RequestData[] requestWindow; + + /** + * Cursor pointing to the current writable location in the buffer. Points to the first empty + * slot or if the buffer has been filled completely to the oldest request in the buffer. + */ + private int indexInWindow = 0; + + /** + * records the total request time across the sliding request window so that it can be used to + * calculate the average request time across the window duration. + */ + private long totalRequestTime = 0l; + + /** + * records the start time of the oldest request across the sliding window so that it can be used + * to calculate the average request time across the window duration. + */ + private Date startTimeOfOldestRequest; + + /** * Construct. */ public RequestLogger() { - requests = Collections.synchronizedList(new LinkedList<RequestData>() - { - private static final long serialVersionUID = 1L; - - /** - * @see java.util.LinkedList#add(java.lang.Object) - */ - @Override - public void add(int index, RequestData o) - { - super.add(index, o); - - // should not happen often that the requests window size changes, but now we can - // increase and shrink the list at will. - IRequestLoggerSettings settings = Application.get().getRequestLoggerSettings(); - while (size() > Math.max(0, settings.getRequestsWindowSize())) - { - removeLast(); - } - } - }); + int requestsWindowSize = Application.get() + .getRequestLoggerSettings() + .getRequestsWindowSize(); + requestWindow = new RequestData[requestsWindowSize]; liveSessions = new ConcurrentHashMap<String, SessionData>(); } @@ -135,94 +157,53 @@ public class RequestLogger implements IR public List<RequestData> getRequests() { - return Collections.unmodifiableList(requests); - } - - public int getTotalCreatedSessions() - { - return totalCreatedSessions.get(); + synchronized (requestWindow) + { + RequestData[] result = new RequestData[hasBufferRolledOver() ? requestWindow.length + : indexInWindow]; + copyRequestsInOrder(result); + return Arrays.asList(result); + } } - public void logRequestedUrl(String url) + /** + * Copies all request data into {@code copy} such that the oldest request is in slot 0 and the + * most recent request is in slot {@code copy.length} + * + * @param copy + * the target, has to have a capacity of at least {@code requestWindow.length} + */ + private void copyRequestsInOrder(RequestData[] copy) { - getCurrentRequest().setRequestedUrl(url); - } + Args.isTrue(copy.length >= requestWindow.length, "copy.length must be at least {}", + requestWindow.length); + if (hasBufferRolledOver()) + { + // first copy the oldest requests stored behind the cursor into the copy + int oldestPos = indexInWindow + 1; + if (oldestPos < requestWindow.length) + arraycopy(requestWindow, oldestPos, copy, 0, requestWindow.length - oldestPos); - public void logEventTarget(IRequestHandler requestHandler) - { - getCurrentRequest().addEventTarget(getRequestHandlerString(requestHandler)); + // then append the newer requests stored from index 0 til the cursor position. + arraycopy(requestWindow, 0, copy, requestWindow.length - oldestPos, indexInWindow); + } + else + { + arraycopy(requestWindow, 0, copy, 0, indexInWindow); + } } - public void logResponseTarget(IRequestHandler requestHandler) + /** + * @return whether the buffer has been filled to capacity at least once + */ + private boolean hasBufferRolledOver() { - getCurrentRequest().addResponseTarget(getRequestHandlerString(requestHandler)); + return requestWindow[requestWindow.length - 1] != null; } - /** - * @param requestHandler - * @return The request target nice display string - */ - private String getRequestHandlerString(final IRequestHandler requestHandler) + public int getTotalCreatedSessions() { - AppendingStringBuffer sb = new AppendingStringBuffer(128); - if (requestHandler instanceof ListenerInterfaceRequestHandler) - { - ListenerInterfaceRequestHandler listener = (ListenerInterfaceRequestHandler)requestHandler; - sb.append("Interface[component: "); - sb.append(Classes.simpleName(listener.getComponent().getClass())); - sb.append("("); - sb.append(listener.getComponent().getPageRelativePath()); - sb.append("), page: "); - sb.append(listener.getPage().getClass().getName()); - sb.append("("); - sb.append(listener.getPage().getId()); - sb.append("), interface: "); - sb.append(listener.getListenerInterface().getName()); - sb.append("."); - sb.append(listener.getListenerInterface().getMethod().getName()); - sb.append("]"); - } - else if (requestHandler instanceof BookmarkablePageRequestHandler) - { - BookmarkablePageRequestHandler pageRequestHandler = (BookmarkablePageRequestHandler)requestHandler; - sb.append("BookmarkablePage["); - sb.append(pageRequestHandler.getPageClass().getName()); - sb.append("(").append(pageRequestHandler.getPageParameters()).append(")"); - sb.append("]"); - } - else if (requestHandler instanceof IPageRequestHandler) - { - IPageRequestHandler pageRequestHandler = (IPageRequestHandler)requestHandler; - sb.append("PageRequest["); - sb.append(pageRequestHandler.getPageClass().getName()); - sb.append("("); - sb.append(pageRequestHandler.getPageId()); - sb.append(")]"); - } - else if (requestHandler instanceof ResourceReferenceRequestHandler) - { - ResourceReferenceRequestHandler resourceRefenceHandler = (ResourceReferenceRequestHandler)requestHandler; - sb.append("ResourceReference["); - sb.append(resourceRefenceHandler.getResourceReference()); - sb.append("]"); - } - else if (requestHandler instanceof IRequestHandlerDelegate) - { - sb.append(requestHandler.getClass().getSimpleName()) - .append(".") - .append( - getRequestHandlerString(((IRequestHandlerDelegate)requestHandler).getDelegateHandler())); - } - else if (requestHandler instanceof BufferedResponseRequestHandler) - { - BufferedResponseRequestHandler bufferedResponseHandler = (BufferedResponseRequestHandler)requestHandler; - sb.append(bufferedResponseHandler.getClass().getSimpleName()); - } - else - { - sb.append(requestHandler.toString()); - } - return sb.toString(); + return totalCreatedSessions.get(); } public void objectCreated(Object value) @@ -231,8 +212,7 @@ public class RequestLogger implements IR if (value instanceof Session) { - Session session = (Session)value; - rd.addEntry("Session created, id: " + session.getId()); + rd.addEntry("Session created"); } else if (value instanceof Page) { @@ -253,7 +233,7 @@ public class RequestLogger implements IR Page page = (Page)value; rd.addEntry("Page removed, id: " + page.getId() + ", class:" + page.getClass()); } - else if (value instanceof Session) + else if (value instanceof WebSession) { rd.addEntry("Session removed"); } @@ -317,7 +297,7 @@ public class RequestLogger implements IR requestdata.setSessionSize(sizeInBytes); requestdata.setTimeTaken(timeTaken); - requests.add(0, requestdata); + addRequest(requestdata); SessionData sessiondata = null; if (sessionId != null) @@ -325,6 +305,12 @@ public class RequestLogger implements IR sessiondata = liveSessions.get(sessionId); if (sessiondata == null) { + // if the session has been destroyed during the request by + // Session#invalidateNow, retrieve the old session data from the RequestCycle. + sessiondata = RequestCycle.get().getMetaData(SESSION_DATA); + } + if (sessiondata == null) + { // passivated session or logger only started after it. sessionCreated(sessionId); sessiondata = liveSessions.get(sessionId); @@ -353,10 +339,10 @@ public class RequestLogger implements IR public void sessionDestroyed(String sessionId) { - liveSessions.remove(sessionId); + RequestCycle.get().setMetaData(SESSION_DATA, liveSessions.remove(sessionId)); } - RequestData getCurrentRequest() + protected RequestData getCurrentRequest() { RequestCycle requestCycle = RequestCycle.get(); RequestData rd = requestCycle.getMetaData(REQUEST_DATA); @@ -374,10 +360,6 @@ public class RequestLogger implements IR return rd; } - /** - * @param rd - * @param sd - */ protected void log(RequestData rd, SessionData sd) { if (log.isInfoEnabled()) @@ -449,4 +431,280 @@ public class RequestLogger implements IR } return ""; } + + protected void addRequest(RequestData rd) + { + // ensure the buffer has the proper installed length + resizeBuffer(); + + synchronized (requestWindow) + { + // if the requestWindow is a zero-length array, nothing gets stored + if (requestWindow.length == 0) + return; + + // use the oldest request data to recalculate the average request time + RequestData old = requestWindow[indexInWindow]; + + // replace the oldest request with the nweset request + requestWindow[indexInWindow] = rd; + + // move the cursor to the next writable position containing the oldest request or if the + // buffer hasn't been filled completely the first empty slot + indexInWindow = (indexInWindow + 1) % requestWindow.length; + if (old != null) + { + startTimeOfOldestRequest = requestWindow[indexInWindow].getStartDate(); + totalRequestTime -= old.getTimeTaken(); + } + else + { + if (startTimeOfOldestRequest == null) + startTimeOfOldestRequest = rd.getStartDate(); + } + totalRequestTime += rd.getTimeTaken(); + } + } + + private int getWindowSize() + { + synchronized (requestWindow) + { + if (requestWindow[requestWindow.length - 1] == null) + return indexInWindow; + else + return requestWindow.length; + } + } + + public long getAverageRequestTime() + { + synchronized (requestWindow) + { + int windowSize = getWindowSize(); + if (windowSize == 0) + return 0; + return totalRequestTime / windowSize; + } + } + + public long getRequestsPerMinute() + { + synchronized (requestWindow) + { + int windowSize = getWindowSize(); + if (windowSize == 0) + return 0; + long start = startTimeOfOldestRequest.getTime(); + long end = System.currentTimeMillis(); + double diff = end - start; + return Math.round(windowSize / (diff / 60000.0)); + } + } + + public void logEventTarget(IRequestHandler requestHandler) + { + RequestData requestData = getCurrentRequest(); + if (requestData != null) + { + requestData.addEventTarget(getRequestHandlerString(requestHandler)); + } + } + + public void logRequestedUrl(String url) + { + getCurrentRequest().setRequestedUrl(url); + } + + public void logResponseTarget(IRequestHandler requestHandler) + { + RequestData requestData = getCurrentRequest(); + if (requestData != null) + requestData.addResponseTarget(getRequestHandlerString(requestHandler)); + } + + private String getRequestHandlerString(IRequestHandler handler) + { + AppendingStringBuffer sb = new AppendingStringBuffer(128); + sb.append(handler.getClass().getSimpleName()); + sb.append("["); + if (handler instanceof ListenerInterfaceRequestHandler) + { + getListenerString(sb, (ListenerInterfaceRequestHandler)handler); + } + else if (handler instanceof BookmarkablePageRequestHandler) + { + getBookmarkableString(sb, (BookmarkablePageRequestHandler)handler); + } + else if (handler instanceof RenderPageRequestHandler) + { + getRendererString(sb, (RenderPageRequestHandler)handler); + } + else if (handler instanceof AjaxRequestTarget) + { + getAjaxString(sb, (AjaxRequestTarget)handler); + } + else if (handler instanceof ResourceReferenceRequestHandler) + { + getResourceString(sb, (ResourceReferenceRequestHandler)handler); + } + else if (handler instanceof IRequestHandlerDelegate) + { + getDelegateString(sb, (IRequestHandlerDelegate)handler); + } + else if (handler instanceof BufferedResponseRequestHandler) + { + // nothing extra to log... BufferedResponse doesn't have identifiable information about + // which request was buffered + } + else + { + sb.append(handler.toString()); + } + sb.append("]"); + return sb.toString(); + } + + private void getDelegateString(AppendingStringBuffer sb, IRequestHandlerDelegate delegateHandler) + { + sb.append("delegatedHandler="); + sb.append(getRequestHandlerString(delegateHandler.getDelegateHandler())); + } + + private void getResourceString(AppendingStringBuffer sb, + ResourceReferenceRequestHandler resourceRefenceHandler) + { + ResourceReference resourceReference = resourceRefenceHandler.getResourceReference(); + sb.append("resourceReferenceClass="); + sb.append(resourceReference.getClass().getName()); + sb.append(",scope="); + sb.append(resourceReference.getScope() != null ? resourceReference.getScope().getName() + : "null"); + sb.append(",name="); + sb.append(resourceReference.getName()); + sb.append(",locale="); + sb.append(resourceReference.getLocale()); + sb.append(",style="); + sb.append(resourceReference.getStyle()); + sb.append(",variation="); + sb.append(resourceReference.getVariation()); + } + + private void getAjaxString(AppendingStringBuffer sb, AjaxRequestTarget ajaxHandler) + { + sb.append("pageClass="); + sb.append(ajaxHandler.getPageClass().getName()); + sb.append(",pageParameters=["); + sb.append(ajaxHandler.getPageParameters()); + sb.append("]"); + sb.append(",pageId="); + sb.append(ajaxHandler.getPage().getId()); + } + + private void getRendererString(AppendingStringBuffer sb, + RenderPageRequestHandler pageRequestHandler) + { + sb.append("pageClass="); + sb.append(pageRequestHandler.getPageClass().getName()); + sb.append(",pageParameters=["); + sb.append(pageRequestHandler.getPageParameters()); + sb.append("]"); + IPageProvider pageProvider = pageRequestHandler.getPageProvider(); + if (!pageProvider.isNewPageInstance()) + { + sb.append(",pageId="); + sb.append(pageRequestHandler.getPage().getId()); + } + } + + private void getBookmarkableString(AppendingStringBuffer sb, + BookmarkablePageRequestHandler pageRequestHandler) + { + sb.append("pageClass="); + sb.append(pageRequestHandler.getPageClass().getName()); + sb.append(",pageParameters=["); + sb.append(pageRequestHandler.getPageParameters()); + sb.append("]"); + } + + private void getListenerString(AppendingStringBuffer sb, + ListenerInterfaceRequestHandler listener) + { + sb.append("pageClass="); + sb.append(listener.getPageClass().getName()); + sb.append(",pageId="); + sb.append(listener.getPage().getId()); + sb.append(",componentClass="); + sb.append(listener.getComponent().getClass().getName()); + sb.append(",componentPath="); + sb.append(listener.getComponent().getPageRelativePath()); + sb.append(",behaviorIndex="); + sb.append(listener.getBehaviorIndex()); + sb.append(",behaviorClass="); + if (listener.getBehaviorIndex() == null) + sb.append("null"); + else + sb.append(listener.getComponent() + .getBehaviorById(listener.getBehaviorIndex()) + .getClass() + .getName()); + sb.append(",interfaceName="); + sb.append(listener.getListenerInterface().getName()); + sb.append(",interfaceMethod="); + sb.append(listener.getListenerInterface().getMethod().getName()); + } + + /** + * Resizes the request buffer to match the + * {@link IRequestLoggerSettings#getRequestsWindowSize() configured window size} + */ + private void resizeBuffer() + { + int newCapacity = Application.get().getRequestLoggerSettings().getRequestsWindowSize(); + + // do nothing if the capacity requirement hasn't changed + if (newCapacity == requestWindow.length) + return; + + RequestData[] newRequestWindow = new RequestData[newCapacity]; + synchronized (requestWindow) + { + int oldCapacity = requestWindow.length; + int oldNumberOfElements = hasBufferRolledOver() ? oldCapacity : indexInWindow; + + if (newCapacity > oldCapacity) + { + // increase the capacity of the buffer when more requests need to be stored + // and preserve the order of the requests while copying them into the new buffer. + copyRequestsInOrder(newRequestWindow); + + // the next writable position is at the first non-copied element in the buffer + indexInWindow = oldNumberOfElements; + requestWindow = newRequestWindow; + } + else if (newCapacity < oldCapacity) + { + // sort the requests in the current buffer such that the oldest request is in slot 0 + RequestData[] sortedRequestWindow = new RequestData[oldCapacity]; + copyRequestsInOrder(sortedRequestWindow); + + // determine the number of elements that need to be copied into the smaller target + int numberOfElementsToCopy = Math.min(newCapacity, oldNumberOfElements); + + // determine the position from where the copying must start + int numberOfElementsToSkip = Math.max(0, oldNumberOfElements - + numberOfElementsToCopy); + + // fill the new buffer with the leftovers of the old buffer, skipping the oldest + // requests + arraycopy(sortedRequestWindow, numberOfElementsToSkip, newRequestWindow, 0, + numberOfElementsToCopy); + + // the next writable position is 0 when the buffer is filled to capacity, or the + // number of copied elements when the buffer isn't filled to capacity. + indexInWindow = numberOfElementsToCopy >= newCapacity ? 0 : numberOfElementsToCopy; + requestWindow = newRequestWindow; + } + } + } }