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 */ 020package org.apache.mina.filter.statistic; 021 022import java.util.HashSet; 023import java.util.Set; 024import java.util.concurrent.TimeUnit; 025import java.util.concurrent.atomic.AtomicLong; 026 027import org.apache.mina.core.filterchain.IoFilterAdapter; 028import org.apache.mina.core.session.IdleStatus; 029import org.apache.mina.core.session.IoEventType; 030import org.apache.mina.core.session.IoSession; 031import org.apache.mina.core.write.WriteRequest; 032 033/** 034 * This class will measure the time it takes for a 035 * method in the {@link IoFilterAdapter} class to execute. The basic 036 * premise of the logic in this class is to get the current time 037 * at the beginning of the method, call method on nextFilter, and 038 * then get the current time again. An example of how to use 039 * the filter is: 040 * 041 * <pre> 042 * ProfilerTimerFilter profiler = new ProfilerTimerFilter( 043 * TimeUnit.MILLISECOND, IoEventType.MESSAGE_RECEIVED); 044 * chain.addFirst("Profiler", profiler); 045 * </pre> 046 * 047 * The profiled {@link IoEventType} are : 048 * <ul> 049 * <li>IoEventType.MESSAGE_RECEIVED</li> 050 * <li>IoEventType.MESSAGE_SENT</li> 051 * <li>IoEventType.SESSION_CREATED</li> 052 * <li>IoEventType.SESSION_OPENED</li> 053 * <li>IoEventType.SESSION_IDLE</li> 054 * <li>IoEventType.SESSION_CLOSED</li> 055 * </ul> 056 * 057 * @author <a href="http://mina.apache.org">Apache MINA Project</a> 058 * @org.apache.xbean.XBean 059 */ 060public class ProfilerTimerFilter extends IoFilterAdapter { 061 /** TRhe selected time unit */ 062 private volatile TimeUnit timeUnit; 063 064 /** A TimerWorker for the MessageReceived events */ 065 private TimerWorker messageReceivedTimerWorker; 066 067 /** A flag to tell the filter that the MessageReceived must be profiled */ 068 private boolean profileMessageReceived = false; 069 070 /** A TimerWorker for the MessageSent events */ 071 private TimerWorker messageSentTimerWorker; 072 073 /** A flag to tell the filter that the MessageSent must be profiled */ 074 private boolean profileMessageSent = false; 075 076 /** A TimerWorker for the SessionCreated events */ 077 private TimerWorker sessionCreatedTimerWorker; 078 079 /** A flag to tell the filter that the SessionCreated must be profiled */ 080 private boolean profileSessionCreated = false; 081 082 /** A TimerWorker for the SessionOpened events */ 083 private TimerWorker sessionOpenedTimerWorker; 084 085 /** A flag to tell the filter that the SessionOpened must be profiled */ 086 private boolean profileSessionOpened = false; 087 088 /** A TimerWorker for the SessionIdle events */ 089 private TimerWorker sessionIdleTimerWorker; 090 091 /** A flag to tell the filter that the SessionIdle must be profiled */ 092 private boolean profileSessionIdle = false; 093 094 /** A TimerWorker for the SessionClosed events */ 095 private TimerWorker sessionClosedTimerWorker; 096 097 /** A flag to tell the filter that the SessionClosed must be profiled */ 098 private boolean profileSessionClosed = false; 099 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 default : 182 break; 183 } 184 } 185 } 186 187 /** 188 * Sets the {@link TimeUnit} being used. 189 * 190 * @param timeUnit the new {@link TimeUnit} to be used. 191 */ 192 public void setTimeUnit(TimeUnit timeUnit) { 193 this.timeUnit = timeUnit; 194 } 195 196 /** 197 * Set the {@link IoEventType} to be profiled 198 * 199 * @param type The {@link IoEventType} to profile 200 */ 201 public void profile(IoEventType type) { 202 switch (type) { 203 case MESSAGE_RECEIVED: 204 profileMessageReceived = true; 205 206 if (messageReceivedTimerWorker == null) { 207 messageReceivedTimerWorker = new TimerWorker(); 208 } 209 210 return; 211 212 case MESSAGE_SENT: 213 profileMessageSent = true; 214 215 if (messageSentTimerWorker == null) { 216 messageSentTimerWorker = new TimerWorker(); 217 } 218 219 return; 220 221 case SESSION_CREATED: 222 profileSessionCreated = true; 223 224 if (sessionCreatedTimerWorker == null) { 225 sessionCreatedTimerWorker = new TimerWorker(); 226 } 227 228 return; 229 230 case SESSION_OPENED: 231 profileSessionOpened = true; 232 233 if (sessionOpenedTimerWorker == null) { 234 sessionOpenedTimerWorker = new TimerWorker(); 235 } 236 237 return; 238 239 case SESSION_IDLE: 240 profileSessionIdle = true; 241 242 if (sessionIdleTimerWorker == null) { 243 sessionIdleTimerWorker = new TimerWorker(); 244 } 245 246 return; 247 248 case SESSION_CLOSED: 249 profileSessionClosed = true; 250 251 if (sessionClosedTimerWorker == null) { 252 sessionClosedTimerWorker = new TimerWorker(); 253 } 254 255 return; 256 257 default: 258 break; 259 } 260 } 261 262 /** 263 * Stop profiling an {@link IoEventType} 264 * 265 * @param type The {@link IoEventType} to stop profiling 266 */ 267 public void stopProfile(IoEventType type) { 268 switch (type) { 269 case MESSAGE_RECEIVED: 270 profileMessageReceived = false; 271 return; 272 273 case MESSAGE_SENT: 274 profileMessageSent = false; 275 return; 276 277 case SESSION_CREATED: 278 profileSessionCreated = false; 279 return; 280 281 case SESSION_OPENED: 282 profileSessionOpened = false; 283 return; 284 285 case SESSION_IDLE: 286 profileSessionIdle = false; 287 return; 288 289 case SESSION_CLOSED: 290 profileSessionClosed = false; 291 return; 292 293 default: 294 return; 295 } 296 } 297 298 /** 299 * Return the set of {@link IoEventType} which are profiled. 300 * 301 * @return a Set containing all the profiled {@link IoEventType} 302 */ 303 public Set<IoEventType> getEventsToProfile() { 304 Set<IoEventType> set = new HashSet<IoEventType>(); 305 306 if (profileMessageReceived) { 307 set.add(IoEventType.MESSAGE_RECEIVED); 308 } 309 310 if (profileMessageSent) { 311 set.add(IoEventType.MESSAGE_SENT); 312 } 313 314 if (profileSessionCreated) { 315 set.add(IoEventType.SESSION_CREATED); 316 } 317 318 if (profileSessionOpened) { 319 set.add(IoEventType.SESSION_OPENED); 320 } 321 322 if (profileSessionIdle) { 323 set.add(IoEventType.SESSION_IDLE); 324 } 325 326 if (profileSessionClosed) { 327 set.add(IoEventType.SESSION_CLOSED); 328 } 329 330 return set; 331 } 332 333 /** 334 * Set the profilers for a list of {@link IoEventType} 335 * 336 * @param eventTypes the list of {@link IoEventType} to profile 337 */ 338 public void setEventsToProfile(IoEventType... eventTypes) { 339 setProfilers(eventTypes); 340 } 341 342 /** 343 * Profile a MessageReceived event. This method will gather the following 344 * informations : 345 * - the method duration 346 * - the shortest execution time 347 * - the slowest execution time 348 * - the average execution time 349 * - the global number of calls 350 * 351 * @param nextFilter The filter to call next 352 * @param session The associated session 353 * @param message the received message 354 */ 355 @Override 356 public void messageReceived(NextFilter nextFilter, IoSession session, Object message) throws Exception { 357 if (profileMessageReceived) { 358 long start = timeNow(); 359 nextFilter.messageReceived(session, message); 360 long end = timeNow(); 361 messageReceivedTimerWorker.addNewDuration(end - start); 362 } else { 363 nextFilter.messageReceived(session, message); 364 } 365 } 366 367 /** 368 * Profile a MessageSent event. This method will gather the following 369 * informations : 370 * - the method duration 371 * - the shortest execution time 372 * - the slowest execution time 373 * - the average execution time 374 * - the global number of calls 375 * 376 * @param nextFilter The filter to call next 377 * @param session The associated session 378 * @param writeRequest the sent message 379 */ 380 @Override 381 public void messageSent(NextFilter nextFilter, IoSession session, WriteRequest writeRequest) throws Exception { 382 if (profileMessageSent) { 383 long start = timeNow(); 384 nextFilter.messageSent(session, writeRequest); 385 long end = timeNow(); 386 messageSentTimerWorker.addNewDuration(end - start); 387 } else { 388 nextFilter.messageSent(session, writeRequest); 389 } 390 } 391 392 /** 393 * Profile a SessionCreated event. This method will gather the following 394 * informations : 395 * - the method duration 396 * - the shortest execution time 397 * - the slowest execution time 398 * - the average execution time 399 * - the global number of calls 400 * 401 * @param nextFilter The filter to call next 402 * @param session The associated session 403 */ 404 @Override 405 public void sessionCreated(NextFilter nextFilter, IoSession session) throws Exception { 406 if (profileSessionCreated) { 407 long start = timeNow(); 408 nextFilter.sessionCreated(session); 409 long end = timeNow(); 410 sessionCreatedTimerWorker.addNewDuration(end - start); 411 } else { 412 nextFilter.sessionCreated(session); 413 } 414 } 415 416 /** 417 * Profile a SessionOpened event. This method will gather the following 418 * informations : 419 * - the method duration 420 * - the shortest execution time 421 * - the slowest execution time 422 * - the average execution time 423 * - the global number of calls 424 * 425 * @param nextFilter The filter to call next 426 * @param session The associated session 427 */ 428 @Override 429 public void sessionOpened(NextFilter nextFilter, IoSession session) throws Exception { 430 if (profileSessionOpened) { 431 long start = timeNow(); 432 nextFilter.sessionOpened(session); 433 long end = timeNow(); 434 sessionOpenedTimerWorker.addNewDuration(end - start); 435 } else { 436 nextFilter.sessionOpened(session); 437 } 438 } 439 440 /** 441 * Profile a SessionIdle event. This method will gather the following 442 * informations : 443 * - the method duration 444 * - the shortest execution time 445 * - the slowest execution time 446 * - the average execution time 447 * - the global number of calls 448 * 449 * @param nextFilter The filter to call next 450 * @param session The associated session 451 * @param status The session's status 452 */ 453 @Override 454 public void sessionIdle(NextFilter nextFilter, IoSession session, IdleStatus status) throws Exception { 455 if (profileSessionIdle) { 456 long start = timeNow(); 457 nextFilter.sessionIdle(session, status); 458 long end = timeNow(); 459 sessionIdleTimerWorker.addNewDuration(end - start); 460 } else { 461 nextFilter.sessionIdle(session, status); 462 } 463 } 464 465 /** 466 * Profile a SessionClosed event. This method will gather the following 467 * informations : 468 * - the method duration 469 * - the shortest execution time 470 * - the slowest execution time 471 * - the average execution time 472 * - the global number of calls 473 * 474 * @param nextFilter The filter to call next 475 * @param session The associated session 476 */ 477 @Override 478 public void sessionClosed(NextFilter nextFilter, IoSession session) throws Exception { 479 if (profileSessionClosed) { 480 long start = timeNow(); 481 nextFilter.sessionClosed(session); 482 long end = timeNow(); 483 sessionClosedTimerWorker.addNewDuration(end - start); 484 } else { 485 nextFilter.sessionClosed(session); 486 } 487 } 488 489 /** 490 * Get the average time for the specified method represented by the {@link IoEventType} 491 * 492 * @param type 493 * The {@link IoEventType} that the user wants to get the average method call time 494 * @return 495 * The average time it took to execute the method represented by the {@link IoEventType} 496 */ 497 public double getAverageTime(IoEventType type) { 498 switch (type) { 499 case MESSAGE_RECEIVED: 500 if (profileMessageReceived) { 501 return messageReceivedTimerWorker.getAverage(); 502 } 503 504 break; 505 506 case MESSAGE_SENT: 507 if (profileMessageSent) { 508 return messageSentTimerWorker.getAverage(); 509 } 510 511 break; 512 513 case SESSION_CREATED: 514 if (profileSessionCreated) { 515 return sessionCreatedTimerWorker.getAverage(); 516 } 517 518 break; 519 520 case SESSION_OPENED: 521 if (profileSessionOpened) { 522 return sessionOpenedTimerWorker.getAverage(); 523 } 524 525 break; 526 527 case SESSION_IDLE: 528 if (profileSessionIdle) { 529 return sessionIdleTimerWorker.getAverage(); 530 } 531 532 break; 533 534 case SESSION_CLOSED: 535 if (profileSessionClosed) { 536 return sessionClosedTimerWorker.getAverage(); 537 } 538 539 break; 540 541 default: 542 break; 543 } 544 545 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first."); 546 } 547 548 /** 549 * Gets the total number of times the method has been called that is represented by the 550 * {@link IoEventType} 551 * 552 * @param type 553 * The {@link IoEventType} that the user wants to get the total number of method calls 554 * @return 555 * The total number of method calls for the method represented by the {@link IoEventType} 556 */ 557 public long getTotalCalls(IoEventType type) { 558 switch (type) { 559 case MESSAGE_RECEIVED: 560 if (profileMessageReceived) { 561 return messageReceivedTimerWorker.getCallsNumber(); 562 } 563 564 break; 565 566 case MESSAGE_SENT: 567 if (profileMessageSent) { 568 return messageSentTimerWorker.getCallsNumber(); 569 } 570 571 break; 572 573 case SESSION_CREATED: 574 if (profileSessionCreated) { 575 return sessionCreatedTimerWorker.getCallsNumber(); 576 } 577 578 break; 579 580 case SESSION_OPENED: 581 if (profileSessionOpened) { 582 return sessionOpenedTimerWorker.getCallsNumber(); 583 } 584 585 break; 586 587 case SESSION_IDLE: 588 if (profileSessionIdle) { 589 return sessionIdleTimerWorker.getCallsNumber(); 590 } 591 592 break; 593 594 case SESSION_CLOSED: 595 if (profileSessionClosed) { 596 return sessionClosedTimerWorker.getCallsNumber(); 597 } 598 599 break; 600 601 default: 602 break; 603 } 604 605 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first."); 606 } 607 608 /** 609 * The total time this method has been executing 610 * 611 * @param type 612 * The {@link IoEventType} that the user wants to get the total time this method has 613 * been executing 614 * @return 615 * The total time for the method represented by the {@link IoEventType} 616 */ 617 public long getTotalTime(IoEventType type) { 618 switch (type) { 619 case MESSAGE_RECEIVED: 620 if (profileMessageReceived) { 621 return messageReceivedTimerWorker.getTotal(); 622 } 623 624 break; 625 626 case MESSAGE_SENT: 627 if (profileMessageSent) { 628 return messageSentTimerWorker.getTotal(); 629 } 630 631 break; 632 633 case SESSION_CREATED: 634 if (profileSessionCreated) { 635 return sessionCreatedTimerWorker.getTotal(); 636 } 637 638 break; 639 640 case SESSION_OPENED: 641 if (profileSessionOpened) { 642 return sessionOpenedTimerWorker.getTotal(); 643 } 644 645 break; 646 647 case SESSION_IDLE: 648 if (profileSessionIdle) { 649 return sessionIdleTimerWorker.getTotal(); 650 } 651 652 break; 653 654 case SESSION_CLOSED: 655 if (profileSessionClosed) { 656 return sessionClosedTimerWorker.getTotal(); 657 } 658 659 break; 660 661 default: 662 break; 663 } 664 665 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first."); 666 } 667 668 /** 669 * The minimum time the method represented by {@link IoEventType} has executed 670 * 671 * @param type 672 * The {@link IoEventType} that the user wants to get the minimum time this method has 673 * executed 674 * @return 675 * The minimum time this method has executed represented by the {@link IoEventType} 676 */ 677 public long getMinimumTime(IoEventType type) { 678 switch (type) { 679 case MESSAGE_RECEIVED: 680 if (profileMessageReceived) { 681 return messageReceivedTimerWorker.getMinimum(); 682 } 683 684 break; 685 686 case MESSAGE_SENT: 687 if (profileMessageSent) { 688 return messageSentTimerWorker.getMinimum(); 689 } 690 691 break; 692 693 case SESSION_CREATED: 694 if (profileSessionCreated) { 695 return sessionCreatedTimerWorker.getMinimum(); 696 } 697 698 break; 699 700 case SESSION_OPENED: 701 if (profileSessionOpened) { 702 return sessionOpenedTimerWorker.getMinimum(); 703 } 704 705 break; 706 707 case SESSION_IDLE: 708 if (profileSessionIdle) { 709 return sessionIdleTimerWorker.getMinimum(); 710 } 711 712 break; 713 714 case SESSION_CLOSED: 715 if (profileSessionClosed) { 716 return sessionClosedTimerWorker.getMinimum(); 717 } 718 719 break; 720 721 default: 722 break; 723 } 724 725 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first."); 726 } 727 728 /** 729 * The maximum time the method represented by {@link IoEventType} has executed 730 * 731 * @param type 732 * The {@link IoEventType} that the user wants to get the maximum time this method has 733 * executed 734 * @return 735 * The maximum time this method has executed represented by the {@link IoEventType} 736 */ 737 public long getMaximumTime(IoEventType type) { 738 switch (type) { 739 case MESSAGE_RECEIVED: 740 if (profileMessageReceived) { 741 return messageReceivedTimerWorker.getMaximum(); 742 } 743 744 break; 745 746 case MESSAGE_SENT: 747 if (profileMessageSent) { 748 return messageSentTimerWorker.getMaximum(); 749 } 750 751 break; 752 753 case SESSION_CREATED: 754 if (profileSessionCreated) { 755 return sessionCreatedTimerWorker.getMaximum(); 756 } 757 758 break; 759 760 case SESSION_OPENED: 761 if (profileSessionOpened) { 762 return sessionOpenedTimerWorker.getMaximum(); 763 } 764 765 break; 766 767 case SESSION_IDLE: 768 if (profileSessionIdle) { 769 return sessionIdleTimerWorker.getMaximum(); 770 } 771 772 break; 773 774 case SESSION_CLOSED: 775 if (profileSessionClosed) { 776 return sessionClosedTimerWorker.getMaximum(); 777 } 778 779 break; 780 781 default: 782 break; 783 } 784 785 throw new IllegalArgumentException("You are not monitoring this event. Please add this event first."); 786 } 787 788 /** 789 * Class that will track the time each method takes and be able to provide information 790 * for each method. 791 * 792 */ 793 private class TimerWorker { 794 /** The sum of all operation durations */ 795 private final AtomicLong total; 796 797 /** The number of calls */ 798 private final AtomicLong callsNumber; 799 800 /** The fastest operation */ 801 private final AtomicLong minimum; 802 803 /** The slowest operation */ 804 private final AtomicLong maximum; 805 806 /** A lock for synchinized blocks */ 807 private final Object lock = new Object(); 808 809 /** 810 * Creates a new instance of TimerWorker. 811 * 812 */ 813 public TimerWorker() { 814 total = new AtomicLong(); 815 callsNumber = new AtomicLong(); 816 minimum = new AtomicLong(); 817 maximum = new AtomicLong(); 818 } 819 820 /** 821 * Add a new operation duration to this class. Total is updated 822 * and calls is incremented 823 * 824 * @param duration 825 * The new operation duration 826 */ 827 public void addNewDuration(long duration) { 828 callsNumber.incrementAndGet(); 829 total.addAndGet(duration); 830 831 synchronized (lock) { 832 // this is not entirely thread-safe, must lock 833 if (duration < minimum.longValue()) { 834 minimum.set(duration); 835 } 836 837 // this is not entirely thread-safe, must lock 838 if (duration > maximum.longValue()) { 839 maximum.set(duration); 840 } 841 } 842 } 843 844 /** 845 * Gets the average reading for this event 846 * 847 * @return the average reading for this event 848 */ 849 public double getAverage() { 850 synchronized (lock) { 851 // There are two operations, we need to synchronize the block 852 return total.longValue() / callsNumber.longValue(); 853 } 854 } 855 856 /** 857 * @return The total number of profiled operation 858 */ 859 public long getCallsNumber() { 860 return callsNumber.longValue(); 861 } 862 863 /** 864 * @return the total time 865 */ 866 public long getTotal() { 867 return total.longValue(); 868 } 869 870 /** 871 * @return the lowest execution time 872 */ 873 public long getMinimum() { 874 return minimum.longValue(); 875 } 876 877 /** 878 * @return the longest execution time 879 */ 880 public long getMaximum() { 881 return maximum.longValue(); 882 } 883 } 884 885 /** 886 * @return the current time, expressed using the fixed TimeUnit. 887 */ 888 private long timeNow() { 889 switch (timeUnit) { 890 case SECONDS: 891 return System.currentTimeMillis() / 1000; 892 893 case MICROSECONDS: 894 return System.nanoTime() / 1000; 895 896 case NANOSECONDS: 897 return System.nanoTime(); 898 899 default: 900 return System.currentTimeMillis(); 901 } 902 } 903}