You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@mina.apache.org by mw...@apache.org on 2007/07/16 07:18:58 UTC
svn commit: r556504 - in
/mina/trunk/core/src/main/java/org/apache/mina/filter:
ProfilerTimerFilter.java ProfilerTimerUnit.java
Author: mwebb
Date: Sun Jul 15 22:18:57 2007
New Revision: 556504
URL: http://svn.apache.org/viewvc?view=rev&rev=556504
Log:
made updates based on Trustin's comments.
Removed:
mina/trunk/core/src/main/java/org/apache/mina/filter/ProfilerTimerUnit.java
Modified:
mina/trunk/core/src/main/java/org/apache/mina/filter/ProfilerTimerFilter.java
Modified: mina/trunk/core/src/main/java/org/apache/mina/filter/ProfilerTimerFilter.java
URL: http://svn.apache.org/viewvc/mina/trunk/core/src/main/java/org/apache/mina/filter/ProfilerTimerFilter.java?view=diff&rev=556504&r1=556503&r2=556504
==============================================================================
--- mina/trunk/core/src/main/java/org/apache/mina/filter/ProfilerTimerFilter.java (original)
+++ mina/trunk/core/src/main/java/org/apache/mina/filter/ProfilerTimerFilter.java Sun Jul 15 22:18:57 2007
@@ -20,11 +20,16 @@
package org.apache.mina.filter;
+import java.util.EnumSet;
+import java.util.HashMap;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+
import org.apache.mina.common.IdleStatus;
+import org.apache.mina.common.IoEventType;
import org.apache.mina.common.IoFilterAdapter;
import org.apache.mina.common.IoSession;
import org.apache.mina.common.WriteRequest;
-import org.apache.mina.util.SessionLog;
/**
@@ -37,7 +42,7 @@
* the filter is:
*
* <pre>
- * ProfilerTimerFilter profiler = new ProfilerTimerFilter( ProfilerTimerFilter.MSG_RCV, 6, ProfilerTimerUnit.NANOSECONDS );
+ * ProfilerTimerFilter profiler = new ProfilerTimerFilter( ProfilerTimerFilter.MSG_RCV, ProfilerTimerUnit.MILLISECOND );
* profiler.setLogLevel( 6 );
* chain.addFirst( "Profiler", profiler);
* </pre>
@@ -47,55 +52,21 @@
*/
public class ProfilerTimerFilter extends IoFilterAdapter
{
- /**
- * Do not profile any methods
- */
- public static final int ZERO = 0;
-
- /**
- * Profile the messageReceived method
- */
- public static final int MSG_RCV = 1;
-
- /**
- * Profile the messageSent method
- */
- public static final int MSG_SND = 2;
-
- /**
- * Profile the sessionCreated method
- */
- public static final int SES_CRT = 4;
-
- /**
- * Profile the sessionClosed method
- */
- public static final int SES_CLS = 8;
-
- /**
- * Profile the sessionOpened method
- */
- public static final int SES_OPN = 16;
-
- /**
- * Profile the sessionIdle method
- */
- public static final int SES_IDL = 32;
-
- private int methodsToLog;
- private int logLevel;
+ private EnumSet<IoEventType> eventsToProfile;
private ProfilerTimerUnit timeUnit;
-
+ private HashMap<IoEventType,TimerWorker> timerManager;
+
/**
* Creates a new instance of ProfilerFilter. This is the
* default constructor and will print out timings for
- * messageReceived and messageSent to the SessionLog.debug
- * level and the time increment will be in nanoseconds.
+ * messageReceived and messageSent and the time increment
+ * will be in milliseconds.
*/
public ProfilerTimerFilter()
{
- this( MSG_RCV | MSG_SND, 7, ProfilerTimerUnit.NANOSECONDS );
+ this( EnumSet.of( IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT ),
+ TimeUnit.MILLISECONDS );
}
@@ -104,26 +75,38 @@
* of this call would be:
*
* <code>
- * new ProfilerTimerFilter( MSG_RCV|MSG_SND, 6, ProfilerTimerUnit.MILLISECONDS );
+ * new ProfilerTimerFilter( EnumSet.of( IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT ),
+ * TimeUnit.MILLISECONDS );
* </code>
*
- * @param methodsToLog
- * A bitmask representation of the methods to profile
- * @param logLevel
- * The {@link SessionLog} level that this filter should
- * print out the information. 1=error, 5=warn, 6=info,
- * 7=debug. This follows syslog convention.
- * @param timeUnit
+ * @param eventsToProfile
+ * A set of {@link IoEventType} representation of the methods to profile
+ * @param unit
* Used to determine the level of precision you need in your timing.
*/
- public ProfilerTimerFilter( int methodsToLog, int logLevel, ProfilerTimerUnit timeUnit )
+ public ProfilerTimerFilter( EnumSet<IoEventType> eventsToProfile, TimeUnit unit )
{
- this.methodsToLog = methodsToLog;
- this.logLevel = logLevel;
- this.timeUnit = timeUnit;
+ this.eventsToProfile = eventsToProfile;
+
+ if( unit == TimeUnit.MILLISECONDS ){
+ this.timeUnit = ProfilerTimerUnit.MILLISECONDS;
+ } else if( unit == TimeUnit.NANOSECONDS ){
+ this.timeUnit = ProfilerTimerUnit.NANOSECONDS;
+ } else if( unit == TimeUnit.SECONDS ){
+ this.timeUnit = ProfilerTimerUnit.SECONDS;
+ } else {
+ throw new IllegalArgumentException( "Invalid Time specified" );
+ }
+
+ timerManager = new HashMap<IoEventType,TimerWorker>();
+ timerManager.put( IoEventType.MESSAGE_RECEIVED, new TimerWorker() );
+ timerManager.put( IoEventType.MESSAGE_SENT, new TimerWorker() );
+ timerManager.put( IoEventType.SESSION_CREATED, new TimerWorker() );
+ timerManager.put( IoEventType.SESSION_OPENED, new TimerWorker() );
+ timerManager.put( IoEventType.SESSION_IDLE, new TimerWorker() );
+ timerManager.put( IoEventType.SESSION_CLOSED, new TimerWorker() );
}
-
/**
* Returns the {@link ProfilerTimerUnit} being used.
*
@@ -155,9 +138,9 @@
* @return
* An int representing the methods that will be logged
*/
- public int getMethodsToLog()
+ public EnumSet<IoEventType> getEventsToProfile()
{
- return methodsToLog;
+ return eventsToProfile;
}
@@ -165,61 +148,12 @@
* Set the bitmask in order to tell this filter which
* methods to print out timing information
*
- * @param methodsToLog
+ * @param eventsToProfile
* An int representing the new methods that should be logged
*/
- public void setMethodsToLog( int methodsToLog )
+ public void setEventsToProfile( EnumSet<IoEventType> methodsToLog )
{
- this.methodsToLog = methodsToLog;
- }
-
-
- /**
- * Returns the level of logging that this filter is using
- *
- * @return
- * An int representing the level of logging
- */
- public int getLogLevel()
- {
- return logLevel;
- }
-
-
- /**
- * Sets the level of logging that this filter will use
- *
- * @param logLevel
- * An int representing the level of logging to use
- */
- public void setLogLevel( int logLevel )
- {
- this.logLevel = logLevel;
- }
-
-
- private void log( IoSession session, String message )
- {
- switch ( getLogLevel() )
- {
- case 1:
- SessionLog.error( session, message );
- return;
- case 2:
- case 3:
- case 4:
- case 5:
- SessionLog.warn( session, message );
- return;
- case 6:
- SessionLog.info( session, message );
- return;
- case 7:
- SessionLog.debug( session, message );
- return;
- default:
- SessionLog.debug( session, message );
- }
+ this.eventsToProfile = methodsToLog;
}
@@ -230,8 +164,8 @@
nextFilter.messageReceived( session, message );
long end = timeUnit.timeNow();
- if ( ( getMethodsToLog() & MSG_RCV ) > 0 )
- log( session, "Message received time : " + ( end - start ) + " " + timeUnit.getDescription() );
+ if ( getEventsToProfile().contains( IoEventType.MESSAGE_RECEIVED ) )
+ timerManager.get( IoEventType.MESSAGE_RECEIVED ).addNewReading( end-start );
}
@@ -242,8 +176,8 @@
nextFilter.messageSent( session, writeRequest );
long end = timeUnit.timeNow();
- if ( ( getMethodsToLog() & MSG_SND ) > 0 )
- log( session, "Message sent time : " + ( end - start ) + " " + timeUnit.getDescription() );
+ if ( getEventsToProfile().contains( IoEventType.MESSAGE_SENT ) )
+ timerManager.get( IoEventType.MESSAGE_SENT ).addNewReading( end-start );
}
@@ -254,8 +188,8 @@
nextFilter.sessionClosed( session );
long end = timeUnit.timeNow();
- if ( ( getMethodsToLog() & SES_CLS ) > 0 )
- log( session, "Session closed time : " + ( end - start ) + " " + timeUnit.getDescription() );
+ if ( getEventsToProfile().contains( IoEventType.SESSION_CLOSED ) )
+ timerManager.get( IoEventType.SESSION_CLOSED ).addNewReading( end-start );
}
@@ -266,8 +200,8 @@
nextFilter.sessionCreated( session );
long end = timeUnit.timeNow();
- if ( ( getMethodsToLog() & SES_CRT ) > 0 )
- log( session, "Session created time : " + ( end - start ) + " " + timeUnit.getDescription() );
+ if ( getEventsToProfile().contains( IoEventType.SESSION_CREATED ) )
+ timerManager.get( IoEventType.SESSION_CREATED ).addNewReading( end-start );
}
@@ -278,8 +212,8 @@
nextFilter.sessionIdle( session, status );
long end = timeUnit.timeNow();
- if ( ( getMethodsToLog() & SES_IDL ) > 0 )
- log( session, "Session idle time : " + ( end - start ) + " " + timeUnit.getDescription() );
+ if ( getEventsToProfile().contains( IoEventType.SESSION_IDLE ) )
+ timerManager.get( IoEventType.SESSION_IDLE ).addNewReading( end-start );
}
@@ -290,7 +224,235 @@
nextFilter.sessionOpened( session );
long end = timeUnit.timeNow();
- if ( ( getMethodsToLog() & SES_OPN ) > 0 )
- log( session, "Session opened time : " + ( end - start ) + " " + timeUnit.getDescription() );
+ if ( getEventsToProfile().contains( IoEventType.SESSION_OPENED ) )
+ timerManager.get( IoEventType.SESSION_OPENED ).addNewReading( end-start );
+ }
+
+ /**
+ * 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 ){
+ return timerManager.get( type ).getAverage();
+ }
+
+ /**
+ * 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 ){
+ return timerManager.get( type ).getCalls();
+ }
+
+ /**
+ * 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 ){
+ return timerManager.get( type ).getTotal();
+ }
+
+ /**
+ * 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 getMinValue( IoEventType type ){
+ return timerManager.get( type ).getMin();
+ }
+
+ /**
+ * 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 getMaxValue( IoEventType type ){
+ return timerManager.get( type ).getMax();
+ }
+
+ /**
+ * Class that will track the time each method takes and be able to provide information
+ * for each method.
+ *
+ */
+ class TimerWorker {
+
+ private AtomicLong total;
+ private AtomicLong calls;
+ private AtomicLong min;
+ private AtomicLong max;
+ private Object lock = new Object();
+
+ /**
+ * Creates a new instance of TimerWorker.
+ *
+ */
+ public TimerWorker(){
+ total = new AtomicLong();
+ calls = new AtomicLong();
+ min = new AtomicLong();
+ max = new AtomicLong();
+ }
+
+ /**
+ * Add a new reading to this class. Total is updated
+ * and calls is incremented
+ *
+ * @param newReading
+ * The new reading
+ */
+ public void addNewReading( long newReading ){
+ calls.incrementAndGet();
+ total.addAndGet( newReading );
+
+ synchronized( lock ){
+ // this is not entirely thread-safe, must lock
+ if( newReading < min.longValue() ){
+ min.set( newReading );
+ }
+
+ // this is not entirely thread-safe, must lock
+ if( newReading > max.longValue() ){
+ max.set( newReading );
+ }
+ }
+ }
+
+ /**
+ * Gets the average reading for this event
+ *
+ * @return
+ * Gets the average reading for this event
+ */
+ public double getAverage(){
+ return total.longValue() / calls.longValue();
+ }
+
+ /**
+ * Returns the total number of readings
+ *
+ * @return
+ * total number of readings
+ */
+ public long getCalls(){
+ return calls.longValue();
+ }
+
+ /**
+ * Returns the total time
+ *
+ * @return
+ * the total time
+ */
+ public long getTotal(){
+ return total.longValue();
+ }
+
+ /**
+ * Returns the minimum value
+ *
+ * @return
+ * the minimum value
+ */
+ public long getMin(){
+ return min.longValue();
+ }
+
+ /**
+ * Returns the maximum value
+ *
+ * @return
+ * the maximum value
+ */
+ public long getMax(){
+ return max.longValue();
+ }
+ }
+
+ enum ProfilerTimerUnit
+ {
+ SECONDS
+ {
+ public long timeNow()
+ {
+ return System.currentTimeMillis() / 1000;
+ }
+
+
+ public String getDescription()
+ {
+ return "seconds";
+ }
+ },
+ MILLISECONDS
+ {
+ public long timeNow()
+ {
+ return System.currentTimeMillis();
+ }
+
+
+ public String getDescription()
+ {
+ return "milliseconds";
+ }
+ },
+ NANOSECONDS
+ {
+ public long timeNow()
+ {
+ return System.nanoTime();
+ }
+
+
+ public String getDescription()
+ {
+ return "nanoseconds";
+ }
+ };
+
+ /*
+ * I was looking at possibly using the java.util.concurrent.TimeUnit
+ * and I found this construct for writing enums. Here is what the
+ * JDK developers say for why these methods below cannot be marked as
+ * abstract, but should act in an abstract way...
+ *
+ * To maintain full signature compatibility with 1.5, and to improve the
+ * clarity of the generated javadoc (see 6287639: Abstract methods in
+ * enum classes should not be listed as abstract), method convert
+ * etc. are not declared abstract but otherwise act as abstract methods.
+ */
+ public long timeNow()
+ {
+ throw new AbstractMethodError();
+ }
+
+
+ public String getDescription()
+ {
+ throw new AbstractMethodError();
+ }
}
}