001 /* 002 * Copyright 2009-2015 UnboundID Corp. 003 * All Rights Reserved. 004 */ 005 /* 006 * Copyright (C) 2015 UnboundID Corp. 007 * 008 * This program is free software; you can redistribute it and/or modify 009 * it under the terms of the GNU General Public License (GPLv2 only) 010 * or the terms of the GNU Lesser General Public License (LGPLv2.1 only) 011 * as published by the Free Software Foundation. 012 * 013 * This program is distributed in the hope that it will be useful, 014 * but WITHOUT ANY WARRANTY; without even the implied warranty of 015 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 016 * GNU General Public License for more details. 017 * 018 * You should have received a copy of the GNU General Public License 019 * along with this program; if not, see <http://www.gnu.org/licenses>. 020 */ 021 package com.unboundid.ldap.sdk.unboundidds.examples; 022 023 024 025 import java.io.File; 026 import java.io.FileInputStream; 027 import java.io.InputStreamReader; 028 import java.io.IOException; 029 import java.io.OutputStream; 030 import java.io.Serializable; 031 import java.text.DecimalFormat; 032 import java.util.ArrayList; 033 import java.util.HashMap; 034 import java.util.HashSet; 035 import java.util.Iterator; 036 import java.util.LinkedHashMap; 037 import java.util.List; 038 import java.util.Map; 039 import java.util.TreeMap; 040 import java.util.concurrent.atomic.AtomicLong; 041 import java.util.zip.GZIPInputStream; 042 043 import com.unboundid.ldap.sdk.Filter; 044 import com.unboundid.ldap.sdk.ResultCode; 045 import com.unboundid.ldap.sdk.SearchScope; 046 import com.unboundid.ldap.sdk.Version; 047 import com.unboundid.ldap.sdk.unboundidds.logs.AbandonRequestAccessLogMessage; 048 import com.unboundid.ldap.sdk.unboundidds.logs.AccessLogMessage; 049 import com.unboundid.ldap.sdk.unboundidds.logs.AccessLogReader; 050 import com.unboundid.ldap.sdk.unboundidds.logs.AddResultAccessLogMessage; 051 import com.unboundid.ldap.sdk.unboundidds.logs.BindResultAccessLogMessage; 052 import com.unboundid.ldap.sdk.unboundidds.logs.CompareResultAccessLogMessage; 053 import com.unboundid.ldap.sdk.unboundidds.logs.ConnectAccessLogMessage; 054 import com.unboundid.ldap.sdk.unboundidds.logs.DeleteResultAccessLogMessage; 055 import com.unboundid.ldap.sdk.unboundidds.logs.DisconnectAccessLogMessage; 056 import com.unboundid.ldap.sdk.unboundidds.logs.ExtendedRequestAccessLogMessage; 057 import com.unboundid.ldap.sdk.unboundidds.logs.ExtendedResultAccessLogMessage; 058 import com.unboundid.ldap.sdk.unboundidds.logs.LogException; 059 import com.unboundid.ldap.sdk.unboundidds.logs.ModifyDNResultAccessLogMessage; 060 import com.unboundid.ldap.sdk.unboundidds.logs.ModifyResultAccessLogMessage; 061 import com.unboundid.ldap.sdk.unboundidds.logs.OperationAccessLogMessage; 062 import com.unboundid.ldap.sdk.unboundidds.logs.SearchRequestAccessLogMessage; 063 import com.unboundid.ldap.sdk.unboundidds.logs.SearchResultAccessLogMessage; 064 import com.unboundid.ldap.sdk.unboundidds.logs.UnbindRequestAccessLogMessage; 065 import com.unboundid.util.CommandLineTool; 066 import com.unboundid.util.NotMutable; 067 import com.unboundid.util.ObjectPair; 068 import com.unboundid.util.ReverseComparator; 069 import com.unboundid.util.ThreadSafety; 070 import com.unboundid.util.ThreadSafetyLevel; 071 import com.unboundid.util.args.ArgumentException; 072 import com.unboundid.util.args.ArgumentParser; 073 import com.unboundid.util.args.BooleanArgument; 074 075 import static com.unboundid.util.StaticUtils.*; 076 077 078 079 /** 080 * <BLOCKQUOTE> 081 * <B>NOTE:</B> This class is part of the Commercial Edition of the UnboundID 082 * LDAP SDK for Java. It is not available for use in applications that 083 * include only the Standard Edition of the LDAP SDK, and is not supported for 084 * use in conjunction with non-UnboundID products. 085 * </BLOCKQUOTE> 086 * This class provides a tool that may be used to read and summarize the 087 * contents of one or more access log files from UnboundID or Alcatel-Lucent 088 * 8661 server products. Information that will be reported includes: 089 * <UL> 090 * <LI>The total length of time covered by the log files.</LI> 091 * <LI>The number of connections established and disconnected, the addresses 092 * of the most commonly-connecting clients, and the average rate of 093 * connects and disconnects per second.</LI> 094 * <LI>The number of operations processed, overall and by operation type, 095 * and the average rate of operations per second.</LI> 096 * <LI>The average duration for operations processed, overall and by operation 097 * type.</LI> 098 * <LI>A breakdown of operation processing times into a number of predefined 099 * categories (less than 1ms, between 1ms and 2ms, between 2ms and 3ms, 100 * between 3ms and 5ms, between 5ms and 10ms, between 10ms and 20ms, 101 * between 20ms and 30ms, between 30ms and 50ms, between 50ms and 100ms, 102 * between 100ms and 1000ms, and over 1000ms).</LI> 103 * <LI>A breakdown of the most common result codes for each type of operation 104 * and their relative frequencies.</LI> 105 * <LI>The most common types of extended requests processed and their 106 * relative frequencies.</LI> 107 * <LI>The number of unindexed search operations processed.</LI> 108 * <LI>A breakdown of the relative frequencies for each type of search 109 * scope.</LI> 110 * <LI>The most common types of search filters used for search 111 * operations and their relative frequencies.</LI> 112 * </UL> 113 * It is designed to work with access log files using either the default log 114 * format with separate request and response messages, as well as log files 115 * in which the request and response details have been combined on the same 116 * line. The log files to be processed should be provided as command-line 117 * arguments. 118 * <BR><BR> 119 * The APIs demonstrated by this example include: 120 * <UL> 121 * <LI>Access log parsing (from the 122 * {@code com.unboundid.ldap.sdk.unboundidds.logs} package)</LI> 123 * <LI>Argument parsing (from the {@code com.unboundid.util.args} 124 * package)</LI> 125 * </UL> 126 */ 127 @NotMutable() 128 @ThreadSafety(level=ThreadSafetyLevel.NOT_THREADSAFE) 129 public final class SummarizeAccessLog 130 extends CommandLineTool 131 implements Serializable 132 { 133 /** 134 * The serial version UID for this serializable class. 135 */ 136 private static final long serialVersionUID = -1211445611798245343L; 137 138 139 140 // Variables used for accessing argument information. 141 private ArgumentParser argumentParser; 142 143 // And argument which may be used to indicate that the log files are 144 // compressed. 145 private BooleanArgument isCompressed; 146 147 // The decimal format that will be used for this class. 148 private final DecimalFormat decimalFormat; 149 150 // The total duration for log content, in milliseconds. 151 private long logDurationMillis; 152 153 // The total processing time for each type of operation. 154 private double addProcessingDuration; 155 private double bindProcessingDuration; 156 private double compareProcessingDuration; 157 private double deleteProcessingDuration; 158 private double extendedProcessingDuration; 159 private double modifyProcessingDuration; 160 private double modifyDNProcessingDuration; 161 private double searchProcessingDuration; 162 163 // A variable used for counting the number of messages of each type. 164 private long numAbandons; 165 private long numAdds; 166 private long numBinds; 167 private long numCompares; 168 private long numConnects; 169 private long numDeletes; 170 private long numDisconnects; 171 private long numExtended; 172 private long numModifies; 173 private long numModifyDNs; 174 private long numNonBaseSearches; 175 private long numSearches; 176 private long numUnbinds; 177 178 // The number of operations of each type that accessed uncached data. 179 private long numUncachedAdds; 180 private long numUncachedBinds; 181 private long numUncachedCompares; 182 private long numUncachedDeletes; 183 private long numUncachedExtended; 184 private long numUncachedModifies; 185 private long numUncachedModifyDNs; 186 private long numUncachedSearches; 187 188 // The number of unindexed searches processed within the server. 189 private long numUnindexedAttempts; 190 private long numUnindexedFailed; 191 private long numUnindexedSuccessful; 192 193 // Variables used for maintaining counts for common types of information. 194 private final HashMap<Long,AtomicLong> searchEntryCounts; 195 private final HashMap<ResultCode,AtomicLong> addResultCodes; 196 private final HashMap<ResultCode,AtomicLong> bindResultCodes; 197 private final HashMap<ResultCode,AtomicLong> compareResultCodes; 198 private final HashMap<ResultCode,AtomicLong> deleteResultCodes; 199 private final HashMap<ResultCode,AtomicLong> extendedResultCodes; 200 private final HashMap<ResultCode,AtomicLong> modifyResultCodes; 201 private final HashMap<ResultCode,AtomicLong> modifyDNResultCodes; 202 private final HashMap<ResultCode,AtomicLong> searchResultCodes; 203 private final HashMap<SearchScope,AtomicLong> searchScopes; 204 private final HashMap<String,AtomicLong> clientAddresses; 205 private final HashMap<String,AtomicLong> clientConnectionPolicies; 206 private final HashMap<String,AtomicLong> disconnectReasons; 207 private final HashMap<String,AtomicLong> extendedOperations; 208 private final HashMap<String,AtomicLong> filterTypes; 209 private final HashSet<String> processedRequests; 210 private final LinkedHashMap<Long,AtomicLong> addProcessingTimes; 211 private final LinkedHashMap<Long,AtomicLong> bindProcessingTimes; 212 private final LinkedHashMap<Long,AtomicLong> compareProcessingTimes; 213 private final LinkedHashMap<Long,AtomicLong> deleteProcessingTimes; 214 private final LinkedHashMap<Long,AtomicLong> extendedProcessingTimes; 215 private final LinkedHashMap<Long,AtomicLong> modifyProcessingTimes; 216 private final LinkedHashMap<Long,AtomicLong> modifyDNProcessingTimes; 217 private final LinkedHashMap<Long,AtomicLong> searchProcessingTimes; 218 219 220 221 /** 222 * Parse the provided command line arguments and perform the appropriate 223 * processing. 224 * 225 * @param args The command line arguments provided to this program. 226 */ 227 public static void main(final String[] args) 228 { 229 final ResultCode resultCode = main(args, System.out, System.err); 230 if (resultCode != ResultCode.SUCCESS) 231 { 232 System.exit(resultCode.intValue()); 233 } 234 } 235 236 237 238 /** 239 * Parse the provided command line arguments and perform the appropriate 240 * processing. 241 * 242 * @param args The command line arguments provided to this program. 243 * @param outStream The output stream to which standard out should be 244 * written. It may be {@code null} if output should be 245 * suppressed. 246 * @param errStream The output stream to which standard error should be 247 * written. It may be {@code null} if error messages 248 * should be suppressed. 249 * 250 * @return A result code indicating whether the processing was successful. 251 */ 252 public static ResultCode main(final String[] args, 253 final OutputStream outStream, 254 final OutputStream errStream) 255 { 256 final SummarizeAccessLog summarizer = 257 new SummarizeAccessLog(outStream, errStream); 258 return summarizer.runTool(args); 259 } 260 261 262 263 /** 264 * Creates a new instance of this tool. 265 * 266 * @param outStream The output stream to which standard out should be 267 * written. It may be {@code null} if output should be 268 * suppressed. 269 * @param errStream The output stream to which standard error should be 270 * written. It may be {@code null} if error messages 271 * should be suppressed. 272 */ 273 public SummarizeAccessLog(final OutputStream outStream, 274 final OutputStream errStream) 275 { 276 super(outStream, errStream); 277 278 decimalFormat = new DecimalFormat("0.000"); 279 280 logDurationMillis = 0L; 281 282 addProcessingDuration = 0.0; 283 bindProcessingDuration = 0.0; 284 compareProcessingDuration = 0.0; 285 deleteProcessingDuration = 0.0; 286 extendedProcessingDuration = 0.0; 287 modifyProcessingDuration = 0.0; 288 modifyDNProcessingDuration = 0.0; 289 searchProcessingDuration = 0.0; 290 291 numAbandons = 0L; 292 numAdds = 0L; 293 numBinds = 0L; 294 numCompares = 0L; 295 numConnects = 0L; 296 numDeletes = 0L; 297 numDisconnects = 0L; 298 numExtended = 0L; 299 numModifies = 0L; 300 numModifyDNs = 0L; 301 numNonBaseSearches = 0L; 302 numSearches = 0L; 303 numUnbinds = 0L; 304 305 numUncachedAdds = 0L; 306 numUncachedBinds = 0L; 307 numUncachedCompares = 0L; 308 numUncachedDeletes = 0L; 309 numUncachedExtended = 0L; 310 numUncachedModifies = 0L; 311 numUncachedModifyDNs = 0L; 312 numUncachedSearches = 0L; 313 314 searchEntryCounts = new HashMap<Long,AtomicLong>(10); 315 addResultCodes = new HashMap<ResultCode,AtomicLong>(10); 316 bindResultCodes = new HashMap<ResultCode,AtomicLong>(10); 317 compareResultCodes = new HashMap<ResultCode,AtomicLong>(10); 318 deleteResultCodes = new HashMap<ResultCode,AtomicLong>(10); 319 extendedResultCodes = new HashMap<ResultCode,AtomicLong>(10); 320 modifyResultCodes = new HashMap<ResultCode,AtomicLong>(10); 321 modifyDNResultCodes = new HashMap<ResultCode,AtomicLong>(10); 322 searchResultCodes = new HashMap<ResultCode,AtomicLong>(10); 323 searchScopes = new HashMap<SearchScope,AtomicLong>(4); 324 clientAddresses = new HashMap<String,AtomicLong>(100); 325 clientConnectionPolicies = new HashMap<String,AtomicLong>(100); 326 disconnectReasons = new HashMap<String,AtomicLong>(100); 327 extendedOperations = new HashMap<String,AtomicLong>(10); 328 filterTypes = new HashMap<String,AtomicLong>(100); 329 processedRequests = new HashSet<String>(100); 330 addProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 331 bindProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 332 compareProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 333 deleteProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 334 extendedProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 335 modifyProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 336 modifyDNProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 337 searchProcessingTimes = new LinkedHashMap<Long,AtomicLong>(11); 338 339 populateProcessingTimeMap(addProcessingTimes); 340 populateProcessingTimeMap(bindProcessingTimes); 341 populateProcessingTimeMap(compareProcessingTimes); 342 populateProcessingTimeMap(deleteProcessingTimes); 343 populateProcessingTimeMap(extendedProcessingTimes); 344 populateProcessingTimeMap(modifyProcessingTimes); 345 populateProcessingTimeMap(modifyDNProcessingTimes); 346 populateProcessingTimeMap(searchProcessingTimes); 347 } 348 349 350 351 /** 352 * Retrieves the name for this tool. 353 * 354 * @return The name for this tool. 355 */ 356 @Override() 357 public String getToolName() 358 { 359 return "summarize-access-log"; 360 } 361 362 363 364 /** 365 * Retrieves the description for this tool. 366 * 367 * @return The description for this tool. 368 */ 369 @Override() 370 public String getToolDescription() 371 { 372 return "Examine one or more access log files from UnboundID or " + 373 "Alcatel-Lucent 8661 server products to display a number of " + 374 "metrics about operations processed within the server."; 375 } 376 377 378 379 /** 380 * Retrieves the version string for this tool. 381 * 382 * @return The version string for this tool. 383 */ 384 @Override() 385 public String getToolVersion() 386 { 387 return Version.NUMERIC_VERSION_STRING; 388 } 389 390 391 392 /** 393 * Retrieves the maximum number of unnamed trailing arguments that may be 394 * provided for this tool. 395 * 396 * @return The maximum number of unnamed trailing arguments that may be 397 * provided for this tool. 398 */ 399 @Override() 400 public int getMaxTrailingArguments() 401 { 402 return -1; 403 } 404 405 406 407 /** 408 * Retrieves a placeholder string that should be used for trailing arguments 409 * in the usage information for this tool. 410 * 411 * @return A placeholder string that should be used for trailing arguments in 412 * the usage information for this tool. 413 */ 414 @Override() 415 public String getTrailingArgumentsPlaceholder() 416 { 417 return "{path}"; 418 } 419 420 421 422 /** 423 * Adds the command-line arguments supported for use with this tool to the 424 * provided argument parser. The tool may need to retain references to the 425 * arguments (and/or the argument parser, if trailing arguments are allowed) 426 * to it in order to obtain their values for use in later processing. 427 * 428 * @param parser The argument parser to which the arguments are to be added. 429 * 430 * @throws ArgumentException If a problem occurs while adding any of the 431 * tool-specific arguments to the provided 432 * argument parser. 433 */ 434 @Override() 435 public void addToolArguments(final ArgumentParser parser) 436 throws ArgumentException 437 { 438 // We need to save a reference to the argument parser so that we can get 439 // the trailing arguments later. 440 argumentParser = parser; 441 442 // Add an argument that makes it possible to read a compressed log file. 443 final String description = "Indicates that the log file is compressed.."; 444 isCompressed = new BooleanArgument('c', "isCompressed", description); 445 parser.addArgument(isCompressed); 446 } 447 448 449 450 /** 451 * Performs any necessary processing that should be done to ensure that the 452 * provided set of command-line arguments were valid. This method will be 453 * called after the basic argument parsing has been performed and immediately 454 * before the {@link CommandLineTool#doToolProcessing} method is invoked. 455 * 456 * @throws ArgumentException If there was a problem with the command-line 457 * arguments provided to this program. 458 */ 459 @Override() 460 public void doExtendedArgumentValidation() 461 throws ArgumentException 462 { 463 // Make sure that at least one access log file path was provided. 464 final List<String> trailingArguments = 465 argumentParser.getTrailingArguments(); 466 if ((trailingArguments == null) || trailingArguments.isEmpty()) 467 { 468 throw new ArgumentException("No access log file paths were provided."); 469 } 470 } 471 472 473 474 /** 475 * Performs the core set of processing for this tool. 476 * 477 * @return A result code that indicates whether the processing completed 478 * successfully. 479 */ 480 @Override() 481 public ResultCode doToolProcessing() 482 { 483 long logLines = 0L; 484 for (final String path : argumentParser.getTrailingArguments()) 485 { 486 final File f = new File(path); 487 out("Examining access log ", f.getAbsolutePath()); 488 final AccessLogReader reader; 489 try 490 { 491 if (isCompressed.isPresent()) 492 { 493 reader = new AccessLogReader(new InputStreamReader( 494 new GZIPInputStream(new FileInputStream(f)))); 495 } 496 else 497 { 498 reader = new AccessLogReader(f); 499 } 500 } 501 catch (IOException ioe) 502 { 503 err("Unable to open access log file ", f.getAbsolutePath(), ": ", 504 getExceptionMessage(ioe)); 505 return ResultCode.LOCAL_ERROR; 506 } 507 508 long startTime = 0L; 509 long stopTime = 0L; 510 511 while (true) 512 { 513 final AccessLogMessage msg; 514 try 515 { 516 msg = reader.read(); 517 } 518 catch (IOException ioe) 519 { 520 err("Error reading from access log file ", f.getAbsolutePath(), 521 ": ", getExceptionMessage(ioe)); 522 return ResultCode.LOCAL_ERROR; 523 } 524 catch (LogException le) 525 { 526 err("Encountered an error while attempting to parse a line in" + 527 "access log file ", f.getAbsolutePath(), ": ", 528 getExceptionMessage(le)); 529 continue; 530 } 531 532 if (msg == null) 533 { 534 break; 535 } 536 537 logLines++; 538 stopTime = msg.getTimestamp().getTime(); 539 if (startTime == 0L) 540 { 541 startTime = stopTime; 542 } 543 544 switch (msg.getMessageType()) 545 { 546 case CONNECT: 547 processConnect((ConnectAccessLogMessage) msg); 548 break; 549 case DISCONNECT: 550 processDisconnect((DisconnectAccessLogMessage) msg); 551 break; 552 case REQUEST: 553 switch (((OperationAccessLogMessage) msg).getOperationType()) 554 { 555 case ABANDON: 556 processAbandonRequest((AbandonRequestAccessLogMessage) msg); 557 break; 558 case EXTENDED: 559 processExtendedRequest((ExtendedRequestAccessLogMessage) msg); 560 break; 561 case SEARCH: 562 processSearchRequest((SearchRequestAccessLogMessage) msg); 563 break; 564 case UNBIND: 565 processUnbindRequest((UnbindRequestAccessLogMessage) msg); 566 break; 567 } 568 break; 569 case RESULT: 570 switch (((OperationAccessLogMessage) msg).getOperationType()) 571 { 572 case ADD: 573 processAddResult((AddResultAccessLogMessage) msg); 574 break; 575 case BIND: 576 processBindResult((BindResultAccessLogMessage) msg); 577 break; 578 case COMPARE: 579 processCompareResult((CompareResultAccessLogMessage) msg); 580 break; 581 case DELETE: 582 processDeleteResult((DeleteResultAccessLogMessage) msg); 583 break; 584 case EXTENDED: 585 processExtendedResult((ExtendedResultAccessLogMessage) msg); 586 break; 587 case MODIFY: 588 processModifyResult((ModifyResultAccessLogMessage) msg); 589 break; 590 case MODDN: 591 processModifyDNResult((ModifyDNResultAccessLogMessage) msg); 592 break; 593 case SEARCH: 594 processSearchResult((SearchResultAccessLogMessage) msg); 595 break; 596 } 597 break; 598 599 case ASSURANCE_COMPLETE: 600 case CLIENT_CERTIFICATE: 601 case ENTRY_REBALANCING_REQUEST: 602 case ENTRY_REBALANCING_RESULT: 603 case FORWARD: 604 case FORWARD_FAILED: 605 case ENTRY: 606 case REFERENCE: 607 default: 608 // Nothing needs to be done for these message types. 609 } 610 } 611 612 try 613 { 614 reader.close(); 615 } catch (Exception e) {} 616 logDurationMillis += (stopTime - startTime); 617 } 618 619 620 final int numFiles = argumentParser.getTrailingArguments().size(); 621 out(); 622 out("Examined ", logLines, " lines in ", numFiles, 623 ((numFiles == 1) ? " file" : " files"), 624 " covering a total duration of ", 625 millisToHumanReadableDuration(logDurationMillis)); 626 627 out(); 628 629 final double logDurationSeconds = logDurationMillis / 1000.0; 630 final double connectsPerSecond = numConnects / logDurationSeconds; 631 final double disconnectsPerSecond = numDisconnects / logDurationSeconds; 632 633 out("Total connections established: ", numConnects, " (", 634 decimalFormat.format(connectsPerSecond), "/second)"); 635 out("Total disconnects: ", numDisconnects, " (", 636 decimalFormat.format(disconnectsPerSecond), "/second)"); 637 638 if (! clientAddresses.isEmpty()) 639 { 640 out(); 641 final List<ObjectPair<String,Long>> connectCounts = 642 getMostCommonElements(clientAddresses, 20); 643 out("Most common client addresses:"); 644 for (final ObjectPair<String,Long> p : connectCounts) 645 { 646 final long count = p.getSecond(); 647 final double percent = 100.0 * count / numConnects; 648 649 out(p.getFirst(), ": ", count, " (", decimalFormat.format(percent), 650 ")"); 651 } 652 } 653 654 if (! clientConnectionPolicies.isEmpty()) 655 { 656 long totalCCPs = 0; 657 for (final AtomicLong l : clientConnectionPolicies.values()) 658 { 659 totalCCPs += l.get(); 660 } 661 662 final List<ObjectPair<String,Long>> reasonCounts = 663 getMostCommonElements(clientConnectionPolicies, 20); 664 665 out(); 666 out("Most common client connection policies:"); 667 for (final ObjectPair<String,Long> p : reasonCounts) 668 { 669 final long count = p.getSecond(); 670 final double percent = 100.0 * count / totalCCPs; 671 out(p.getFirst(), ": ", p.getSecond(), " (", 672 decimalFormat.format(percent), "%)"); 673 } 674 } 675 676 if (! disconnectReasons.isEmpty()) 677 { 678 final List<ObjectPair<String,Long>> reasonCounts = 679 getMostCommonElements(disconnectReasons, 20); 680 681 out(); 682 out("Most common disconnect reasons:"); 683 for (final ObjectPair<String,Long> p : reasonCounts) 684 { 685 final long count = p.getSecond(); 686 final double percent = 100.0 * count / numDisconnects; 687 out(p.getFirst(), ": ", p.getSecond(), " (", 688 decimalFormat.format(percent), "%)"); 689 } 690 } 691 692 final long totalOps = numAbandons + numAdds + numBinds + numCompares + 693 numDeletes + numExtended + numModifies + numModifyDNs + numSearches + 694 numUnbinds; 695 if (totalOps > 0) 696 { 697 final double percentAbandon = 100.0 * numAbandons / totalOps; 698 final double percentAdd = 100.0 * numAdds / totalOps; 699 final double percentBind = 100.0 * numBinds / totalOps; 700 final double percentCompare = 100.0 * numCompares / totalOps; 701 final double percentDelete = 100.0 * numDeletes / totalOps; 702 final double percentExtended = 100.0 * numExtended / totalOps; 703 final double percentModify = 100.0 * numModifies / totalOps; 704 final double percentModifyDN = 100.0 * numModifyDNs / totalOps; 705 final double percentSearch = 100.0 * numSearches / totalOps; 706 final double percentUnbind = 100.0 * numUnbinds / totalOps; 707 708 final double abandonsPerSecond = numAbandons / logDurationSeconds; 709 final double addsPerSecond = numAdds / logDurationSeconds; 710 final double bindsPerSecond = numBinds / logDurationSeconds; 711 final double comparesPerSecond = numCompares / logDurationSeconds; 712 final double deletesPerSecond = numDeletes / logDurationSeconds; 713 final double extendedPerSecond = numExtended / logDurationSeconds; 714 final double modifiesPerSecond = numModifies / logDurationSeconds; 715 final double modifyDNsPerSecond = numModifyDNs / logDurationSeconds; 716 final double searchesPerSecond = numSearches / logDurationSeconds; 717 final double unbindsPerSecond = numUnbinds / logDurationSeconds; 718 719 out(); 720 out("Total operations examined: ", totalOps); 721 out("Abandon operations examined: ", numAbandons, " (", 722 decimalFormat.format(percentAbandon), "%, ", 723 decimalFormat.format(abandonsPerSecond), "/second)"); 724 out("Add operations examined: ", numAdds, " (", 725 decimalFormat.format(percentAdd), "%, ", 726 decimalFormat.format(addsPerSecond), "/second)"); 727 out("Bind operations examined: ", numBinds, " (", 728 decimalFormat.format(percentBind), "%, ", 729 decimalFormat.format(bindsPerSecond), "/second)"); 730 out("Compare operations examined: ", numCompares, " (", 731 decimalFormat.format(percentCompare), "%, ", 732 decimalFormat.format(comparesPerSecond), "/second)"); 733 out("Delete operations examined: ", numDeletes, " (", 734 decimalFormat.format(percentDelete), "%, ", 735 decimalFormat.format(deletesPerSecond), "/second)"); 736 out("Extended operations examined: ", numExtended, " (", 737 decimalFormat.format(percentExtended), "%, ", 738 decimalFormat.format(extendedPerSecond), "/second)"); 739 out("Modify operations examined: ", numModifies, " (", 740 decimalFormat.format(percentModify), "%, ", 741 decimalFormat.format(modifiesPerSecond), "/second)"); 742 out("Modify DN operations examined: ", numModifyDNs, " (", 743 decimalFormat.format(percentModifyDN), "%, ", 744 decimalFormat.format(modifyDNsPerSecond), "/second)"); 745 out("Search operations examined: ", numSearches, " (", 746 decimalFormat.format(percentSearch), "%, ", 747 decimalFormat.format(searchesPerSecond), "/second)"); 748 out("Unbind operations examined: ", numUnbinds, " (", 749 decimalFormat.format(percentUnbind), "%, ", 750 decimalFormat.format(unbindsPerSecond), "/second)"); 751 752 final double totalProcessingDuration = addProcessingDuration + 753 bindProcessingDuration + compareProcessingDuration + 754 deleteProcessingDuration + extendedProcessingDuration + 755 modifyProcessingDuration + modifyDNProcessingDuration + 756 searchProcessingDuration; 757 758 out(); 759 out("Average operation processing duration: ", 760 decimalFormat.format(totalProcessingDuration / totalOps), "ms"); 761 762 if (numAdds > 0) 763 { 764 out("Average add operation processing duration: ", 765 decimalFormat.format(addProcessingDuration / numAdds), "ms"); 766 } 767 768 if (numBinds > 0) 769 { 770 out("Average bind operation processing duration: ", 771 decimalFormat.format(bindProcessingDuration / numBinds), "ms"); 772 } 773 774 if (numCompares > 0) 775 { 776 out("Average compare operation processing duration: ", 777 decimalFormat.format(compareProcessingDuration / numCompares), 778 "ms"); 779 } 780 781 if (numDeletes > 0) 782 { 783 out("Average delete operation processing duration: ", 784 decimalFormat.format(deleteProcessingDuration / numDeletes), "ms"); 785 } 786 787 if (numExtended > 0) 788 { 789 out("Average extended operation processing duration: ", 790 decimalFormat.format(extendedProcessingDuration / numExtended), 791 "ms"); 792 } 793 794 if (numModifies > 0) 795 { 796 out("Average modify operation processing duration: ", 797 decimalFormat.format(modifyProcessingDuration / numModifies), "ms"); 798 } 799 800 if (numModifyDNs > 0) 801 { 802 out("Average modify DN operation processing duration: ", 803 decimalFormat.format(modifyDNProcessingDuration / numModifyDNs), 804 "ms"); 805 } 806 807 if (numSearches > 0) 808 { 809 out("Average search operation processing duration: ", 810 decimalFormat.format(searchProcessingDuration / numSearches), "ms"); 811 } 812 813 printProcessingTimeHistogram("add", numAdds, addProcessingTimes); 814 printProcessingTimeHistogram("bind", numBinds, bindProcessingTimes); 815 printProcessingTimeHistogram("compare", numCompares, 816 compareProcessingTimes); 817 printProcessingTimeHistogram("delete", numDeletes, deleteProcessingTimes); 818 printProcessingTimeHistogram("extended", numExtended, 819 extendedProcessingTimes); 820 printProcessingTimeHistogram("modify", numModifies, 821 modifyProcessingTimes); 822 printProcessingTimeHistogram("modify DN", numModifyDNs, 823 modifyDNProcessingTimes); 824 printProcessingTimeHistogram("search", numSearches, 825 searchProcessingTimes); 826 827 if (! addResultCodes.isEmpty()) 828 { 829 final List<ObjectPair<ResultCode,Long>> rcCounts = 830 getMostCommonElements(addResultCodes, 20); 831 832 out(); 833 out("Most common add operation result codes:"); 834 for (final ObjectPair<ResultCode,Long> p : rcCounts) 835 { 836 final long count = p.getSecond(); 837 final double percent = 100.0 * count / numAdds; 838 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 839 decimalFormat.format(percent), "%)"); 840 } 841 } 842 843 if (! bindResultCodes.isEmpty()) 844 { 845 final List<ObjectPair<ResultCode,Long>> rcCounts = 846 getMostCommonElements(bindResultCodes, 20); 847 848 out(); 849 out("Most common bind operation result codes:"); 850 for (final ObjectPair<ResultCode,Long> p : rcCounts) 851 { 852 final long count = p.getSecond(); 853 final double percent = 100.0 * count / numBinds; 854 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 855 decimalFormat.format(percent), "%)"); 856 } 857 } 858 859 if (! compareResultCodes.isEmpty()) 860 { 861 final List<ObjectPair<ResultCode,Long>> rcCounts = 862 getMostCommonElements(compareResultCodes, 20); 863 864 out(); 865 out("Most common compare operation result codes:"); 866 for (final ObjectPair<ResultCode,Long> p : rcCounts) 867 { 868 final long count = p.getSecond(); 869 final double percent = 100.0 * count / numCompares; 870 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 871 decimalFormat.format(percent), "%)"); 872 } 873 } 874 875 if (! deleteResultCodes.isEmpty()) 876 { 877 final List<ObjectPair<ResultCode,Long>> rcCounts = 878 getMostCommonElements(deleteResultCodes, 20); 879 880 out(); 881 out("Most common delete operation result codes:"); 882 for (final ObjectPair<ResultCode,Long> p : rcCounts) 883 { 884 final long count = p.getSecond(); 885 final double percent = 100.0 * count / numDeletes; 886 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 887 decimalFormat.format(percent), "%)"); 888 } 889 } 890 891 if (! extendedResultCodes.isEmpty()) 892 { 893 final List<ObjectPair<ResultCode,Long>> rcCounts = 894 getMostCommonElements(extendedResultCodes, 20); 895 896 out(); 897 out("Most common extended operation result codes:"); 898 for (final ObjectPair<ResultCode,Long> p : rcCounts) 899 { 900 final long count = p.getSecond(); 901 final double percent = 100.0 * count / numExtended; 902 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 903 decimalFormat.format(percent), "%)"); 904 } 905 } 906 907 if (! modifyResultCodes.isEmpty()) 908 { 909 final List<ObjectPair<ResultCode,Long>> rcCounts = 910 getMostCommonElements(modifyResultCodes, 20); 911 912 out(); 913 out("Most common modify operation result codes:"); 914 for (final ObjectPair<ResultCode,Long> p : rcCounts) 915 { 916 final long count = p.getSecond(); 917 final double percent = 100.0 * count / numModifies; 918 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 919 decimalFormat.format(percent), "%)"); 920 } 921 } 922 923 if (! modifyDNResultCodes.isEmpty()) 924 { 925 final List<ObjectPair<ResultCode,Long>> rcCounts = 926 getMostCommonElements(modifyDNResultCodes, 20); 927 928 out(); 929 out("Most common modify DN operation result codes:"); 930 for (final ObjectPair<ResultCode,Long> p : rcCounts) 931 { 932 final long count = p.getSecond(); 933 final double percent = 100.0 * count / numModifyDNs; 934 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 935 decimalFormat.format(percent), "%)"); 936 } 937 } 938 939 if (! searchResultCodes.isEmpty()) 940 { 941 final List<ObjectPair<ResultCode,Long>> rcCounts = 942 getMostCommonElements(searchResultCodes, 20); 943 944 out(); 945 out("Most common search operation result codes:"); 946 for (final ObjectPair<ResultCode,Long> p : rcCounts) 947 { 948 final long count = p.getSecond(); 949 final double percent = 100.0 * count / numSearches; 950 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 951 decimalFormat.format(percent), "%)"); 952 } 953 } 954 955 if (! extendedOperations.isEmpty()) 956 { 957 final List<ObjectPair<String,Long>> extOpCounts = 958 getMostCommonElements(extendedOperations, 20); 959 960 out(); 961 out("Most common extended operation types:"); 962 for (final ObjectPair<String,Long> p : extOpCounts) 963 { 964 final long count = p.getSecond(); 965 final double percent = 100.0 * count / numExtended; 966 out(p.getFirst(), ": ", p.getSecond(), " (", 967 decimalFormat.format(percent), "%)"); 968 } 969 } 970 971 out(); 972 out("Number of unindexed search attempts: ", numUnindexedAttempts); 973 out("Number of successfully-completed unindexed searches: ", 974 numUnindexedSuccessful); 975 out("Number of failed unindexed searches: ", numUnindexedFailed); 976 977 if (! searchScopes.isEmpty()) 978 { 979 final List<ObjectPair<SearchScope,Long>> scopeCounts = 980 getMostCommonElements(searchScopes, 20); 981 982 out(); 983 out("Most common search scopes:"); 984 for (final ObjectPair<SearchScope,Long> p : scopeCounts) 985 { 986 final long count = p.getSecond(); 987 final double percent = 100.0 * count / numSearches; 988 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 989 decimalFormat.format(percent), "%)"); 990 } 991 } 992 993 if (! searchEntryCounts.isEmpty()) 994 { 995 final List<ObjectPair<Long,Long>> entryCounts = 996 getMostCommonElements(searchEntryCounts, 20); 997 998 out(); 999 out("Most common search entry counts:"); 1000 for (final ObjectPair<Long,Long> p : entryCounts) 1001 { 1002 final long count = p.getSecond(); 1003 final double percent = 100.0 * count / numSearches; 1004 out(p.getFirst(), ": ", p.getSecond(), " (", 1005 decimalFormat.format(percent), "%)"); 1006 } 1007 } 1008 1009 if (! filterTypes.isEmpty()) 1010 { 1011 final List<ObjectPair<String,Long>> filterCounts = 1012 getMostCommonElements(filterTypes, 20); 1013 1014 out(); 1015 out("Most common generic filters for searches with a non-base scope:"); 1016 for (final ObjectPair<String,Long> p : filterCounts) 1017 { 1018 final long count = p.getSecond(); 1019 final double percent = 100.0 * count / numNonBaseSearches; 1020 out(p.getFirst(), ": ", p.getSecond(), " (", 1021 decimalFormat.format(percent), "%)"); 1022 } 1023 } 1024 } 1025 1026 final long totalUncached = numUncachedAdds + numUncachedBinds + 1027 numUncachedCompares + numUncachedDeletes + numUncachedExtended + 1028 numUncachedModifies + numUncachedModifyDNs + numUncachedSearches; 1029 if (totalUncached > 0L) 1030 { 1031 out(); 1032 out("Operations accessing uncached data:"); 1033 printUncached("Add", numUncachedAdds, numAdds); 1034 printUncached("Bind", numUncachedBinds, numBinds); 1035 printUncached("Compare", numUncachedCompares, numCompares); 1036 printUncached("Delete", numUncachedDeletes, numDeletes); 1037 printUncached("Extended", numUncachedExtended, numExtended); 1038 printUncached("Modify", numUncachedModifies, numModifies); 1039 printUncached("Modify DN", numUncachedModifyDNs, numModifyDNs); 1040 printUncached("Search", numUncachedSearches, numSearches); 1041 } 1042 1043 1044 return ResultCode.SUCCESS; 1045 } 1046 1047 1048 1049 /** 1050 * Retrieves a set of information that may be used to generate example usage 1051 * information. Each element in the returned map should consist of a map 1052 * between an example set of arguments and a string that describes the 1053 * behavior of the tool when invoked with that set of arguments. 1054 * 1055 * @return A set of information that may be used to generate example usage 1056 * information. It may be {@code null} or empty if no example usage 1057 * information is available. 1058 */ 1059 @Override() 1060 public LinkedHashMap<String[],String> getExampleUsages() 1061 { 1062 final LinkedHashMap<String[],String> examples = 1063 new LinkedHashMap<String[],String>(1); 1064 1065 final String[] args = 1066 { 1067 "/ds/logs/access" 1068 }; 1069 final String description = 1070 "Analyze the contents of the /ds/logs/access access log file."; 1071 examples.put(args, description); 1072 1073 return examples; 1074 } 1075 1076 1077 1078 /** 1079 * Populates the provided processing time map with an initial set of values. 1080 * 1081 * @param m The processing time map to be populated. 1082 */ 1083 private static void populateProcessingTimeMap( 1084 final HashMap<Long,AtomicLong> m) 1085 { 1086 m.put(1L, new AtomicLong(0L)); 1087 m.put(2L, new AtomicLong(0L)); 1088 m.put(3L, new AtomicLong(0L)); 1089 m.put(5L, new AtomicLong(0L)); 1090 m.put(10L, new AtomicLong(0L)); 1091 m.put(20L, new AtomicLong(0L)); 1092 m.put(30L, new AtomicLong(0L)); 1093 m.put(50L, new AtomicLong(0L)); 1094 m.put(100L, new AtomicLong(0L)); 1095 m.put(1000L, new AtomicLong(0L)); 1096 m.put(Long.MAX_VALUE, new AtomicLong(0L)); 1097 } 1098 1099 1100 1101 /** 1102 * Performs any necessary processing for a connect message. 1103 * 1104 * @param m The log message to be processed. 1105 */ 1106 private void processConnect(final ConnectAccessLogMessage m) 1107 { 1108 numConnects++; 1109 1110 final String clientAddr = m.getSourceAddress(); 1111 if (clientAddr != null) 1112 { 1113 AtomicLong count = clientAddresses.get(clientAddr); 1114 if (count == null) 1115 { 1116 count = new AtomicLong(0L); 1117 clientAddresses.put(clientAddr, count); 1118 } 1119 count.incrementAndGet(); 1120 } 1121 1122 final String ccp = m.getClientConnectionPolicy(); 1123 if (ccp != null) 1124 { 1125 AtomicLong l = clientConnectionPolicies.get(ccp); 1126 if (l == null) 1127 { 1128 l = new AtomicLong(0L); 1129 clientConnectionPolicies.put(ccp, l); 1130 } 1131 l.incrementAndGet(); 1132 } 1133 } 1134 1135 1136 1137 /** 1138 * Performs any necessary processing for a disconnect message. 1139 * 1140 * @param m The log message to be processed. 1141 */ 1142 private void processDisconnect(final DisconnectAccessLogMessage m) 1143 { 1144 numDisconnects++; 1145 1146 final String reason = m.getDisconnectReason(); 1147 if (reason != null) 1148 { 1149 AtomicLong l = disconnectReasons.get(reason); 1150 if (l == null) 1151 { 1152 l = new AtomicLong(0L); 1153 disconnectReasons.put(reason, l); 1154 } 1155 l.incrementAndGet(); 1156 } 1157 } 1158 1159 1160 1161 /** 1162 * Performs any necessary processing for an abandon request message. 1163 * 1164 * @param m The log message to be processed. 1165 */ 1166 private void processAbandonRequest(final AbandonRequestAccessLogMessage m) 1167 { 1168 numAbandons++; 1169 } 1170 1171 1172 1173 /** 1174 * Performs any necessary processing for an extended request message. 1175 * 1176 * @param m The log message to be processed. 1177 */ 1178 private void processExtendedRequest(final ExtendedRequestAccessLogMessage m) 1179 { 1180 processedRequests.add(m.getConnectionID() + "-" + m.getOperationID()); 1181 processExtendedRequestInternal(m); 1182 } 1183 1184 1185 1186 /** 1187 * Performs the internal processing for an extended request message. 1188 * 1189 * @param m The log message to be processed. 1190 */ 1191 private void processExtendedRequestInternal( 1192 final ExtendedRequestAccessLogMessage m) 1193 { 1194 final String oid = m.getRequestOID(); 1195 if (oid != null) 1196 { 1197 AtomicLong l = extendedOperations.get(oid); 1198 if (l == null) 1199 { 1200 l = new AtomicLong(0L); 1201 extendedOperations.put(oid, l); 1202 } 1203 l.incrementAndGet(); 1204 } 1205 } 1206 1207 1208 1209 /** 1210 * Performs any necessary processing for a search request message. 1211 * 1212 * @param m The log message to be processed. 1213 */ 1214 private void processSearchRequest(final SearchRequestAccessLogMessage m) 1215 { 1216 processedRequests.add(m.getConnectionID() + "-" + m.getOperationID()); 1217 processSearchRequestInternal(m); 1218 } 1219 1220 1221 1222 /** 1223 * Performs any necessary processing for a search request message. 1224 * 1225 * @param m The log message to be processed. 1226 */ 1227 private void processSearchRequestInternal( 1228 final SearchRequestAccessLogMessage m) 1229 { 1230 final SearchScope scope = m.getScope(); 1231 if (scope != null) 1232 { 1233 if (scope != SearchScope.BASE) 1234 { 1235 numNonBaseSearches++; 1236 } 1237 1238 AtomicLong scopeCount = searchScopes.get(scope); 1239 if (scopeCount == null) 1240 { 1241 scopeCount = new AtomicLong(0L); 1242 searchScopes.put(scope, scopeCount); 1243 } 1244 scopeCount.incrementAndGet(); 1245 1246 if (! scope.equals(SearchScope.BASE)) 1247 { 1248 final Filter filter = m.getParsedFilter(); 1249 if (filter != null) 1250 { 1251 final String genericString = new GenericFilter(filter).toString(); 1252 AtomicLong filterCount = filterTypes.get(genericString); 1253 if (filterCount == null) 1254 { 1255 filterCount = new AtomicLong(0L); 1256 filterTypes.put(genericString, filterCount); 1257 } 1258 filterCount.incrementAndGet(); 1259 } 1260 } 1261 } 1262 } 1263 1264 1265 1266 /** 1267 * Performs any necessary processing for an unbind request message. 1268 * 1269 * @param m The log message to be processed. 1270 */ 1271 private void processUnbindRequest(final UnbindRequestAccessLogMessage m) 1272 { 1273 numUnbinds++; 1274 } 1275 1276 1277 1278 /** 1279 * Performs any necessary processing for an add result message. 1280 * 1281 * @param m The log message to be processed. 1282 */ 1283 private void processAddResult(final AddResultAccessLogMessage m) 1284 { 1285 numAdds++; 1286 1287 updateResultCodeCount(m.getResultCode(), addResultCodes); 1288 addProcessingDuration += 1289 doubleValue(m.getProcessingTimeMillis(), addProcessingTimes); 1290 1291 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1292 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1293 { 1294 numUncachedAdds++; 1295 } 1296 } 1297 1298 1299 1300 /** 1301 * Performs any necessary processing for a bind result message. 1302 * 1303 * @param m The log message to be processed. 1304 */ 1305 private void processBindResult(final BindResultAccessLogMessage m) 1306 { 1307 numBinds++; 1308 1309 updateResultCodeCount(m.getResultCode(), bindResultCodes); 1310 bindProcessingDuration += 1311 doubleValue(m.getProcessingTimeMillis(), bindProcessingTimes); 1312 1313 final String ccp = m.getClientConnectionPolicy(); 1314 if (ccp != null) 1315 { 1316 AtomicLong l = clientConnectionPolicies.get(ccp); 1317 if (l == null) 1318 { 1319 l = new AtomicLong(0L); 1320 clientConnectionPolicies.put(ccp, l); 1321 } 1322 l.incrementAndGet(); 1323 } 1324 1325 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1326 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1327 { 1328 numUncachedBinds++; 1329 } 1330 } 1331 1332 1333 1334 /** 1335 * Performs any necessary processing for a compare result message. 1336 * 1337 * @param m The log message to be processed. 1338 */ 1339 private void processCompareResult(final CompareResultAccessLogMessage m) 1340 { 1341 numCompares++; 1342 1343 updateResultCodeCount(m.getResultCode(), compareResultCodes); 1344 compareProcessingDuration += 1345 doubleValue(m.getProcessingTimeMillis(), compareProcessingTimes); 1346 1347 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1348 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1349 { 1350 numUncachedCompares++; 1351 } 1352 } 1353 1354 1355 1356 /** 1357 * Performs any necessary processing for a delete result message. 1358 * 1359 * @param m The log message to be processed. 1360 */ 1361 private void processDeleteResult(final DeleteResultAccessLogMessage m) 1362 { 1363 numDeletes++; 1364 1365 updateResultCodeCount(m.getResultCode(), deleteResultCodes); 1366 deleteProcessingDuration += 1367 doubleValue(m.getProcessingTimeMillis(), deleteProcessingTimes); 1368 1369 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1370 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1371 { 1372 numUncachedDeletes++; 1373 } 1374 } 1375 1376 1377 1378 /** 1379 * Performs any necessary processing for an extended result message. 1380 * 1381 * @param m The log message to be processed. 1382 */ 1383 private void processExtendedResult(final ExtendedResultAccessLogMessage m) 1384 { 1385 numExtended++; 1386 1387 final String id = m.getConnectionID() + "-" + m.getOperationID(); 1388 if (!processedRequests.remove(id)) 1389 { 1390 processExtendedRequestInternal(m); 1391 } 1392 1393 updateResultCodeCount(m.getResultCode(), extendedResultCodes); 1394 extendedProcessingDuration += 1395 doubleValue(m.getProcessingTimeMillis(), extendedProcessingTimes); 1396 1397 final String ccp = m.getClientConnectionPolicy(); 1398 if (ccp != null) 1399 { 1400 AtomicLong l = clientConnectionPolicies.get(ccp); 1401 if (l == null) 1402 { 1403 l = new AtomicLong(0L); 1404 clientConnectionPolicies.put(ccp, l); 1405 } 1406 l.incrementAndGet(); 1407 } 1408 1409 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1410 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1411 { 1412 numUncachedExtended++; 1413 } 1414 } 1415 1416 1417 1418 /** 1419 * Performs any necessary processing for a modify result message. 1420 * 1421 * @param m The log message to be processed. 1422 */ 1423 private void processModifyResult(final ModifyResultAccessLogMessage m) 1424 { 1425 numModifies++; 1426 1427 updateResultCodeCount(m.getResultCode(), modifyResultCodes); 1428 modifyProcessingDuration += 1429 doubleValue(m.getProcessingTimeMillis(), modifyProcessingTimes); 1430 1431 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1432 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1433 { 1434 numUncachedModifies++; 1435 } 1436 } 1437 1438 1439 1440 /** 1441 * Performs any necessary processing for a modify DN result message. 1442 * 1443 * @param m The log message to be processed. 1444 */ 1445 private void processModifyDNResult(final ModifyDNResultAccessLogMessage m) 1446 { 1447 numModifyDNs++; 1448 1449 updateResultCodeCount(m.getResultCode(), modifyDNResultCodes); 1450 modifyDNProcessingDuration += 1451 doubleValue(m.getProcessingTimeMillis(), modifyDNProcessingTimes); 1452 1453 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1454 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1455 { 1456 numUncachedModifyDNs++; 1457 } 1458 } 1459 1460 1461 1462 /** 1463 * Performs any necessary processing for a search result message. 1464 * 1465 * @param m The log message to be processed. 1466 */ 1467 private void processSearchResult(final SearchResultAccessLogMessage m) 1468 { 1469 numSearches++; 1470 1471 final String id = m.getConnectionID() + "-" + m.getOperationID(); 1472 if (!processedRequests.remove(id)) 1473 { 1474 processSearchRequestInternal(m); 1475 } 1476 1477 final ResultCode resultCode = m.getResultCode(); 1478 updateResultCodeCount(resultCode, searchResultCodes); 1479 searchProcessingDuration += 1480 doubleValue(m.getProcessingTimeMillis(), searchProcessingTimes); 1481 1482 final Long entryCount = m.getEntriesReturned(); 1483 if (entryCount != null) 1484 { 1485 AtomicLong l = searchEntryCounts.get(entryCount); 1486 if (l == null) 1487 { 1488 l = new AtomicLong(0L); 1489 searchEntryCounts.put(entryCount, l); 1490 } 1491 l.incrementAndGet(); 1492 } 1493 1494 final Boolean isUnindexed = m.isUnindexed(); 1495 if ((isUnindexed != null) && isUnindexed) 1496 { 1497 numUnindexedAttempts++; 1498 if (resultCode == ResultCode.SUCCESS) 1499 { 1500 numUnindexedSuccessful++; 1501 } 1502 else 1503 { 1504 numUnindexedFailed++; 1505 } 1506 } 1507 1508 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1509 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1510 { 1511 numUncachedSearches++; 1512 } 1513 } 1514 1515 1516 1517 /** 1518 * Updates the count for the provided result code in the given map. 1519 * 1520 * @param rc The result code for which to update the count. 1521 * @param m The map used to hold counts by result code. 1522 */ 1523 private static void updateResultCodeCount(final ResultCode rc, 1524 final HashMap<ResultCode,AtomicLong> m) 1525 { 1526 if (rc == null) 1527 { 1528 return; 1529 } 1530 1531 AtomicLong l = m.get(rc); 1532 if (l == null) 1533 { 1534 l = new AtomicLong(0L); 1535 m.put(rc, l); 1536 } 1537 l.incrementAndGet(); 1538 } 1539 1540 1541 1542 /** 1543 * Retrieves the double value for the provided {@code Double} object. 1544 * 1545 * @param d The {@code Double} object for which to retrieve the value. 1546 * @param m The processing time histogram map to be updated. 1547 * 1548 * @return The double value of the provided {@code Double} object if it was 1549 * non-{@code null}, or 0.0 if it was {@code null}. 1550 */ 1551 private static double doubleValue(final Double d, 1552 final HashMap<Long,AtomicLong> m) 1553 { 1554 if (d == null) 1555 { 1556 return 0.0; 1557 } 1558 else 1559 { 1560 for (final Map.Entry<Long,AtomicLong> e : m.entrySet()) 1561 { 1562 if (d <= e.getKey()) 1563 { 1564 e.getValue().incrementAndGet(); 1565 break; 1566 } 1567 } 1568 1569 return d; 1570 } 1571 } 1572 1573 1574 1575 /** 1576 * Retrieves a list of the most frequently-occurring elements in the 1577 * provided map, paired with the number of times each value occurred. 1578 * 1579 * @param <K> The type of object used as the key for the provided map. 1580 * @param m The map to be examined. It is expected that the values of the 1581 * map will be the count of occurrences for the keys. 1582 * @param n The number of elements to return. 1583 * 1584 * @return A list of the most frequently-occurring elements in the provided 1585 * map. 1586 */ 1587 private static <K> List<ObjectPair<K,Long>> getMostCommonElements( 1588 final Map<K,AtomicLong> m, 1589 final int n) 1590 { 1591 final TreeMap<Long,List<K>> reverseMap = 1592 new TreeMap<Long,List<K>>(new ReverseComparator<Long>()); 1593 for (final Map.Entry<K,AtomicLong> e : m.entrySet()) 1594 { 1595 final Long count = e.getValue().get(); 1596 List<K> list = reverseMap.get(count); 1597 if (list == null) 1598 { 1599 list = new ArrayList<K>(n); 1600 reverseMap.put(count, list); 1601 } 1602 list.add(e.getKey()); 1603 } 1604 1605 final ArrayList<ObjectPair<K,Long>> returnList = 1606 new ArrayList<ObjectPair<K,Long>>(n); 1607 for (final Map.Entry<Long,List<K>> e : reverseMap.entrySet()) 1608 { 1609 final Long l = e.getKey(); 1610 for (final K k : e.getValue()) 1611 { 1612 returnList.add(new ObjectPair<K,Long>(k, l)); 1613 } 1614 1615 if (returnList.size() >= n) 1616 { 1617 break; 1618 } 1619 } 1620 1621 return returnList; 1622 } 1623 1624 1625 1626 /** 1627 * Writes a breakdown of the processing times for a specified type of 1628 * operation. 1629 * 1630 * @param t The name of the operation type. 1631 * @param n The total number of operations of the specified type that were 1632 * processed by the server. 1633 * @param m The map of operation counts by processing time bucket. 1634 */ 1635 private void printProcessingTimeHistogram(final String t, final long n, 1636 final LinkedHashMap<Long,AtomicLong> m) 1637 { 1638 if (n <= 0) 1639 { 1640 return; 1641 } 1642 1643 out(); 1644 out("Count of ", t, " operations by processing time:"); 1645 1646 long lowerBound = 0; 1647 long accumulatedCount = 0; 1648 final Iterator<Map.Entry<Long,AtomicLong>> i = m.entrySet().iterator(); 1649 while (i.hasNext()) 1650 { 1651 final Map.Entry<Long,AtomicLong> e = i.next(); 1652 final long upperBound = e.getKey(); 1653 final long count = e.getValue().get(); 1654 final double categoryPercent = 100.0 * count / n; 1655 1656 accumulatedCount += count; 1657 final double accumulatedPercent = 100.0 * accumulatedCount / n; 1658 1659 if (i.hasNext()) 1660 { 1661 out("Between ", lowerBound, "ms and ", upperBound, "ms: ", 1662 count, " (", decimalFormat.format(categoryPercent), "%, ", 1663 decimalFormat.format(accumulatedPercent), "% accumulated)"); 1664 lowerBound = upperBound; 1665 } 1666 else 1667 { 1668 out("Greater than ", lowerBound, "ms: ", count, " (", 1669 decimalFormat.format(categoryPercent), "%, ", 1670 decimalFormat.format(accumulatedPercent), "% accumulated)"); 1671 } 1672 } 1673 } 1674 1675 1676 1677 /** 1678 * Optionally prints information about the number and percent of operations of 1679 * the specified type that involved access to uncached data. 1680 * 1681 * @param operationType The type of operation. 1682 * @param numUncached The number of operations of the specified type that 1683 * involved access to uncached data. 1684 * @param numTotal The total number of operations of the specified 1685 * type. 1686 */ 1687 private void printUncached(final String operationType, final long numUncached, 1688 final long numTotal) 1689 { 1690 if (numUncached == 0) 1691 { 1692 return; 1693 } 1694 1695 out(operationType, ": ", numUncached, " (", 1696 decimalFormat.format(100.0 * numUncached / numTotal), "%)"); 1697 } 1698 }