/*
* eXist Open Source Native XML Database
* Copyright (C) 2001-06 The eXist Project
* http://exist-db.org
*
* This program is free software; you can redistribute it and/or
* modify it under the terms of the GNU Lesser General Public License
* as published by the Free Software Foundation; either version 2
* of the License, or (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU Lesser General Public License for more details.
*
* You should have received a copy of the GNU Lesser General Public License
* along with this program; if not, write to the Free Software
* Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA.
*
* $Id$
*/
package org.exist.xquery;
import java.util.Stack;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.exist.Database;
import org.exist.storage.DBBroker;
import org.exist.xquery.value.Sequence;
/**
* XQuery profiling output. Profiling information is written to a
* logger. The profiler can be enabled/disabled and configured
* via an XQuery pragma or "declare option" expression. Example:
*
* <pre>declare option exist:profiling "enabled=yes verbosity=10 logger=profiler";</pre>
*
* @author wolf
*
*/
public class Profiler {
/** value for Verbosity property: basic profiling : just elapsed time */
public static final int TIME = 1;
/** value for Verbosity property: For optimizations */
public static final int OPTIMIZATIONS = 2;
/** For computations that will trigger further optimizations */
public static final int OPTIMIZATION_FLAGS = 3;
/** Indicates the dependencies of the expression */
public static final int DEPENDENCIES = 4;
/** An abstract level for viewing the expression's context sequence/item */
public static final int START_SEQUENCES = 4;
/** Just returns the number of items in the sequence */
public static final int ITEM_COUNT = 5;
/** For a truncated string representation of the context sequence (TODO) */
public static final int SEQUENCE_PREVIEW = 6;
/** For a full representation of the context sequence (TODO) */
public static final int SEQUENCE_DUMP = 8;
public static final String CONFIG_PROPERTY_TRACELOG = "xquery.profiling.tracelog";
/**
* The logger where all output goes.
*/
private Logger log = LogManager.getLogger("xquery.profiling");
private Stack<ProfiledExpr> stack = new Stack<ProfiledExpr>();
private final StringBuilder buf = new StringBuilder(64);
private boolean enabled = false;
private boolean logEnabled = false;
private int verbosity = 0;
private PerformanceStats stats;
private long queryStart = 0;
private Database db;
public Profiler(Database db) {
this.db = db;
this.stats = new PerformanceStats(db);
}
/**
* Configure the profiler from an XQuery pragma.
* Parameters are:
*
* <ul>
* <li><strong>enabled</strong>: yes|no.</li>
* <li><strong>logger</strong>: name of the logger to use.</li>
* <li><strong>verbosity</strong>: integer value > 0. 1 does only output function calls.</li>
* </ul>
* @param pragma
*/
public final void configure(Option pragma) {
final String options[] = pragma.tokenizeContents();
String params[];
for (int i = 0; i < options.length; i++) {
params = Option.parseKeyValuePair(options[i]);
if (params != null) {
if ("trace".equals(params[0])) {
stats.setEnabled(true);
} else if ("tracelog".equals(params[0])) {
logEnabled = "yes".equals(params[1]);
} else if ("logger".equals(params[0])) {
log = LogManager.getLogger(params[1]);
} else if ("enabled".equals(params[0])) {
enabled = "yes".equals(params[1]);
} else if ("verbosity".equals(params[0])) {
try {
verbosity = Integer.parseInt(params[1]);
} catch (final NumberFormatException e) {
log.warn( "invalid value for verbosity: " +
"should be an integer between 0 and " +
SEQUENCE_DUMP );
}
}
}
}
if (verbosity == 0)
{enabled=false;}
}
/**
* Is profiling enabled?
*
* @return True if profiling is enabled
*/
public final boolean isEnabled() {
return enabled;
}
public final boolean isLogEnabled() {
try {
final DBBroker broker = db.getActiveBroker();
final Boolean globalProp = (Boolean) broker.getConfiguration().getProperty(CONFIG_PROPERTY_TRACELOG);
return logEnabled || (globalProp != null && globalProp.booleanValue());
} catch (Throwable t) {
log.debug("Ignored exception: " + t.getMessage());
return logEnabled;
}
}
public final void setLogEnabled(boolean enabled) {
logEnabled = enabled;
}
public final boolean traceFunctions() {
return stats.isEnabled() || isLogEnabled();
}
/**
* @return the verbosity of the profiler.
*/
public final int verbosity() {
return verbosity;
}
public final void traceQueryStart() {
queryStart = System.currentTimeMillis();
}
public final void traceQueryEnd(XQueryContext context) {
stats.recordQuery(context.getSource().path(), (System.currentTimeMillis() - queryStart));
}
public final void traceFunctionStart(Function function) {
if (isLogEnabled()) {
log.trace(String.format("ENTER %-25s", function.getSignature().getName()));
}
}
public final void traceFunctionEnd(Function function, long elapsed) {
if (stats.isEnabled()) {
final String source = String.format("%s [%d:%d]", function.getContext().getSource().getKey(),
function
.getLine(), function.getColumn());
stats.recordFunctionCall(function.getSignature().getName(), source, elapsed);
}
if (isLogEnabled()) {
log.trace(String.format("EXIT %-25s %10d ms", function.getSignature().getName(), elapsed));
}
}
public final void traceIndexUsage(XQueryContext context, String indexType, Expression expression, int mode, long elapsed) {
stats.recordIndexUse(expression, indexType, context.getSource().path(), mode, elapsed);
}
private void save() {
if (db != null) {
db.getPerformanceStats().merge(stats);
}
}
/**
* Called by an expression to indicate the start of an operation.
* The profiler registers the start time.
*
* @param expr the expression.
*/
public final void start(Expression expr) {
start(expr, null);
}
/**
* Called by an expression to indicate the start of an operation.
* The profiler registers the start time.
*
* @param expr the expression.
* @param message if not null, contains an optional message to print in the log.
*/
public final void start(Expression expr, String message) {
if (!enabled)
{return;}
if (stack.size() == 0) {
log.debug("QUERY START");
}
buf.setLength(0);
for (int i = 0; i < stack.size(); i++)
buf.append('\t');
final ProfiledExpr e = new ProfiledExpr(expr);
stack.push(e);
buf.append("START\t");
printPosition(e.expr);
buf.append(expr.toString());
log.debug(buf.toString());
if (message != null && !"".equals(message)) {
buf.setLength(0);
for (int i = 0; i < stack.size(); i++)
buf.append('\t');
buf.append("MSG\t");
buf.append(message);
buf.append("\t");
printPosition(e.expr);
buf.append(expr.toString());
log.debug(buf.toString());
}
}
/**
* Called by an expression to indicate the end of an operation.
* The profiler computes the elapsed time.
*
* @param expr the expression.
* @param message required: a message to be printed to the log.
*/
public final void end(Expression expr, String message, Sequence result) {
if (!enabled)
{return;}
try {
final ProfiledExpr e = stack.pop();
if (e.expr != expr) {
log.warn("Error: the object passed to end() does not correspond to the expression on top of the stack.");
stack.clear();
return;
}
final long elapsed = System.currentTimeMillis() - e.start;
if (message != null && !"".equals(message)) {
buf.setLength(0);
for (int i = 0; i < stack.size(); i++)
buf.append('\t');
buf.append("MSG\t");
buf.append(message);
buf.append("\t");
printPosition(e.expr);
buf.append(expr.toString());
log.debug(buf.toString());
}
if (verbosity > START_SEQUENCES) {
buf.setLength(0);
for (int i = 0; i < stack.size(); i++)
buf.append('\t');
buf.append("RESULT\t");
/* if (verbosity >= SEQUENCE_DUMP)
buf.append(result.toString());
else if (verbosity >= SEQUENCE_PREVIEW)
buf.append(sequencePreview(result));
else*/ if (verbosity >= ITEM_COUNT)
{
buf.append(result.getItemCount()).append(" item(s)");}
buf.append("\t");
printPosition(e.expr);
buf.append(expr.toString());
log.debug(buf.toString());
}
if (verbosity >= TIME) {
buf.setLength(0);
for (int i = 0; i < stack.size(); i++)
buf.append('\t');
buf.append("TIME\t");
buf.append(elapsed).append(" ms");
buf.append("\t");
printPosition(e.expr);
buf.append(expr.toString());
log.debug(buf.toString());
}
buf.setLength(0);
for (int i = 0; i < stack.size(); i++)
buf.append('\t');
buf.append("END\t");
printPosition(e.expr);
buf.append(expr.toString());
log.debug(buf.toString());
if (stack.size() == 0) {
log.debug("QUERY END");
}
} catch (final RuntimeException e) {
log.debug("Profiler: could not pop from expression stack - " + expr + " - "+ message + ". Error : "+ e.getMessage());
}
}
/**
* Print out a single profiling message for the given
* expression object.
*
*
* @param level
* @param title
* @param sequence
* @param expr
*/
public final void message(Expression expr, int level, String title, Sequence sequence) {
if (!enabled)
{return;}
if (level > verbosity)
{return;}
buf.setLength(0);
for (int i = 0; i < stack.size() - 1; i++)
buf.append('\t');
if (title != null && !"".equals(title))
{buf.append(title);}
else
{buf.append("MSG");}
buf.append("\t");
/* if (verbosity >= SEQUENCE_DUMP)
buf.append(sequence.toString());
else if (verbosity >= SEQUENCE_PREVIEW)
buf.append(sequencePreview(sequence));
else */ if (verbosity >= ITEM_COUNT)
{
buf.append(sequence.getItemCount()).append(" item(s)");}
buf.append("\t");
buf.append(expr.toString());
log.debug(buf.toString());
}
public final void message(Expression expr, int level, String title, String message) {
if (!enabled)
{return;}
if (level > verbosity)
{return;}
buf.setLength(0);
for (int i = 0; i < stack.size() - 1; i++)
buf.append('\t');
if (title != null && !"".equals(title))
{buf.append(title);}
else
{buf.append("MSG");}
if (message != null && !"".equals(message)) {
buf.append("\t");
buf.append(message);
}
buf.append("\t");
printPosition(expr);
buf.append(expr.toString());
log.debug(buf.toString());
}
public void reset() {
if (stack.size() > 0)
{log.debug("QUERY RESET");}
stack.clear();
if (stats.isEnabled() && stats.hasData()) {
save();
stats.reset();
}
}
private void printPosition(Expression expr) {
if (expr.getLine() > -1) {
buf.append('[');
buf.append(expr.getLine());
buf.append(',');
buf.append(expr.getColumn());
buf.append("]\t");
}
else
{buf.append("\t");}
}
//TODO : find a way to preview "abstract" sequences
// never used locally
@SuppressWarnings("unused")
private String sequencePreview(Sequence sequence) {
final StringBuilder truncation = new StringBuilder();
if (sequence.isEmpty())
{truncation.append(sequence.toString());}
else if (sequence.hasOne()) {
truncation.append("(");
if (sequence.itemAt(0).toString().length() > 20)
{truncation.append(sequence.itemAt(0).toString().substring(0, 20)).append("... ");}
else
{truncation.append(sequence.itemAt(0).toString());}
truncation.append(")");
} else {
truncation.append("(");
if (sequence.itemAt(0).toString().length() > 20)
{truncation.append(sequence.itemAt(0).toString().substring(0, 20)).append("... ");}
else
{truncation.append(sequence.itemAt(0).toString());}
truncation.append(", ... )");
}
return truncation.toString();
}
private final static class ProfiledExpr {
long start;
Expression expr;
private ProfiledExpr(Expression expression) {
this.expr = expression;
this.start = System.currentTimeMillis();
}
}
public void setEnabled(boolean enabled) {
this.enabled = enabled;
}
public void setVerbosity(int verbosity) {
this.verbosity = verbosity;
}
}