From 3efb6ba5151068a585b72c126d4586fc0aff3a51 Mon Sep 17 00:00:00 2001 From: Adam Retter Date: Wed, 4 Oct 2023 15:38:34 +0100 Subject: [PATCH 1/3] [refactor] Cleanup XQuery Pragma code --- .../java/org/exist/xquery/AbstractPragma.java | 98 +++++++++++++++++++ .../org/exist/xquery/ExtensionExpression.java | 56 +++++------ .../main/java/org/exist/xquery/Optimizer.java | 3 - .../main/java/org/exist/xquery/Pragma.java | 60 +++--------- .../java/org/exist/xquery/XQueryContext.java | 1 + .../exist/xquery/pragmas/ForceIndexUse.java | 53 ++++------ .../exist/xquery/pragmas/NoIndexPragma.java | 31 +----- .../org/exist/xquery/pragmas/Optimize.java | 26 +---- .../exist/xquery/pragmas/ProfilePragma.java | 28 ++---- .../org/exist/xquery/pragmas/TimerPragma.java | 55 +++++------ extensions/indexes/range/pom.xml | 5 + .../modules/range/OptimizeFieldPragma.java | 69 +++++-------- 12 files changed, 232 insertions(+), 253 deletions(-) create mode 100644 exist-core/src/main/java/org/exist/xquery/AbstractPragma.java diff --git a/exist-core/src/main/java/org/exist/xquery/AbstractPragma.java b/exist-core/src/main/java/org/exist/xquery/AbstractPragma.java new file mode 100644 index 00000000000..bd96758ba10 --- /dev/null +++ b/exist-core/src/main/java/org/exist/xquery/AbstractPragma.java @@ -0,0 +1,98 @@ +/* + * eXist-db Open Source Native XML Database + * Copyright (C) 2001 The eXist-db Authors + * + * info@exist-db.org + * http://www.exist-db.org + * + * This library 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.1 of the License, or (at your option) any later version. + * + * This library 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 library; if not, write to the Free Software + * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA + */ +package org.exist.xquery; + +import org.exist.dom.QName; +import org.exist.xquery.util.ExpressionDumper; +import org.exist.xquery.value.Item; +import org.exist.xquery.value.Sequence; + +import javax.annotation.Nullable; + +/** + * Base class for implementing an XQuery Pragma expression. + * + * @author Adam Retter + */ +public abstract class AbstractPragma implements Pragma { + private final QName name; + private @Nullable final String contents; + private @Nullable final Expression expression; + + public AbstractPragma(@Nullable final Expression expression, final QName name, @Nullable final String contents) { + this.expression = expression; + this.name = name; + this.contents = contents; + } + + @Override + public QName getName() { + return name; + } + + public @Nullable Expression getExpression() { + return expression; + } + + @Override + public void analyze(final AnalyzeContextInfo contextInfo) throws XPathException { + // no-op by default + } + + @Override + public void before(final XQueryContext context, @Nullable final Expression expression, final Sequence contextSequence) throws XPathException { + // no-op by default + } + + @Override + public Sequence eval(final Sequence contextSequence, final Item contextItem) throws XPathException { + // no-op by default + return null; + } + + @Override + public void after(final XQueryContext context, @Nullable final Expression expression) throws XPathException { + // no-op by default + } + + protected @Nullable String getContents() { + return contents; + } + + @Override + public void dump(final ExpressionDumper dumper) { + dumper.display("(# " + getName().getStringValue()); + if (getContents() != null) { + dumper.display(' ').display(getContents()); + } + } + + @Override + public void resetState(final boolean postOptimization) { + //no-op by default + } + + @Override + public String toString() { + return "(# " + name + ' ' + contents + "#)"; + } +} diff --git a/exist-core/src/main/java/org/exist/xquery/ExtensionExpression.java b/exist-core/src/main/java/org/exist/xquery/ExtensionExpression.java index f97235c02fe..e18dcaf600e 100644 --- a/exist-core/src/main/java/org/exist/xquery/ExtensionExpression.java +++ b/exist-core/src/main/java/org/exist/xquery/ExtensionExpression.java @@ -33,24 +33,23 @@ * Implements an XQuery extension expression. An extension expression starts with * a list of pragmas, followed by an expression enclosed in curly braces. For evaluation * details check {{@link #eval(Sequence, Item)}. - * - * @author wolf * + * @author wolf */ public class ExtensionExpression extends AbstractExpression { private Expression innerExpression; - private List pragmas = new ArrayList<>(3); + private final List pragmas = new ArrayList<>(3); - public ExtensionExpression(XQueryContext context) { + public ExtensionExpression(final XQueryContext context) { super(context); } - public void setExpression(Expression inner) { + public void setExpression(final Expression inner) { this.innerExpression = inner; } - public void addPragma(Pragma pragma) { + public void addPragma(final Pragma pragma) { pragmas.add(pragma); } @@ -62,19 +61,20 @@ public void addPragma(Pragma pragma) { * will be thrown. If all pragmas return null, we call eval on the original expression and return * that. */ - public Sequence eval(Sequence contextSequence, Item contextItem) - throws XPathException { + @Override + public Sequence eval(final Sequence contextSequence, final Item contextItem) throws XPathException { callBefore(contextSequence); Sequence result = null; for (final Pragma pragma : pragmas) { - Sequence temp = pragma.eval(contextSequence, contextItem); + final Sequence temp = pragma.eval(contextSequence, contextItem); if (temp != null) { result = temp; break; } } - if (result == null) - {result = innerExpression.eval(contextSequence, contextItem);} + if (result == null) { + result = innerExpression.eval(contextSequence, contextItem); + } callAfter(); return result; } @@ -85,7 +85,7 @@ private void callAfter() throws XPathException { } } - private void callBefore(Sequence contextSequence) throws XPathException { + private void callBefore(final Sequence contextSequence) throws XPathException { for (final Pragma pragma : pragmas) { pragma.before(context, innerExpression, contextSequence); } @@ -95,7 +95,7 @@ public int returnsType() { return innerExpression.returnsType(); } - public void analyze(AnalyzeContextInfo contextInfo) throws XPathException { + public void analyze(final AnalyzeContextInfo contextInfo) throws XPathException { final AnalyzeContextInfo newContext = new AnalyzeContextInfo(contextInfo); for (final Pragma pragma : pragmas) { pragma.analyze(newContext); @@ -103,23 +103,19 @@ public void analyze(AnalyzeContextInfo contextInfo) throws XPathException { innerExpression.analyze(newContext); } - public void dump(ExpressionDumper dumper) { + public void dump(final ExpressionDumper dumper) { for (final Pragma pragma : pragmas) { - dumper.display("(# " + pragma.getQName().getStringValue(), line); - if (pragma.getContents() != null) - {dumper.display(' ').display(pragma.getContents());} - dumper.display("#)").nl(); + pragma.dump(dumper); + dumper.nl(); } dumper.display('{'); dumper.startIndent(); innerExpression.dump(dumper); dumper.endIndent(); - dumper.nl().display('}').nl(); + dumper.nl().display("}", line).nl(); } - /* (non-Javadoc) - * @see org.exist.xquery.AbstractExpression#getDependencies() - */ + @Override public int getDependencies() { return innerExpression.getDependencies(); } @@ -129,23 +125,24 @@ public Cardinality getCardinality() { return innerExpression.getCardinality(); } - public void setContextDocSet(DocumentSet contextSet) { + @Override + public void setContextDocSet(final DocumentSet contextSet) { super.setContextDocSet(contextSet); innerExpression.setContextDocSet(contextSet); } - public void setPrimaryAxis(int axis) { + @Override + public void setPrimaryAxis(final int axis) { innerExpression.setPrimaryAxis(axis); } + @Override public int getPrimaryAxis() { return innerExpression.getPrimaryAxis(); } - /* (non-Javadoc) - * @see org.exist.xquery.AbstractExpression#resetState() - */ - public void resetState(boolean postOptimization) { + @Override + public void resetState(final boolean postOptimization) { super.resetState(postOptimization); innerExpression.resetState(postOptimization); for (final Pragma pragma : pragmas) { @@ -153,7 +150,8 @@ public void resetState(boolean postOptimization) { } } - public void accept(ExpressionVisitor visitor) { + @Override + public void accept(final ExpressionVisitor visitor) { visitor.visit(innerExpression); } } diff --git a/exist-core/src/main/java/org/exist/xquery/Optimizer.java b/exist-core/src/main/java/org/exist/xquery/Optimizer.java index 828a1e41041..e8e163a6982 100644 --- a/exist-core/src/main/java/org/exist/xquery/Optimizer.java +++ b/exist-core/src/main/java/org/exist/xquery/Optimizer.java @@ -21,15 +21,12 @@ */ package org.exist.xquery; -import org.exist.dom.QName; import org.exist.storage.DBBroker; import org.exist.xquery.functions.array.ArrayConstructor; import org.exist.xquery.pragmas.Optimize; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.exist.xquery.util.ExpressionDumper; -import org.exist.xquery.value.AtomicValue; -import org.exist.xquery.value.Type; import javax.annotation.Nullable; import java.util.*; diff --git a/exist-core/src/main/java/org/exist/xquery/Pragma.java b/exist-core/src/main/java/org/exist/xquery/Pragma.java index c693ad7e31c..4d881789779 100644 --- a/exist-core/src/main/java/org/exist/xquery/Pragma.java +++ b/exist-core/src/main/java/org/exist/xquery/Pragma.java @@ -22,60 +22,30 @@ package org.exist.xquery; import org.exist.dom.QName; +import org.exist.xquery.util.ExpressionDumper; import org.exist.xquery.value.Item; import org.exist.xquery.value.Sequence; import javax.annotation.Nullable; -public abstract class Pragma { - - private QName qname; - private @Nullable String contents; - private Expression expression; - - public Pragma(final QName qname, final @Nullable String contents) throws XPathException { - this(null, qname, contents); - } - - public Pragma(final Expression expression, final QName qname, @Nullable final String contents) throws XPathException { - this.expression = expression; - this.qname = qname; - this.contents = contents; - } +/** + * Interface for implementing an XQuery Pragma expression. + * + * @author Adam Retter + */ +public interface Pragma { - public Expression getExpression() { - return expression; - } + QName getName(); - public void analyze(final AnalyzeContextInfo contextInfo) throws XPathException { - } + void analyze(AnalyzeContextInfo contextInfo) throws XPathException; - public Sequence eval(final Sequence contextSequence, @Nullable final Item contextItem) - throws XPathException { - return null; - } - - public abstract void before(final XQueryContext context, final Sequence contextSequence) throws XPathException; - - public abstract void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException; - - public abstract void after(final XQueryContext context) throws XPathException; - - public abstract void after(final XQueryContext context, final Expression expression) throws XPathException; + void before(XQueryContext context, @Nullable Expression expression, Sequence contextSequence) throws XPathException; - protected String getContents() { - return contents; - } + Sequence eval(Sequence contextSequence, Item contextItem) throws XPathException; - protected QName getQName() { - return qname; - } + void after(XQueryContext context, @Nullable Expression expression) throws XPathException; - public void resetState(final boolean postOptimization) { - } + void dump(final ExpressionDumper dumper); - @Override - public String toString() { - return "(# " + qname + (contents == null ? "" : ' ' + contents) + " #)"; - } -} \ No newline at end of file + void resetState(boolean postOptimization); +} diff --git a/exist-core/src/main/java/org/exist/xquery/XQueryContext.java b/exist-core/src/main/java/org/exist/xquery/XQueryContext.java index f81619da86e..edf761e90fb 100644 --- a/exist-core/src/main/java/org/exist/xquery/XQueryContext.java +++ b/exist-core/src/main/java/org/exist/xquery/XQueryContext.java @@ -2984,6 +2984,7 @@ public Pragma getPragma(final String name, final String contents) throws XPathEx } catch (final QName.IllegalQNameException e) { throw new XPathException(rootExpression, ErrorCodes.XPST0081, "No namespace defined for prefix " + name); } + final String ns = qname.getNamespaceURI(); if (ns.isEmpty()) { throw new XPathException(rootExpression, ErrorCodes.XPST0081, diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/ForceIndexUse.java b/exist-core/src/main/java/org/exist/xquery/pragmas/ForceIndexUse.java index 5cba1b661d7..1fed704790d 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/ForceIndexUse.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/ForceIndexUse.java @@ -24,47 +24,34 @@ import org.exist.xquery.*; import org.exist.Namespaces; import org.exist.dom.QName; -import org.exist.xquery.value.Sequence; -public class ForceIndexUse extends Pragma { +public class ForceIndexUse extends AbstractPragma { public static final String FORCE_INDEX_USE_PRAGMA_LOCAL_NAME = "force-index-use"; public static final QName EXCEPTION_IF_INDEX_NOT_USED_PRAGMA = new QName(FORCE_INDEX_USE_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); - Expression expression; - boolean bailout = true; + private boolean bailout = true; - public ForceIndexUse(QName qname, String contents) throws XPathException { - this(null, qname, contents); + public ForceIndexUse(final Expression expression, final QName qname, final String contents) { + super(expression, qname, contents); } - public ForceIndexUse(final Expression expression, QName qname, String contents) throws XPathException { - super(expression, qname, contents); - } - - public void before(XQueryContext context,Sequence contextSequence) throws XPathException { - before(context, null, contextSequence); - } - - public void before(XQueryContext context, final Expression expression, Sequence contextSequence) throws XPathException { - } - - public void after(XQueryContext context) throws XPathException { - after(context, null); - } - - public void after(XQueryContext context, final Expression expression) throws XPathException { - expression.accept(new DefaultExpressionVisitor() { - public void visitGeneralComparison(GeneralComparison expression) { - bailout = !expression.hasUsedIndex(); - } - public void visitBuiltinFunction(Function expression) { - if (expression instanceof IndexUseReporter) - {bailout = !((IndexUseReporter)expression).hasUsedIndex();} + @Override + public void after(final XQueryContext context, final Expression expression) throws XPathException { + expression.accept(new DefaultExpressionVisitor() { + public void visitGeneralComparison(final GeneralComparison expression) { + bailout = !expression.hasUsedIndex(); } - }); - - if (bailout) - {throw new XPathException(expression, "XQDYxxxx: Can not use index on expression '" + expression + "'");} + + public void visitBuiltinFunction(final Function expression) { + if (expression instanceof IndexUseReporter) { + bailout = !((IndexUseReporter) expression).hasUsedIndex(); + } + } + }); + + if (bailout) { + throw new XPathException(expression, "XQDYxxxx: Can not use index on expression '" + expression + "'"); + } /* if (expression instanceof PathExpr) { diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/NoIndexPragma.java b/exist-core/src/main/java/org/exist/xquery/pragmas/NoIndexPragma.java index 7b7ed24081d..46b598e212f 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/NoIndexPragma.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/NoIndexPragma.java @@ -26,45 +26,22 @@ import org.apache.logging.log4j.Logger; import org.exist.Namespaces; import org.exist.dom.QName; -import org.exist.xquery.value.Item; -import org.exist.xquery.value.Sequence; -public class NoIndexPragma extends Pragma { +public class NoIndexPragma extends AbstractPragma { public static final String NO_INDEX_PRAGMA_LOCAL_NAME = "no-index"; public static final QName NO_INDEX_PRAGMA = new QName(NO_INDEX_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); private static final Logger LOG = LogManager.getLogger(NoIndexPragma.class); - public NoIndexPragma(QName qname, String contents) throws XPathException { - this(null, qname, contents); - } - - public NoIndexPragma(final Expression expression, QName qname, String contents) throws XPathException { + public NoIndexPragma(final Expression expression, final QName qname, final String contents) { super(expression, qname, contents); } - public void analyze(AnalyzeContextInfo contextInfo) throws XPathException { + @Override + public void analyze(final AnalyzeContextInfo contextInfo) throws XPathException { if (LOG.isTraceEnabled()) { LOG.trace("Switching indexes off ..."); } contextInfo.addFlag(Expression.USE_TREE_TRAVERSAL); } - - public Sequence eval(Sequence contextSequence, Item contextItem) throws XPathException { - return null; - } - - public void before(XQueryContext context, Sequence contextSequence) throws XPathException { - before(context, null, contextSequence); - } - - public void before(XQueryContext context, final Expression expression, Sequence contextSequence) throws XPathException { - } - - public void after(XQueryContext context) throws XPathException { - after(context, null); - } - - public void after(XQueryContext context, final Expression expression) throws XPathException { - } } diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/Optimize.java b/exist-core/src/main/java/org/exist/xquery/pragmas/Optimize.java index bd4fb5ea86a..f6744171de3 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/Optimize.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/Optimize.java @@ -39,9 +39,7 @@ import java.util.Iterator; import java.util.List; -import static java.lang.System.arraycopy; - -public class Optimize extends Pragma { +public class Optimize extends AbstractPragma { public static final String OPTIMIZE_PRAGMA_LOCAL_NAME = "optimize"; public static final QName OPTIMIZE_PRAGMA = new QName(OPTIMIZE_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); @@ -59,11 +57,7 @@ public class Optimize extends Pragma { private int cachedTimestamp; private boolean cachedOptimize; - public Optimize(final XQueryContext context, final QName pragmaName, @Nullable final String contents, final boolean explicit) throws XPathException { - this(null, context, pragmaName, contents, explicit); - } - - public Optimize(@Nullable final Expression expression, final XQueryContext context, final QName pragmaName, @Nullable final String contents, boolean explicit) throws XPathException { + public Optimize(@Nullable final Expression expression, final XQueryContext context, final QName pragmaName, @Nullable final String contents, final boolean explicit) throws XPathException { super(expression, pragmaName, contents); this.context = context; this.enabled = explicit || context.optimizationsEnabled(); @@ -199,11 +193,6 @@ public Sequence eval(Sequence contextSequence, final Item contextItem) throws XP } } - @Override - public void before(final XQueryContext context, final Sequence contextSequence) throws XPathException { - before(context, null, contextSequence); - } - @Override public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException { if (innerExpr != null) { @@ -214,7 +203,6 @@ public void before(final XQueryContext context, final Expression expression, fin return; } innerExpr.accept(new BasicExpressionVisitor() { - @Override public void visitPathExpr(final PathExpr expression) { for (int i = 0; i < expression.getSubExpressionCount(); i++) { @@ -285,18 +273,12 @@ public void visitBuiltinFunction(final Function function) { } } - @Override - public void after(final XQueryContext context) throws XPathException { - after(context, null); - } - @Override public void after(final XQueryContext context, @Nullable final Expression expression) throws XPathException { } private void addOptimizable(final Optimizable optimizable) { final int axis = optimizable.getOptimizeAxis(); - if (!(axis == Constants.CHILD_AXIS || axis == Constants.SELF_AXIS || axis == Constants.DESCENDANT_AXIS || axis == Constants.DESCENDANT_SELF_AXIS || axis == Constants.ATTRIBUTE_AXIS || axis == Constants.DESCENDANT_ATTRIBUTE_AXIS)) { @@ -311,7 +293,7 @@ private void addOptimizable(final Optimizable optimizable) { } Optimizable[] o = new Optimizable[optimizables.length + 1]; - arraycopy(optimizables, 0, o, 0, optimizables.length); + System.arraycopy(optimizables, 0, o, 0, optimizables.length); o[optimizables.length] = optimizable; optimizables = o; } @@ -385,4 +367,4 @@ public static int getQNameIndexType(final XQueryContext context, @Nullable final } return indexType; } -} \ No newline at end of file +} diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/ProfilePragma.java b/exist-core/src/main/java/org/exist/xquery/pragmas/ProfilePragma.java index e70dbba8717..480b5d38c38 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/ProfilePragma.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/ProfilePragma.java @@ -26,34 +26,24 @@ import org.exist.dom.QName; import org.exist.xquery.value.Sequence; -public class ProfilePragma extends Pragma { +public class ProfilePragma extends AbstractPragma { public static final String PROFILING_PRAGMA_LOCAL_NAME = "profiling"; public static final QName PROFILING_PRAGMA = new QName(PROFILING_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); - public ProfilePragma(QName qname, String contents) throws XPathException { - this(null, qname, contents); - } - - public ProfilePragma(final Expression expression, QName qname, String contents) throws XPathException { + public ProfilePragma(final Expression expression, final QName qname, final String contents) { super(expression, qname, contents); } - public void after(XQueryContext context) throws XPathException { - after(context, null); + @Override + public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException { + final Profiler profiler = context.getProfiler(); + final Option pragma = new Option(getExpression(), getName(), getContents()); + profiler.configure(pragma); } - public void after(XQueryContext context, Expression expression) throws XPathException { + @Override + public void after(final XQueryContext context, final Expression expression) throws XPathException { final Profiler profiler = context.getProfiler(); profiler.setEnabled(false); } - - public void before(XQueryContext context,Sequence contextSequence) throws XPathException { - before(context, null, contextSequence); - } - - public void before(XQueryContext context, Expression expression, Sequence contextSequence) throws XPathException { - final Profiler profiler = context.getProfiler(); - final Option pragma = new Option(getExpression(), getQName(), getContents()); - profiler.configure(pragma); - } } diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java b/exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java index 5488997371a..a0414de7088 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java @@ -29,29 +29,26 @@ import org.exist.xquery.util.ExpressionDumper; import org.exist.xquery.value.Sequence; -public class TimerPragma extends Pragma { +public class TimerPragma extends AbstractPragma { public static final String TIMER_PRAGMA_LOCAL_NAME = "timer"; public static final QName TIMER_PRAGMA = new QName(TIMER_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); private Logger log = null; - + private long start; private boolean verbose = true; - public TimerPragma(QName qname, String contents) throws XPathException { - this(null, qname, contents); - } - - public TimerPragma(final Expression expression, QName qname, String contents) throws XPathException { + public TimerPragma(final Expression expression, final QName qname, final String contents) throws XPathException { super(expression, qname, contents); - if (contents != null && contents.length() > 0) { - final String options[] = Option.tokenize(contents); - for (String option : options) { - final String param[] = Option.parseKeyValuePair(option); + if (contents != null && !contents.isEmpty()) { + + final String[] options = Option.tokenize(contents); + for (final String option : options) { + final String[] param = Option.parseKeyValuePair(option); if (param == null) { - throw new XPathException((Expression) null, "Invalid content found for pragma " + TIMER_PRAGMA.getStringValue() + - ": " + contents); + throw new XPathException((Expression) null, "Invalid content found for pragma " + TIMER_PRAGMA.getStringValue() + ": " + contents); } + if ("verbose".equals(param[0])) { verbose = "yes".equals(param[1]); } else if ("logger".equals(param[0])) { @@ -59,31 +56,25 @@ public TimerPragma(final Expression expression, QName qname, String contents) th } } } - if (log == null) - {log = LogManager.getLogger(TimerPragma.class);} + if (log == null) { + log = LogManager.getLogger(TimerPragma.class); + } } - public void after(XQueryContext context) throws XPathException { - after(context, null); + @Override + public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException { + this.start = System.currentTimeMillis(); } - public void after(XQueryContext context, Expression expression) throws XPathException { + @Override + public void after(final XQueryContext context, final Expression expression) throws XPathException { final long elapsed = System.currentTimeMillis() - start; if (log.isTraceEnabled()) { - if (verbose) - { - log.trace("Elapsed: {}ms. for expression:\n{}", elapsed, ExpressionDumper.dump(expression));} - else - { - log.trace("Elapsed: {}ms.", elapsed);} + if (verbose) { + log.trace("Elapsed: {}ms. for expression:\n{}", elapsed, ExpressionDumper.dump(expression)); + } else { + log.trace("Elapsed: {}ms.", elapsed); + } } } - - public void before(XQueryContext context, Sequence contextSequence) throws XPathException { - before(context, null, contextSequence); - } - - public void before(XQueryContext context, Expression expression, Sequence contextSequence) throws XPathException { - start = System.currentTimeMillis(); - } } diff --git a/extensions/indexes/range/pom.xml b/extensions/indexes/range/pom.xml index 907e03f0a14..dedd0b2ac62 100644 --- a/extensions/indexes/range/pom.xml +++ b/extensions/indexes/range/pom.xml @@ -91,6 +91,11 @@ ${lucene.version} + + com.google.code.findbugs + jsr305 + + xml-apis xml-apis diff --git a/extensions/indexes/range/src/main/java/org/exist/xquery/modules/range/OptimizeFieldPragma.java b/extensions/indexes/range/src/main/java/org/exist/xquery/modules/range/OptimizeFieldPragma.java index ba0a04bcdcc..2bf981842a5 100644 --- a/extensions/indexes/range/src/main/java/org/exist/xquery/modules/range/OptimizeFieldPragma.java +++ b/extensions/indexes/range/src/main/java/org/exist/xquery/modules/range/OptimizeFieldPragma.java @@ -39,28 +39,28 @@ * * @author wolf */ -public class OptimizeFieldPragma extends Pragma { +public class OptimizeFieldPragma extends AbstractPragma { - public final static QName OPTIMIZE_RANGE_PRAGMA = new QName("optimize-field", Namespaces.EXIST_NS, "exist"); + public static final QName OPTIMIZE_RANGE_PRAGMA = new QName("optimize-field", Namespaces.EXIST_NS, "exist"); private final XQueryContext context; private Expression rewritten = null; private AnalyzeContextInfo contextInfo; private int axis; - public OptimizeFieldPragma(final Expression expression, QName qname, String contents, XQueryContext context) throws XPathException { + public OptimizeFieldPragma(final Expression expression, final QName qname, final String contents, final XQueryContext context) { super(expression, qname, contents); this.context = context; } @Override - public void analyze(AnalyzeContextInfo contextInfo) throws XPathException { + public void analyze(final AnalyzeContextInfo contextInfo) throws XPathException { super.analyze(contextInfo); this.contextInfo = contextInfo; } @Override - public Sequence eval(Sequence contextSequence, Item contextItem) throws XPathException { + public Sequence eval(final Sequence contextSequence, final Item contextItem) throws XPathException { if (rewritten != null) { rewritten.analyze(contextInfo); return rewritten.eval(contextSequence, contextItem); @@ -68,11 +68,6 @@ public Sequence eval(Sequence contextSequence, Item contextItem) throws XPathExc return null; } - @Override - public void before(final XQueryContext context, final Sequence contextSequence) throws XPathException { - before(context, null, contextSequence); - } - @Override public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException { final LocationStep locationStep = (LocationStep) expression; @@ -91,20 +86,11 @@ public void before(final XQueryContext context, final Expression expression, fin } } - public void after(XQueryContext context) throws XPathException { - after(context, null); - } - - @Override - public void after(XQueryContext context, Expression expression) throws XPathException { - - } - - private Expression tryRewriteToFields(LocationStep locationStep, final Predicate[] preds, NodePath contextPath, Sequence contextSequence) throws XPathException { + private @Nullable Expression tryRewriteToFields(final LocationStep locationStep, final Predicate[] preds, final NodePath contextPath, final Sequence contextSequence) throws XPathException { // without context path, we cannot rewrite the entire query if (contextPath != null) { final List notOptimizable = new ArrayList<>(preds.length); - List configs = getConfigurations(contextSequence); + final List configs = getConfigurations(contextSequence); // walk through the predicates attached to the current location step // check if expression can be optimized @@ -120,19 +106,19 @@ private Expression tryRewriteToFields(LocationStep locationStep, final Predicate notOptimizable.add(pred); continue; } - Expression innerExpr = pred.getExpression(0); - List steps = RangeQueryRewriter.getStepsToOptimize(innerExpr); + final Expression innerExpr = pred.getExpression(0); + final List steps = RangeQueryRewriter.getStepsToOptimize(innerExpr); if (steps == null) { notOptimizable.add(pred); continue; } // compute left hand path - NodePath innerPath = RangeQueryRewriter.toNodePath(steps); + final NodePath innerPath = RangeQueryRewriter.toNodePath(steps); if (innerPath == null) { notOptimizable.add(pred); continue; } - NodePath path = new NodePath(contextPath); + final NodePath path = new NodePath(contextPath); path.append(innerPath); if (path.length() > 0) { @@ -160,14 +146,14 @@ private Expression tryRewriteToFields(LocationStep locationStep, final Predicate final ArrayList matchedPreds = new ArrayList<>(); ComplexRangeIndexConfigElement rice = null; - for (ComplexRangeIndexConfigElement testRice : rices) { + for (final ComplexRangeIndexConfigElement testRice : rices) { if (testRice.getNumberOfConditions() > 0) { // find a config element where the conditions match preceding predicates matchedPreds.clear(); - for (Predicate precedingPred : precedingPreds ) { + for (final Predicate precedingPred : precedingPreds) { if (testRice.findCondition(precedingPred)) { matchedPreds.add(precedingPred); @@ -195,7 +181,7 @@ private Expression tryRewriteToFields(LocationStep locationStep, final Predicate if (rice != null && rice.getNodePath().match(contextPath)) { // check for a matching sub-path and retrieve field information - RangeIndexConfigField field = rice.getField(path); + final RangeIndexConfigField field = rice.getField(path); if (field != null) { if (args == null) { // initialize args @@ -235,7 +221,7 @@ private Expression tryRewriteToFields(LocationStep locationStep, final Predicate // the entire filter expression can be replaced // create range:field-equals function - FieldLookup func = new FieldLookup(context, FieldLookup.signatures[0]); + final FieldLookup func = new FieldLookup(context, FieldLookup.signatures[0]); func.setFallback(locationStep); func.setLocation(locationStep.getLine(), locationStep.getColumn()); @@ -271,12 +257,12 @@ private Expression tryRewriteToFields(LocationStep locationStep, final Predicate return null; } - private Expression getKeyArg(Expression expression) { + private @Nullable Expression getKeyArg(final Expression expression) { if (expression instanceof GeneralComparison) { - return ((GeneralComparison)expression).getRight(); + return ((GeneralComparison) expression).getRight(); } else if (expression instanceof InternalFunctionCall) { - InternalFunctionCall fcall = (InternalFunctionCall) expression; - Function function = fcall.getFunction(); + final InternalFunctionCall fcall = (InternalFunctionCall) expression; + final Function function = fcall.getFunction(); if (function instanceof Lookup) { return function.getArgument(1); } @@ -284,31 +270,28 @@ private Expression getKeyArg(Expression expression) { return null; } - /** * Find all complex configurations matching the path */ - private List findConfigurations(NodePath path, List configs) { - ArrayList rices = new ArrayList<>(); - - for (RangeIndexConfig config : configs) { - List foundRices = config.findAll(path); + private List findConfigurations(final NodePath path, final List configs) { + final List rices = new ArrayList<>(); + for (final RangeIndexConfig config : configs) { + final List foundRices = config.findAll(path); if (rices.addAll(foundRices)) { break; } } - return rices; } - private List getConfigurations(Sequence contextSequence) { - List configs = new ArrayList<>(); + private List getConfigurations(final Sequence contextSequence) { + final List configs = new ArrayList<>(); for (final Iterator i = contextSequence.getCollectionIterator(); i.hasNext(); ) { final Collection collection = i.next(); if (collection.getURI().startsWith(XmldbURI.SYSTEM_COLLECTION_URI)) { continue; } - IndexSpec idxConf = collection.getIndexConfiguration(context.getBroker()); + final IndexSpec idxConf = collection.getIndexConfiguration(context.getBroker()); if (idxConf != null) { final RangeIndexConfig config = (RangeIndexConfig) idxConf.getCustomIndexSpec(RangeIndex.ID); if (config != null) { From 5368116e66b5e488a0e67d265db01f22d46559c5 Mon Sep 17 00:00:00 2001 From: Adam Retter Date: Wed, 4 Oct 2023 15:51:37 +0100 Subject: [PATCH 2/3] [refactor] Renamed 'exist:timer' pragma to 'exist:time' to better reflect its purpose. Leaves 'exist:timer' as an intact legacy supported name for now too --- .../java/org/exist/xquery/XQueryContext.java | 2 +- .../{TimerPragma.java => TimePragma.java} | 18 ++++++++++++------ 2 files changed, 13 insertions(+), 7 deletions(-) rename exist-core/src/main/java/org/exist/xquery/pragmas/{TimerPragma.java => TimePragma.java} (80%) diff --git a/exist-core/src/main/java/org/exist/xquery/XQueryContext.java b/exist-core/src/main/java/org/exist/xquery/XQueryContext.java index edf761e90fb..6953d748945 100644 --- a/exist-core/src/main/java/org/exist/xquery/XQueryContext.java +++ b/exist-core/src/main/java/org/exist/xquery/XQueryContext.java @@ -3000,7 +3000,7 @@ public Pragma getPragma(final String name, final String contents) throws XPathEx return switch(qname.getLocalPart()) { case Optimize.OPTIMIZE_PRAGMA_LOCAL_NAME -> new Optimize(rootExpression, this, qname, sanitizedContents, true); - case TimerPragma.TIMER_PRAGMA_LOCAL_NAME -> new TimerPragma(rootExpression, qname, sanitizedContents); + case TimePragma.TIME_PRAGMA_LOCAL_NAME, TimePragma.DEPRECATED_TIMER_PRAGMA_LOCAL_NAME -> new TimePragma(rootExpression, qname, sanitizedContents); case ProfilePragma.PROFILING_PRAGMA_LOCAL_NAME -> new ProfilePragma(rootExpression, qname, sanitizedContents); case ForceIndexUse.FORCE_INDEX_USE_PRAGMA_LOCAL_NAME -> new ForceIndexUse(rootExpression, qname, sanitizedContents); case NoIndexPragma.NO_INDEX_PRAGMA_LOCAL_NAME -> new NoIndexPragma(rootExpression, qname, sanitizedContents); diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java b/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java similarity index 80% rename from exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java rename to exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java index a0414de7088..8cc23e633ed 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/TimerPragma.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java @@ -29,16 +29,22 @@ import org.exist.xquery.util.ExpressionDumper; import org.exist.xquery.value.Sequence; -public class TimerPragma extends AbstractPragma { - public static final String TIMER_PRAGMA_LOCAL_NAME = "timer"; - public static final QName TIMER_PRAGMA = new QName(TIMER_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); +/** + * An XQuery Pragma that will record the execution + * time of the associated expression. + */ +public class TimePragma extends AbstractPragma { + + public static final String TIME_PRAGMA_LOCAL_NAME = "time"; + public static final QName TIME_PRAGMA = new QName(TIME_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); + public static final String DEPRECATED_TIMER_PRAGMA_LOCAL_NAME = "timer"; private Logger log = null; private long start; private boolean verbose = true; - public TimerPragma(final Expression expression, final QName qname, final String contents) throws XPathException { + public TimePragma(final Expression expression, final QName qname, final String contents) throws XPathException { super(expression, qname, contents); if (contents != null && !contents.isEmpty()) { @@ -46,7 +52,7 @@ public TimerPragma(final Expression expression, final QName qname, final String for (final String option : options) { final String[] param = Option.parseKeyValuePair(option); if (param == null) { - throw new XPathException((Expression) null, "Invalid content found for pragma " + TIMER_PRAGMA.getStringValue() + ": " + contents); + throw new XPathException((Expression) null, "Invalid content found for pragma " + TIME_PRAGMA.getStringValue() + ": " + contents); } if ("verbose".equals(param[0])) { @@ -57,7 +63,7 @@ public TimerPragma(final Expression expression, final QName qname, final String } } if (log == null) { - log = LogManager.getLogger(TimerPragma.class); + log = LogManager.getLogger(TimePragma.class); } } From 381294b705cf235aa8093480715cd6ac73b2d4af Mon Sep 17 00:00:00 2001 From: Adam Retter Date: Wed, 4 Oct 2023 17:09:01 +0100 Subject: [PATCH 3/3] [feature] A new and improved 'exist:time' XQuery pragma. Backported from FusionDB --- exist-core/pom.xml | 2 + .../main/java/org/exist/xquery/Option.java | 6 +- .../org/exist/xquery/pragmas/TimePragma.java | 511 +++++++++++++++++- 3 files changed, 487 insertions(+), 32 deletions(-) diff --git a/exist-core/pom.xml b/exist-core/pom.xml index 90bf0dc120f..90163e4ad44 100644 --- a/exist-core/pom.xml +++ b/exist-core/pom.xml @@ -758,6 +758,7 @@ src/test/java/org/exist/xquery/functions/session/AttributeTest.java src/test/java/org/exist/xquery/functions/xmldb/XMLDBAuthenticateTest.java src/main/java/org/exist/xquery/functions/util/Eval.java + src/main/java/org/exist/xquery/pragmas/TimePragma.java src/test/java/org/exist/xquery/util/URIUtilsTest.java src/main/java/org/exist/xquery/value/ArrayListValueSequence.java src/test/java/org/exist/xquery/value/BifurcanMapTest.java @@ -918,6 +919,7 @@ The original license statement is also included below.]]> src/test/java/org/exist/xquery/functions/session/AttributeTest.java src/test/java/org/exist/xquery/functions/xmldb/XMLDBAuthenticateTest.java src/main/java/org/exist/xquery/functions/util/Eval.java + src/main/java/org/exist/xquery/pragmas/TimePragma.java src/test/java/org/exist/xquery/util/URIUtilsTest.java src/main/java/org/exist/xquery/value/ArrayListValueSequence.java src/test/java/org/exist/xquery/value/BifurcanMapTest.java diff --git a/exist-core/src/main/java/org/exist/xquery/Option.java b/exist-core/src/main/java/org/exist/xquery/Option.java index 72b7d86b385..27f8615dfdb 100644 --- a/exist-core/src/main/java/org/exist/xquery/Option.java +++ b/exist-core/src/main/java/org/exist/xquery/Option.java @@ -28,6 +28,8 @@ import org.exist.Namespaces; import org.exist.dom.QName; +import javax.annotation.Nullable; + /** * Represents an XQuery option declared via "declare option". * @@ -89,9 +91,9 @@ public static String[] tokenize(final String contents) { return items; } - public static String[] parseKeyValuePair(final String s) { + public static @Nullable String[] parseKeyValuePair(final String s) { final Matcher matcher = pattern.matcher(s); - if(matcher.matches()) { + if (matcher.matches()) { String value = matcher.group(2); if(value.charAt(0) == '\'' || value.charAt(0) == '"') { value = value.substring(1, value.length() - 1); diff --git a/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java b/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java index 8cc23e633ed..d4e50043a21 100644 --- a/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java +++ b/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java @@ -1,14 +1,25 @@ /* - * eXist-db Open Source Native XML Database - * Copyright (C) 2001 The eXist-db Authors + * Copyright (C) 2014, Evolved Binary Ltd * - * info@exist-db.org - * http://www.exist-db.org + * This file was originally ported from FusionDB to eXist-db by + * Evolved Binary, for the benefit of the eXist-db Open Source community. + * Only the ported code as it appears in this file, at the time that + * it was contributed to eXist-db, was re-licensed under The GNU + * Lesser General Public License v2.1 only for use in eXist-db. + * + * This license grant applies only to a snapshot of the code as it + * appeared when ported, it does not offer or infer any rights to either + * updates of this source code or access to the original source code. + * + * The GNU Lesser General Public License v2.1 only license follows. + * + * --------------------------------------------------------------------- + * + * Copyright (C) 2014, Evolved Binary Ltd * * This library 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.1 of the License, or (at your option) any later version. + * License as published by the Free Software Foundation; version 2.1. * * This library is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of @@ -21,6 +32,8 @@ */ package org.exist.xquery.pragmas; +import com.evolvedbinary.j8fu.tuple.Tuple2; +import org.apache.logging.log4j.Level; import org.exist.xquery.*; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; @@ -29,9 +42,29 @@ import org.exist.xquery.util.ExpressionDumper; import org.exist.xquery.value.Sequence; +import javax.annotation.Nullable; +import java.util.Optional; + +import static com.evolvedbinary.j8fu.tuple.Tuple.Tuple; + /** * An XQuery Pragma that will record the execution - * time of the associated expression. + * time of the associated expression via logging. + * + * 
{@code
+ * (# exist:time verbose=yes logger-name=MyLog logging-level=TRACE log-message-prefix=LOOK-HERE #) {
+ *     (: the XQuery Expression that you wish to time goes here :)
+ * }
+ * }
+ * + * The following optional configuration options may be given to the Time Pragma via the pragma's contents: + * * verbose - Set to 'true' if you want the associated expression to be logged to. You may also use 'yes' instead of 'true' but its use is deprecated and may be removed in the future. + * * logger-name - The name of the logger to use, if omitted the logger for {@link TimePragma} will be used. + * * logging-level - The Slf4j level at which the timing should be logged, e.g. Trace, Debug, Info, Warn, Error, etc. If omitted this defaults to 'Trace' level. + * * log-message-prefix - An optional prefix to append to the start of the log message to help you identify it. + * * measurement-mode - indicates whether we should measure a single invocation of the additional expression or multiple invocations 'single' or 'multiple'. The default is 'single'. + * + * @author Adam Retter */ public class TimePragma extends AbstractPragma { @@ -39,48 +72,466 @@ public class TimePragma extends AbstractPragma { public static final QName TIME_PRAGMA = new QName(TIME_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist"); public static final String DEPRECATED_TIMER_PRAGMA_LOCAL_NAME = "timer"; - private Logger log = null; - - private long start; - private boolean verbose = true; + private final Options options; + @Nullable private Timing timing = null; public TimePragma(final Expression expression, final QName qname, final String contents) throws XPathException { super(expression, qname, contents); - if (contents != null && !contents.isEmpty()) { + this.options = parseOptions(getContents()); + } + + @Override + public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException { + if (timing == null) { + this.timing = new Timing(); + } + timing.setStartTimestamp(System.nanoTime()); + } + + @Override + public void after(final XQueryContext context, final Expression expression) throws XPathException { + timing.setEndTimestamp(System.nanoTime()); + + if (options.measurementMode == MeasurementMode.SINGLE) { + logSingleMeasurement(expression); + this.timing.reset(); + } + } + + @Override + public void resetState(final boolean postOptimization) { + if (timing != null && options.measurementMode == MeasurementMode.MULTIPLE) { + logMultipleMeasurement(); + } + this.timing.reset(); + } + + /** + * Return the nanoseconds as either + * nanoseconds or milliseconds. + * + * @param nanoseconds the time in milliseconds. + * + * @return the time. + */ + private static Tuple2 nsOrMs(final long nanoseconds) { + final long timeValue; + final String timeUnit; + if (nanoseconds > 999_999) { + timeValue = nanoseconds / 1_000_000; + timeUnit = "ms"; + } else { + timeValue = nanoseconds; + timeUnit = "ns"; + } + return Tuple(timeValue, timeUnit); + } + + /** + * Return the nanoseconds as either + * nanoseconds or milliseconds. + * + * @param nanoseconds the time in milliseconds. + * + * @return the time. + */ + private static String nsOrMsStr(final long nanoseconds) { + final Tuple2 time = nsOrMs(nanoseconds); + return String.format("%d %s", time._1, time._2); + } + + /** + * Return the nanoseconds as either + * nanoseconds or milliseconds. + * + * @param nanoseconds the time in milliseconds. + * + * @return the time. + */ + private static Tuple2 nsOrMsDbl(final double nanoseconds) { + final double timeValue; + final String timeUnit; + if (nanoseconds > 999_999) { + timeValue = nanoseconds / 1_000_000; + timeUnit = "ms"; + } else { + timeValue = nanoseconds; + timeUnit = "ns"; + } + return Tuple(timeValue, timeUnit); + } + + /** + * Return the nanoseconds as either + * nanoseconds or milliseconds. + * + * @param nanoseconds the time in milliseconds. + * + * @return the time. + */ + private static String nsOrMsStrDbl(final double nanoseconds) { + final Tuple2 time = nsOrMsDbl(nanoseconds); + return String.format("%.2f %s", time._1, time._2); + } + + private void logSingleMeasurement(final Expression expression) { + final long elapsedTime = timing.getTotalElapsed(); + @Nullable final String humaneElapsedTime = elapsedTime > (1_000_000 * 999) ? formatHumaneElapsedTime(elapsedTime) : null; + + final String displayTime = nsOrMsStr(elapsedTime); + + if (options.logger.isEnabled(options.loggingLevel)) { + + if (options.logMessagePrefix != null) { + if (options.verbose) { + if (humaneElapsedTime != null) { + options.logger.log(options.loggingLevel, "{} Elapsed: {} ({}) for expression: {}", options.logMessagePrefix, displayTime, humaneElapsedTime, ExpressionDumper.dump(expression)); + } else { + options.logger.log(options.loggingLevel, "{} Elapsed: {} for expression: {}", options.logMessagePrefix, displayTime, ExpressionDumper.dump(expression)); + } + } else { + if (humaneElapsedTime != null) { + options.logger.log(options.loggingLevel, "{} Elapsed: {} ({}).", options.logMessagePrefix, displayTime, humaneElapsedTime); + } else { + options.logger.log(options.loggingLevel, "{} Elapsed: {}.", options.logMessagePrefix, displayTime); + } + } + } else { + if (options.verbose) { + if (humaneElapsedTime != null) { + options.logger.log(options.loggingLevel, "Elapsed: {} ({}) for expression: {}", displayTime, humaneElapsedTime, ExpressionDumper.dump(expression)); + } else { + options.logger.log(options.loggingLevel, "Elapsed: {} for expression: {}", displayTime, ExpressionDumper.dump(expression)); + } + } else { + if (humaneElapsedTime != null) { + options.logger.log(options.loggingLevel, "Elapsed: {} ({}).", displayTime, humaneElapsedTime); + } else { + options.logger.log(options.loggingLevel, "Elapsed: {}.", displayTime); + } + } + } + } + } + + private void logMultipleMeasurement() { + final long elapsedTime = timing.getTotalElapsed(); + @Nullable final String humaneElapsedTime = elapsedTime > 999 ? formatHumaneElapsedTime(elapsedTime) : null; + + final String displayTime = nsOrMsStr(elapsedTime); + + if (options.logMessagePrefix != null) { + if (humaneElapsedTime != null) { + options.logger.log(options.loggingLevel, "{} Elapsed: {} ({}) [iterations={} first={}, min={}, avg={}, max={}, last={}].", options.logMessagePrefix, displayTime, humaneElapsedTime, timing.getIterations(), nsOrMsStr(timing.getFirstElapsed()), nsOrMsStr(timing.getMinElapsed()), nsOrMsStrDbl(timing.getAvgElapsed()), nsOrMsStr(timing.getMaxElapsed()), nsOrMsStr(timing.getLastElapsed())); + } else { + options.logger.log(options.loggingLevel, "{} Elapsed: {} [iterations={} first={}, min={}, avg={}, max={}, last={}].", options.logMessagePrefix, displayTime, timing.getIterations(), nsOrMsStr(timing.getFirstElapsed()), nsOrMsStr(timing.getMinElapsed()), nsOrMsStrDbl(timing.getAvgElapsed()), nsOrMsStr(timing.getMaxElapsed()), nsOrMsStr(timing.getLastElapsed())); + } + } else { + if (humaneElapsedTime != null) { + options.logger.log(options.loggingLevel, "Elapsed: {} ({}) [iterations={} first={}, min={}, avg={}, max={}, last={}].", displayTime, humaneElapsedTime, timing.getIterations(), nsOrMsStr(timing.getFirstElapsed()), nsOrMsStr(timing.getMinElapsed()), nsOrMsStrDbl(timing.getAvgElapsed()), nsOrMsStr(timing.getMaxElapsed()), nsOrMsStr(timing.getLastElapsed())); + } else { + options.logger.log(options.loggingLevel, "Elapsed: {} [iterations={} first={}, min={}, avg={}, max={}, last={}].", displayTime, timing.getIterations(), nsOrMsStr(timing.getFirstElapsed()), nsOrMsStr(timing.getMinElapsed()), nsOrMsStrDbl(timing.getAvgElapsed()), nsOrMsStr(timing.getMaxElapsed()), nsOrMsStr(timing.getLastElapsed())); + } + } + } + + /** + * Format the elapsed time in a humane manner. + * + * @param elapsedTime the elapsed time in nanoseconds. + * + * @return a string of the duration which is suitable for consumptions by humans. + */ + private static String formatHumaneElapsedTime(final long elapsedTime) { + final long nanoseconds = elapsedTime % 1_000_000; + + final double ms = elapsedTime / 1_000_000; + final long milliseconds = (long)(ms % 1_000); + + final double s = ms / 1_000; + final long seconds = (long)(s % 60); + + final double m = s / 60; + final long minutes = (long)(m % 60); + + final double h = m / 60; + final long hours = (long)(h % 60); + + final StringBuilder humane = new StringBuilder(); + + if (hours > 0) { + humane.append(hours).append(" hour"); + if (hours > 1) { + humane.append('s'); + } + } + + if (minutes > 0) { + if (humane.length() > 0) { + humane.append(", "); + if (seconds == 0 && milliseconds == 0 && nanoseconds == 0) { + humane.append("and "); + } + } + humane.append(minutes).append(" minute"); + if (minutes > 1) { + humane.append('s'); + } + } + + if (seconds > 0) { + if (humane.length() > 0) { + humane.append(", "); + if (milliseconds == 0 && nanoseconds == 0) { + humane.append("and "); + } + } + + humane.append(seconds).append(" second"); + if (seconds > 1) { + humane.append('s'); + } + } + + if (milliseconds > 0) { + if (humane.length() > 0) { + humane.append(", "); + if (nanoseconds == 0) { + humane.append("and "); + } + } + + humane.append(milliseconds).append(" ms"); + } + + if (nanoseconds > 0) { + if (humane.length() > 0) { + humane.append(", and "); + } + + humane.append(nanoseconds).append(" ns"); + } + + return humane.toString(); + } + + /** + * Extract any options for the TimePragma from the Pragma Contents. + * + * @param contents the pragma contents. + * + * @return the options. + */ + private static Options parseOptions(@Nullable final String contents) throws XPathException { + boolean verbose = false; + @Nullable String loggerName = null; + @Nullable String loggingLevelName = null; + @Nullable String logMessagePrefix = null; + @Nullable String measurementModeStr = null; + + if (contents != null && !contents.isEmpty()) { final String[] options = Option.tokenize(contents); for (final String option : options) { - final String[] param = Option.parseKeyValuePair(option); + @Nullable final String[] param = Option.parseKeyValuePair(option); if (param == null) { throw new XPathException((Expression) null, "Invalid content found for pragma " + TIME_PRAGMA.getStringValue() + ": " + contents); } - if ("verbose".equals(param[0])) { - verbose = "yes".equals(param[1]); - } else if ("logger".equals(param[0])) { - log = LogManager.getLogger(param[1]); + switch (param[0]) { + case "verbose": + verbose = "true".equals(param[1]) || "yes".equals(param[1]); + break; + + case "logger-name": + loggerName = param[1]; + break; + + case "logging-level": + loggingLevelName = param[1]; + break; + + case "log-message-prefix": + logMessagePrefix = param[1]; + break; + + case "measurement-mode": + measurementModeStr = param[1]; + break; } } } - if (log == null) { - log = LogManager.getLogger(TimePragma.class); + + final Logger logger = Optional.ofNullable(loggerName).flatMap(s -> Optional.ofNullable(LogManager.getLogger(s))).orElseGet(() -> LogManager.getLogger(TimePragma.class)); + final Level loggingLevel = Optional.ofNullable(loggingLevelName).flatMap(s -> Optional.ofNullable(Level.getLevel(s))).orElse(Level.TRACE); + final MeasurementMode measurementMode = Optional.ofNullable(measurementModeStr).map(String::toUpperCase).map(s -> { + try { + return MeasurementMode.valueOf(s); + } catch (final IllegalArgumentException e) { + return MeasurementMode.SINGLE; + } + }).orElse(MeasurementMode.SINGLE); + + return new Options(verbose, logger, loggingLevel, logMessagePrefix, measurementMode); + } + + /** + * Holds the options for the Timer Pragma. + */ + private static class Options { + final boolean verbose; + final Logger logger; + final Level loggingLevel; + @Nullable final String logMessagePrefix; + final MeasurementMode measurementMode; + + private Options(final boolean verbose, final Logger logger, final Level loggingLevel, @Nullable final String logMessagePrefix, final MeasurementMode measurementMode) { + this.verbose = verbose; + this.logger = logger; + this.loggingLevel = loggingLevel; + this.logMessagePrefix = logMessagePrefix; + this.measurementMode = measurementMode; } } - @Override - public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException { - this.start = System.currentTimeMillis(); + /** + * The mode of measurement. + */ + private enum MeasurementMode { + SINGLE, + MULTIPLE } - @Override - public void after(final XQueryContext context, final Expression expression) throws XPathException { - final long elapsed = System.currentTimeMillis() - start; - if (log.isTraceEnabled()) { - if (verbose) { - log.trace("Elapsed: {}ms. for expression:\n{}", elapsed, ExpressionDumper.dump(expression)); - } else { - log.trace("Elapsed: {}ms.", elapsed); + /** + * Holds the timings for multiple iterations of the Pragma's additional expression. + */ + private static class Timing { + private static final int UNSET = -1; + + private long startTimestamp = UNSET; + + private long lastStartTimestamp = UNSET; + + private long firstElapsed = UNSET; + private long minElapsed = UNSET; + private long maxElapsed = UNSET; + private long lastElapsed = UNSET; + private long totalElapsed = 0; + + private int iterations = 0; + + /** + * Set the start timestamp of an iteration. + * + * @param startTimestamp the starting timestamp of an iteration. + */ + public void setStartTimestamp(final long startTimestamp) { + if (this.startTimestamp == UNSET) { + this.startTimestamp = startTimestamp; } + this.lastStartTimestamp = startTimestamp; + } + + /** + * Set the end timestamp of an iteration. + * + * @param endTimestamp the end timestamp of an iteration. + */ + public void setEndTimestamp(final long endTimestamp) { + this.iterations++; + + final long elapsed = endTimestamp - lastStartTimestamp; + if (firstElapsed == UNSET) { + this.firstElapsed = elapsed; + } + if (minElapsed == UNSET || elapsed < minElapsed) { + minElapsed = elapsed; + } + if (elapsed > maxElapsed) { + maxElapsed = elapsed; + } + this.lastElapsed = elapsed; + this.totalElapsed += elapsed; + } + + /** + * Get the number of iterations that have been recorded. + * + * @return the number of iterations + */ + public int getIterations() { + return iterations; + } + + /** + * Get the elapsed time of the first iteration. + * + * @return the elapsed time of the first iteration. + */ + public long getFirstElapsed() { + return firstElapsed; + } + + /** + * Get the elapsed time of the shortest iteration, i.e. the least time spent on an iteration. + * + * @return the elapsed time of the shortest iteration. + */ + public long getMinElapsed() { + return minElapsed; + } + + /** + * Get the average elapsed time of all iterations. + * + * @return the average elapsed time of all iterations. + */ + public double getAvgElapsed() { + return getTotalElapsed() / (double) iterations; + } + + /** + * Get the elapsed time of the longest iteration, i.e. the most time spent on an iteration. + * + * @return the elapsed time of the longest iteration. + */ + public long getMaxElapsed() { + return maxElapsed; + } + + /** + * Get the elapsed time of the last iteration. + * + * @return the elapsed time of the last iteration. + */ + public long getLastElapsed() { + return lastElapsed; + } + + /** + * Get the total elapsed time of all iterations. + * + * @return the total elapsed time of all iterations. + */ + public long getTotalElapsed() { + return totalElapsed; + } + + /** + * Reset the class for next use. + */ + public void reset() { + this.startTimestamp = UNSET; + + this.lastStartTimestamp = UNSET; + + this.firstElapsed = UNSET; + this.minElapsed = UNSET; + this.maxElapsed = UNSET; + this.lastElapsed = UNSET; + this.totalElapsed = 0; + + this.iterations = 0; } } }