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    }