evolvedbinary / elemental / 982

Committed 29 Apr 2025 08:34PM UTC coverage: 56.409% (+0.007%) from 56.402%

Build # 982

Build Type

push

circleci

Committed by

adamretter

Commit Message

[feature] Improve README.md badges

Run Details

28451 of 55847 branches covered (50.94%)

Branch coverage included in aggregate %.

77468 of 131924 relevant lines covered (58.72%)

0.59 hits per line

Source File
Press 'n' to go to next uncovered line, 'b' for previous

0.0

/exist-core/src/main/java/org/exist/xquery/pragmas/TimePragma.java

/*
 * Elemental
 * Copyright (C) 2024, Evolved Binary Ltd
 *
 * admin@evolvedbinary.com
 * https://www.evolvedbinary.com | https://www.elemental.xyz
 *
 * Use of this software is governed by the Business Source License 1.1
 * included in the LICENSE file and at www.mariadb.com/bsl11.
 *
 * Change Date: 2028-04-27
 *
 * On the date above, in accordance with the Business Source License, use
 * of this software will be governed by the Apache License, Version 2.0.
 *
 * Additional Use Grant: Production use of the Licensed Work for a permitted
 * purpose. A Permitted Purpose is any purpose other than a Competing Use.
 * A Competing Use means making the Software available to others in a commercial
 * product or service that: substitutes for the Software; substitutes for any
 * other product or service we offer using the Software that exists as of the
 * date we make the Software available; or offers the same or substantially
 * similar functionality as the Software.
 */
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;
import org.exist.Namespaces;
import org.exist.dom.QName;
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 via logging.
 *
 * <pre>{@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 :)
 * }
 * }</pre>
 *
 * 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 <a href="mailto:adam@evolvedbinary.com">Adam Retter</a>
 */
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 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);
        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) {
            if (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<Long, String> 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<Long, String> 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<Double, String> 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<Double, String> 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) {
                @Nullable final String[] param = Option.parseKeyValuePair(option);
                if (param == null) {
                    throw new XPathException((Expression) null, "Invalid content found for pragma " + TIME_PRAGMA.getStringValue() + ": " + contents);
                }

                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;
                }
            }
        }

        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;
        }
    }

    /**
     * The mode of measurement.
     */
    private enum MeasurementMode {
        SINGLE,
        MULTIPLE
    }

    /**
     * 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;
        }
    }
}

1	/*
2	* Elemental
3	* Copyright (C) 2024, Evolved Binary Ltd
4	*
5	* admin@evolvedbinary.com
6	* https://www.evolvedbinary.com \| https://www.elemental.xyz
7	*
8	* Use of this software is governed by the Business Source License 1.1
9	* included in the LICENSE file and at www.mariadb.com/bsl11.
10	*
11	* Change Date: 2028-04-27
12	*
13	* On the date above, in accordance with the Business Source License, use
14	* of this software will be governed by the Apache License, Version 2.0.
15	*
16	* Additional Use Grant: Production use of the Licensed Work for a permitted
17	* purpose. A Permitted Purpose is any purpose other than a Competing Use.
18	* A Competing Use means making the Software available to others in a commercial
19	* product or service that: substitutes for the Software; substitutes for any
20	* other product or service we offer using the Software that exists as of the
21	* date we make the Software available; or offers the same or substantially
22	* similar functionality as the Software.
23	*/
24	package org.exist.xquery.pragmas;
25
26	import com.evolvedbinary.j8fu.tuple.Tuple2;
27	import org.apache.logging.log4j.Level;
28	import org.exist.xquery.*;
29	import org.apache.logging.log4j.LogManager;
30	import org.apache.logging.log4j.Logger;
31	import org.exist.Namespaces;
32	import org.exist.dom.QName;
33	import org.exist.xquery.util.ExpressionDumper;
34	import org.exist.xquery.value.Sequence;
35
36	import javax.annotation.Nullable;
37	import java.util.Optional;
38
39	import static com.evolvedbinary.j8fu.tuple.Tuple.Tuple;
40
41	/**
42	* An XQuery Pragma that will record the execution
43	* time of the associated expression via logging.
44	*
45	* <pre>{@code
46	* (# exist:time verbose=yes logger-name=MyLog logging-level=TRACE log-message-prefix=LOOK-HERE #) {
47	* (: the XQuery Expression that you wish to time goes here :)
48	* }
49	* }</pre>
50	*
51	* The following optional configuration options may be given to the Time Pragma via the pragma's contents:
52	* * 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.
53	* * logger-name - The name of the logger to use, if omitted the logger for {@link TimePragma} will be used.
54	* * 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.
55	* * log-message-prefix - An optional prefix to append to the start of the log message to help you identify it.
56	* * measurement-mode - indicates whether we should measure a single invocation of the additional expression or multiple invocations 'single' or 'multiple'. The default is 'single'.
57	*
58	* @author <a href="mailto:adam@evolvedbinary.com">Adam Retter</a>
59	*/
60	public class TimePragma extends AbstractPragma {
61
62	public static final String TIME_PRAGMA_LOCAL_NAME = "time";
63	public static final QName TIME_PRAGMA = new QName(TIME_PRAGMA_LOCAL_NAME, Namespaces.EXIST_NS, "exist");	×
64	public static final String DEPRECATED_TIMER_PRAGMA_LOCAL_NAME = "timer";	×
65
66	private final Options options;
67	@Nullable private Timing timing = null;	×
68
69	public TimePragma(final Expression expression, final QName qname, final String contents) throws XPathException {
70	super(expression, qname, contents);	×
71	this.options = parseOptions(getContents());	×
72	}	×
73
74	@Override
75	public void before(final XQueryContext context, final Expression expression, final Sequence contextSequence) throws XPathException {
76	if (timing == null) {	×
77	this.timing = new Timing();	×
78	}
79	timing.setStartTimestamp(System.nanoTime());	×
80	}	×
81
82	@Override
83	public void after(final XQueryContext context, final Expression expression) throws XPathException {
84	timing.setEndTimestamp(System.nanoTime());	×
85
86	if (options.measurementMode == MeasurementMode.SINGLE) {	×
87	logSingleMeasurement(expression);	×
88	this.timing.reset();	×
89	}
90	}	×
91
92	@Override
93	public void resetState(final boolean postOptimization) {
94	if (timing != null) {	×
95	if (options.measurementMode == MeasurementMode.MULTIPLE) {	×
96	logMultipleMeasurement();	×
97	}
98	this.timing.reset();	×
99	}
100	}	×
101
102	/**
103	* Return the nanoseconds as either
104	* nanoseconds or milliseconds.
105	*
106	* @param nanoseconds the time in milliseconds.
107	*
108	* @return the time.
109	*/
110	private static Tuple2<Long, String> nsOrMs(final long nanoseconds) {
111	final long timeValue;
112	final String timeUnit;
113	if (nanoseconds > 999_999) {	×
114	timeValue = nanoseconds / 1_000_000;	×
115	timeUnit = "ms";	×
116	} else {	×
117	timeValue = nanoseconds;	×
118	timeUnit = "ns";	×
119	}
120	return Tuple(timeValue, timeUnit);	×
121	}
122
123	/**
124	* Return the nanoseconds as either
125	* nanoseconds or milliseconds.
126	*
127	* @param nanoseconds the time in milliseconds.
128	*
129	* @return the time.
130	*/
131	private static String nsOrMsStr(final long nanoseconds) {
132	final Tuple2<Long, String> time = nsOrMs(nanoseconds);	×
133	return String.format("%d %s", time._1, time._2);	×
134	}
135
136	/**
137	* Return the nanoseconds as either
138	* nanoseconds or milliseconds.
139	*
140	* @param nanoseconds the time in milliseconds.
141	*
142	* @return the time.
143	*/
144	private static Tuple2<Double, String> nsOrMsDbl(final double nanoseconds) {
145	final double timeValue;
146	final String timeUnit;
147	if (nanoseconds > 999_999) {	×
148	timeValue = nanoseconds / 1_000_000;	×
149	timeUnit = "ms";	×
150	} else {	×
151	timeValue = nanoseconds;	×
152	timeUnit = "ns";	×
153	}
154	return Tuple(timeValue, timeUnit);	×
155	}
156
157	/**
158	* Return the nanoseconds as either
159	* nanoseconds or milliseconds.
160	*
161	* @param nanoseconds the time in milliseconds.
162	*
163	* @return the time.
164	*/
165	private static String nsOrMsStrDbl(final double nanoseconds) {
166	final Tuple2<Double, String> time = nsOrMsDbl(nanoseconds);	×
167	return String.format("%.2f %s", time._1, time._2);	×
168	}
169
170	private void logSingleMeasurement(final Expression expression) {
171	final long elapsedTime = timing.getTotalElapsed();	×
172	@Nullable final String humaneElapsedTime = elapsedTime > (1_000_000 * 999) ? formatHumaneElapsedTime(elapsedTime) : null;	×
173
174	final String displayTime = nsOrMsStr(elapsedTime);	×
175
176	if (options.logger.isEnabled(options.loggingLevel)) {	×
177
178	if (options.logMessagePrefix != null) {	×
179	if (options.verbose) {	×
180	if (humaneElapsedTime != null) {	×
181	options.logger.log(options.loggingLevel, "{} Elapsed: {} ({}) for expression: {}", options.logMessagePrefix, displayTime, humaneElapsedTime, ExpressionDumper.dump(expression));	×
182	} else {	×
183	options.logger.log(options.loggingLevel, "{} Elapsed: {} for expression: {}", options.logMessagePrefix, displayTime, ExpressionDumper.dump(expression));	×
184	}
185	} else {	×
186	if (humaneElapsedTime != null) {	×
187	options.logger.log(options.loggingLevel, "{} Elapsed: {} ({}).", options.logMessagePrefix, displayTime, humaneElapsedTime);	×
188	} else {	×
189	options.logger.log(options.loggingLevel, "{} Elapsed: {}.", options.logMessagePrefix, displayTime);	×
190	}
191	}
192	} else {	×
193	if (options.verbose) {	×
194	if (humaneElapsedTime != null) {	×
195	options.logger.log(options.loggingLevel, "Elapsed: {} ({}) for expression: {}", displayTime, humaneElapsedTime, ExpressionDumper.dump(expression));	×
196	} else {	×
197	options.logger.log(options.loggingLevel, "Elapsed: {} for expression: {}", displayTime, ExpressionDumper.dump(expression));	×
198	}
199	} else {	×
200	if (humaneElapsedTime != null) {	×
201	options.logger.log(options.loggingLevel, "Elapsed: {} ({}).", displayTime, humaneElapsedTime);	×
202	} else {	×
203	options.logger.log(options.loggingLevel, "Elapsed: {}.", displayTime);	×
204	}
205	}
206	}
207	}
208	}	×
209
210	private void logMultipleMeasurement() {
211	final long elapsedTime = timing.getTotalElapsed();	×
212	@Nullable final String humaneElapsedTime = elapsedTime > 999 ? formatHumaneElapsedTime(elapsedTime) : null;	×
213
214	final String displayTime = nsOrMsStr(elapsedTime);	×
215
216	if (options.logMessagePrefix != null) {	×
217	if (humaneElapsedTime != null) {	×
218	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()));	×
219	} else {	×
220	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()));	×
221	}
222	} else {	×
223	if (humaneElapsedTime != null) {	×
224	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()));	×
225	} else {	×
226	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()));	×
227	}
228	}
229	}	×
230
231	/**
232	* Format the elapsed time in a humane manner.
233	*
234	* @param elapsedTime the elapsed time in nanoseconds.
235	*
236	* @return a string of the duration which is suitable for consumptions by humans.
237	*/
238	private static String formatHumaneElapsedTime(final long elapsedTime) {
239	final long nanoseconds = elapsedTime % 1_000_000;	×
240
241	final double ms = elapsedTime / 1_000_000;	×
242	final long milliseconds = (long)(ms % 1_000);	×
243
244	final double s = ms / 1_000;	×
245	final long seconds = (long)(s % 60);	×
246
247	final double m = s / 60;	×
248	final long minutes = (long)(m % 60);	×
249
250	final double h = m / 60;	×
251	final long hours = (long)(h % 60);	×
252
253	final StringBuilder humane = new StringBuilder();	×
254
255	if (hours > 0) {	×
256	humane.append(hours).append(" hour");	×
257	if (hours > 1) {	×
258	humane.append('s');	×
259	}
260	}
261
262	if (minutes > 0) {	×
263	if (humane.length() > 0) {	×
264	humane.append(", ");	×
265	if (seconds == 0 && milliseconds == 0 && nanoseconds == 0) {	×
266	humane.append("and ");	×
267	}
268	}
269
270	humane.append(minutes).append(" minute");	×
271	if (minutes > 1) {	×
272	humane.append('s');	×
273	}
274	}
275
276	if (seconds > 0) {	×
277	if (humane.length() > 0) {	×
278	humane.append(", ");	×
279	if (milliseconds == 0 && nanoseconds == 0) {	×
280	humane.append("and ");	×
281	}
282	}
283
284	humane.append(seconds).append(" second");	×
285	if (seconds > 1) {	×
286	humane.append('s');	×
287	}
288	}
289
290	if (milliseconds > 0) {	×
291	if (humane.length() > 0) {	×
292	humane.append(", ");	×
293	if (nanoseconds == 0) {	×
294	humane.append("and ");	×
295	}
296	}
297
298	humane.append(milliseconds).append(" ms");	×
299	}
300
301	if (nanoseconds > 0) {	×
302	if (humane.length() > 0) {	×
303	humane.append(", and ");	×
304	}
305
306	humane.append(nanoseconds).append(" ns");	×
307	}
308
309	return humane.toString();	×
310	}
311
312	/**
313	* Extract any options for the TimePragma from the Pragma Contents.
314	*
315	* @param contents the pragma contents.
316	*
317	* @return the options.
318	*/
319	private static Options parseOptions(@Nullable final String contents) throws XPathException {
320	boolean verbose = false;	×
321	@Nullable String loggerName = null;	×
322	@Nullable String loggingLevelName = null;	×
323	@Nullable String logMessagePrefix = null;	×
324	@Nullable String measurementModeStr = null;	×
325
326	if (contents != null && !contents.isEmpty()) {	×
327	final String[] options = Option.tokenize(contents);	×
328	for (final String option : options) {	×
329	@Nullable final String[] param = Option.parseKeyValuePair(option);	×
330	if (param == null) {	×
331	throw new XPathException((Expression) null, "Invalid content found for pragma " + TIME_PRAGMA.getStringValue() + ": " + contents);	×
332	}
333
334	switch (param[0]) {	×
335	case "verbose":
336	verbose = "true".equals(param[1]) \|\| "yes".equals(param[1]);	×
337	break;	×
338
339	case "logger-name":
340	loggerName = param[1];	×
341	break;	×
342
343	case "logging-level":
344	loggingLevelName = param[1];	×
345	break;	×
346
347	case "log-message-prefix":
348	logMessagePrefix = param[1];	×
349	break;	×
350
351	case "measurement-mode":
352	measurementModeStr = param[1];	×
353	break;
354	}
355	}
356	}
357
358	final Logger logger = Optional.ofNullable(loggerName).flatMap(s -> Optional.ofNullable(LogManager.getLogger(s))).orElseGet(() -> LogManager.getLogger(TimePragma.class));	×
359	final Level loggingLevel = Optional.ofNullable(loggingLevelName).flatMap(s -> Optional.ofNullable(Level.getLevel(s))).orElse(Level.TRACE);	×
360	final MeasurementMode measurementMode = Optional.ofNullable(measurementModeStr).map(String::toUpperCase).map(s -> {	×
361	try {
362	return MeasurementMode.valueOf(s);	×
363	} catch (final IllegalArgumentException e) {	×
364	return MeasurementMode.SINGLE;	×
365	}
366	}).orElse(MeasurementMode.SINGLE);	×
367
368	return new Options(verbose, logger, loggingLevel, logMessagePrefix, measurementMode);	×
369	}
370
371	/**
372	* Holds the options for the Timer Pragma.
373	*/
374	private static class Options {
375	final boolean verbose;
376	final Logger logger;
377	final Level loggingLevel;
378	@Nullable final String logMessagePrefix;
379	final MeasurementMode measurementMode;
380
381	private Options(final boolean verbose, final Logger logger, final Level loggingLevel, @Nullable final String logMessagePrefix, final MeasurementMode measurementMode) {	×
382	this.verbose = verbose;	×
383	this.logger = logger;	×
384	this.loggingLevel = loggingLevel;	×
385	this.logMessagePrefix = logMessagePrefix;	×
386	this.measurementMode = measurementMode;	×
387	}	×
388	}
389
390	/**
391	* The mode of measurement.
392	*/
393	private enum MeasurementMode {	×
394	SINGLE,	×
395	MULTIPLE	×
396	}
397
398	/**
399	* Holds the timings for multiple iterations of the Pragma's additional expression.
400	*/
401	private static class Timing {	×
402	private static final int UNSET = -1;
403
404	private long startTimestamp = UNSET;	×
405
406	private long lastStartTimestamp = UNSET;	×
407
408	private long firstElapsed = UNSET;	×
409	private long minElapsed = UNSET;	×
410	private long maxElapsed = UNSET;	×
411	private long lastElapsed = UNSET;	×
412	private long totalElapsed = 0;	×
413
414	private int iterations = 0;	×
415
416	/**
417	* Set the start timestamp of an iteration.
418	*
419	* @param startTimestamp the starting timestamp of an iteration.
420	*/
421	public void setStartTimestamp(final long startTimestamp) {
422	if (this.startTimestamp == UNSET) {	×
423	this.startTimestamp = startTimestamp;	×
424	}
425	this.lastStartTimestamp = startTimestamp;	×
426	}	×
427
428	/**
429	* Set the end timestamp of an iteration.
430	*
431	* @param endTimestamp the end timestamp of an iteration.
432	*/
433	public void setEndTimestamp(final long endTimestamp) {
434	this.iterations++;	×
435
436	final long elapsed = endTimestamp - lastStartTimestamp;	×
437	if (firstElapsed == UNSET) {	×
438	this.firstElapsed = elapsed;	×
439	}
440	if (minElapsed == UNSET \|\| elapsed < minElapsed) {	×
441	minElapsed = elapsed;	×
442	}
443	if (elapsed > maxElapsed) {	×
444	maxElapsed = elapsed;	×
445	}
446	this.lastElapsed = elapsed;	×
447	this.totalElapsed += elapsed;	×
448	}	×
449
450	/**
451	* Get the number of iterations that have been recorded.
452	*
453	* @return the number of iterations
454	*/
455	public int getIterations() {
456	return iterations;	×
457	}
458
459	/**
460	* Get the elapsed time of the first iteration.
461	*
462	* @return the elapsed time of the first iteration.
463	*/
464	public long getFirstElapsed() {
465	return firstElapsed;	×
466	}
467
468	/**
469	* Get the elapsed time of the shortest iteration, i.e. the least time spent on an iteration.
470	*
471	* @return the elapsed time of the shortest iteration.
472	*/
473	public long getMinElapsed() {
474	return minElapsed;	×
475	}
476
477	/**
478	* Get the average elapsed time of all iterations.
479	*
480	* @return the average elapsed time of all iterations.
481	*/
482	public double getAvgElapsed() {
483	return getTotalElapsed() / (double) iterations;	×
484	}
485
486	/**
487	* Get the elapsed time of the longest iteration, i.e. the most time spent on an iteration.
488	*
489	* @return the elapsed time of the longest iteration.
490	*/
491	public long getMaxElapsed() {
492	return maxElapsed;	×
493	}
494
495	/**
496	* Get the elapsed time of the last iteration.
497	*
498	* @return the elapsed time of the last iteration.
499	*/
500	public long getLastElapsed() {
501	return lastElapsed;	×
502	}
503
504	/**
505	* Get the total elapsed time of all iterations.
506	*
507	* @return the total elapsed time of all iterations.
508	*/
509	public long getTotalElapsed() {
510	return totalElapsed;	×
511	}
512
513	/**
514	* Reset the class for next use.
515	*/
516	public void reset() {
517	this.startTimestamp = UNSET;	×
518
519	this.lastStartTimestamp = UNSET;	×
520
521	this.firstElapsed = UNSET;	×
522	this.minElapsed = UNSET;	×
523	this.maxElapsed = UNSET;	×
524	this.lastElapsed = UNSET;	×
525	this.totalElapsed = 0;	×
526
527	this.iterations = 0;	×
528	}	×
529	}
530	}

evolvedbinary / elemental / 982

Source File Press 'n' to go to next uncovered line, 'b' for previous

Source File
Press 'n' to go to next uncovered line, 'b' for previous