1 /*
2 * Licensed to the Apache Software Foundation (ASF) under one
3 * or more contributor license agreements. See the NOTICE file
4 * distributed with this work for additional information
5 * regarding copyright ownership. The ASF licenses this file
6 * to you under the Apache License, Version 2.0 (the
7 * "License"); you may not use this file except in compliance
8 * with the License. You may obtain a copy of the License at
9 *
10 * http://www.apache.org/licenses/LICENSE-2.0
11 *
12 * Unless required by applicable law or agreed to in writing,
13 * software distributed under the License is distributed on an
14 * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
15 * KIND, either express or implied. See the License for the
16 * specific language governing permissions and limitations
17 * under the License.
18 *
19 */
20 package org.apache.mina.filter.statistic;
21
22 import java.util.Collections;
23 import java.util.EnumSet;
24 import java.util.Map;
25 import java.util.Set;
26 import java.util.concurrent.TimeUnit;
27 import java.util.concurrent.atomic.AtomicLong;
28
29 import org.apache.mina.core.filterchain.IoFilterAdapter;
30 import org.apache.mina.core.session.IdleStatus;
31 import org.apache.mina.core.session.IoEventType;
32 import org.apache.mina.core.session.IoSession;
33 import org.apache.mina.core.write.WriteRequest;
34 import org.apache.mina.util.CopyOnWriteMap;
35
36 /**
37 * This class will measure, the time it takes for a
38 * method in the {@link IoFilterAdapter} class to execute. The basic
39 * premise of the logic in this class is to get the current time
40 * at the beginning of the method, call method on nextFilter, and
41 * then get the current time again. An example of how to use
42 * the filter is:
43 *
44 * <pre>
45 * ProfilerTimerFilter profiler = new ProfilerTimerFilter(
46 * TimeUnit.MILLISECOND, IoEventType.MESSAGE_RECEIVED);
47 * chain.addFirst("Profiler", profiler);
48 * </pre>
49 *
50 * @author The Apache MINA Project (dev@mina.apache.org)
51 * @version $Rev: 671827 $, $Date: 2008-06-26 10:49:48 +0200 (jeu, 26 jun 2008) $
52 */
53 public class ProfilerTimerFilter extends IoFilterAdapter {
54
55 private volatile EnumSet<IoEventType> eventsToProfile;
56 private volatile ProfilerTimerUnit timeUnit;
57 private final Map<IoEventType, TimerWorker> timerManager;
58
59 /**
60 * Creates a new instance of ProfilerFilter. This is the
61 * default constructor and will print out timings for
62 * messageReceived and messageSent and the time increment
63 * will be in milliseconds.
64 */
65 public ProfilerTimerFilter() {
66 this(
67 TimeUnit.MILLISECONDS, EnumSet.of(IoEventType.MESSAGE_RECEIVED,
68 IoEventType.MESSAGE_SENT));
69 }
70
71 /**
72 * Creates a new instance of ProfilerFilter. This is the
73 * default constructor and will print out timings for
74 * messageReceived and messageSent and the time increment
75 * will be in milliseconds.
76 */
77 public ProfilerTimerFilter(TimeUnit unit) {
78 this(
79 unit,
80 IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT);
81 }
82
83 /**
84 * Creates a new instance of ProfilerFilter. An example
85 * of this call would be:
86 *
87 * <pre>
88 * new ProfilerTimerFilter(
89 * TimeUnit.MILLISECONDS,
90 * IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT);
91 * </pre>
92 * @param unit
93 * Used to determine the level of precision you need in your timing.
94 * @param firstEventType an event type to profile
95 * @param otherEventTypes event types to profile
96 */
97 public ProfilerTimerFilter(TimeUnit unit, IoEventType firstEventType, IoEventType... otherEventTypes) {
98 this(unit, EnumSet.of(firstEventType, otherEventTypes));
99 }
100
101
102 /**
103 * Creates a new instance of ProfilerFilter. An example
104 * of this call would be:
105 *
106 * <pre>
107 * new ProfilerTimerFilter(
108 * TimeUnit.MILLISECONDS,
109 * EnumSet.of(IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT));
110 * </pre>
111 * @param unit
112 * Used to determine the level of precision you need in your timing.
113 * @param eventTypes
114 * A set of {@link IoEventType} representation of the methods to profile
115 */
116 public ProfilerTimerFilter(TimeUnit unit, EnumSet<IoEventType> eventTypes) {
117 setTimeUnit(unit);
118 setEventsToProfile(eventTypes);
119
120 timerManager = new CopyOnWriteMap<IoEventType, TimerWorker>();
121 for (IoEventType type : eventsToProfile) {
122 timerManager.put(type, new TimerWorker());
123 }
124 }
125
126 /**
127 * Sets the {@link TimeUnit} being used.
128 *
129 * @param unit the new {@link TimeUnit} to be used.
130 */
131 public void setTimeUnit(TimeUnit unit) {
132 if (unit == TimeUnit.MILLISECONDS) {
133 this.timeUnit = ProfilerTimerUnit.MILLISECONDS;
134 } else if (unit == TimeUnit.NANOSECONDS) {
135 this.timeUnit = ProfilerTimerUnit.NANOSECONDS;
136 } else if (unit == TimeUnit.SECONDS) {
137 this.timeUnit = ProfilerTimerUnit.SECONDS;
138 } else {
139 throw new IllegalArgumentException(
140 "Invalid Time specified: " + unit + " (expected: " +
141 TimeUnit.MILLISECONDS + ", " +
142 TimeUnit.NANOSECONDS + " or " +
143 TimeUnit.SECONDS + ')');
144 }
145 }
146
147 /**
148 * Add an {@link IoEventType} to profile
149 *
150 * @param type
151 * The {@link IoEventType} to profile
152 */
153 public void addEventToProfile(IoEventType type) {
154 if (!timerManager.containsKey(type)) {
155 timerManager.put(type, new TimerWorker());
156 }
157 }
158
159 /**
160 * Remove an {@link IoEventType} to profile
161 *
162 * @param type
163 * The {@link IoEventType} to profile
164 */
165 public void removeEventToProfile(IoEventType type) {
166 timerManager.remove(type);
167 }
168
169 /**
170 * Return the bitmask that is being used to display
171 * timing information for this filter.
172 *
173 * @return
174 * An int representing the methods that will be logged
175 */
176 public Set<IoEventType> getEventsToProfile() {
177 return Collections.unmodifiableSet(eventsToProfile);
178 }
179
180 /**
181 * Set the bitmask in order to tell this filter which
182 * methods to print out timing information
183 */
184 public void setEventsToProfile(IoEventType firstEventType, IoEventType... otherEventTypes) {
185 this.setEventsToProfile(EnumSet.of(firstEventType, otherEventTypes));
186 }
187
188 /**
189 * Set the bitmask in order to tell this filter which
190 * methods to print out timing information
191 *
192 * @param eventTypes
193 * An int representing the new methods that should be logged
194 */
195 public void setEventsToProfile(Set<IoEventType> eventTypes) {
196 if (eventTypes == null) {
197 throw new NullPointerException("eventTypes");
198 }
199 if (eventTypes.isEmpty()) {
200 throw new IllegalArgumentException("eventTypes is empty.");
201 }
202
203 EnumSet<IoEventType> newEventsToProfile = EnumSet.noneOf(IoEventType.class);
204 for (IoEventType e: eventTypes) {
205 newEventsToProfile.add(e);
206 }
207
208 this.eventsToProfile = newEventsToProfile;
209 }
210
211 @Override
212 public void messageReceived(NextFilter nextFilter, IoSession session,
213 Object message) throws Exception {
214 long start = timeUnit.timeNow();
215 nextFilter.messageReceived(session, message);
216 long end = timeUnit.timeNow();
217
218 if (getEventsToProfile().contains(IoEventType.MESSAGE_RECEIVED)) {
219 timerManager.get(IoEventType.MESSAGE_RECEIVED).addNewReading(
220 end - start);
221 }
222 }
223
224 @Override
225 public void messageSent(NextFilter nextFilter, IoSession session,
226 WriteRequest writeRequest) throws Exception {
227 long start = timeUnit.timeNow();
228 nextFilter.messageSent(session, writeRequest);
229 long end = timeUnit.timeNow();
230
231 if (getEventsToProfile().contains(IoEventType.MESSAGE_SENT)) {
232 timerManager.get(IoEventType.MESSAGE_SENT).addNewReading(
233 end - start);
234 }
235 }
236
237 @Override
238 public void sessionClosed(NextFilter nextFilter, IoSession session)
239 throws Exception {
240 long start = timeUnit.timeNow();
241 nextFilter.sessionClosed(session);
242 long end = timeUnit.timeNow();
243
244 if (getEventsToProfile().contains(IoEventType.SESSION_CLOSED)) {
245 timerManager.get(IoEventType.SESSION_CLOSED).addNewReading(
246 end - start);
247 }
248 }
249
250 @Override
251 public void sessionCreated(NextFilter nextFilter, IoSession session)
252 throws Exception {
253 long start = timeUnit.timeNow();
254 nextFilter.sessionCreated(session);
255 long end = timeUnit.timeNow();
256
257 if (getEventsToProfile().contains(IoEventType.SESSION_CREATED)) {
258 timerManager.get(IoEventType.SESSION_CREATED).addNewReading(
259 end - start);
260 }
261 }
262
263 @Override
264 public void sessionIdle(NextFilter nextFilter, IoSession session,
265 IdleStatus status) throws Exception {
266 long start = timeUnit.timeNow();
267 nextFilter.sessionIdle(session, status);
268 long end = timeUnit.timeNow();
269
270 if (getEventsToProfile().contains(IoEventType.SESSION_IDLE)) {
271 timerManager.get(IoEventType.SESSION_IDLE).addNewReading(
272 end - start);
273 }
274 }
275
276 @Override
277 public void sessionOpened(NextFilter nextFilter, IoSession session)
278 throws Exception {
279 long start = timeUnit.timeNow();
280 nextFilter.sessionOpened(session);
281 long end = timeUnit.timeNow();
282
283 if (getEventsToProfile().contains(IoEventType.SESSION_OPENED)) {
284 timerManager.get(IoEventType.SESSION_OPENED).addNewReading(
285 end - start);
286 }
287 }
288
289 /**
290 * Get the average time for the specified method represented by the {@link IoEventType}
291 *
292 * @param type
293 * The {@link IoEventType} that the user wants to get the average method call time
294 * @return
295 * The average time it took to execute the method represented by the {@link IoEventType}
296 */
297 public double getAverageTime(IoEventType type) {
298 if (!timerManager.containsKey(type)) {
299 throw new IllegalArgumentException(
300 "You are not monitoring this event. Please add this event first.");
301 }
302
303 return timerManager.get(type).getAverage();
304 }
305
306 /**
307 * Gets the total number of times the method has been called that is represented by the
308 * {@link IoEventType}
309 *
310 * @param type
311 * The {@link IoEventType} that the user wants to get the total number of method calls
312 * @return
313 * The total number of method calls for the method represented by the {@link IoEventType}
314 */
315 public long getTotalCalls(IoEventType type) {
316 if (!timerManager.containsKey(type)) {
317 throw new IllegalArgumentException(
318 "You are not monitoring this event. Please add this event first.");
319 }
320
321 return timerManager.get(type).getCalls();
322 }
323
324 /**
325 * The total time this method has been executing
326 *
327 * @param type
328 * The {@link IoEventType} that the user wants to get the total time this method has
329 * been executing
330 * @return
331 * The total time for the method represented by the {@link IoEventType}
332 */
333 public long getTotalTime(IoEventType type) {
334 if (!timerManager.containsKey(type)) {
335 throw new IllegalArgumentException(
336 "You are not monitoring this event. Please add this event first.");
337 }
338
339 return timerManager.get(type).getTotal();
340 }
341
342 /**
343 * The minimum time the method represented by {@link IoEventType} has executed
344 *
345 * @param type
346 * The {@link IoEventType} that the user wants to get the minimum time this method has
347 * executed
348 * @return
349 * The minimum time this method has executed represented by the {@link IoEventType}
350 */
351 public long getMinimumTime(IoEventType type) {
352 if (!timerManager.containsKey(type)) {
353 throw new IllegalArgumentException(
354 "You are not monitoring this event. Please add this event first.");
355 }
356
357 return timerManager.get(type).getMinimum();
358 }
359
360 /**
361 * The maximum time the method represented by {@link IoEventType} has executed
362 *
363 * @param type
364 * The {@link IoEventType} that the user wants to get the maximum time this method has
365 * executed
366 * @return
367 * The maximum time this method has executed represented by the {@link IoEventType}
368 */
369 public long getMaximumTime(IoEventType type) {
370 if (!timerManager.containsKey(type)) {
371 throw new IllegalArgumentException(
372 "You are not monitoring this event. Please add this event first.");
373 }
374
375 return timerManager.get(type).getMaximum();
376 }
377
378 /**
379 * Class that will track the time each method takes and be able to provide information
380 * for each method.
381 *
382 */
383 private class TimerWorker {
384
385 private final AtomicLong total;
386 private final AtomicLong calls;
387 private final AtomicLong minimum;
388 private final AtomicLong maximum;
389 private final Object lock = new Object();
390
391 /**
392 * Creates a new instance of TimerWorker.
393 *
394 */
395 public TimerWorker() {
396 total = new AtomicLong();
397 calls = new AtomicLong();
398 minimum = new AtomicLong();
399 maximum = new AtomicLong();
400 }
401
402 /**
403 * Add a new reading to this class. Total is updated
404 * and calls is incremented
405 *
406 * @param newReading
407 * The new reading
408 */
409 public void addNewReading(long newReading) {
410 calls.incrementAndGet();
411 total.addAndGet(newReading);
412
413 synchronized (lock) {
414 // this is not entirely thread-safe, must lock
415 if (newReading < minimum.longValue()) {
416 minimum.set(newReading);
417 }
418
419 // this is not entirely thread-safe, must lock
420 if (newReading > maximum.longValue()) {
421 maximum.set(newReading);
422 }
423 }
424 }
425
426 /**
427 * Gets the average reading for this event
428 *
429 * @return
430 * Gets the average reading for this event
431 */
432 public double getAverage() {
433 return total.longValue() / calls.longValue();
434 }
435
436 /**
437 * Returns the total number of readings
438 *
439 * @return
440 * total number of readings
441 */
442 public long getCalls() {
443 return calls.longValue();
444 }
445
446 /**
447 * Returns the total time
448 *
449 * @return
450 * the total time
451 */
452 public long getTotal() {
453 return total.longValue();
454 }
455
456 /**
457 * Returns the minimum value
458 *
459 * @return
460 * the minimum value
461 */
462 public long getMinimum() {
463 return minimum.longValue();
464 }
465
466 /**
467 * Returns the maximum value
468 *
469 * @return
470 * the maximum value
471 */
472 public long getMaximum() {
473 return maximum.longValue();
474 }
475 }
476
477 private enum ProfilerTimerUnit {
478 SECONDS {
479 @Override
480 public long timeNow() {
481 return System.currentTimeMillis() / 1000;
482 }
483
484 @Override
485 public String getDescription() {
486 return "seconds";
487 }
488 },
489 MILLISECONDS {
490 @Override
491 public long timeNow() {
492 return System.currentTimeMillis();
493 }
494
495 @Override
496 public String getDescription() {
497 return "milliseconds";
498 }
499 },
500 NANOSECONDS {
501 @Override
502 public long timeNow() {
503 return System.nanoTime();
504 }
505
506 @Override
507 public String getDescription() {
508 return "nanoseconds";
509 }
510 };
511
512 /*
513 * I was looking at possibly using the java.util.concurrent.TimeUnit
514 * and I found this construct for writing enums. Here is what the
515 * JDK developers say for why these methods below cannot be marked as
516 * abstract, but should act in an abstract way...
517 *
518 * To maintain full signature compatibility with 1.5, and to improve the
519 * clarity of the generated javadoc (see 6287639: Abstract methods in
520 * enum classes should not be listed as abstract), method convert
521 * etc. are not declared abstract but otherwise act as abstract methods.
522 */
523 public long timeNow() {
524 throw new AbstractMethodError();
525 }
526
527 public String getDescription() {
528 throw new AbstractMethodError();
529 }
530 }
531 }