dblib/common/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java

   1 /*-
   2  * ============LICENSE_START=======================================================
   3  * openecomp
   4  * ================================================================================
   5  * Copyright (C) 2016 - 2017 AT&T
   6  * ================================================================================
   7  * Licensed under the Apache License, Version 2.0 (the "License");
   8  * you may not use this file except in compliance with the License.
   9  * You may obtain a copy of the License at
  10  *
  11  *      http://www.apache.org/licenses/LICENSE-2.0
  12  *
  13  * Unless required by applicable law or agreed to in writing, software
  14  * distributed under the License is distributed on an "AS IS" BASIS,
  15  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  16  * See the License for the specific language governing permissions and
  17  * limitations under the License.
  18  * ============LICENSE_END=========================================================
  19  */
  20
  21 /*
  22  * Licensed to the Apache Software Foundation (ASF) under one or more
  23  * contributor license agreements.  See the NOTICE file distributed with
  24  * this work for additional information regarding copyright ownership.
  25  * The ASF licenses this file to You under the Apache License, Version 2.0
  26  * (the "License"); you may not use this file except in compliance with
  27  * the License.  You may obtain a copy of the License at
  28  *
  29  *      http://www.apache.org/licenses/LICENSE-2.0
  30  *
  31  * Unless required by applicable law or agreed to in writing, software
  32  * distributed under the License is distributed on an "AS IS" BASIS,
  33  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  34  * See the License for the specific language governing permissions and
  35  * limitations under the License.
  36  */
  37 package org.apache.tomcat.jdbc.pool.interceptor;
  38
  39 import java.text.SimpleDateFormat;
  40 import java.util.ArrayList;
  41 import java.util.Collections;
  42 import java.util.Comparator;
  43 import java.util.Locale;
  44 import java.util.Map;
  45 import java.util.TimeZone;
  46 import java.util.concurrent.ConcurrentHashMap;
  47
  48 import javax.management.openmbean.CompositeDataSupport;
  49 import javax.management.openmbean.CompositeType;
  50 import javax.management.openmbean.OpenDataException;
  51 import javax.management.openmbean.OpenType;
  52 import javax.management.openmbean.SimpleType;
  53
  54 import org.apache.juli.logging.Log;
  55 import org.apache.juli.logging.LogFactory;
  56 import org.apache.tomcat.jdbc.pool.ConnectionPool;
  57 import org.apache.tomcat.jdbc.pool.PoolProperties.InterceptorProperty;
  58 import org.apache.tomcat.jdbc.pool.PooledConnection;
  59
  60 /**
  61  * Slow query report interceptor. Tracks timing of query executions.
  62  * @version 1.0
  63  */
  64 public class SlowQueryReport extends AbstractQueryReport  {
  65     //logger
  66     private static final Log log = LogFactory.getLog(SlowQueryReport.class);
  67
  68     /**
  69      * we will be keeping track of query stats on a per pool basis
  70      */
  71     protected static final ConcurrentHashMap<String,ConcurrentHashMap<String,QueryStats>> perPoolStats =
  72         new ConcurrentHashMap<>();
  73     /**
  74      * the queries that are used for this interceptor.
  75      */
  76     protected volatile ConcurrentHashMap<String,QueryStats> queries = null;
  77     /**
  78      * Maximum number of queries we will be storing
  79      */
  80     protected int  maxQueries= 1000; //don't store more than this amount of queries
  81
  82     /**
  83      * Flag to enable disable logging of slow queries
  84      */
  85     protected boolean logSlow = true;
  86
  87     /**
  88      * Flag to enable disable logging of failed queries
  89      */
  90     protected boolean logFailed = false;
  91
  92     /**
  93      * Sort QueryStats by last invocation time
  94      */
  95     protected final Comparator<QueryStats> queryStatsComparator = new QueryStatsComparator();
  96
  97     /**
  98      * Returns the query stats for a given pool
  99      * @param poolname - the name of the pool we want to retrieve stats for
 100      * @return a hash map containing statistics for 0 to maxQueries
 101      */
 102     public static ConcurrentHashMap<String,QueryStats> getPoolStats(String poolname) {
 103         return perPoolStats.get(poolname);
 104     }
 105
 106     /**
 107      * Creates a slow query report interceptor
 108      */
 109     public SlowQueryReport() {
 110         super();
 111     }
 112
 113     public void setMaxQueries(int maxQueries) {
 114         this.maxQueries = maxQueries;
 115     }
 116
 117
 118     @Override
 119     protected String reportFailedQuery(String query, Object[] args, String name, long start, Throwable t) {
 120         String sql = super.reportFailedQuery(query, args, name, start, t);
 121         if (this.maxQueries > 0 ) {
 122             long now = System.currentTimeMillis();
 123             long delta = now - start;
 124             QueryStats qs = this.getQueryStats(sql);
 125             if (qs != null) {
 126                 qs.failure(delta, now);
 127                 if (isLogFailed() && log.isWarnEnabled()) {
 128                     log.warn("Failed Query Report SQL="+sql+"; time="+delta+" ms;");
 129                 }
 130             }
 131         }
 132         return sql;
 133     }
 134
 135     @Override
 136     protected String reportQuery(String query, Object[] args, final String name, long start, long delta) {
 137         String sql = super.reportQuery(query, args, name, start, delta);
 138         if (this.maxQueries > 0 ) {
 139             QueryStats qs = this.getQueryStats(sql);
 140             if (qs != null) qs.add(delta, start);
 141         }
 142         return sql;
 143     }
 144
 145     @Override
 146     protected String reportSlowQuery(String query, Object[] args, String name, long start, long delta) {
 147         String sql = super.reportSlowQuery(query, args, name, start, delta);
 148         if (this.maxQueries > 0 ) {
 149             QueryStats qs = this.getQueryStats(sql);
 150             if (qs != null) {
 151                 qs.add(delta, start);
 152                 if (isLogSlow() && log.isWarnEnabled()) {
 153                     log.warn("Slow Query Report SQL="+sql+"; time="+delta+" ms;");
 154                 }
 155             }
 156         }
 157         return sql;
 158     }
 159
 160     /**
 161      * invoked when the connection receives the close request
 162      * Not used for now.
 163      */
 164     @Override
 165     public void closeInvoked() {
 166         // NOOP
 167     }
 168
 169     @Override
 170     public void prepareStatement(String sql, long time) {
 171         if (this.maxQueries > 0 ) {
 172             QueryStats qs = getQueryStats(sql);
 173             if (qs != null) qs.prepare(time);
 174         }
 175     }
 176
 177     @Override
 178     public void prepareCall(String sql, long time) {
 179         if (this.maxQueries > 0 ) {
 180             QueryStats qs = getQueryStats(sql);
 181             if (qs != null) qs.prepare(time);
 182         }
 183     }
 184
 185     /**
 186      * {@inheritDoc}
 187      */
 188     @Override
 189     public void poolStarted(ConnectionPool pool) {
 190         super.poolStarted(pool);
 191         //see if we already created a map for this pool
 192         queries = SlowQueryReport.perPoolStats.get(pool.getName());
 193         if (queries==null) {
 194             //create the map to hold our stats
 195             //however TODO we need to improve the eviction
 196             //selection
 197             queries = new ConcurrentHashMap<>();
 198             if (perPoolStats.putIfAbsent(pool.getName(), queries)!=null) {
 199                 //there already was one
 200                 queries = SlowQueryReport.perPoolStats.get(pool.getName());
 201             }
 202         }
 203     }
 204
 205     /**
 206      * {@inheritDoc}
 207      */
 208     @Override
 209     public void poolClosed(ConnectionPool pool) {
 210         perPoolStats.remove(pool.getName());
 211         super.poolClosed(pool);
 212     }
 213
 214     protected QueryStats getQueryStats(String sql) {
 215         if (sql==null) sql = "";
 216         ConcurrentHashMap<String,QueryStats> queries = SlowQueryReport.this.queries;
 217         if (queries==null) {
 218             if (log.isWarnEnabled()) log.warn("Connection has already been closed or abandoned");
 219             return null;
 220         }
 221         QueryStats qs = queries.get(sql);
 222         if (qs == null) {
 223             qs = new QueryStats(sql);
 224             if (queries.putIfAbsent(sql,qs)!=null) {
 225                 qs = queries.get(sql);
 226             } else {
 227                 //we added a new element, see if we need to remove the oldest
 228                 if (queries.size() > maxQueries) {
 229                     removeOldest(queries);
 230                 }
 231             }
 232         }
 233         return qs;
 234     }
 235
 236     /**
 237      * Sort QueryStats by last invocation time
 238      * @param queries The queries map
 239      */
 240     protected void removeOldest(ConcurrentHashMap<String,QueryStats> queries) {
 241         ArrayList<QueryStats> list = new ArrayList<>(queries.values());
 242         Collections.sort(list, queryStatsComparator);
 243         int removeIndex = 0;
 244         while (queries.size() > maxQueries) {
 245             String sql = list.get(removeIndex).getQuery();
 246             queries.remove(sql);
 247             if (log.isDebugEnabled()) log.debug("Removing slow query, capacity reached:"+sql);
 248             removeIndex++;
 249         }
 250     }
 251
 252
 253     @Override
 254     public void reset(ConnectionPool parent, PooledConnection con) {
 255         super.reset(parent, con);
 256         if (parent!=null)
 257             queries = SlowQueryReport.perPoolStats.get(parent.getName());
 258         else
 259             queries = null;
 260     }
 261
 262
 263     public boolean isLogSlow() {
 264         return logSlow;
 265     }
 266
 267     public void setLogSlow(boolean logSlow) {
 268         this.logSlow = logSlow;
 269     }
 270
 271     public boolean isLogFailed() {
 272         return logFailed;
 273     }
 274
 275     public void setLogFailed(boolean logFailed) {
 276         this.logFailed = logFailed;
 277     }
 278
 279     @Override
 280     public void setProperties(Map<String, InterceptorProperty> properties) {
 281         super.setProperties(properties);
 282         final String threshold = "threshold";
 283         final String maxqueries= "maxQueries";
 284         final String logslow = "logSlow";
 285         final String logfailed = "logFailed";
 286         InterceptorProperty p1 = properties.get(threshold);
 287         InterceptorProperty p2 = properties.get(maxqueries);
 288         InterceptorProperty p3 = properties.get(logslow);
 289         InterceptorProperty p4 = properties.get(logfailed);
 290         if (p1!=null) {
 291             setThreshold(Long.parseLong(p1.getValue()));
 292         }
 293         if (p2!=null) {
 294             setMaxQueries(Integer.parseInt(p2.getValue()));
 295         }
 296         if (p3!=null) {
 297             setLogSlow(Boolean.parseBoolean(p3.getValue()));
 298         }
 299         if (p4!=null) {
 300             setLogFailed(Boolean.parseBoolean(p4.getValue()));
 301         }
 302     }
 303
 304
 305     public static class QueryStats {
 306         static final String[] FIELD_NAMES = new String[] {
 307             "query",
 308             "nrOfInvocations",
 309             "maxInvocationTime",
 310             "maxInvocationDate",
 311             "minInvocationTime",
 312             "minInvocationDate",
 313             "totalInvocationTime",
 314             "failures",
 315             "prepareCount",
 316             "prepareTime",
 317             "lastInvocation"
 318         };
 319
 320         static final  String[] FIELD_DESCRIPTIONS = new String[] {
 321             "The SQL query",
 322             "The number of query invocations, a call to executeXXX",
 323             "The longest time for this query in milliseconds",
 324             "The time and date for when the longest query took place",
 325             "The shortest time for this query in milliseconds",
 326             "The time and date for when the shortest query took place",
 327             "The total amount of milliseconds spent executing this query",
 328             "The number of failures for this query",
 329             "The number of times this query was prepared (prepareStatement/prepareCall)",
 330             "The total number of milliseconds spent preparing this query",
 331             "The date and time of the last invocation"
 332         };
 333
 334         static final OpenType<?>[] FIELD_TYPES = new OpenType[] {
 335             SimpleType.STRING,
 336             SimpleType.INTEGER,
 337             SimpleType.LONG,
 338             SimpleType.LONG,
 339             SimpleType.LONG,
 340             SimpleType.LONG,
 341             SimpleType.LONG,
 342             SimpleType.LONG,
 343             SimpleType.INTEGER,
 344             SimpleType.LONG,
 345             SimpleType.LONG
 346         };
 347
 348         private final String query;
 349         private volatile int nrOfInvocations;
 350         private volatile long maxInvocationTime = Long.MIN_VALUE;
 351         private volatile long maxInvocationDate;
 352         private volatile long minInvocationTime = Long.MAX_VALUE;
 353         private volatile long minInvocationDate;
 354         private volatile long totalInvocationTime;
 355         private volatile long failures;
 356         private volatile int prepareCount;
 357         private volatile long prepareTime;
 358         private volatile long lastInvocation = 0;
 359
 360         public static String[] getFieldNames() {
 361             return FIELD_NAMES;
 362         }
 363
 364         public static String[] getFieldDescriptions() {
 365             return FIELD_DESCRIPTIONS;
 366         }
 367
 368         public static OpenType<?>[] getFieldTypes() {
 369             return FIELD_TYPES;
 370         }
 371
 372         @Override
 373         public String toString() {
 374             SimpleDateFormat sdf =
 375                     new SimpleDateFormat("d MMM yyyy HH:mm:ss z", Locale.US);
 376             sdf.setTimeZone(TimeZone.getTimeZone("GMT"));
 377             StringBuilder buf = new StringBuilder("QueryStats[query:");
 378             buf.append(query);
 379             buf.append(", nrOfInvocations:");
 380             buf.append(nrOfInvocations);
 381             buf.append(", maxInvocationTime:");
 382             buf.append(maxInvocationTime);
 383             buf.append(", maxInvocationDate:");
 384             buf.append(sdf.format(new java.util.Date(maxInvocationDate)));
 385             buf.append(", minInvocationTime:");
 386             buf.append(minInvocationTime);
 387             buf.append(", minInvocationDate:");
 388             buf.append(sdf.format(new java.util.Date(minInvocationDate)));
 389             buf.append(", totalInvocationTime:");
 390             buf.append(totalInvocationTime);
 391             buf.append(", averageInvocationTime:");
 392             buf.append((float)totalInvocationTime / (float)nrOfInvocations);
 393             buf.append(", failures:");
 394             buf.append(failures);
 395             buf.append(", prepareCount:");
 396             buf.append(prepareCount);
 397             buf.append(", prepareTime:");
 398             buf.append(prepareTime);
 399             buf.append("]");
 400             return buf.toString();
 401         }
 402
 403         public CompositeDataSupport getCompositeData(final CompositeType type) throws OpenDataException{
 404             Object[] values = new Object[] {
 405                     query,
 406                     Integer.valueOf(nrOfInvocations),
 407                     Long.valueOf(maxInvocationTime),
 408                     Long.valueOf(maxInvocationDate),
 409                     Long.valueOf(minInvocationTime),
 410                     Long.valueOf(minInvocationDate),
 411                     Long.valueOf(totalInvocationTime),
 412                     Long.valueOf(failures),
 413                     Integer.valueOf(prepareCount),
 414                     Long.valueOf(prepareTime),
 415                     Long.valueOf(lastInvocation)
 416             };
 417             return new CompositeDataSupport(type,FIELD_NAMES,values);
 418         }
 419
 420         public QueryStats(String query) {
 421             this.query = query;
 422         }
 423
 424         public void prepare(long invocationTime) {
 425             prepareCount++;
 426             prepareTime+=invocationTime;
 427
 428         }
 429
 430         public void add(long invocationTime, long now) {
 431             //not thread safe, but don't sacrifice performance for this kind of stuff
 432             maxInvocationTime = Math.max(invocationTime, maxInvocationTime);
 433             if (maxInvocationTime == invocationTime) {
 434                 maxInvocationDate = now;
 435             }
 436             minInvocationTime = Math.min(invocationTime, minInvocationTime);
 437             if (minInvocationTime==invocationTime) {
 438                 minInvocationDate = now;
 439             }
 440             nrOfInvocations++;
 441             totalInvocationTime+=invocationTime;
 442             lastInvocation = now;
 443         }
 444
 445         public void failure(long invocationTime, long now) {
 446             add(invocationTime,now);
 447             failures++;
 448
 449         }
 450
 451         public String getQuery() {
 452             return query;
 453         }
 454
 455         public int getNrOfInvocations() {
 456             return nrOfInvocations;
 457         }
 458
 459         public long getMaxInvocationTime() {
 460             return maxInvocationTime;
 461         }
 462
 463         public long getMaxInvocationDate() {
 464             return maxInvocationDate;
 465         }
 466
 467         public long getMinInvocationTime() {
 468             return minInvocationTime;
 469         }
 470
 471         public long getMinInvocationDate() {
 472             return minInvocationDate;
 473         }
 474
 475         public long getTotalInvocationTime() {
 476             return totalInvocationTime;
 477         }
 478
 479         @Override
 480         public int hashCode() {
 481             return query.hashCode();
 482         }
 483
 484         @Override
 485         public boolean equals(Object other) {
 486             if (other instanceof QueryStats) {
 487                 QueryStats qs = (QueryStats)other;
 488                 return qs.query.equals(this.query);
 489             }
 490             return false;
 491         }
 492
 493         public boolean isOlderThan(QueryStats other) {
 494             return this.lastInvocation < other.lastInvocation;
 495         }
 496     }
 497
 498     /** Compare QueryStats by their lastInvocation value. QueryStats that
 499      * have never been updated, have a lastInvocation value of {@code 0}
 500      * which should be handled as the newest possible invocation.
 501      */
 502     private static class QueryStatsComparator implements Comparator<QueryStats> {
 503
 504         @Override
 505         public int compare(QueryStats stats1, QueryStats stats2) {
 506             return Long.compare(handleZero(stats1.lastInvocation),
 507                     handleZero(stats2.lastInvocation));
 508         }
 509
 510         private static long handleZero(long value) {
 511             return value == 0 ? Long.MAX_VALUE : value;
 512         }
 513
 514     }
 515
 516 }