001: /*
002: * Licensed to the Apache Software Foundation (ASF) under one
003: * or more contributor license agreements. See the NOTICE file
004: * distributed with this work for additional information
005: * regarding copyright ownership. The ASF licenses this file
006: * to you under the Apache License, Version 2.0 (the
007: * "License"); you may not use this file except in compliance
008: * with the License. You may obtain a copy of the License at
009: *
010: * http://www.apache.org/licenses/LICENSE-2.0
011: *
012: * Unless required by applicable law or agreed to in writing,
013: * software distributed under the License is distributed on an
014: * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
015: * KIND, either express or implied. See the License for the
016: * specific language governing permissions and limitations
017: * under the License.
018: *
019: */
020: package org.apache.mina.filter.statistic;
021:
022: import java.util.Collections;
023: import java.util.EnumSet;
024: import java.util.Map;
025: import java.util.Set;
026: import java.util.concurrent.TimeUnit;
027: import java.util.concurrent.atomic.AtomicLong;
028:
029: import org.apache.mina.common.IdleStatus;
030: import org.apache.mina.common.IoEventType;
031: import org.apache.mina.common.IoFilterAdapter;
032: import org.apache.mina.common.IoSession;
033: import org.apache.mina.common.WriteRequest;
034: import org.apache.mina.util.CopyOnWriteMap;
035:
036: /**
037: * This class will measure, the time it takes for a
038: * method in the {@link IoFilterAdapter} class to execute. The basic
039: * premise of the logic in this class is to get the current time
040: * at the beginning of the method, call method on nextFilter, and
041: * then get the current time again. An example of how to use
042: * the filter is:
043: *
044: * <pre>
045: * ProfilerTimerFilter profiler = new ProfilerTimerFilter(
046: * TimeUnit.MILLISECOND, IoEventType.MESSAGE_RECEIVED);
047: * chain.addFirst("Profiler", profiler);
048: * </pre>
049: *
050: * @author The Apache MINA Project (dev@mina.apache.org)
051: * @version $Rev: 597988 $, $Date: 2007-11-25 07:02:29 -0700 (Sun, 25 Nov 2007) $
052: */
053: public class ProfilerTimerFilter extends IoFilterAdapter {
054:
055: private volatile EnumSet<IoEventType> eventsToProfile;
056: private volatile ProfilerTimerUnit timeUnit;
057: private final Map<IoEventType, TimerWorker> timerManager;
058:
059: /**
060: * Creates a new instance of ProfilerFilter. This is the
061: * default constructor and will print out timings for
062: * messageReceived and messageSent and the time increment
063: * will be in milliseconds.
064: */
065: public ProfilerTimerFilter() {
066: this (TimeUnit.MILLISECONDS, EnumSet.of(
067: IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT));
068: }
069:
070: /**
071: * Creates a new instance of ProfilerFilter. This is the
072: * default constructor and will print out timings for
073: * messageReceived and messageSent and the time increment
074: * will be in milliseconds.
075: */
076: public ProfilerTimerFilter(TimeUnit unit) {
077: this (unit, IoEventType.MESSAGE_RECEIVED,
078: IoEventType.MESSAGE_SENT);
079: }
080:
081: /**
082: * Creates a new instance of ProfilerFilter. An example
083: * of this call would be:
084: *
085: * <pre>
086: * new ProfilerTimerFilter(
087: * TimeUnit.MILLISECONDS,
088: * IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT);
089: * </pre>
090: * @param unit
091: * Used to determine the level of precision you need in your timing.
092: * @param firstEventType an event type to profile
093: * @param otherEventTypes event types to profile
094: */
095: public ProfilerTimerFilter(TimeUnit unit,
096: IoEventType firstEventType, IoEventType... otherEventTypes) {
097: this (unit, EnumSet.of(firstEventType, otherEventTypes));
098: }
099:
100: /**
101: * Creates a new instance of ProfilerFilter. An example
102: * of this call would be:
103: *
104: * <pre>
105: * new ProfilerTimerFilter(
106: * TimeUnit.MILLISECONDS,
107: * EnumSet.of(IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT));
108: * </pre>
109: * @param unit
110: * Used to determine the level of precision you need in your timing.
111: * @param eventTypes
112: * A set of {@link IoEventType} representation of the methods to profile
113: */
114: public ProfilerTimerFilter(TimeUnit unit,
115: EnumSet<IoEventType> eventTypes) {
116: setTimeUnit(unit);
117: setEventsToProfile(eventTypes);
118:
119: timerManager = new CopyOnWriteMap<IoEventType, TimerWorker>();
120: for (IoEventType type : eventsToProfile) {
121: timerManager.put(type, new TimerWorker());
122: }
123: }
124:
125: /**
126: * Sets the {@link TimeUnit} being used.
127: *
128: * @param unit the new {@link TimeUnit} to be used.
129: */
130: public void setTimeUnit(TimeUnit unit) {
131: if (unit == TimeUnit.MILLISECONDS) {
132: this .timeUnit = ProfilerTimerUnit.MILLISECONDS;
133: } else if (unit == TimeUnit.NANOSECONDS) {
134: this .timeUnit = ProfilerTimerUnit.NANOSECONDS;
135: } else if (unit == TimeUnit.SECONDS) {
136: this .timeUnit = ProfilerTimerUnit.SECONDS;
137: } else {
138: throw new IllegalArgumentException(
139: "Invalid Time specified: " + unit + " (expected: "
140: + TimeUnit.MILLISECONDS + ", "
141: + TimeUnit.NANOSECONDS + " or "
142: + TimeUnit.SECONDS + ')');
143: }
144: }
145:
146: /**
147: * Add an {@link IoEventType} to profile
148: *
149: * @param type
150: * The {@link IoEventType} to profile
151: */
152: public void addEventToProfile(IoEventType type) {
153: if (!timerManager.containsKey(type)) {
154: timerManager.put(type, new TimerWorker());
155: }
156: }
157:
158: /**
159: * Remove an {@link IoEventType} to profile
160: *
161: * @param type
162: * The {@link IoEventType} to profile
163: */
164: public void removeEventToProfile(IoEventType type) {
165: timerManager.remove(type);
166: }
167:
168: /**
169: * Return the bitmask that is being used to display
170: * timing information for this filter.
171: *
172: * @return
173: * An int representing the methods that will be logged
174: */
175: public Set<IoEventType> getEventsToProfile() {
176: return Collections.unmodifiableSet(eventsToProfile);
177: }
178:
179: /**
180: * Set the bitmask in order to tell this filter which
181: * methods to print out timing information
182: */
183: public void setEventsToProfile(IoEventType firstEventType,
184: IoEventType... otherEventTypes) {
185: this .setEventsToProfile(EnumSet.of(firstEventType,
186: otherEventTypes));
187: }
188:
189: /**
190: * Set the bitmask in order to tell this filter which
191: * methods to print out timing information
192: *
193: * @param eventTypes
194: * An int representing the new methods that should be logged
195: */
196: public void setEventsToProfile(Set<IoEventType> eventTypes) {
197: if (eventTypes == null) {
198: throw new NullPointerException("eventTypes");
199: }
200: if (eventTypes.isEmpty()) {
201: throw new IllegalArgumentException("eventTypes is empty.");
202: }
203:
204: EnumSet<IoEventType> newEventsToProfile = EnumSet
205: .noneOf(IoEventType.class);
206: for (IoEventType e : eventTypes) {
207: newEventsToProfile.add(e);
208: }
209:
210: this .eventsToProfile = newEventsToProfile;
211: }
212:
213: @Override
214: public void messageReceived(NextFilter nextFilter,
215: IoSession session, Object message) throws Exception {
216: long start = timeUnit.timeNow();
217: nextFilter.messageReceived(session, message);
218: long end = timeUnit.timeNow();
219:
220: if (getEventsToProfile().contains(IoEventType.MESSAGE_RECEIVED)) {
221: timerManager.get(IoEventType.MESSAGE_RECEIVED)
222: .addNewReading(end - start);
223: }
224: }
225:
226: @Override
227: public void messageSent(NextFilter nextFilter, IoSession session,
228: WriteRequest writeRequest) throws Exception {
229: long start = timeUnit.timeNow();
230: nextFilter.messageSent(session, writeRequest);
231: long end = timeUnit.timeNow();
232:
233: if (getEventsToProfile().contains(IoEventType.MESSAGE_SENT)) {
234: timerManager.get(IoEventType.MESSAGE_SENT).addNewReading(
235: end - start);
236: }
237: }
238:
239: @Override
240: public void sessionClosed(NextFilter nextFilter, IoSession session)
241: throws Exception {
242: long start = timeUnit.timeNow();
243: nextFilter.sessionClosed(session);
244: long end = timeUnit.timeNow();
245:
246: if (getEventsToProfile().contains(IoEventType.SESSION_CLOSED)) {
247: timerManager.get(IoEventType.SESSION_CLOSED).addNewReading(
248: end - start);
249: }
250: }
251:
252: @Override
253: public void sessionCreated(NextFilter nextFilter, IoSession session)
254: throws Exception {
255: long start = timeUnit.timeNow();
256: nextFilter.sessionCreated(session);
257: long end = timeUnit.timeNow();
258:
259: if (getEventsToProfile().contains(IoEventType.SESSION_CREATED)) {
260: timerManager.get(IoEventType.SESSION_CREATED)
261: .addNewReading(end - start);
262: }
263: }
264:
265: @Override
266: public void sessionIdle(NextFilter nextFilter, IoSession session,
267: IdleStatus status) throws Exception {
268: long start = timeUnit.timeNow();
269: nextFilter.sessionIdle(session, status);
270: long end = timeUnit.timeNow();
271:
272: if (getEventsToProfile().contains(IoEventType.SESSION_IDLE)) {
273: timerManager.get(IoEventType.SESSION_IDLE).addNewReading(
274: end - start);
275: }
276: }
277:
278: @Override
279: public void sessionOpened(NextFilter nextFilter, IoSession session)
280: throws Exception {
281: long start = timeUnit.timeNow();
282: nextFilter.sessionOpened(session);
283: long end = timeUnit.timeNow();
284:
285: if (getEventsToProfile().contains(IoEventType.SESSION_OPENED)) {
286: timerManager.get(IoEventType.SESSION_OPENED).addNewReading(
287: end - start);
288: }
289: }
290:
291: /**
292: * Get the average time for the specified method represented by the {@link IoEventType}
293: *
294: * @param type
295: * The {@link IoEventType} that the user wants to get the average method call time
296: * @return
297: * The average time it took to execute the method represented by the {@link IoEventType}
298: */
299: public double getAverageTime(IoEventType type) {
300: if (!timerManager.containsKey(type)) {
301: throw new IllegalArgumentException(
302: "You are not monitoring this event. Please add this event first.");
303: }
304:
305: return timerManager.get(type).getAverage();
306: }
307:
308: /**
309: * Gets the total number of times the method has been called that is represented by the
310: * {@link IoEventType}
311: *
312: * @param type
313: * The {@link IoEventType} that the user wants to get the total number of method calls
314: * @return
315: * The total number of method calls for the method represented by the {@link IoEventType}
316: */
317: public long getTotalCalls(IoEventType type) {
318: if (!timerManager.containsKey(type)) {
319: throw new IllegalArgumentException(
320: "You are not monitoring this event. Please add this event first.");
321: }
322:
323: return timerManager.get(type).getCalls();
324: }
325:
326: /**
327: * The total time this method has been executing
328: *
329: * @param type
330: * The {@link IoEventType} that the user wants to get the total time this method has
331: * been executing
332: * @return
333: * The total time for the method represented by the {@link IoEventType}
334: */
335: public long getTotalTime(IoEventType type) {
336: if (!timerManager.containsKey(type)) {
337: throw new IllegalArgumentException(
338: "You are not monitoring this event. Please add this event first.");
339: }
340:
341: return timerManager.get(type).getTotal();
342: }
343:
344: /**
345: * The minimum time the method represented by {@link IoEventType} has executed
346: *
347: * @param type
348: * The {@link IoEventType} that the user wants to get the minimum time this method has
349: * executed
350: * @return
351: * The minimum time this method has executed represented by the {@link IoEventType}
352: */
353: public long getMinimumTime(IoEventType type) {
354: if (!timerManager.containsKey(type)) {
355: throw new IllegalArgumentException(
356: "You are not monitoring this event. Please add this event first.");
357: }
358:
359: return timerManager.get(type).getMinimum();
360: }
361:
362: /**
363: * The maximum time the method represented by {@link IoEventType} has executed
364: *
365: * @param type
366: * The {@link IoEventType} that the user wants to get the maximum time this method has
367: * executed
368: * @return
369: * The maximum time this method has executed represented by the {@link IoEventType}
370: */
371: public long getMaximumTime(IoEventType type) {
372: if (!timerManager.containsKey(type)) {
373: throw new IllegalArgumentException(
374: "You are not monitoring this event. Please add this event first.");
375: }
376:
377: return timerManager.get(type).getMaximum();
378: }
379:
380: /**
381: * Class that will track the time each method takes and be able to provide information
382: * for each method.
383: *
384: */
385: private class TimerWorker {
386:
387: private final AtomicLong total;
388: private final AtomicLong calls;
389: private final AtomicLong minimum;
390: private final AtomicLong maximum;
391: private final Object lock = new Object();
392:
393: /**
394: * Creates a new instance of TimerWorker.
395: *
396: */
397: public TimerWorker() {
398: total = new AtomicLong();
399: calls = new AtomicLong();
400: minimum = new AtomicLong();
401: maximum = new AtomicLong();
402: }
403:
404: /**
405: * Add a new reading to this class. Total is updated
406: * and calls is incremented
407: *
408: * @param newReading
409: * The new reading
410: */
411: public void addNewReading(long newReading) {
412: calls.incrementAndGet();
413: total.addAndGet(newReading);
414:
415: synchronized (lock) {
416: // this is not entirely thread-safe, must lock
417: if (newReading < minimum.longValue()) {
418: minimum.set(newReading);
419: }
420:
421: // this is not entirely thread-safe, must lock
422: if (newReading > maximum.longValue()) {
423: maximum.set(newReading);
424: }
425: }
426: }
427:
428: /**
429: * Gets the average reading for this event
430: *
431: * @return
432: * Gets the average reading for this event
433: */
434: public double getAverage() {
435: return total.longValue() / calls.longValue();
436: }
437:
438: /**
439: * Returns the total number of readings
440: *
441: * @return
442: * total number of readings
443: */
444: public long getCalls() {
445: return calls.longValue();
446: }
447:
448: /**
449: * Returns the total time
450: *
451: * @return
452: * the total time
453: */
454: public long getTotal() {
455: return total.longValue();
456: }
457:
458: /**
459: * Returns the minimum value
460: *
461: * @return
462: * the minimum value
463: */
464: public long getMinimum() {
465: return minimum.longValue();
466: }
467:
468: /**
469: * Returns the maximum value
470: *
471: * @return
472: * the maximum value
473: */
474: public long getMaximum() {
475: return maximum.longValue();
476: }
477: }
478:
479: private enum ProfilerTimerUnit {
480: SECONDS {
481: @Override
482: public long timeNow() {
483: return System.currentTimeMillis() / 1000;
484: }
485:
486: @Override
487: public String getDescription() {
488: return "seconds";
489: }
490: },
491: MILLISECONDS {
492: @Override
493: public long timeNow() {
494: return System.currentTimeMillis();
495: }
496:
497: @Override
498: public String getDescription() {
499: return "milliseconds";
500: }
501: },
502: NANOSECONDS {
503: @Override
504: public long timeNow() {
505: return System.nanoTime();
506: }
507:
508: @Override
509: public String getDescription() {
510: return "nanoseconds";
511: }
512: };
513:
514: /*
515: * I was looking at possibly using the java.util.concurrent.TimeUnit
516: * and I found this construct for writing enums. Here is what the
517: * JDK developers say for why these methods below cannot be marked as
518: * abstract, but should act in an abstract way...
519: *
520: * To maintain full signature compatibility with 1.5, and to improve the
521: * clarity of the generated javadoc (see 6287639: Abstract methods in
522: * enum classes should not be listed as abstract), method convert
523: * etc. are not declared abstract but otherwise act as abstract methods.
524: */
525: public long timeNow() {
526: throw new AbstractMethodError();
527: }
528:
529: public String getDescription() {
530: throw new AbstractMethodError();
531: }
532: }
533: }
|