From 16389cca53b861f3766533f75c6dc44cc36872ce Mon Sep 17 00:00:00 2001 From: Adam Retter Date: Wed, 4 Oct 2023 17:09:01 +0100 Subject: [PATCH] [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..23a8f7568a5 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/TimerPragma.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/TimerPragma.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; } } }