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 }