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.HashSet;
23 import java.util.Set;
24 import java.util.concurrent.TimeUnit;
25 import java.util.concurrent.atomic.AtomicLong;
26
27 import org.apache.mina.core.filterchain.IoFilterAdapter;
28 import org.apache.mina.core.session.IdleStatus;
29 import org.apache.mina.core.session.IoEventType;
30 import org.apache.mina.core.session.IoSession;
31 import org.apache.mina.core.write.WriteRequest;
32
33 /**
34 * This class will measure the time it takes for a
35 * method in the {@link IoFilterAdapter} class to execute. The basic
36 * premise of the logic in this class is to get the current time
37 * at the beginning of the method, call method on nextFilter, and
38 * then get the current time again. An example of how to use
39 * the filter is:
40 *
41 * <pre>
42 * ProfilerTimerFilter profiler = new ProfilerTimerFilter(
43 * TimeUnit.MILLISECOND, IoEventType.MESSAGE_RECEIVED);
44 * chain.addFirst("Profiler", profiler);
45 * </pre>
46 *
47 * The profiled {@link IoEventType} are :
48 * <ul>
49 * <li>IoEventType.MESSAGE_RECEIVED</li>
50 * <li>IoEventType.MESSAGE_SENT</li>
51 * <li>IoEventType.SESSION_CREATED</li>
52 * <li>IoEventType.SESSION_OPENED</li>
53 * <li>IoEventType.SESSION_IDLE</li>
54 * <li>IoEventType.SESSION_CLOSED</li>
55 * </ul>
56 *
57 * @author <a href="http://mina.apache.org">Apache MINA Project</a>
58 * @org.apache.xbean.XBean
59 */
60 public class ProfilerTimerFilter extends IoFilterAdapter {
61 /** TRhe selected time unit */
62 private volatile TimeUnit timeUnit;
63
64 /** A TimerWorker for the MessageReceived events */
65 private TimerWorker messageReceivedTimerWorker;
66
67 /** A flag to tell the filter that the MessageReceived must be profiled */
68 private boolean profileMessageReceived = false;
69
70 /** A TimerWorker for the MessageSent events */
71 private TimerWorker messageSentTimerWorker;
72
73 /** A flag to tell the filter that the MessageSent must be profiled */
74 private boolean profileMessageSent = false;
75
76 /** A TimerWorker for the SessionCreated events */
77 private TimerWorker sessionCreatedTimerWorker;
78
79 /** A flag to tell the filter that the SessionCreated must be profiled */
80 private boolean profileSessionCreated = false;
81
82 /** A TimerWorker for the SessionOpened events */
83 private TimerWorker sessionOpenedTimerWorker;
84
85 /** A flag to tell the filter that the SessionOpened must be profiled */
86 private boolean profileSessionOpened = false;
87
88 /** A TimerWorker for the SessionIdle events */
89 private TimerWorker sessionIdleTimerWorker;
90
91 /** A flag to tell the filter that the SessionIdle must be profiled */
92 private boolean profileSessionIdle = false;
93
94 /** A TimerWorker for the SessionClosed events */
95 private TimerWorker sessionClosedTimerWorker;
96
97 /** A flag to tell the filter that the SessionClosed must be profiled */
98 private boolean profileSessionClosed = false;
99
100 /**
101 * Creates a new instance of ProfilerFilter. This is the
102 * default constructor and will print out timings for
103 * messageReceived and messageSent and the time increment
104 * will be in milliseconds.
105 */
106 public ProfilerTimerFilter() {
107 this(TimeUnit.MILLISECONDS, IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT);
108 }
109
110 /**
111 * Creates a new instance of ProfilerFilter. This is the
112 * default constructor and will print out timings for
113 * messageReceived and messageSent.
114 *
115 * @param timeUnit the time increment to set
116 */
117 public ProfilerTimerFilter(TimeUnit timeUnit) {
118 this(timeUnit, IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT);
119 }
120
121 /**
122 * Creates a new instance of ProfilerFilter. An example
123 * of this call would be:
124 *
125 * <pre>
126 * new ProfilerTimerFilter(
127 * TimeUnit.MILLISECONDS,
128 * IoEventType.MESSAGE_RECEIVED, IoEventType.MESSAGE_SENT);
129 * </pre>
130 *
131 * Note : you can add as many {@link IoEventType} as you want. The method accepts
132 * a variable number of arguments.
133 *
134 * @param timeUnit Used to determine the level of precision you need in your timing.
135 * @param eventTypes A list of {@link IoEventType} representation of the methods to profile
136 */
137 public ProfilerTimerFilter(TimeUnit timeUnit, IoEventType... eventTypes) {
138 this.timeUnit = timeUnit;
139
140 setProfilers(eventTypes);
141 }
142
143 /**
144 * Create the profilers for a list of {@link IoEventType}.
145 *
146 * @param eventTypes the list of {@link IoEventType} to profile
147 */
148 private void setProfilers(IoEventType... eventTypes) {
149 for (IoEventType type : eventTypes) {
150 switch (type) {
151 case MESSAGE_RECEIVED:
152 messageReceivedTimerWorker = new TimerWorker();
153 profileMessageReceived = true;
154 break;
155
156 case MESSAGE_SENT:
157 messageSentTimerWorker = new TimerWorker();
158 profileMessageSent = true;
159 break;
160
161 case SESSION_CREATED:
162 sessionCreatedTimerWorker = new TimerWorker();
163 profileSessionCreated = true;
164 break;
165
166 case SESSION_OPENED:
167 sessionOpenedTimerWorker = new TimerWorker();
168 profileSessionOpened = true;
169 break;
170
171 case SESSION_IDLE:
172 sessionIdleTimerWorker = new TimerWorker();
173 profileSessionIdle = true;
174 break;
175
176 case SESSION_CLOSED:
177 sessionClosedTimerWorker = new TimerWorker();
178 profileSessionClosed = true;
179 break;
180 }
181 }
182 }
183
184 /**
185 * Sets the {@link TimeUnit} being used.
186 *
187 * @param timeUnit the new {@link TimeUnit} to be used.
188 */
189 public void setTimeUnit(TimeUnit timeUnit) {
190 this.timeUnit = timeUnit;
191 }
192
193 /**
194 * Set the {@link IoEventType} to be profiled
195 *
196 * @param type The {@link IoEventType} to profile
197 */
198 public void profile(IoEventType type) {
199 switch (type) {
200 case MESSAGE_RECEIVED:
201 profileMessageReceived = true;
202
203 if (messageReceivedTimerWorker == null) {
204 messageReceivedTimerWorker = new TimerWorker();
205 }
206
207 return;
208
209 case MESSAGE_SENT:
210 profileMessageSent = true;
211
212 if (messageSentTimerWorker == null) {
213 messageSentTimerWorker = new TimerWorker();
214 }
215
216 return;
217
218 case SESSION_CREATED:
219 profileSessionCreated = true;
220
221 if (sessionCreatedTimerWorker == null) {
222 sessionCreatedTimerWorker = new TimerWorker();
223 }
224
225 return;
226
227 case SESSION_OPENED:
228 profileSessionOpened = true;
229
230 if (sessionOpenedTimerWorker == null) {
231 sessionOpenedTimerWorker = new TimerWorker();
232 }
233
234 return;
235
236 case SESSION_IDLE:
237 profileSessionIdle = true;
238
239 if (sessionIdleTimerWorker == null) {
240 sessionIdleTimerWorker = new TimerWorker();
241 }
242
243 return;
244
245 case SESSION_CLOSED:
246 profileSessionClosed = true;
247
248 if (sessionClosedTimerWorker == null) {
249 sessionClosedTimerWorker = new TimerWorker();
250 }
251
252 return;
253 }
254 }
255
256 /**
257 * Stop profiling an {@link IoEventType}
258 *
259 * @param type The {@link IoEventType} to stop profiling
260 */
261 public void stopProfile(IoEventType type) {
262 switch (type) {
263 case MESSAGE_RECEIVED:
264 profileMessageReceived = false;
265 return;
266
267 case MESSAGE_SENT:
268 profileMessageSent = false;
269 return;
270
271 case SESSION_CREATED:
272 profileSessionCreated = false;
273 return;
274
275 case SESSION_OPENED:
276 profileSessionOpened = false;
277 return;
278
279 case SESSION_IDLE:
280 profileSessionIdle = false;
281 return;
282
283 case SESSION_CLOSED:
284 profileSessionClosed = false;
285 return;
286 }
287 }
288
289 /**
290 * Return the set of {@link IoEventType} which are profiled.
291 *
292 * @return a Set containing all the profiled {@link IoEventType}
293 */
294 public Set<IoEventType> getEventsToProfile() {
295 Set<IoEventType> set = new HashSet<IoEventType>();
296
297 if (profileMessageReceived) {
298 set.add(IoEventType.MESSAGE_RECEIVED);
299 }
300
301 if (profileMessageSent) {
302 set.add(IoEventType.MESSAGE_SENT);
303 }
304
305 if (profileSessionCreated) {
306 set.add(IoEventType.SESSION_CREATED);
307 }
308
309 if (profileSessionOpened) {
310 set.add(IoEventType.SESSION_OPENED);
311 }
312
313 if (profileSessionIdle) {
314 set.add(IoEventType.SESSION_IDLE);
315 }
316
317 if (profileSessionClosed) {
318 set.add(IoEventType.SESSION_CLOSED);
319 }
320
321 return set;
322 }
323
324 /**
325 * Set the profilers for a list of {@link IoEventType}
326 *
327 * @param eventTypes the list of {@link IoEventType} to profile
328 */
329 public void setEventsToProfile(IoEventType... eventTypes) {
330 setProfilers(eventTypes);
331 }
332
333 /**
334 * Profile a MessageReceived event. This method will gather the following
335 * informations :
336 * - the method duration
337 * - the shortest execution time
338 * - the slowest execution time
339 * - the average execution time
340 * - the global number of calls
341 *
342 * @param nextFilter The filter to call next
343 * @param session The associated session
344 * @param message the received message
345 */
346 @Override
347 public void messageReceived(NextFilter nextFilter, IoSession session, Object message) throws Exception {
348 if (profileMessageReceived) {
349 long start = timeNow();
350 nextFilter.messageReceived(session, message);
351 long end = timeNow();
352 messageReceivedTimerWorker.addNewDuration(end - start);
353 } else {
354 nextFilter.messageReceived(session, message);
355 }
356 }
357
358 /**
359 * Profile a MessageSent event. This method will gather the following
360 * informations :
361 * - the method duration
362 * - the shortest execution time
363 * - the slowest execution time
364 * - the average execution time
365 * - the global number of calls
366 *
367 * @param nextFilter The filter to call next
368 * @param session The associated session
369 * @param writeRequest the sent message
370 */
371 @Override
372 public void messageSent(NextFilter nextFilter, IoSession session, WriteRequest writeRequest) throws Exception {
373 if (profileMessageSent) {
374 long start = timeNow();
375 nextFilter.messageSent(session, writeRequest);
376 long end = timeNow();
377 messageSentTimerWorker.addNewDuration(end - start);
378 } else {
379 nextFilter.messageSent(session, writeRequest);
380 }
381 }
382
383 /**
384 * Profile a SessionCreated event. This method will gather the following
385 * informations :
386 * - the method duration
387 * - the shortest execution time
388 * - the slowest execution time
389 * - the average execution time
390 * - the global number of calls
391 *
392 * @param nextFilter The filter to call next
393 * @param session The associated session
394 */
395 @Override
396 public void sessionCreated(NextFilter nextFilter, IoSession session) throws Exception {
397 if (profileSessionCreated) {
398 long start = timeNow();
399 nextFilter.sessionCreated(session);
400 long end = timeNow();
401 sessionCreatedTimerWorker.addNewDuration(end - start);
402 } else {
403 nextFilter.sessionCreated(session);
404 }
405 }
406
407 /**
408 * Profile a SessionOpened event. This method will gather the following
409 * informations :
410 * - the method duration
411 * - the shortest execution time
412 * - the slowest execution time
413 * - the average execution time
414 * - the global number of calls
415 *
416 * @param nextFilter The filter to call next
417 * @param session The associated session
418 */
419 @Override
420 public void sessionOpened(NextFilter nextFilter, IoSession session) throws Exception {
421 if (profileSessionOpened) {
422 long start = timeNow();
423 nextFilter.sessionOpened(session);
424 long end = timeNow();
425 sessionOpenedTimerWorker.addNewDuration(end - start);
426 } else {
427 nextFilter.sessionOpened(session);
428 }
429 }
430
431 /**
432 * Profile a SessionIdle event. This method will gather the following
433 * informations :
434 * - the method duration
435 * - the shortest execution time
436 * - the slowest execution time
437 * - the average execution time
438 * - the global number of calls
439 *
440 * @param nextFilter The filter to call next
441 * @param session The associated session
442 * @param status The session's status
443 */
444 @Override
445 public void sessionIdle(NextFilter nextFilter, IoSession session, IdleStatus status) throws Exception {
446 if (profileSessionIdle) {
447 long start = timeNow();
448 nextFilter.sessionIdle(session, status);
449 long end = timeNow();
450 sessionIdleTimerWorker.addNewDuration(end - start);
451 } else {
452 nextFilter.sessionIdle(session, status);
453 }
454 }
455
456 /**
457 * Profile a SessionClosed event. This method will gather the following
458 * informations :
459 * - the method duration
460 * - the shortest execution time
461 * - the slowest execution time
462 * - the average execution time
463 * - the global number of calls
464 *
465 * @param nextFilter The filter to call next
466 * @param session The associated session
467 */
468 @Override
469 public void sessionClosed(NextFilter nextFilter, IoSession session) throws Exception {
470 if (profileSessionClosed) {
471 long start = timeNow();
472 nextFilter.sessionClosed(session);
473 long end = timeNow();
474 sessionClosedTimerWorker.addNewDuration(end - start);
475 } else {
476 nextFilter.sessionClosed(session);
477 }
478 }
479
480 /**
481 * Get the average time for the specified method represented by the {@link IoEventType}
482 *
483 * @param type
484 * The {@link IoEventType} that the user wants to get the average method call time
485 * @return
486 * The average time it took to execute the method represented by the {@link IoEventType}
487 */
488 public double getAverageTime(IoEventType type) {
489 switch (type) {
490 case MESSAGE_RECEIVED:
491 if (profileMessageReceived) {
492 return messageReceivedTimerWorker.getAverage();
493 }
494
495 break;
496
497 case MESSAGE_SENT:
498 if (profileMessageSent) {
499 return messageSentTimerWorker.getAverage();
500 }
501
502 break;
503
504 case SESSION_CREATED:
505 if (profileSessionCreated) {
506 return sessionCreatedTimerWorker.getAverage();
507 }
508
509 break;
510
511 case SESSION_OPENED:
512 if (profileSessionOpened) {
513 return sessionOpenedTimerWorker.getAverage();
514 }
515
516 break;
517
518 case SESSION_IDLE:
519 if (profileSessionIdle) {
520 return sessionIdleTimerWorker.getAverage();
521 }
522
523 break;
524
525 case SESSION_CLOSED:
526 if (profileSessionClosed) {
527 return sessionClosedTimerWorker.getAverage();
528 }
529
530 break;
531 }
532
533 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first.");
534 }
535
536 /**
537 * Gets the total number of times the method has been called that is represented by the
538 * {@link IoEventType}
539 *
540 * @param type
541 * The {@link IoEventType} that the user wants to get the total number of method calls
542 * @return
543 * The total number of method calls for the method represented by the {@link IoEventType}
544 */
545 public long getTotalCalls(IoEventType type) {
546 switch (type) {
547 case MESSAGE_RECEIVED:
548 if (profileMessageReceived) {
549 return messageReceivedTimerWorker.getCallsNumber();
550 }
551
552 break;
553
554 case MESSAGE_SENT:
555 if (profileMessageSent) {
556 return messageSentTimerWorker.getCallsNumber();
557 }
558
559 break;
560
561 case SESSION_CREATED:
562 if (profileSessionCreated) {
563 return sessionCreatedTimerWorker.getCallsNumber();
564 }
565
566 break;
567
568 case SESSION_OPENED:
569 if (profileSessionOpened) {
570 return sessionOpenedTimerWorker.getCallsNumber();
571 }
572
573 break;
574
575 case SESSION_IDLE:
576 if (profileSessionIdle) {
577 return sessionIdleTimerWorker.getCallsNumber();
578 }
579
580 break;
581
582 case SESSION_CLOSED:
583 if (profileSessionClosed) {
584 return sessionClosedTimerWorker.getCallsNumber();
585 }
586
587 break;
588 }
589
590 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first.");
591 }
592
593 /**
594 * The total time this method has been executing
595 *
596 * @param type
597 * The {@link IoEventType} that the user wants to get the total time this method has
598 * been executing
599 * @return
600 * The total time for the method represented by the {@link IoEventType}
601 */
602 public long getTotalTime(IoEventType type) {
603 switch (type) {
604 case MESSAGE_RECEIVED:
605 if (profileMessageReceived) {
606 return messageReceivedTimerWorker.getTotal();
607 }
608
609 break;
610
611 case MESSAGE_SENT:
612 if (profileMessageSent) {
613 return messageSentTimerWorker.getTotal();
614 }
615
616 break;
617
618 case SESSION_CREATED:
619 if (profileSessionCreated) {
620 return sessionCreatedTimerWorker.getTotal();
621 }
622
623 break;
624
625 case SESSION_OPENED:
626 if (profileSessionOpened) {
627 return sessionOpenedTimerWorker.getTotal();
628 }
629
630 break;
631
632 case SESSION_IDLE:
633 if (profileSessionIdle) {
634 return sessionIdleTimerWorker.getTotal();
635 }
636
637 break;
638
639 case SESSION_CLOSED:
640 if (profileSessionClosed) {
641 return sessionClosedTimerWorker.getTotal();
642 }
643
644 break;
645 }
646
647 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first.");
648 }
649
650 /**
651 * The minimum time the method represented by {@link IoEventType} has executed
652 *
653 * @param type
654 * The {@link IoEventType} that the user wants to get the minimum time this method has
655 * executed
656 * @return
657 * The minimum time this method has executed represented by the {@link IoEventType}
658 */
659 public long getMinimumTime(IoEventType type) {
660 switch (type) {
661 case MESSAGE_RECEIVED:
662 if (profileMessageReceived) {
663 return messageReceivedTimerWorker.getMinimum();
664 }
665
666 break;
667
668 case MESSAGE_SENT:
669 if (profileMessageSent) {
670 return messageSentTimerWorker.getMinimum();
671 }
672
673 break;
674
675 case SESSION_CREATED:
676 if (profileSessionCreated) {
677 return sessionCreatedTimerWorker.getMinimum();
678 }
679
680 break;
681
682 case SESSION_OPENED:
683 if (profileSessionOpened) {
684 return sessionOpenedTimerWorker.getMinimum();
685 }
686
687 break;
688
689 case SESSION_IDLE:
690 if (profileSessionIdle) {
691 return sessionIdleTimerWorker.getMinimum();
692 }
693
694 break;
695
696 case SESSION_CLOSED:
697 if (profileSessionClosed) {
698 return sessionClosedTimerWorker.getMinimum();
699 }
700
701 break;
702 }
703
704 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first.");
705 }
706
707 /**
708 * The maximum time the method represented by {@link IoEventType} has executed
709 *
710 * @param type
711 * The {@link IoEventType} that the user wants to get the maximum time this method has
712 * executed
713 * @return
714 * The maximum time this method has executed represented by the {@link IoEventType}
715 */
716 public long getMaximumTime(IoEventType type) {
717 switch (type) {
718 case MESSAGE_RECEIVED:
719 if (profileMessageReceived) {
720 return messageReceivedTimerWorker.getMaximum();
721 }
722
723 break;
724
725 case MESSAGE_SENT:
726 if (profileMessageSent) {
727 return messageSentTimerWorker.getMaximum();
728 }
729
730 break;
731
732 case SESSION_CREATED:
733 if (profileSessionCreated) {
734 return sessionCreatedTimerWorker.getMaximum();
735 }
736
737 break;
738
739 case SESSION_OPENED:
740 if (profileSessionOpened) {
741 return sessionOpenedTimerWorker.getMaximum();
742 }
743
744 break;
745
746 case SESSION_IDLE:
747 if (profileSessionIdle) {
748 return sessionIdleTimerWorker.getMaximum();
749 }
750
751 break;
752
753 case SESSION_CLOSED:
754 if (profileSessionClosed) {
755 return sessionClosedTimerWorker.getMaximum();
756 }
757
758 break;
759 }
760
761 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first.");
762 }
763
764 /**
765 * Class that will track the time each method takes and be able to provide information
766 * for each method.
767 *
768 */
769 private class TimerWorker {
770 /** The sum of all operation durations */
771 private final AtomicLong total;
772
773 /** The number of calls */
774 private final AtomicLong callsNumber;
775
776 /** The fastest operation */
777 private final AtomicLong minimum;
778
779 /** The slowest operation */
780 private final AtomicLong maximum;
781
782 /** A lock for synchinized blocks */
783 private final Object lock = new Object();
784
785 /**
786 * Creates a new instance of TimerWorker.
787 *
788 */
789 public TimerWorker() {
790 total = new AtomicLong();
791 callsNumber = new AtomicLong();
792 minimum = new AtomicLong();
793 maximum = new AtomicLong();
794 }
795
796 /**
797 * Add a new operation duration to this class. Total is updated
798 * and calls is incremented
799 *
800 * @param duration
801 * The new operation duration
802 */
803 public void addNewDuration(long duration) {
804 callsNumber.incrementAndGet();
805 total.addAndGet(duration);
806
807 synchronized (lock) {
808 // this is not entirely thread-safe, must lock
809 if (duration < minimum.longValue()) {
810 minimum.set(duration);
811 }
812
813 // this is not entirely thread-safe, must lock
814 if (duration > maximum.longValue()) {
815 maximum.set(duration);
816 }
817 }
818 }
819
820 /**
821 * Gets the average reading for this event
822 *
823 * @return the average reading for this event
824 */
825 public double getAverage() {
826 synchronized (lock) {
827 // There are two operations, we need to synchronize the block
828 return total.longValue() / callsNumber.longValue();
829 }
830 }
831
832 /**
833 * Returns the total number of profiled operations
834 *
835 * @return The total number of profiled operation
836 */
837 public long getCallsNumber() {
838 return callsNumber.longValue();
839 }
840
841 /**
842 * Returns the total time
843 *
844 * @return the total time
845 */
846 public long getTotal() {
847 return total.longValue();
848 }
849
850 /**
851 * Returns the lowest execution time
852 *
853 * @return the lowest execution time
854 */
855 public long getMinimum() {
856 return minimum.longValue();
857 }
858
859 /**
860 * Returns the longest execution time
861 *
862 * @return the longest execution time
863 */
864 public long getMaximum() {
865 return maximum.longValue();
866 }
867 }
868
869 /**
870 * @return the current time, expressed using the fixed TimeUnit.
871 */
872 private long timeNow() {
873 switch (timeUnit) {
874 case SECONDS:
875 return System.currentTimeMillis() / 1000;
876
877 case MICROSECONDS:
878 return System.nanoTime() / 1000;
879
880 case NANOSECONDS:
881 return System.nanoTime();
882
883 default:
884 return System.currentTimeMillis();
885 }
886 }
887 }