Introduction
This filter is used to 'profile' the events. We will gather some timing informations like :
- the event duration
- the fastest execution for each event
- the slowest execution for each event
- the number of calls to each event
- and the average duration for each operation
new implementation proposal
The current implementation introduces some synchronization, and is a little bit too complex for what we need.
Here is the new implementation proposal
package org.apache.mina.filter.statistic; import java.util.HashSet; import java.util.Set; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; import org.apache.mina.core.filterchain.IoFilterAdapter; import org.apache.mina.core.session.IdleStatus; import org.apache.mina.core.session.IoEventType; import org.apache.mina.core.session.IoSession; import org.apache.mina.core.write.WriteRequest; /** * This class will measure the time it takes for a * method in the {@link IoFilterAdapter} class to execute. The basic * premise of the logic in this class is to get the current time * at the beginning of the method, call method on nextFilter, and * then get the current time again. An example of how to use * the filter is: * * <pre> * ProfilerTimerFilter profiler = new ProfilerTimerFilter( * TimeUnit.MILLISECOND, IoEventType.MESSAGE_RECEIVED); * chain.addFirst("Profiler", profiler); * </pre> * * The profiled {@link IoEventType} are : * <ul> * <li>IoEventType.MESSAGE_RECEIVED</li> * <li>IoEventType.MESSAGE_SENT</li> * <li>IoEventType.SESSION_CREATED</li> * <li>IoEventType.SESSION_OPENED</li> * <li>IoEventType.SESSION_IDLE</li> * <li>IoEventType.SESSION_CLOSED</li> * </ul> * * @author The Apache MINA Project (dev@mina.apache.org) * @version $Rev: 671827 $, $Date: 2008-06-26 10:49:48 +0200 (Thu, 26 Jun 2008) $ */ public class ProfilerTimerFilter extends IoFilterAdapter { /** TRhe selected time unit */ private volatile TimeUnit timeUnit; /** A TimerWorker for the MessageReceived events */ private TimerWorker messageReceivedTimerWorker; /** A flag to tell the filter that the MessageReceived must be profiled */ private boolean profileMessageReceived = false; /** A TimerWorker for the MessageSent events */ private TimerWorker messageSentTimerWorker; /** A flag to tell the filter that the MessageSent must be profiled */ private boolean profileMessageSent = false; /** A TimerWorker for the SessionCreated events */ private TimerWorker sessionCreatedTimerWorker; /** A flag to tell the filter that the SessionCreated must be profiled */ private boolean profileSessionCreated = false; /** A TimerWorker for the SessionOpened events */ private TimerWorker sessionOpenedTimerWorker; /** A flag to tell the filter that the SessionOpened must be profiled */ private boolean profileSessionOpened = false; /** A TimerWorker for the SessionIdle events */ private TimerWorker sessionIdleTimerWorker; /** A flag to tell the filter that the SessionIdle must be profiled */ private boolean profileSessionIdle = false; /** A TimerWorker for the SessionClosed events */ private TimerWorker sessionClosedTimerWorker; /** A flag to tell the filter that the SessionClosed must be profiled */ private boolean profileSessionClosed = false; /** * Creates a new instance of ProfilerFilter. This is the * default constructor and will print out timings for * messageReceived and messageSent and the time increment * will be in milliseconds. */ public ProfilerTimerFilter() { this( TimeUnit.MILLISECONDS, IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT); } /** * Creates a new instance of ProfilerFilter. This is the * default constructor and will print out timings for * messageReceived and messageSent. * * @param timeUnit the time increment to set */ public ProfilerTimerFilter(TimeUnit timeUnit) { this( timeUnit, IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT); } /** * Creates a new instance of ProfilerFilter. An example * of this call would be: * * <pre> * new ProfilerTimerFilter( * TimeUnit.MILLISECONDS, * IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT); * </pre> * * Note : you can add as many {@link IoEventType} as you want. The method accepts * a variable number of arguments. * * @param timeUnit Used to determine the level of precision you need in your timing. * @param eventTypes A list of {@link IoEventType} representation of the methods to profile */ public ProfilerTimerFilter(TimeUnit timeUnit, IoEventType... eventTypes) { this.timeUnit = timeUnit; setProfilers(eventTypes); } /** * Create the profilers for a list of {@link IoEventType}. * * @param eventTypes the list of {@link IoEventType} to profile */ private void setProfilers(IoEventType... eventTypes) { for (IoEventType type : eventTypes) { switch (type) { case MESSAGE_RECEIVED : messageReceivedTimerWorker = new TimerWorker(); profileMessageReceived = true; break; case MESSAGE_SENT : messageSentTimerWorker = new TimerWorker(); profileMessageSent = true; break; case SESSION_CREATED : sessionCreatedTimerWorker = new TimerWorker(); profileSessionCreated = true; break; case SESSION_OPENED : sessionOpenedTimerWorker = new TimerWorker(); profileSessionOpened = true; break; case SESSION_IDLE : sessionIdleTimerWorker = new TimerWorker(); profileSessionIdle = true; break; case SESSION_CLOSED : sessionClosedTimerWorker = new TimerWorker(); profileSessionClosed = true; break; } } } /** * Sets the {@link TimeUnit} being used. * * @param timeUnit the new {@link TimeUnit} to be used. */ public void setTimeUnit(TimeUnit timeUnit) { this.timeUnit = timeUnit; } /** * Set the {@link IoEventType} to be profiled * * @param type The {@link IoEventType} to profile */ public void profile(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : profileMessageReceived = true; if (messageReceivedTimerWorker == null) { messageReceivedTimerWorker = new TimerWorker(); } return; case MESSAGE_SENT : profileMessageSent = true; if (messageSentTimerWorker == null) { messageSentTimerWorker = new TimerWorker(); } return; case SESSION_CREATED : profileSessionCreated = true; if (sessionCreatedTimerWorker == null) { sessionCreatedTimerWorker = new TimerWorker(); } case SESSION_OPENED : profileSessionOpened = true; if (sessionOpenedTimerWorker == null) { sessionOpenedTimerWorker = new TimerWorker(); } case SESSION_IDLE : profileSessionIdle = true; if (sessionIdleTimerWorker == null) { sessionIdleTimerWorker = new TimerWorker(); } case SESSION_CLOSED : profileSessionClosed = true; if (sessionClosedTimerWorker == null) { sessionClosedTimerWorker = new TimerWorker(); } } } /** * Stop profiling an {@link IoEventType} * * @param type The {@link IoEventType} to stop profiling */ public void stopProfile(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : profileMessageReceived = false; return; case MESSAGE_SENT : profileMessageSent = false; return; case SESSION_CREATED : profileSessionCreated = false; return; case SESSION_OPENED : profileSessionOpened = false; return; case SESSION_IDLE : profileSessionIdle = false; return; case SESSION_CLOSED : profileSessionClosed = false; return; } } /** * Return the set of {@link IoEventType} which are profiled. * * @return a Set containing all the profiled {@link IoEventType} */ public Set<IoEventType> getEventsToProfile() { Set<IoEventType> set = new HashSet<IoEventType>(); if ( profileMessageReceived ) { set.add(IoEventType.MESSAGE_RECEIVED); } if ( profileMessageSent) { set.add(IoEventType.MESSAGE_SENT); } if ( profileSessionCreated ) { set.add(IoEventType.SESSION_CREATED); } if ( profileSessionOpened ) { set.add(IoEventType.SESSION_OPENED); } if ( profileSessionIdle ) { set.add(IoEventType.SESSION_IDLE); } if ( profileSessionClosed ) { set.add(IoEventType.SESSION_CLOSED); } return set; } /** * Set the profilers for a list of {@link IoEventType} * * @param eventTypes the list of {@link IoEventType} to profile */ public void setEventsToProfile(IoEventType... eventTypes) { setProfilers(eventTypes); } /** * Profile a MessageReceived event. This method will gather the following * informations : * - the method duration * - the shortest execution time * - the slowest execution time * - the average execution time * - the global number of calls * * @param nextFilter The filter to call next * @param session The associated session * @param message the received message */ @Override public void messageReceived(NextFilter nextFilter, IoSession session, Object message) throws Exception { if (profileMessageReceived) { long start = timeNow(); nextFilter.messageReceived(session, message); long end = timeNow(); messageReceivedTimerWorker.addNewDuration(end - start); } else { nextFilter.messageReceived(session, message); } } /** * Profile a MessageSent event. This method will gather the following * informations : * - the method duration * - the shortest execution time * - the slowest execution time * - the average execution time * - the global number of calls * * @param nextFilter The filter to call next * @param session The associated session * @param writeRequest the sent message */ @Override public void messageSent(NextFilter nextFilter, IoSession session, WriteRequest writeRequest) throws Exception { if (profileMessageSent) { long start = timeNow(); nextFilter.messageSent(session, writeRequest); long end = timeNow(); messageSentTimerWorker.addNewDuration(end - start); } else { nextFilter.messageSent(session, writeRequest); } } /** * Profile a SessionCreated event. This method will gather the following * informations : * - the method duration * - the shortest execution time * - the slowest execution time * - the average execution time * - the global number of calls * * @param nextFilter The filter to call next * @param session The associated session */ @Override public void sessionCreated(NextFilter nextFilter, IoSession session) throws Exception { if (profileSessionCreated) { long start = timeNow(); nextFilter.sessionCreated(session); long end = timeNow(); sessionCreatedTimerWorker.addNewDuration(end - start); } else { nextFilter.sessionCreated(session); } } /** * Profile a SessionOpened event. This method will gather the following * informations : * - the method duration * - the shortest execution time * - the slowest execution time * - the average execution time * - the global number of calls * * @param nextFilter The filter to call next * @param session The associated session */ @Override public void sessionOpened(NextFilter nextFilter, IoSession session) throws Exception { if (profileSessionOpened) { long start = timeNow(); nextFilter.sessionOpened(session); long end = timeNow(); sessionOpenedTimerWorker.addNewDuration(end - start); } else { nextFilter.sessionOpened(session); } } /** * Profile a SessionIdle event. This method will gather the following * informations : * - the method duration * - the shortest execution time * - the slowest execution time * - the average execution time * - the global number of calls * * @param nextFilter The filter to call next * @param session The associated session * @param status The session's status */ @Override public void sessionIdle(NextFilter nextFilter, IoSession session, IdleStatus status) throws Exception { if (profileSessionIdle) { long start = timeNow(); nextFilter.sessionIdle(session, status); long end = timeNow(); sessionIdleTimerWorker.addNewDuration(end - start); } else { nextFilter.sessionIdle(session, status); } } /** * Profile a SessionClosed event. This method will gather the following * informations : * - the method duration * - the shortest execution time * - the slowest execution time * - the average execution time * - the global number of calls * * @param nextFilter The filter to call next * @param session The associated session */ @Override public void sessionClosed(NextFilter nextFilter, IoSession session) throws Exception { if (profileSessionClosed) { long start = timeNow(); nextFilter.sessionClosed(session); long end = timeNow(); sessionClosedTimerWorker.addNewDuration(end - start); } else { nextFilter.sessionClosed(session); } } /** * Get the average time for the specified method represented by the {@link IoEventType} * * @param type * The {@link IoEventType} that the user wants to get the average method call time * @return * The average time it took to execute the method represented by the {@link IoEventType} */ public double getAverageTime(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : if (profileMessageReceived) { return messageReceivedTimerWorker.getAverage(); } break; case MESSAGE_SENT : if (profileMessageSent) { return messageSentTimerWorker.getAverage(); } break; case SESSION_CREATED : if (profileSessionCreated) { return sessionCreatedTimerWorker.getAverage(); } break; case SESSION_OPENED : if (profileSessionOpened) { return sessionOpenedTimerWorker.getAverage(); } break; case SESSION_IDLE : if (profileSessionIdle) { return sessionIdleTimerWorker.getAverage(); } break; case SESSION_CLOSED : if (profileSessionClosed) { return sessionClosedTimerWorker.getAverage(); } break; } throw new IllegalArgumentException( "You are not monitoring this event. Please add this event first."); } /** * Gets the total number of times the method has been called that is represented by the * {@link IoEventType} * * @param type * The {@link IoEventType} that the user wants to get the total number of method calls * @return * The total number of method calls for the method represented by the {@link IoEventType} */ public long getTotalCalls(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : if (profileMessageReceived) { return messageReceivedTimerWorker.getCallsNumber(); } break; case MESSAGE_SENT : if (profileMessageSent) { return messageSentTimerWorker.getCallsNumber(); } break; case SESSION_CREATED : if (profileSessionCreated) { return sessionCreatedTimerWorker.getCallsNumber(); } break; case SESSION_OPENED : if (profileSessionOpened) { return sessionOpenedTimerWorker.getCallsNumber(); } break; case SESSION_IDLE : if (profileSessionIdle) { return sessionIdleTimerWorker.getCallsNumber(); } break; case SESSION_CLOSED : if (profileSessionClosed) { return sessionClosedTimerWorker.getCallsNumber(); } break; } throw new IllegalArgumentException( "You are not monitoring this event. Please add this event first."); } /** * The total time this method has been executing * * @param type * The {@link IoEventType} that the user wants to get the total time this method has * been executing * @return * The total time for the method represented by the {@link IoEventType} */ public long getTotalTime(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : if (profileMessageReceived) { return messageReceivedTimerWorker.getTotal(); } break; case MESSAGE_SENT : if (profileMessageSent) { return messageSentTimerWorker.getTotal(); } break; case SESSION_CREATED : if (profileSessionCreated) { return sessionCreatedTimerWorker.getTotal(); } break; case SESSION_OPENED : if (profileSessionOpened) { return sessionOpenedTimerWorker.getTotal(); } break; case SESSION_IDLE : if (profileSessionIdle) { return sessionIdleTimerWorker.getTotal(); } break; case SESSION_CLOSED : if (profileSessionClosed) { return sessionClosedTimerWorker.getTotal(); } break; } throw new IllegalArgumentException( "You are not monitoring this event. Please add this event first."); } /** * The minimum time the method represented by {@link IoEventType} has executed * * @param type * The {@link IoEventType} that the user wants to get the minimum time this method has * executed * @return * The minimum time this method has executed represented by the {@link IoEventType} */ public long getMinimumTime(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : if (profileMessageReceived) { return messageReceivedTimerWorker.getMinimum(); } break; case MESSAGE_SENT : if (profileMessageSent) { return messageSentTimerWorker.getMinimum(); } break; case SESSION_CREATED : if (profileSessionCreated) { return sessionCreatedTimerWorker.getMinimum(); } break; case SESSION_OPENED : if (profileSessionOpened) { return sessionOpenedTimerWorker.getMinimum(); } break; case SESSION_IDLE : if (profileSessionIdle) { return sessionIdleTimerWorker.getMinimum(); } break; case SESSION_CLOSED : if (profileSessionClosed) { return sessionClosedTimerWorker.getMinimum(); } break; } throw new IllegalArgumentException( "You are not monitoring this event. Please add this event first."); } /** * The maximum time the method represented by {@link IoEventType} has executed * * @param type * The {@link IoEventType} that the user wants to get the maximum time this method has * executed * @return * The maximum time this method has executed represented by the {@link IoEventType} */ public long getMaximumTime(IoEventType type) { switch (type) { case MESSAGE_RECEIVED : if (profileMessageReceived) { return messageReceivedTimerWorker.getMaximum(); } break; case MESSAGE_SENT : if (profileMessageSent) { return messageSentTimerWorker.getMaximum(); } break; case SESSION_CREATED : if (profileSessionCreated) { return sessionCreatedTimerWorker.getMaximum(); } break; case SESSION_OPENED : if (profileSessionOpened) { return sessionOpenedTimerWorker.getMaximum(); } break; case SESSION_IDLE : if (profileSessionIdle) { return sessionIdleTimerWorker.getMaximum(); } break; case SESSION_CLOSED : if (profileSessionClosed) { return sessionClosedTimerWorker.getMaximum(); } break; } throw new IllegalArgumentException( "You are not monitoring this event. Please add this event first."); } /** * Class that will track the time each method takes and be able to provide information * for each method. * */ private class TimerWorker { /** The sum of all operation durations */ private final AtomicLong total; /** The number of calls */ private final AtomicLong callsNumber; /** The fastest operation */ private final AtomicLong minimum; /** The slowest operation */ private final AtomicLong maximum; /** A lock for synchinized blocks */ private final Object lock = new Object(); /** * Creates a new instance of TimerWorker. * */ public TimerWorker() { total = new AtomicLong(); callsNumber = new AtomicLong(); minimum = new AtomicLong(); maximum = new AtomicLong(); } /** * Add a new operation duration to this class. Total is updated * and calls is incremented * * @param duration * The new operation duration */ public void addNewDuration(long duration) { callsNumber.incrementAndGet(); total.addAndGet(duration); synchronized (lock) { // this is not entirely thread-safe, must lock if (duration < minimum.longValue()) { minimum.set(duration); } // this is not entirely thread-safe, must lock if (duration > maximum.longValue()) { maximum.set(duration); } } } /** * Gets the average reading for this event * * @return the average reading for this event */ public double getAverage() { synchronized (lock) { // There are two operations, we need to synchronize the block return total.longValue() / callsNumber.longValue(); } } /** * Returns the total number of profiled operations * * @return The total number of profiled operation */ public long getCallsNumber() { return callsNumber.longValue(); } /** * Returns the total time * * @return the total time */ public long getTotal() { return total.longValue(); } /** * Returns the lowest execution time * * @return the lowest execution time */ public long getMinimum() { return minimum.longValue(); } /** * Returns the longest execution time * * @return the longest execution time */ public long getMaximum() { return maximum.longValue(); } } /** * @return the current time, expressed using the fixed TimeUnit. */ private long timeNow() { switch (timeUnit) { case SECONDS : return System.currentTimeMillis()/1000; case MICROSECONDS : return System.nanoTime()/1000; case NANOSECONDS : return System.nanoTime(); default : return System.currentTimeMillis(); } } }