From 6d8aa027cb9e99a76eeacecb5767698036bc4739 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..d809acbc2bb 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 'yes' if you want the associated expression to be logged to. + * * 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 = "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; } } }