001: package com.protomatter.util;
002:
003: /**
004: * {{{ The Protomatter Software License, Version 1.0
005: * derived from The Apache Software License, Version 1.1
006: *
007: * Copyright (c) 1998-2002 Nate Sammons. All rights reserved.
008: *
009: * Redistribution and use in source and binary forms, with or without
010: * modification, are permitted provided that the following conditions
011: * are met:
012: *
013: * 1. Redistributions of source code must retain the above copyright
014: * notice, this list of conditions and the following disclaimer.
015: *
016: * 2. Redistributions in binary form must reproduce the above copyright
017: * notice, this list of conditions and the following disclaimer in
018: * the documentation and/or other materials provided with the
019: * distribution.
020: *
021: * 3. The end-user documentation included with the redistribution,
022: * if any, must include the following acknowledgment:
023: * "This product includes software developed for the
024: * Protomatter Software Project
025: * (http://protomatter.sourceforge.net/)."
026: * Alternately, this acknowledgment may appear in the software itself,
027: * if and wherever such third-party acknowledgments normally appear.
028: *
029: * 4. The names "Protomatter" and "Protomatter Software Project" must
030: * not be used to endorse or promote products derived from this
031: * software without prior written permission. For written
032: * permission, please contact support@protomatter.com.
033: *
034: * 5. Products derived from this software may not be called "Protomatter",
035: * nor may "Protomatter" appear in their name, without prior written
036: * permission of the Protomatter Software Project
037: * (support@protomatter.com).
038: *
039: * THIS SOFTWARE IS PROVIDED ``AS IS'' AND ANY EXPRESSED OR IMPLIED
040: * WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
041: * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
042: * DISCLAIMED. IN NO EVENT SHALL THE PROTOMATTER SOFTWARE PROJECT OR
043: * ITS CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
044: * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
045: * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
046: * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
047: * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
048: * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
049: * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
050: * SUCH DAMAGE. }}}
051: */
052:
053: import java.io.*;
054: import java.net.*;
055: import java.sql.*;
056: import java.util.*;
057: import java.text.*;
058:
059: import com.protomatter.util.*;
060:
061: /**
062: * A utility class for parsing log files with timer traces.
063: * Run this class as follows for a usage display:<P>
064: *
065: * <PRE>
066: * java com.protomatter.util.OpTimerUtil
067: * </PRE>
068: *
069: * Example output looks like the following:<P>
070: *
071: * <PRE><font size="-1"><B>
072: * Reading file "file.txt"
073: * Parsed 2843 lines.
074: * Found 1 unique timer names
075: * Found 2843 timer traces
076: *
077: * Timing information:
078: * ---------------------------------------------------------------------------
079: * OpTimer: My timer
080: * count = 2,843
081: * total = 222,946 ms
082: * min = 0 ms
083: * max = 360 ms
084: * median = 65 ms
085: * average = 78.42 ms
086: *
087: * Histogram:
088: * Median: ------------v
089: * Average: --------------v
090: * 132 o o
091: * o ooo o o
092: * ooooo o ooo o
093: * 88 oooooooo oooooo
094: * ooooooooooooooooooo
095: * ooooooooooooooooooooo
096: * 44 ooooooooooooooooooooooooo o
097: * ooooooooooooooooooooooooooooooo
098: * oooooooooooooooooooooooooooooooooooooo o
099: * count 0 ooooooooooooooooooooooooooooooooooooooooooooooooooooo ooooooo oo o
100: * | | | | | | |
101: * millis 0 58 116 175 233 291 349
102: *
103: * </B></font></PRE><P>
104: *
105: * The graph axes are automatically scaled for the data being parsed. This
106: * can be very useful for gathering statistics from log files to determine
107: * system bottlenecks.<P>
108: *
109: * Command line options include the ability to only display analytic data for
110: * a subset of the timers traced in a given log file.
111: *
112: * @see OpTimer
113: */
114: public class OpTimerUtil {
115: private static Map countMap = new HashMap();
116: private static Map totalMap = new HashMap();
117: private static Map minMap = new HashMap();
118: private static Map maxMap = new HashMap();
119: private static Map dataMap = new HashMap();
120: private static Collator collator = null;
121: private static Set nameSet = null;
122: private static Map nameMap = new HashMap();
123: private static Set displayNameSet = new HashSet();
124:
125: static {
126: collator = Collator.getInstance(new Locale("en", "US", ""));
127: nameSet = new TreeSet(collator);
128: }
129:
130: /**
131: * Private constructor so people don't go around creating these.
132: */
133: private OpTimerUtil() {
134: }
135:
136: private static void usage() {
137: System.out.println("");
138: System.out.println("Usage:");
139: System.out
140: .println(" java com.protomatter.util.OpTimer logfile.txt [timer_name_1 ... timer_name_N]");
141: System.out.println("");
142: System.out
143: .println("This program examines the given logfile to find all timers and then displays");
144: System.out
145: .println("aggregate timing information. Number of occurrences, min, max, and average");
146: System.out.println("times are reported.");
147: System.out.println("");
148: System.out
149: .println("If timers are named on the command line, then only those timers will be");
150: System.out
151: .println("analyzed. If none are named on the command line, then all timers found");
152: System.out.println("in the log file will be analyzed.");
153: System.exit(0);
154: }
155:
156: public static void main(String args[]) {
157: if (args.length == 0)
158: usage();
159:
160: for (int i = 1; i < args.length; i++)
161: displayNameSet.add(args[i]);
162:
163: try {
164: System.out.println("Reading file \"" + args[0] + "\"");
165: long startTime = System.currentTimeMillis();
166: BufferedReader reader = new BufferedReader(new FileReader(
167: new File(args[0])));
168:
169: String timerName = null;
170: long elapsed = 0;
171: String line = null;
172: long numLines = 0;
173: long numFound = 0;
174: int index0;
175: int index;
176: int index2;
177: int index3;
178: int index4;
179: String elapsedString = null;
180: while ((line = reader.readLine()) != null) {
181: numLines++;
182:
183: index = 0;
184: while ((index0 = line.indexOf("OpTimer[", index)) != -1) {
185: index = index0 + 8;
186: index2 = line.indexOf(", thread=", index);
187: if (index2 != -1) {
188: timerName = line.substring(index, index2);
189: index = index2 + 9;
190: index3 = line.indexOf(", took ", index);
191: if (index3 != -1) {
192: index = index3 + 7;
193: index4 = line.indexOf("ms]", index);
194: if (index4 != -1) {
195: elapsedString = line.substring(index,
196: index4);
197: index = index4 + 3;
198: try {
199: elapsed = Long
200: .parseLong(elapsedString);
201: ++numFound;
202: handleMatch(timerName, elapsed);
203: } catch (Exception x) {
204: ;
205: }
206: }
207: } else {
208: index = index2;
209: }
210: } else {
211: index2 = line.indexOf(", took ", index);
212: if (index2 != -1) {
213: timerName = line.substring(index, index2);
214: index = index2 + 7;
215: index3 = line.indexOf("ms]", index);
216: if (index3 != -1) {
217: elapsedString = line.substring(index,
218: index3);
219: index = index3 + 3;
220: try {
221: elapsed = Long
222: .parseLong(elapsedString);
223: ++numFound;
224: handleMatch(timerName, elapsed);
225: } catch (Exception x) {
226: ;
227: }
228: }
229: }
230: }
231: }
232: }
233: reader.close();
234: startTime = System.currentTimeMillis() - startTime;
235: double parseTime = ((double) startTime) / (double) 1000;
236:
237: DecimalFormat numberFormat = new DecimalFormat(
238: "###,###,###,###,##0.00");
239: DecimalFormat longFormat = new DecimalFormat(
240: "###,###,###,###,##0");
241:
242: System.out.println("Parse took "
243: + numberFormat.format(parseTime) + " sec.");
244: System.out.println("Parsed " + longFormat.format(numLines)
245: + " lines.");
246: System.out.println("Found "
247: + longFormat.format(nameSet.size())
248: + " unique timer names");
249: System.out.println("Found " + longFormat.format(numFound)
250: + " timer traces");
251: System.out.println("");
252: System.out.println("Timing information:");
253:
254: Iterator i = null;
255: if (displayNameSet.size() > 0)
256: i = displayNameSet.iterator();
257: else
258: i = nameSet.iterator();
259:
260: int timerId = 0;
261: while (i.hasNext()) {
262: timerName = (String) i.next();
263: if (!nameSet.contains(timerName))
264: continue;
265:
266: ++timerId;
267:
268: long min = ((Long) minMap.get(timerName)).longValue();
269: long max = ((Long) maxMap.get(timerName)).longValue();
270: long count = ((Long) countMap.get(timerName))
271: .longValue();
272: long total = ((Long) totalMap.get(timerName))
273: .longValue();
274: List data = (List) dataMap.get(timerName);
275:
276: Collections.sort(data, new Comparator() {
277: public int compare(Object o1, Object o2) {
278: long l1 = ((Long) o1).longValue();
279: long l2 = ((Long) o2).longValue();
280: if (l1 < l2)
281: return -1;
282: if (l1 == l2)
283: return 0;
284: return 1;
285: }
286:
287: public boolean equals(Object o) {
288: return false;
289: }
290: });
291:
292: long median = ((Long) data.get(data.size() / 2))
293: .longValue();
294:
295: double average = ((double) total) / ((double) count);
296:
297: System.out
298: .println("---------------------------------------------------------------------------");
299: System.out.println("OpTimer: " + timerName);
300: System.out.println(" count = "
301: + longFormat.format(count));
302: System.out.println(" total = "
303: + longFormat.format(total) + " ms");
304: System.out.println(" min = "
305: + longFormat.format(min) + " ms");
306: System.out.println(" max = "
307: + longFormat.format(max) + " ms");
308: System.out.println(" median = "
309: + longFormat.format(median) + " ms");
310: System.out.println(" average = "
311: + numberFormat.format(average) + " ms");
312: System.out.println("");
313: System.out.println(" Histogram:");
314: histogram(timerName, 80, 10);
315: System.out.println("");
316: System.out.println("");
317: }
318: } catch (Exception x) {
319: x.printStackTrace();
320: }
321: }
322:
323: private static void histogram(String timerName, int size, int height) {
324: size -= 12;
325: long min = ((Long) minMap.get(timerName)).longValue();
326: long max = ((Long) maxMap.get(timerName)).longValue();
327: long count = ((Long) countMap.get(timerName)).longValue();
328: long total = ((Long) totalMap.get(timerName)).longValue();
329: double average = ((double) total) / ((double) count);
330: List data = (List) dataMap.get(timerName);
331: double width = ((double) max) - ((double) min);
332: double bucket = width / (double) size;
333: double point;
334:
335: size++;
336: int graph[] = new int[size];
337: int middle = data.size() / 2;
338: double middlePoint = (double) ((Long) data.get(middle))
339: .longValue();
340:
341: for (int i = 0; i < data.size(); i++) {
342: point = (double) (((Long) data.get(i)).longValue() - min);
343: int position = (int) (point / bucket);
344: graph[position]++;
345: }
346:
347: int top = 0;
348: for (int i = 0; i < size; i++) {
349: if (graph[i] > top)
350: top = graph[i];
351: }
352:
353: DecimalFormat yFormat = new DecimalFormat("#########");
354: DecimalFormat xFormat = new DecimalFormat("#######");
355: double heightBucket = ((double) top) / ((double) height);
356:
357: System.out.print(right("Median: ", 10));
358: boolean mid = false;
359: for (int x = 0; x <= size && !mid; x++) {
360: double val = (bucket * (double) x) + (double) min;
361: double nextVal = (bucket * (double) (x + 1)) + (double) min;
362: if ((val <= middlePoint) && (middlePoint < nextVal)) {
363: System.out.println("v");
364: mid = true;
365: } else if (val < average) {
366: System.out.print("-");
367: }
368: }
369:
370: System.out.print(right("Average: ", 10));
371: boolean avg = false;
372: for (int x = 0; x <= size && !avg; x++) {
373: double val = (bucket * (double) x) + (double) min;
374: double nextVal = (bucket * (double) (x + 1)) + (double) min;
375: if ((val <= average) && (average < nextVal)) {
376: System.out.println("v");
377: avg = true;
378: } else if (val < average) {
379: System.out.print("-");
380: }
381: }
382:
383: for (int y = (height - 1); y >= 0; y--) {
384: if ((y % 3) == 0) {
385: double localMin = (heightBucket * (double) y)
386: + (double) min;
387: if (y == 0) {
388: System.out.print(right("count 0", 9));
389: } else {
390: System.out
391: .print(right(yFormat.format(localMin), 9));
392: }
393: } else {
394: System.out.print(right("", 9));
395: }
396:
397: System.out.print(" ");
398: for (int x = 0; x < size; x++) {
399: if (graph[x] > (int) (heightBucket * (double) y))
400: System.out.print("o");
401: else
402: System.out.print(" ");
403: }
404: System.out.println("");
405: }
406:
407: int xTick = 11;
408: System.out.print(left("", 10));
409: for (int x = 0; x <= size; x++) {
410: if ((x % xTick) == 0) {
411: if (x == 0) {
412: System.out.print("|");
413: } else {
414: System.out.print(right("|", xTick));
415: }
416: }
417: }
418: System.out.println("");
419:
420: System.out.print(right("millis ", 10));
421: for (int x = 0; x <= size; x++) {
422: if ((x % xTick) == 0) {
423: if (x == 0) {
424: System.out.print("0");
425: } else {
426: System.out.print(right(xFormat.format((bucket * x)
427: + min), xTick));
428: }
429: }
430: }
431: System.out.println("");
432: }
433:
434: private static String left(String text, int width) {
435: StringBuffer b = new StringBuffer(width);
436: b.append(text);
437: int size = width - text.length();
438: for (int i = 0; i < size; i++)
439: b.append(" ");
440: return b.toString();
441: }
442:
443: private static String right(String text, int width) {
444: StringBuffer b = new StringBuffer(width);
445: int size = width - text.length();
446: for (int i = 0; i < size; i++)
447: b.append(" ");
448: b.append(text);
449: return b.toString();
450: }
451:
452: private static void handleMatch(String timerName, long elapsed) {
453: if ((displayNameSet.size() > 0)
454: && (!displayNameSet.contains(timerName)))
455: return;
456:
457: nameSet.add(timerName);
458:
459: List data = (List) dataMap.get(timerName);
460: if (data == null) {
461: data = new ArrayList();
462: dataMap.put(timerName, data);
463: }
464: data.add(new Long(elapsed));
465: Long longVal = (Long) totalMap.get(timerName);
466: if (longVal == null) {
467: longVal = new Long(elapsed);
468: } else {
469: longVal = new Long(longVal.longValue() + elapsed);
470: }
471: totalMap.put(timerName, longVal);
472:
473: longVal = (Long) countMap.get(timerName);
474: if (longVal == null) {
475: longVal = new Long(1);
476: } else {
477: longVal = new Long(longVal.longValue() + 1);
478: }
479: countMap.put(timerName, longVal);
480:
481: longVal = (Long) minMap.get(timerName);
482: if (longVal == null) {
483: longVal = new Long(elapsed);
484: } else {
485: if (longVal.longValue() > elapsed)
486: longVal = new Long(elapsed);
487: }
488: minMap.put(timerName, longVal);
489:
490: longVal = (Long) maxMap.get(timerName);
491: if (longVal == null) {
492: longVal = new Long(elapsed);
493: } else {
494: if (longVal.longValue() < elapsed)
495: longVal = new Long(elapsed);
496: }
497: maxMap.put(timerName, longVal);
498: }
499: }
|