    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    }