ProfilerTimerFilter discussion
Skip to end of metadata
Go to start of metadata

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();

    	}

    }

}


Labels
  • No labels