001 /** 002 * Copyright 2007-2008 Arthur Blake 003 * 004 * Licensed under the Apache License, Version 2.0 (the "License"); 005 * you may not use this file except in compliance with the License. 006 * You may obtain a copy of the License at 007 * 008 * http://www.apache.org/licenses/LICENSE-2.0 009 * 010 * Unless required by applicable law or agreed to in writing, software 011 * distributed under the License is distributed on an "AS IS" BASIS, 012 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 013 * See the License for the specific language governing permissions and 014 * limitations under the License. 015 */ 016 package net.sf.log4jdbc; 017 018 import java.io.FileReader; 019 import java.io.LineNumberReader; 020 import java.io.PrintStream; 021 import java.util.List; 022 import java.util.LinkedList; 023 import java.util.Arrays; 024 025 /** 026 * Post processes an existing sqltiming log, and creates a profiling report from it. 027 * Name of log file is passed in on the command line as the only argument. 028 * 029 * Assumptions: 030 * 031 * 1. Each sql statement in the log is separated by a blank line. 032 * 2. Each sql statement is terminated with the timing string "{executed in N msec}" where N is the number of 033 * milliseconds that the sql executed in. 034 * 035 */ 036 public class PostLogProfilerProcessor { 037 038 //todo: needs to be able to gracefully handle sql exceptions in log output 039 040 /** 041 * Post Process log4jdbc sqltiming log data. 042 * 043 * @param args command line arguments. Expects one argument, the name of the file to post process. 044 * @throws Exception if something goes wrong during processing. 045 */ 046 public static void main(String[] args) throws Exception 047 { 048 if (args.length < 1) 049 { 050 System.out.println("usage: java PostLogProfilerProcessor <log-file>"); 051 System.exit(1); 052 } 053 new PostLogProfilerProcessor(args[0], System.out); 054 } 055 056 /** 057 * Total number of sql statements processed. 058 */ 059 private long totalSql = 0L; 060 061 /** 062 * Number of lines processed. 063 */ 064 private long lineNo = 0L; 065 066 /** 067 * Total number of milliseconds that all processed sql took to run. 068 */ 069 private long totalMsec = 0L; 070 071 /** 072 * Milliseconds of the worst single offending sql statement. 073 */ 074 private long maxMsec = 0L; 075 076 /** 077 * Total combined milliseconds of all flagged sql statements. 078 */ 079 private long flaggedSqlTotalMsec = 0L; 080 081 /** 082 * Threshold at which sql is deemed to be running slow enough to be flagged. 083 */ 084 private long threshold = 100L; 085 086 /** 087 * How many top offender sql statements to display in final report 088 */ 089 private long topOffenderCount = 1000L; 090 091 /** 092 * Collection of all sql that took longer than "threshold" msec to run. 093 */ 094 private List flaggedSql = new LinkedList(); 095 096 /** 097 * Process given filename, and produce sql profiling report to given PrintStream. 098 * 099 * @param filename sqltiming log to process. 100 * @param out PrintStream to write profiling report to. 101 * @throws Exception if reading error occurs. 102 */ 103 public PostLogProfilerProcessor (String filename, PrintStream out) throws Exception 104 { 105 FileReader f= new FileReader(filename); 106 LineNumberReader l = new LineNumberReader(f); 107 108 String line; 109 boolean blankLine; 110 111 StringBuffer sql = new StringBuffer(); 112 113 do 114 { 115 line = l.readLine(); 116 117 if (line != null) 118 { 119 blankLine = line.length()==0; 120 lineNo++; 121 /* 122 if (lineNo%100000L==0L) 123 { 124 out.println("" + lineNo + " lines..."); 125 } 126 */ 127 if (blankLine) 128 { 129 processSql(sql); 130 sql = new StringBuffer(); 131 } 132 else 133 { 134 sql.append(line); 135 } 136 137 } 138 } while (line != null); 139 140 out.println("processed " + lineNo + " lines."); 141 142 f.close(); 143 144 // display report to stdout 145 146 out.println("Number of sql statements: " + totalSql); 147 out.println("Total number of msec : " + totalMsec); 148 if (totalMsec>0) 149 { 150 out.println("Average msec/statement : " + totalSql/totalMsec); 151 } 152 153 int flaggedSqlStmts = flaggedSql.size(); 154 155 if (flaggedSqlStmts>0) 156 { 157 out.println("Sql statements that took more than "+ threshold + " msec were flagged."); 158 out.println("Flagged sql statements : " + flaggedSqlStmts); 159 out.println("Flagged sql Total number of msec : " + flaggedSqlTotalMsec); 160 out.println("Flagged sql Average msec/statement : " + flaggedSqlTotalMsec/flaggedSqlStmts); 161 162 out.println("sorting..."); 163 164 Object[] flaggedSqlArray = flaggedSql.toArray(); 165 Arrays.sort(flaggedSqlArray); 166 167 int execTimeSize = ("" + maxMsec).length(); 168 169 170 if (topOffenderCount > flaggedSqlArray.length) 171 { 172 topOffenderCount = flaggedSqlArray.length; 173 } 174 175 out.println("top " + topOffenderCount + " offender"+ (topOffenderCount==1?"":"s") + ":"); 176 177 ProfiledSql p; 178 179 for (int i=0; i < topOffenderCount; i++) 180 { 181 p = (ProfiledSql) flaggedSqlArray[i]; 182 out.println(Utilities.rightJustify(execTimeSize,""+p.getExecTime()) + " " + p.getSql()); 183 } 184 } 185 } 186 187 188 private void processSql(StringBuffer sql) 189 { 190 if (sql.length()>0) 191 { 192 totalSql++; 193 String sqlStr = sql.toString(); 194 if (sqlStr.endsWith("msec}")) 195 { 196 int executedIn = sqlStr.indexOf("{executed in "); 197 if (executedIn == -1) 198 { 199 System.err.println("WARNING: sql w/o timing info found at line " + lineNo); 200 return; 201 } 202 203 //todo: proper error handling for parse 204 String msecStr = sqlStr.substring(executedIn+13, sqlStr.length()-6); 205 long msec = Long.parseLong(msecStr); 206 totalMsec +=msec; 207 if (msec > maxMsec) 208 { 209 maxMsec = msec; 210 } 211 212 if (msec >threshold) 213 { 214 flagSql(msec,sqlStr); 215 flaggedSqlTotalMsec += msec; 216 } 217 } 218 else 219 { 220 System.err.println("WARNING: sql w/o timing info found at line " + lineNo); 221 } 222 } 223 } 224 225 private void flagSql(long msec, String sql) 226 { 227 flaggedSql.add(new ProfiledSql(msec,sql)); 228 } 229 230 private class ProfiledSql implements Comparable { 231 private Long execTime; 232 private String sql; 233 234 public ProfiledSql (long msec, String sql) 235 { 236 this.execTime= new Long(msec); 237 this.sql = sql; 238 } 239 240 /** 241 * Compares this object with the specified object for order. Returns a 242 * negative integer, zero, or a positive integer as this object is less 243 * than, equal to, or greater than the specified object.<p> 244 * 245 * In this case the comparison is used to sort flagged sql in descending order. 246 * @param o ProfiledSql Object to compare to this ProfiledSql. Must not be null. 247 */ 248 public int compareTo(Object o) { 249 return ((ProfiledSql)o).execTime.compareTo(execTime); 250 } 251 252 public Long getExecTime() { 253 return execTime; 254 } 255 256 public String getSql() { 257 return sql; 258 } 259 260 public String toString() 261 { 262 return this.execTime + " msec: " + this.sql; 263 } 264 } 265 }