From a8cf537f07b77ad8a7ac5c5b17f959de7ca052a2 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 10:25:22 -0500 Subject: [PATCH 01/10] add integration test Signed-off-by: Matthew Khouzam --- .../trace_event_logger/OldLogUtils.java | 854 ++++++++++++++++++ .../TestLoggerBenchmark.java | 354 ++++++++ 2 files changed, 1208 insertions(+) create mode 100644 src/test/java/org/eclipse/tracecompass/trace_event_logger/OldLogUtils.java create mode 100644 src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/OldLogUtils.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/OldLogUtils.java new file mode 100644 index 0000000..a646c0d --- /dev/null +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/OldLogUtils.java @@ -0,0 +1,854 @@ +/******************************************************************************* + * Copyright (c) 2024 Ericsson + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the “Software”), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * SPDX-License-Identifier: MIT + *******************************************************************************/ + +package org.eclipse.tracecompass.trace_event_logger; + +import java.text.DecimalFormat; +import java.text.Format; +import java.util.Arrays; +import java.util.HashMap; +import java.util.HashSet; +import java.util.Iterator; +import java.util.Map; +import java.util.Map.Entry; +import java.util.Set; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.function.Supplier; +import java.util.logging.Level; +import java.util.logging.Logger; + +/** + * Note: this was TraceCompassLogUtil copied as-is. It is relicensed to MIT, + * permissions from all contributing parties were obtained. This is used for + * testing purposes only. + * + * Logger helper + * + * This is a logger helper, it will allow entry-exit analysis to be much easier. + * + * The events are saved in a JSON-like message in the phase of the event. It is + * an event type but with extra information associated to it. Typical types can + * be the following. + * + *

+ * To use durations and/or flows, see + * {@link ScopeLog} and {@link FlowScopeLog}. These 2 concepts are related. + * Durations would typically be used to instrument simple methods, while flows + * would be preferred if there are links to be made with other threads. + *

+ * To use Asynchronous nested messages, see + * {@link #traceAsyncStart(Logger, Level, String, String, int, Object...)}, and + * {@link #traceAsyncEnd(Logger, Level, String, String, int, Object...)} + *

+ * To use Object tracking, see + * {@link #traceObjectCreation(Logger, Level, Object)} and + * {@link #traceObjectDestruction(Logger, Level, Object)} + * + * The design philosophy of this class is very heavily inspired by the trace + * event format of Google. The full specification is available here. + *

+ * + * The main goals are clarity of output and simplicity for the developer. + * Performance is a nice to have, but is not the main concern of this helper. A + * minor performance impact compared to simply logging the events is to be + * expected. + * + * @author Matthew Khouzam + * @noinstantiate This class is not intended to be instantiated by clients. It + * is a helper class. + */ +public final class OldLogUtils { + + private static final Format FORMAT = new DecimalFormat("#.###"); //$NON-NLS-1$ + + /* + * Field names + */ + private static final String ARGS = "args"; //$NON-NLS-1$ + private static final String NAME = "name"; //$NON-NLS-1$ + private static final String CATEGORY = "cat"; //$NON-NLS-1$ + private static final String ID = "id"; //$NON-NLS-1$ + private static final String TID = "tid"; //$NON-NLS-1$ + private static final String PID = "pid"; //$NON-NLS-1$ + private static final String TIMESTAMP = "ts"; //$NON-NLS-1$ + private static final String PHASE = "ph"; //$NON-NLS-1$ + + private static final String ARGS_ERROR_MESSAGE = "Data should be in the form of key, value, key1, value1, ... oldScopeLog was supplied "; //$NON-NLS-1$ + private static final AtomicInteger ID_GENERATOR = new AtomicInteger(0); + + private OldLogUtils() { + // do nothing + } + + /** + * Scope Logger helper. This will automatically log entry and exit of the scope. + * This scope log will be shown under any scope enclosing it, but will not be + * the source, or destination of any link to other scopes. If relations should + * be done with other scopes, the {@link FlowScopeLog} class is more + * appropriate. + * + * Usage: + * + * 

+	 * {@code usage of ScopeLog}
+	 *  try (ScopeLog linksLogger = new ScopeLog(LOGGER, Level.CONFIG, "Perform Query")) { //$NON-NLS-1$
+	 *      ss.updateAllReferences();
+	 *      dataStore.addAll(ss.query(ts, trace));
+	 *  }
+	 *
+ *

+ * will generate the following trace + * + * 

+	 * {@code trace output}
+	 *  INFO: {"ts":12345,"ph":"B",tid:1,"name:Perform Query"}
+	 *  INFO: {"ts":"12366,"ph":"E","tid":1}
+	 *
+ */ + public static class ScopeLog implements AutoCloseable { + + private final long fTime; + private final long fThreadId; + private final Logger fLogger; + private final Level fLevel; + private final String fLabel; + private final Map fData = new HashMap<>(); + + /** + * Scope logger constructor + * + * @param log the JUL logger to log to + * @param level the log level see {@link Level} + * @param label The label of the event pair + * @param args Additional messages to pass for this scope, should be in pairs + * key, value, key2, value2.... typically arguments. Note that + * these arguments will be logged only at the beginning of the + * scope + */ + public ScopeLog(Logger log, Level level, String label, Object... args) { + fTime = System.nanoTime(); + fLogger = log; + fLevel = level; + fThreadId = Thread.currentThread().getId(); + fLabel = label; + char phase = 'B'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, fTime, fThreadId); + appendName(sb, fLabel); + appendArgs(sb, args); + sb.append('}'); + return sb.toString(); + }; + fLogger.log(fLevel, msgSupplier); + } + + /** + * Add a tag to the scope logger, will be written at the exit. This can save + * space on the trace by having a field appended to an event rather than writing + * a whole new event for a small chunk of data. + * + * If the timing information is important than it would be more appropriate to + * call {@link OldLogUtils#traceInstant(Logger, Level, String, Object...)} + * + * @param name the name of the field + * @param value The value of the field. + */ + public void addData(String name, Object value) { + fData.put(name, value); + } + + @Override + public void close() { + long time = System.nanoTime(); + char phase = 'E'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, fThreadId); + return appendArgs(sb, fData).append('}').toString(); + }; + fLogger.log(fLevel, msgSupplier); + } + } + + /** + * Builder class for the {@link FlowScopeLog}. One can either set a category or + * a parent scope before building the flow scope log. If none is set, a default + * category called "null" will be used. + * + * @author Geneviève Bastien + */ + public static class FlowScopeLogBuilder { + + private final Logger fLogger; + private final Level fLevel; + private final String fLabel; + private final Object[] fArgs; + private int fId = Integer.MIN_VALUE; + private String fCategory = null; + private FlowScopeLog fParent = null; + private boolean fHasParent = false; + + /** + * Flow scope log builder constructor + * + * @param logger the JUL logger + * @param level the log level see {@link Level} + * @param label The label of the event pair + * @param args the messages to pass, should be in pairs key, value, key2, + * value2.... typically arguments + */ + public FlowScopeLogBuilder(Logger logger, Level level, String label, Object... args) { + fLogger = logger; + fLevel = level; + fLabel = label; + fArgs = args; + } + + /** + * Set a category for the flow scope. When building the scope, an ID will be + * automatically generated. + * + * This method is mutually exclusive with {@link #setParentScope(FlowScopeLog)}. + * Calling both will throw an exception. + * + * @param category The category of this flow + * @return This builder + */ + public FlowScopeLogBuilder setCategory(String category) { + if (fParent != null) { + throw new IllegalStateException( + "FlowScopeLogBuilder: Cannot set a category if a parent has already been set"); //$NON-NLS-1$ + } + fCategory = category; + return this; + } + + /** + * Set a category and ID for the flow scope. + * + * This method is mutually exclusive with {@link #setParentScope(FlowScopeLog)}. + * Calling both will throw an exception. + * + * @param category The category of this flow + * @param id The ID of this flow + * @return This builder + */ + public FlowScopeLogBuilder setCategoryAndId(String category, int id) { + if (fParent != null) { + throw new IllegalStateException( + "FlowScopeLogBuilder: Cannot set a category if a parent has already been set"); //$NON-NLS-1$ + } + fCategory = category; + fId = id; + // Id is already set, so assume this scope has a parent, even if the + // parent object is not available + fHasParent = true; + return this; + } + + /** + * Set a parent scope for the flow scope to build. The scope will have the same + * category and ID as the parent scope. + * + * This method is mutually exclusive with {@link #setCategory(String)} and + * {@link #setCategoryAndId(String, int)}. Calling both will throw an exception. + * + * @param parent The parent scope + * @return This builder + */ + public FlowScopeLogBuilder setParentScope(FlowScopeLog parent) { + if (fCategory != null) { + throw new IllegalStateException( + "FlowScopeLogBuilder: Cannot set a parent scope if a category has already been set"); //$NON-NLS-1$ + } + fParent = parent; + return this; + } + + /** + * Build the flow scope log + * + * @return The flow scope log + */ + public FlowScopeLog build() { + FlowScopeLog parent = fParent; + if (parent != null) { + // Has a parent scope, so step in flow + return new FlowScopeLog(fLogger, fLevel, fLabel, parent.fCategory, parent.fId, false, fArgs); + } + return new FlowScopeLog(fLogger, fLevel, fLabel, String.valueOf(fCategory), + (fId == Integer.MIN_VALUE ? ID_GENERATOR.incrementAndGet() : fId), !fHasParent, fArgs); + } + + } + + /** + * Flow Scope Logger helper. It will automatically log entry and exit of the + * scope. It can be used with other flow scopes to follow the program flow + * across threads. To do so, these scopes save more data, so take more disk + * space. If there is no inter-process/thread communication to follow, the + * {@link ScopeLog} class would be more appropriate. + * + * Usage: this can be used to track asynchronous threads communication. This can + * be used in scatter-gather/map-reduce operations as well as threads that + * trigger a UI Thread operation. + * + * 
+	 * {@code usage of FlowScopeLog}
+	 *  try (FlowScopeLog linksLogger = new FlowScopeLog(LOGGER, Level.CONFIG, "Perform Query", "category", 0x100)) { //$NON-NLS-1$
+	 *      Display.asynchExec(()->{
+	 *      try(FlowScopeLog linksLogger2 = new FlowScopeLog(LOGGER, Level.CONFIG, "Update UI", "category", linksLogger.getId()) {
+	 *          linksLogger.step("updating ui");
+	 *      };
+	 *      linksLogger.step("forked thread");
+	 *  }
+	 *
+ *

+ * will generate the following trace (order not guaranteed) + * + * 

+	 * {@code trace output}
+	 *  INFO: {"ts":12345,"ph":"s",tid:1,"name":"Perform Query", "cat":"category", "id":256}
+	 *  INFO: {"ts":12346","ph":"t",tid:1,"name":"forked thread","cat":"category", "id":256}
+	 *  INFO: {"ts":"12366,"ph":"f","tid":1,"cat":"category", "id":256}
+	 *  INFO: {"ts":12400,"ph":"s",tid:0,"name":"Update UI","cat":"category", "id":256}
+	 *  INFO: {"ts":12416","ph":"t",tid:0,"name":"updating ui", "cat":"category", "id":256}
+	 *  INFO: {"ts":"12420,"ph":"f","tid":0,"cat":"category", "id":256}
+	 *
+ */ + public static class FlowScopeLog implements AutoCloseable { + + private final long fThreadId; + private final Logger fLogger; + private final Level fLevel; + private final int fId; + private final String fCategory; + private final Map fData = new HashMap<>(); + private final String fLabel; + private final long fTime; + + /** + * Flow scope logger constructor + * + * @param log the JUL logger + * @param level the log level see {@link Level} + * @param label The label of the event pair + * @param category the category of the flow events + * @param id The id of the flow + * @param startFlow Whether this flow scope object is the start of a flow, or a + * step + * @param args the messages to pass, should be in pairs key, value, key2, + * value2.... typically arguments + */ + private FlowScopeLog(Logger log, Level level, String label, String category, int id, boolean startFlow, + Object... args) { + fTime = System.nanoTime(); + fId = id; + fLogger = log; + fLevel = level; + fCategory = category; + fLabel = label; + fThreadId = Thread.currentThread().getId(); + char phaseB = 'B'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phaseB, fTime, fThreadId); + appendName(sb, label); + appendArgs(sb, args); + sb.append('}'); + return sb.toString(); + }; + fLogger.log(fLevel, msgSupplier); + // Add a flow event, either start or step in enclosing scope + char phase = startFlow ? 's' : 't'; + msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, fTime, fThreadId); + appendName(sb, label); + appendCategory(sb, category); + appendId(sb, fId); + appendArgs(sb, args); + sb.append('}'); + return sb.toString(); + }; + fLogger.log(fLevel, msgSupplier); + } + + /** + * Flow step, it will add a stop point for an arrow + * + * @param label The label for this step + * @param args the arguments to log + */ + public void step(String label, Object... args) { + long time = System.nanoTime(); + char phase = 't'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, fThreadId); + appendName(sb, label); + appendCategory(sb, fCategory); + appendId(sb, fId); + appendArgs(sb, args); + sb.append('}'); + return sb.toString(); + }; + fLogger.log(fLevel, msgSupplier); + } + + /** + * Add a tag to the scope logger, will be written at the exit. This can save + * space on the trace by having a field appended to an event rather than writing + * a whole new event for a small chunk of data. + * + * + * If the timing information is important, then it would be more appropriate to + * call {@link #step(String, Object...)} + * + * @param name the name of the field + * @param value The value of the field. + */ + public void addData(String name, Object value) { + fData.put(name, value); + } + + /** + * Get the ID for this scope. The ID can be injected to other components that + * can use it for the scope loggers + * + * @return The ID of this scope + */ + public int getId() { + return fId; + } + + @Override + public void close() { + long time = System.nanoTime(); + char phase = 'E'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, fThreadId); + appendArgs(sb, fData); + sb.append('}'); + return sb.toString(); + }; + fLogger.log(fLevel, msgSupplier); + } + } + + /** + * Trace Object Creation, logs the beginning of an object's life cycle. + * Typically one can put this in the object's constructor. However if an object + * is mutable, it can be tracked through phases with this method, then the + * object can be re-used, however, the resulting analyses may yield erroneous + * data if precautions are not taken. + * + * For mutable objects, save the return value of the call. This will be passed + * to the destruction of the object and then it can be matched. + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param item the Object to trace + * @return The unique ID of this object (there may be collisions) + */ + public static int traceObjectCreation(Logger logger, Level level, Object item) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + int identityHashCode = System.identityHashCode(item); + char phase = 'N'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, item.getClass().getSimpleName()); + appendId(sb, identityHashCode); + return sb.append('}').toString(); + }; + logger.log(level, msgSupplier); + return identityHashCode; + } + + /** + * Trace Object Destruction, logs the end of an object's life cycle. Typically + * one can put this in the object's Dispose(). However if an object is mutable, + * it can be tracked through phases with this method, then the object can be + * re-used, however, the resulting analyses may yield erroneous data if + * precautions are not taken. + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param item the Object to trace + */ + public static void traceObjectDestruction(Logger logger, Level level, Object item) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'D'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, item.getClass().getSimpleName()); + appendId(sb, System.identityHashCode(item)); + return sb.append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * Trace Object Destruction, logs the end of an object's life cycle. Typically + * one can put this in the object's Dispose(). However if an object is mutable, + * it can be tracked through phases with this method, then the object can be + * re-used, however, the resulting analyses may be + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param item the Object to trace + * @param uniqueId The unique ID + */ + public static void traceObjectDestruction(Logger logger, Level level, Object item, int uniqueId) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'D'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, item.getClass().getSimpleName()); + appendId(sb, uniqueId); + return sb.append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * Asynchronous events are used to specify asynchronous operations, such as an + * asynchronous (or synchronous) draw, or a network operation. Call this method + * at the beginning of such an operation. + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param name The name of the asynchronous message + * @param category the category of the asynchronous event + * @param id The unique ID of a transaction + * @param args Additional arguments to log + */ + public static void traceAsyncStart(Logger logger, Level level, String name, String category, int id, + Object... args) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'b'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, name); + appendCategory(sb, category); + appendId(sb, id); + return appendArgs(sb, args).append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * Asynchronous events are used to specify asynchronous operations, such as an + * asynchronous (or synchronous) draw, or a network operation. Call this method + * to augment the asynchronous event with nested information. + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param name The name of the asynchronous message + * @param category the category of the asynchronous event + * @param id The unique ID of a transaction + * @param args Additional arguments to log + */ + public static void traceAsyncNested(Logger logger, Level level, String name, String category, int id, + Object... args) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'n'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, name); + appendCategory(sb, category); + appendId(sb, id); + return appendArgs(sb, args).append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * Asynchronous events are used to specify asynchronous operations, such as an + * asynchronous (or synchronous) draw, or a network operation. Call this method + * at the end of such an operation. + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param name The name of the asynchronous message + * @param category the category of the asynchronous event + * @param id The unique ID of a transaction + * @param args Additional arguments to log + */ + public static void traceAsyncEnd(Logger logger, Level level, String name, String category, int id, Object... args) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'e'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, name); + appendCategory(sb, category); + appendId(sb, id); + return appendArgs(sb, args).append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * Instant events, created to indicate an item of interest has occurred, similar + * to a standard System.out.println() or a Java.util.Logger#log(Level). This one + * provides an event in a more structured way. This should be the method to call + * to save data that should have a zero duration, as it will ensure a log format + * that can then be parsed by a trace type. + * + * @param logger The JUL logger + * @param level The {@link Level} of this event. + * @param name The name of the asynchronous message + * @param args Additional arguments to log + */ + public static void traceInstant(Logger logger, Level level, String name, Object... args) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'i'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, name); + return appendArgs(sb, args).append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * The counter events can track a value or multiple values as they change over + * time. + * + * @param logger The Logger + * @param level The {@link Level} of this event. + * @param name The name of the asynchronous message + * @param args The counters to log in the format : "title", value + */ + public static void traceCounter(Logger logger, Level level, String name, Object... args) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'C'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, name); + return appendArgs(sb, args).append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + /** + * The Marker events are events with a duration that define a region of + * interest. These regions can be displayed in views as Markers or other + * indicators. + * + * @param logger The Logger + * @param level The {@link Level} of this event. + * @param name The name of the marker message message + * @param duration How long the marker should last + * @param args The counters to log in the format : "title", value, note + * "color" and an rbga will be used + */ + public static void traceMarker(Logger logger, Level level, String name, long duration, Object... args) { + long time = System.nanoTime(); + long threadId = Thread.currentThread().getId(); + char phase = 'R'; + Supplier msgSupplier = () -> { + StringBuilder sb = new StringBuilder(); + sb.append('{'); + appendCommon(sb, phase, time, threadId); + appendName(sb, name); + sb.append(','); + writeObject(sb, "dur", duration); //$NON-NLS-1$ + return appendArgs(sb, args).append('}').toString(); + }; + logger.log(level, msgSupplier); + } + + // ------------------------------------------------------------------------- + // Helpers + // ------------------------------------------------------------------------- + + /* + * USE ME FIRST + */ + private static StringBuilder appendCommon(StringBuilder appendTo, char phase, long time, long threadId) { + writeObject(appendTo, TIMESTAMP, FORMAT.format((double) time / 1000)).append(','); // $NON-NLS-1$ + writeObject(appendTo, PHASE, phase).append(','); + writeObject(appendTo, TID, threadId).append(','); + return writeObject(appendTo, PID, threadId); // $NON-NLS-1$ + } + + private static StringBuilder appendName(StringBuilder sb, String name) { + if (name != null) { + sb.append(','); + writeObject(sb, NAME, name); + } + return sb; + } + + private static StringBuilder appendCategory(StringBuilder sb, String category) { + if (category != null) { + sb.append(','); + writeObject(sb, CATEGORY, category); + } + return sb; + } + + private static StringBuilder appendId(StringBuilder sb, int id) { + return sb.append(',').append('"').append(ID).append("\":\"0x") //$NON-NLS-1$ + .append(Integer.toHexString(id)).append('"'); + } + + private static StringBuilder appendArgs(StringBuilder sb, Map args) { + if (!args.isEmpty()) { + sb.append(',').append('"').append(ARGS).append('"').append(':'); + Object[] argsArray = new Object[2 * args.size()]; + Iterator> entryIter = args.entrySet().iterator(); + for (int i = 0; i < args.size(); i++) { + Entry entry = entryIter.next(); + argsArray[i] = entry.getKey(); + argsArray[i + 1] = entry.getValue(); + } + getArgs(sb, argsArray); + } + return sb; + } + + private static StringBuilder appendArgs(StringBuilder sb, Object... args) { + if (args.length > 0) { + sb.append(',').append('"').append(ARGS).append('"').append(':'); + getArgs(sb, args); + } + return sb; + } + + private static StringBuilder getArgs(StringBuilder appendTo, Object[] data) { + if (data.length == 0) { + return appendTo; + } + Set tester = new HashSet<>(); + appendTo.append('{'); + if (data.length == 1) { + // not in contract, but let's assume here that people are still new + // at this + appendTo.append("\"msg\":\"").append(data[0]).append('"'); //$NON-NLS-1$ + } else { + if (data.length % 2 != 0) { + throw new IllegalArgumentException( + ARGS_ERROR_MESSAGE + "an odd number of messages" + Arrays.asList(data).toString()); //$NON-NLS-1$ + } + for (int i = 0; i < data.length - 1; i += 2) { + Object value = data[i + 1]; + String keyVal = String.valueOf(data[i]); + if (tester.contains(keyVal)) { + throw new IllegalArgumentException(ARGS_ERROR_MESSAGE + "an duplicate field names : " + keyVal); //$NON-NLS-1$ + } + tester.add(keyVal); + if (i > 0) { + appendTo.append(','); + } + writeObject(appendTo, keyVal, value); + } + } + + return appendTo.append('}'); + } + + private static StringBuilder writeObject(StringBuilder appendTo, Object key, Object value) { + appendTo.append('"').append(key).append('"').append(':'); + if (value instanceof Number) { + appendTo.append(value); + } else { + appendTo.append('"').append(String.valueOf(value)).append('"'); + } + return appendTo; + } +} diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java new file mode 100644 index 0000000..7076830 --- /dev/null +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java @@ -0,0 +1,354 @@ +package org.eclipse.tracecompass.trace_event_logger; + +import static org.junit.Assert.fail; + +import java.io.File; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.ArrayList; +import java.util.List; +import java.util.logging.FileHandler; +import java.util.logging.Formatter; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; +import java.util.stream.Stream; + +import org.junit.After; +import org.junit.Test; + +public class TestLoggerBenchmark { + + private Logger fLogger; + private Handler fileHandler; + private File[] files = new File[2]; + + @Test + public void testBench() throws SecurityException, IOException { + long warmUp = 10000; + long maxRuns = 100000; + fLogger = Logger.getAnonymousLogger(); + files[0] = new File("/tmp/trace-old.json"); + files[1] = new File("/tmp/trace-new.json"); + fileHandler = new FileHandler(files[0].getAbsolutePath()); + fileHandler.setFormatter(new Formatter() { + @Override + public String format(LogRecord record) { + return record.getMessage() + ",\n"; + } + }); + fileHandler.setLevel(Level.ALL); + fLogger.addHandler(fileHandler); + fLogger.setLevel(Level.ALL); + Logger logger = fLogger; + List asyncNew = new ArrayList<>(); + List asyncOld = new ArrayList<>(); + List syncNew = new ArrayList<>(); + List syncOld = new ArrayList<>(); + List run = new ArrayList<>(); + for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + for (long i = 0; i < warmUp; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo", "run", runs, "test", i)) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar", "run", runs, "test", + i)) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz", "run", runs, + "test", i)) { + // do something + new Object(); + } + } + } + } + long end = System.nanoTime(); + syncNew.add(end - start); + for (long i = 0; i < warmUp; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", + "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar", "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz", "run", runs, "test", i)) { + // do something + new Object(); + } + } + } + } + + long start2 = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", + "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar", "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz", "run", runs, "test", i)) { + // do something + new Object(); + } + } + } + } + long end2 = System.nanoTime(); + syncOld.add(end2 - start2); + run.add(runs); + } + fLogger.removeHandler(fileHandler); + fileHandler = new AsyncFileHandler(files[1].getAbsolutePath()); + fileHandler.setFormatter(new Formatter() { + @Override + public String format(LogRecord record) { + return record.getMessage() + ",\n"; + } + }); + fileHandler.setLevel(Level.ALL); + fLogger.addHandler(fileHandler); + for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + for (long i = 0; i < warmUp; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo", "run", runs, "test", i)) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar", "run", runs, "test", + i)) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz", "run", runs, + "test", i)) { + // do something + new Object(); + } + } + } + } + long end = System.nanoTime(); + asyncNew.add(end - start); + for (long i = 0; i < warmUp; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start2 = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", + "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar", "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz", "run", runs, "test", i)) { + // do something + new Object(); + } + } + } + } + long end2 = System.nanoTime(); + asyncOld.add(end2 - start2); + } + System.out.println("Runs,SyncOld,SyncNew,AsyncOld,AsyncNew"); + for (int i = 0; i < run.size(); i++) { + System.out.println(String.format("%d,%d,%d,%d,%d", run.get(i), syncOld.get(i), syncNew.get(i), + asyncOld.get(i), asyncNew.get(i))); + } + } + + private static long linecount(Path path) throws IOException { + long linecount = 0; + try (Stream stream = Files.lines(path, StandardCharsets.UTF_8)) { + linecount = stream.count(); + } + return linecount; + } + + @After + public void waiting() { + try { + while (linecount(files[0].toPath()) != linecount(files[1].toPath())) { + Thread.currentThread().sleep(100); + } + } catch (IOException | InterruptedException e) { + fail(e.toString()); + } + } + + @Test + public void testLeanBench() throws SecurityException, IOException { + long warmUp = 10000; + long maxRuns = 100000; + fLogger = Logger.getAnonymousLogger(); + files[0] = new File("/tmp/trace-lean-old.json"); + files[1] = new File("/tmp/trace-lean-new.json"); + fileHandler = new FileHandler(files[0].getAbsolutePath()); + fileHandler.setFormatter(new Formatter() { + @Override + public String format(LogRecord record) { + return record.getMessage() + ",\n"; + } + }); + fileHandler.setLevel(Level.ALL); + fLogger.addHandler(fileHandler); + fLogger.setLevel(Level.ALL); + Logger logger = fLogger; + List asyncNew = new ArrayList<>(); + List asyncOld = new ArrayList<>(); + List syncNew = new ArrayList<>(); + List syncOld = new ArrayList<>(); + List run = new ArrayList<>(); + for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + for (long i = 0; i < warmUp; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + long end = System.nanoTime(); + syncNew.add(end - start); + for (long i = 0; i < warmUp; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start2 = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + long end2 = System.nanoTime(); + syncOld.add(end2 - start2); + run.add(runs); + } + fLogger.removeHandler(fileHandler); + fileHandler = new AsyncFileHandler(files[1].getAbsolutePath()); + fileHandler.setFormatter(new Formatter() { + @Override + public String format(LogRecord record) { + return record.getMessage() + ",\n"; + } + }); + fileHandler.setLevel(Level.ALL); + fLogger.addHandler(fileHandler); + for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + for (long i = 0; i < warmUp; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (LogUtils.ScopeLog log2 = new LogUtils.ScopeLog(logger, Level.FINEST, "baz", "run", runs, + "test", i)) { + // do something + new Object(); + } + } + } + } + long end = System.nanoTime(); + asyncNew.add(end - start); + for (long i = 0; i < warmUp; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + + long start2 = System.nanoTime(); + for (long i = 0; i < runs; i++) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", + "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, + "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, + Level.FINEST, "baz")) { + // do something + new Object(); + } + } + } + } + long end2 = System.nanoTime(); + asyncOld.add(end2 - start2); + } + System.out.println("Runs,SyncOldLean,SyncNewLean,AsyncOldLean,AsyncNewLean"); + for (int i = 0; i < run.size(); i++) { + System.out.println(String.format("%d,%d,%d,%d,%d", run.get(i), syncOld.get(i), syncNew.get(i), + asyncOld.get(i), asyncNew.get(i))); + } + } +} \ No newline at end of file From ebb1b58b642526a229b05f6d4e173196ddfca354 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 13:02:02 -0500 Subject: [PATCH 02/10] make asynclogger more null resiliant Signed-off-by: Matthew Khouzam --- .../trace_event_logger/AsyncFileHandler.java | 20 ++++++++++++++----- 1 file changed, 15 insertions(+), 5 deletions(-) diff --git a/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java b/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java index 59e4832..fd6e596 100644 --- a/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java +++ b/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java @@ -150,13 +150,23 @@ public AsyncFileHandler() throws SecurityException, IOException { this(""); // let's hope it's configured in logging properties. } + /** + * Asynchronous file handler, wraps a {@link FileHandler} behind a thread + * @param pattern the file pattern + * @throws SecurityException + * @throws IOException + */ public AsyncFileHandler(String pattern) throws SecurityException, IOException { configure(); fileHandler = new FileHandler(pattern); - fileHandler.setEncoding(encoding); - fileHandler.setErrorManager(errorManager); - fileHandler.setFilter(filter); - fileHandler.setLevel(level); + if (encoding != null) + fileHandler.setEncoding(encoding); + if (errorManager != null) + fileHandler.setErrorManager(errorManager); + if (filter != null) + fileHandler.setFilter(filter); + if (level != null) + fileHandler.setLevel(level); queue = new ArrayBlockingQueue<>(queueDepth); timer.scheduleAtFixedRate(task, flushRate, flushRate); @@ -277,7 +287,7 @@ public ErrorManager getErrorManager() { public synchronized void publish(LogRecord record) { try { recordBuffer.add(record); - if (recordBuffer.size() >= maxSize) { + if (recordBuffer.size() >= maxSize && isLoggable(record)) { queue.put(recordBuffer); recordBuffer = new ArrayList<>(maxSize); } From 055be6f0be2c519f7fc2592c3754cdd8e7993060 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 16:23:03 -0500 Subject: [PATCH 03/10] fix snapshot handler and test it Works with events using parameters rather than dedicated getters. Signed-off-by: Matthew Khouzam --- .../trace_event_logger/SnapshotHandler.java | 263 +++++++++++------- .../trace_event_logger/SnapshotTest.java | 103 +++++++ .../TestLoggerBenchmark.java | 131 +++++---- 3 files changed, 322 insertions(+), 175 deletions(-) create mode 100644 src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java diff --git a/src/main/java/org/eclipse/tracecompass/trace_event_logger/SnapshotHandler.java b/src/main/java/org/eclipse/tracecompass/trace_event_logger/SnapshotHandler.java index 6f15a86..a328354 100644 --- a/src/main/java/org/eclipse/tracecompass/trace_event_logger/SnapshotHandler.java +++ b/src/main/java/org/eclipse/tracecompass/trace_event_logger/SnapshotHandler.java @@ -37,6 +37,7 @@ import java.util.Map; import java.util.logging.FileHandler; import java.util.logging.Level; +import java.util.logging.LogManager; import java.util.logging.LogRecord; import org.eclipse.tracecompass.trace_event_logger.LogUtils.TraceEventLogRecord; @@ -55,122 +56,168 @@ */ public class SnapshotHandler extends FileHandler { - // the following can be configured by Logging.properties - private final int maxEvents = 1000000; - private final double timeout = 30.0; - protected final String filePath = "request-"; //$NON-NLS-1$ - // Enable scope logs by default - private volatile boolean isEnabled = true; + // the following can be configured by Logging.properties + private int maxEvents = 1000000; + private double timeout = 30.0; + protected String filePath = "request-"; //$NON-NLS-1$ + // Enable scope logs by default + private volatile boolean isEnabled = true; - private Deque fData = new ArrayDeque<>(); - private Map>> fStacks = new HashMap<>(); + private Deque fData = new ArrayDeque<>(); + private Map>> fStacks = new HashMap<>(); - /** - * Snapshot handler constructor - * - * @throws IOException - * If there is a file error - * @throws SecurityException - * if we don't have the permissions - */ - public SnapshotHandler() throws IOException, SecurityException { - super(); - } + /** + * Snapshot handler constructor + * + * @throws IOException If there is a file error + * @throws SecurityException if we don't have the permissions + */ + public SnapshotHandler() throws IOException, SecurityException { + super(); + configure(); + } - @Override - public boolean isLoggable(LogRecord record) { - return (isEnabled && record != null - && super.isLoggable(record) - && (record.getLevel().intValue() <= Level.FINE.intValue()) - && (record instanceof TraceEventLogRecord)); // add feature switch here - } + /** + * Snapshot handler constructor + * + * @param timeout the timeout in seconds + * + * @throws IOException If there is a file error + * @throws SecurityException if we don't have the permissions + */ + public SnapshotHandler(double timeout) throws IOException, SecurityException { + super(); + configure(); + if (timeout > 0.0) { + this.timeout = timeout; + } + } + private void configure() { + LogManager manager = LogManager.getLogManager(); + String cname = getClass().getName(); + String prop = manager.getProperty(cname + ".maxEvents"); + maxEvents = 1000000; + try { + maxEvents = Integer.parseInt(prop.trim()); + } catch (Exception ex) { + // we tried! + } + if (maxEvents < 0) { + maxEvents = 1000000; + } + timeout = 10000; + prop = manager.getProperty(cname + ".timeout"); + try { + timeout = Double.parseDouble(prop.trim()); + } catch (Exception ex) { + // we tried! + } + if (timeout < 0) { + timeout = 30.0; + } + filePath = "request-"; + prop = manager.getProperty(cname + ".filePath"); + try { + filePath = prop.trim(); + } catch (Exception ex) { + // we tried! + } + } - private boolean addToSnapshot(LogRecord message) { - InnerEvent event = InnerEvent.create(message); - if (event == null) { - return false; - } - fData.add(event); - while (fData.size() > maxEvents) { - fData.remove(); - } - Map> pidMap = - fStacks.computeIfAbsent(event.getPid(), unused -> new HashMap<>()); - List stack = pidMap.computeIfAbsent(event.getTid(), unused -> new ArrayList<>()); - String phase = event.getPhase(); - switch (phase) { - case "B": //$NON-NLS-1$ - { - stack.add(event); - break; - } - case "E": //$NON-NLS-1$ - { - InnerEvent lastEvent = stack.remove(stack.size() - 1); - if (stack.isEmpty()) { - double delta = event.getTs() - lastEvent.getTs(); - if (delta > timeout) { - drain(fData); - } - } - break; - } - default: - // do nothing - } - return true; - } + @Override + public boolean isLoggable(LogRecord record) { + return (isEnabled && record != null && super.isLoggable(record) + && (record.getLevel().intValue() <= Level.FINE.intValue()) && (record instanceof TraceEventLogRecord)); // add + // feature + // switch + // here + } - @Override - public synchronized void publish(LogRecord record) { - if(record != null) { - addToSnapshot(record); - } - super.publish(record); - } + private boolean addToSnapshot(LogRecord message) { + InnerEvent event = InnerEvent.create(message); + if (event == null) { + return false; + } + fData.add(event); + while (fData.size() > maxEvents) { + fData.remove(); + } + Map> pidMap = fStacks.computeIfAbsent(event.getPid(), unused -> new HashMap<>()); + List stack = pidMap.computeIfAbsent(event.getTid(), unused -> new ArrayList<>()); + String phase = event.getPhase(); + switch (phase) { + case "B": //$NON-NLS-1$ + { + stack.add(event); + break; + } + case "E": //$NON-NLS-1$ + { + InnerEvent lastEvent = stack.remove(stack.size() - 1); + if (stack.isEmpty()) { + double delta = (event.getTs() - lastEvent.getTs()) * 0.000001; // convert to seconds + if (delta > timeout) { + drain(fData); + } + } + break; + } + default: + // do nothing + } + return true; + } - private void drain(Deque data) { - Thread thread = - new Thread( - () -> { - Path path = new File(filePath + data.getFirst().getTs() + ".json").toPath(); //$NON-NLS-1$ - try (BufferedWriter fw = Files.newBufferedWriter(path, Charset.defaultCharset())) { - fw.write('['); - boolean first = true; - for (InnerEvent event : data) { - if (first) { - first = false; - } else { - fw.write(','); - fw.write('\n'); - } - fw.write(event.getMessage()); - } - data.clear(); - fw.write(']'); - } catch (IOException e) { - // we tried! - } - }); - thread.setName("Trace Drainer"); //$NON-NLS-1$ - thread.start(); - } + @Override + public synchronized void publish(LogRecord record) { + if (record != null) { + addToSnapshot(record); + } + super.publish(record); + } - /** - * Enable or disable snapshotter - * @param isEnabled true is enabled, false is disabled - */ - public void setEnabled(Boolean isEnabled) { - this.isEnabled = isEnabled; - } + private void drain(Deque data) { + Thread thread = new Thread(() -> { + Path path = new File(filePath + Long.toString((long) data.getFirst().getTs()) + ".json").toPath(); //$NON-NLS-1$ + try (BufferedWriter fw = Files.newBufferedWriter(path, Charset.defaultCharset())) { + fw.write('['); + boolean first = true; + for (InnerEvent event : data) { + if (first) { + first = false; + } else { + fw.write(','); + fw.write('\n'); + } + fw.write(event.getMessage()); + } + data.clear(); + fw.write(']'); + } catch (IOException e) { + // we tried! + } + }); + thread.setName("Trace Drainer"); //$NON-NLS-1$ + thread.start(); + } - /** - * Is the snapshotter enabled? - * @return true if enabled - */ - public boolean isEnabled() { - return isEnabled; - } + /** + * Enable or disable snapshotter + * + * @param isEnabled true is enabled, false is disabled + */ + public void setEnabled(Boolean isEnabled) { + this.isEnabled = isEnabled; + } + + /** + * Is the snapshotter enabled? + * + * @return true if enabled + */ + public boolean isEnabled() { + return isEnabled; + } } diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java new file mode 100644 index 0000000..12f4031 --- /dev/null +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java @@ -0,0 +1,103 @@ +/******************************************************************************* + * Copyright (c) 2024 Ericsson + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the “Software”), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * SPDX-License-Identifier: MIT + *******************************************************************************/ +package org.eclipse.tracecompass.trace_event_logger; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; + +import java.io.File; +import java.io.FileReader; +import java.io.IOException; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.Logger; +import java.util.logging.StreamHandler; + +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +/** + * Test cases for snapshotter + * + * @author Matthew Khouzam + */ +public class SnapshotTest { + + private Logger logger; + private StreamHandler streamHandler; + + public SnapshotTest() { + // Do nothing + } + + @Before + public void before() throws SecurityException, IOException { + logger = Logger.getAnonymousLogger(); + streamHandler = new SnapshotHandler(0.5); + for (Handler handler : logger.getHandlers()) { + logger.removeHandler(handler); + } + logger.addHandler(streamHandler); + logger.setLevel(Level.ALL); + streamHandler.setLevel(Level.ALL); + } + + @Test + public void fastTest() { + Logger logger = this.logger; + assertNotNull(logger); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'a', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'B', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'E', "Bla")); + streamHandler.flush(); + } + + @Test + public void slowTest() throws InterruptedException, IOException { + Logger logger = this.logger; + assertNotNull(logger); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"a\"", 10000000000L, 'a', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"b\"", 20000000000L, 'B', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"c\"", 30000000000L, 'c', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"d\"", 40000000000L, 'd', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"e\"", 50000000000L, 'e', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"f\"", 60000000000L, 'f', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"g\"", 70000000000L, 'E', "Bla")); + Thread.currentThread().sleep(1000); + streamHandler.flush(); + File input = new File("request-10000000.json"); + try (FileReader fr = new FileReader(input)) { + char[] data = new char[(int) input.length()]; + fr.read(data); + assertEquals("[\"a\",\n" + "\"b\",\n" + "\"c\",\n" + "\"d\",\n" + "\"e\",\n" + "\"f\",\n" + "\"g\"]", String.valueOf(data)); + } + } + + @After + public void after() { + logger.removeHandler(streamHandler); + } + +} \ No newline at end of file diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java index 7076830..f42b5da 100644 --- a/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java @@ -23,25 +23,26 @@ public class TestLoggerBenchmark { private Logger fLogger; - private Handler fileHandler; + private Handler oldFileHandler; + private Handler newFileHandler; private File[] files = new File[2]; @Test public void testBench() throws SecurityException, IOException { - long warmUp = 10000; - long maxRuns = 100000; + long warmUp = 2000; + long maxRuns = warmUp * 10; fLogger = Logger.getAnonymousLogger(); files[0] = new File("/tmp/trace-old.json"); files[1] = new File("/tmp/trace-new.json"); - fileHandler = new FileHandler(files[0].getAbsolutePath()); - fileHandler.setFormatter(new Formatter() { + oldFileHandler = new FileHandler(files[0].getAbsolutePath()); + oldFileHandler.setFormatter(new Formatter() { @Override public String format(LogRecord record) { return record.getMessage() + ",\n"; } }); - fileHandler.setLevel(Level.ALL); - fLogger.addHandler(fileHandler); + oldFileHandler.setLevel(Level.ALL); + fLogger.addHandler(oldFileHandler); fLogger.setLevel(Level.ALL); Logger logger = fLogger; List asyncNew = new ArrayList<>(); @@ -49,7 +50,7 @@ public String format(LogRecord record) { List syncNew = new ArrayList<>(); List syncOld = new ArrayList<>(); List run = new ArrayList<>(); - for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + for (long runs = 2000; runs < maxRuns; runs *= 1.4) { for (long i = 0; i < warmUp; i++) { try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { @@ -77,12 +78,12 @@ public String format(LogRecord record) { long end = System.nanoTime(); syncNew.add(end - start); for (long i = 0; i < warmUp; i++) { - try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", - "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar", "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz", "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", "run", runs, "test", + i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar", "run", runs, + "test", i)) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz", "run", + runs, "test", i)) { // do something new Object(); } @@ -92,12 +93,12 @@ public String format(LogRecord record) { long start2 = System.nanoTime(); for (long i = 0; i < runs; i++) { - try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", - "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar", "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz", "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", "run", runs, "test", + i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar", "run", runs, + "test", i)) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz", "run", + runs, "test", i)) { // do something new Object(); } @@ -108,17 +109,17 @@ public String format(LogRecord record) { syncOld.add(end2 - start2); run.add(runs); } - fLogger.removeHandler(fileHandler); - fileHandler = new AsyncFileHandler(files[1].getAbsolutePath()); - fileHandler.setFormatter(new Formatter() { + fLogger.removeHandler(oldFileHandler); + newFileHandler = new AsyncFileHandler(files[1].getAbsolutePath()); + newFileHandler.setFormatter(new Formatter() { @Override public String format(LogRecord record) { return record.getMessage() + ",\n"; } }); - fileHandler.setLevel(Level.ALL); - fLogger.addHandler(fileHandler); - for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + newFileHandler.setLevel(Level.ALL); + fLogger.addHandler(newFileHandler); + for (long runs = 2000; runs < maxRuns; runs *= 1.4) { for (long i = 0; i < warmUp; i++) { try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { @@ -147,10 +148,8 @@ public String format(LogRecord record) { asyncNew.add(end - start); for (long i = 0; i < warmUp; i++) { try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar")) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz")) { // do something new Object(); } @@ -160,12 +159,12 @@ public String format(LogRecord record) { long start2 = System.nanoTime(); for (long i = 0; i < runs; i++) { - try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", - "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar", "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz", "run", runs, "test", i)) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", "run", runs, "test", + i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar", "run", runs, + "test", i)) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz", "run", + runs, "test", i)) { // do something new Object(); } @@ -194,6 +193,12 @@ private static long linecount(Path path) throws IOException { public void waiting() { try { while (linecount(files[0].toPath()) != linecount(files[1].toPath())) { + if(oldFileHandler != null) { + oldFileHandler.close(); + } + if(newFileHandler != null) { + newFileHandler.close(); + } Thread.currentThread().sleep(100); } } catch (IOException | InterruptedException e) { @@ -203,20 +208,20 @@ public void waiting() { @Test public void testLeanBench() throws SecurityException, IOException { - long warmUp = 10000; - long maxRuns = 100000; + long warmUp = 2000; + long maxRuns = warmUp * 10; fLogger = Logger.getAnonymousLogger(); files[0] = new File("/tmp/trace-lean-old.json"); files[1] = new File("/tmp/trace-lean-new.json"); - fileHandler = new FileHandler(files[0].getAbsolutePath()); - fileHandler.setFormatter(new Formatter() { + oldFileHandler = new FileHandler(files[0].getAbsolutePath()); + oldFileHandler.setFormatter(new Formatter() { @Override public String format(LogRecord record) { return record.getMessage() + ",\n"; } }); - fileHandler.setLevel(Level.ALL); - fLogger.addHandler(fileHandler); + oldFileHandler.setLevel(Level.ALL); + fLogger.addHandler(oldFileHandler); fLogger.setLevel(Level.ALL); Logger logger = fLogger; List asyncNew = new ArrayList<>(); @@ -224,7 +229,7 @@ public String format(LogRecord record) { List syncNew = new ArrayList<>(); List syncOld = new ArrayList<>(); List run = new ArrayList<>(); - for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + for (long runs = 2000; runs < maxRuns; runs *= 1.4) { for (long i = 0; i < warmUp; i++) { try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { @@ -251,10 +256,8 @@ public String format(LogRecord record) { syncNew.add(end - start); for (long i = 0; i < warmUp; i++) { try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar")) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz")) { // do something new Object(); } @@ -265,10 +268,8 @@ public String format(LogRecord record) { long start2 = System.nanoTime(); for (long i = 0; i < runs; i++) { try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar")) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz")) { // do something new Object(); } @@ -279,17 +280,17 @@ public String format(LogRecord record) { syncOld.add(end2 - start2); run.add(runs); } - fLogger.removeHandler(fileHandler); - fileHandler = new AsyncFileHandler(files[1].getAbsolutePath()); - fileHandler.setFormatter(new Formatter() { + fLogger.removeHandler(oldFileHandler); + newFileHandler = new AsyncFileHandler(files[1].getAbsolutePath()); + newFileHandler.setFormatter(new Formatter() { @Override public String format(LogRecord record) { return record.getMessage() + ",\n"; } }); - fileHandler.setLevel(Level.ALL); - fLogger.addHandler(fileHandler); - for (long runs = 2000; runs < maxRuns; runs *= 1.2) { + newFileHandler.setLevel(Level.ALL); + fLogger.addHandler(newFileHandler); + for (long runs = 2000; runs < maxRuns; runs *= 1.4) { for (long i = 0; i < warmUp; i++) { try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { try (LogUtils.ScopeLog log1 = new LogUtils.ScopeLog(logger, Level.FINER, "bar")) { @@ -317,10 +318,8 @@ public String format(LogRecord record) { asyncNew.add(end - start); for (long i = 0; i < warmUp; i++) { try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo")) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar")) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz")) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz")) { // do something new Object(); } @@ -330,12 +329,10 @@ public String format(LogRecord record) { long start2 = System.nanoTime(); for (long i = 0; i < runs; i++) { - try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", - "run", runs, "test", i)) { - try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, - "bar")) { - try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, - Level.FINEST, "baz")) { + try (OldLogUtils.ScopeLog log = new OldLogUtils.ScopeLog(logger, Level.FINE, "foo", "run", runs, "test", + i)) { + try (OldLogUtils.ScopeLog log1 = new OldLogUtils.ScopeLog(logger, Level.FINER, "bar")) { + try (OldLogUtils.ScopeLog log2 = new OldLogUtils.ScopeLog(logger, Level.FINEST, "baz")) { // do something new Object(); } From 004f74b85876c3469ce5685a75f0c77524a21b98 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 16:24:00 -0500 Subject: [PATCH 04/10] reflow InnerEvent.java Signed-off-by: Matthew Khouzam --- .../trace_event_logger/InnerEvent.java | 79 ++++++++++--------- 1 file changed, 41 insertions(+), 38 deletions(-) diff --git a/src/main/java/org/eclipse/tracecompass/trace_event_logger/InnerEvent.java b/src/main/java/org/eclipse/tracecompass/trace_event_logger/InnerEvent.java index ae79027..a2c55c7 100644 --- a/src/main/java/org/eclipse/tracecompass/trace_event_logger/InnerEvent.java +++ b/src/main/java/org/eclipse/tracecompass/trace_event_logger/InnerEvent.java @@ -29,49 +29,52 @@ class InnerEvent { - public static InnerEvent create(LogRecord lRecord) { - if (lRecord instanceof LogUtils.TraceEventLogRecord) { - TraceEventLogRecord rec = (TraceEventLogRecord) lRecord; - double ts = (double) rec.getParameters()[0]; - String phase = (String) rec.getParameters()[1]; - String pid = (String) rec.getParameters()[2]; - String tid = (String) rec.getParameters()[2]; - return new InnerEvent(rec, ts, phase, pid, tid); - } - return null; - } + public static InnerEvent create(LogRecord lRecord) { + if (lRecord instanceof LogUtils.TraceEventLogRecord) { + TraceEventLogRecord rec = (TraceEventLogRecord) lRecord; + Object[] parameters = rec.getParameters(); + if (parameters != null && parameters.length >= 3) { + double ts = ((Long) parameters[0]).longValue()*0.001; + String phase = String.valueOf(parameters[1]); + String pid = String.valueOf(parameters[2]); + String tid = String.valueOf(parameters[2]); + return new InnerEvent(rec, ts, phase, pid, tid); + } + } + return null; + } - private final LogRecord message; - private final double ts; - private final String tid; - private final String pid; - private final String phase; + private final LogRecord message; + private final double ts; + private final String tid; + private final String pid; + private final String phase; - public InnerEvent(LogRecord message, double ts, String phase, String pid, String tid) { - this.message = message; - this.ts = ts; - this.phase = phase; - this.tid = tid; - this.pid = pid; - } + public InnerEvent(LogRecord message, double ts, String phase, String pid, String tid) { + this.message = message; + this.ts = ts; + this.phase = phase; + this.tid = tid; + this.pid = pid; + } - public String getMessage() { - return message.getMessage(); - } + public String getMessage() { + return message.getMessage(); + } - public double getTs() { - return ts; - } + public double getTs() { + return ts; + } - public String getTid() { - return tid; - } + public String getTid() { + return tid; + } - public String getPid() { - return pid; - } + public String getPid() { + return pid; + } - public String getPhase() { - return phase; - } + public String getPhase() { + return phase; + } } From 6631a47c6d71358f98fdcb1b0da389a36c9b18c6 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 16:29:08 -0500 Subject: [PATCH 05/10] Make benchmark windows compatible Signed-off-by: Matthew Khouzam --- .../trace_event_logger/TestLoggerBenchmark.java | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java index f42b5da..ccd22ca 100644 --- a/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/TestLoggerBenchmark.java @@ -32,8 +32,8 @@ public void testBench() throws SecurityException, IOException { long warmUp = 2000; long maxRuns = warmUp * 10; fLogger = Logger.getAnonymousLogger(); - files[0] = new File("/tmp/trace-old.json"); - files[1] = new File("/tmp/trace-new.json"); + files[0] = File.createTempFile("trace-old" ,".json"); + files[1] = File.createTempFile("trace-new" ,".json"); oldFileHandler = new FileHandler(files[0].getAbsolutePath()); oldFileHandler.setFormatter(new Formatter() { @Override @@ -211,8 +211,8 @@ public void testLeanBench() throws SecurityException, IOException { long warmUp = 2000; long maxRuns = warmUp * 10; fLogger = Logger.getAnonymousLogger(); - files[0] = new File("/tmp/trace-lean-old.json"); - files[1] = new File("/tmp/trace-lean-new.json"); + files[0] = File.createTempFile("trace-lean-old" ,".json"); + files[1] = File.createTempFile("trace-lean-new" ,".json"); oldFileHandler = new FileHandler(files[0].getAbsolutePath()); oldFileHandler.setFormatter(new Formatter() { @Override From ce5879caa3f55354bfcdfdaad15726cf6a01415c Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 16:30:44 -0500 Subject: [PATCH 06/10] update pom.xml Signed-off-by: Matthew Khouzam --- pom.xml | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/pom.xml b/pom.xml index 5c1d1a5..4486047 100644 --- a/pom.xml +++ b/pom.xml @@ -30,6 +30,28 @@ + + org.apache.maven.plugins + maven-shade-plugin + 3.2.0 + + + package + + shade + + + benchmarks + + + org.openjdk.jmh.Main + + + + + + maven-clean-plugin From a6f0fe7b08da0d3f37dec74f2a4ba9e538df1d84 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 16:46:52 -0500 Subject: [PATCH 07/10] improve code coverage from 99.2% to 99.8% for tracer Signed-off-by: Matthew Khouzam --- .../trace_event_logger/LoggerTest.java | 36 +++++++++++++++++++ .../trace_event_logger/SnapshotTest.java | 11 ++++++ 2 files changed, 47 insertions(+) diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/LoggerTest.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/LoggerTest.java index 25547a7..1d11a37 100644 --- a/src/test/java/org/eclipse/tracecompass/trace_event_logger/LoggerTest.java +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/LoggerTest.java @@ -378,7 +378,43 @@ public void testFlowBuilderParentThenCat() { } } } + + /** + * Test the flow scope builder calling + * {@link FlowScopeLogBuilder#setParentScope(FlowScopeLog)}, then + * {@link FlowScopeLogBuilder#setCategory(String)}. + */ + @Test(expected = IllegalStateException.class) + public void testFlowBuilderParentThenCatId() { + Logger logger = fLogger; + assertNotNull(logger); + try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").setCategory("myspider").build()) { + try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINE, "bar").setParentScope(log).setCategoryAndId("myspider",1).build()) { + // do something + new Object(); + } + } + } + + /** + * Test the flow scope builder calling + * {@link FlowScopeLogBuilder#setParentScope(FlowScopeLog)}, then + * {@link FlowScopeLogBuilder#setCategory(String)}. + */ + @Test(expected = IllegalStateException.class) + public void testFlowBuilderCatIdThenParent() { + Logger logger = fLogger; + assertNotNull(logger); + try (FlowScopeLog log = new FlowScopeLogBuilder(logger, Level.WARNING, "foo").setCategory("myspider").build()) { + try (FlowScopeLog log1 = new FlowScopeLogBuilder(logger, Level.FINE, "bar").setCategoryAndId("myspider",1).setParentScope(log).build()) { + // do something + new Object(); + } + } + } + + /** * Test nesting with different arguments */ diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java index 12f4031..396e66b 100644 --- a/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java @@ -73,6 +73,17 @@ public void fastTest() { logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'E', "Bla")); streamHandler.flush(); } + + + @Test + public void badTest() { + Logger logger = this.logger; + assertNotNull(logger); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'a')); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'B')); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'E')); + streamHandler.flush(); + } @Test public void slowTest() throws InterruptedException, IOException { From 05a689e7d4044ee4c9bb1d0dcee134c084bb325e Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 17:01:49 -0500 Subject: [PATCH 08/10] remove dependency graph... Until we have dependencies Signed-off-by: Matthew Khouzam --- .github/workflows/maven.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/maven.yml b/.github/workflows/maven.yml index 001e7b5..09c5613 100644 --- a/.github/workflows/maven.yml +++ b/.github/workflows/maven.yml @@ -31,5 +31,5 @@ jobs: run: mvn -B package --file pom.xml # Optional: Uploads the full dependency graph to GitHub to improve the quality of Dependabot alerts this repository can receive - - name: Update dependency graph - uses: advanced-security/maven-dependency-submission-action@571e99aab1055c2e71a1e2309b9691de18d6b7d6 +# - name: Update dependency graph +# uses: advanced-security/maven-dependency-submission-action@571e99aab1055c2e71a1e2309b9691de18d6b7d6 From c030689d23ebf483a5ff6631b88880de3b6eb255 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 20:32:46 -0500 Subject: [PATCH 09/10] Add more tests Bring unit test coverage to 97.9%. The majority of the rest of the code are failsafes for races. Signed-off-by: Matthew Khouzam --- .../trace_event_logger/AsyncFileHandler.java | 3 +- .../AsyncFileHandlerTest.java | 132 ++++++++++++++++++ .../trace_event_logger/SnapshotTest.java | 115 ++++++++++++++- .../res/badlogging.properties | 8 ++ .../trace_event_logger/res/logging.properties | 1 + 5 files changed, 254 insertions(+), 5 deletions(-) create mode 100644 src/test/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandlerTest.java create mode 100644 src/test/java/org/eclipse/tracecompass/trace_event_logger/res/badlogging.properties create mode 100644 src/test/java/org/eclipse/tracecompass/trace_event_logger/res/logging.properties diff --git a/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java b/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java index fd6e596..b1be244 100644 --- a/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java +++ b/src/main/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandler.java @@ -152,8 +152,9 @@ public AsyncFileHandler() throws SecurityException, IOException { /** * Asynchronous file handler, wraps a {@link FileHandler} behind a thread + * * @param pattern the file pattern - * @throws SecurityException + * @throws SecurityException * @throws IOException */ public AsyncFileHandler(String pattern) throws SecurityException, IOException { diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandlerTest.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandlerTest.java new file mode 100644 index 0000000..1826a81 --- /dev/null +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/AsyncFileHandlerTest.java @@ -0,0 +1,132 @@ +/******************************************************************************* + * Copyright (c) 2024 Ericsson + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the “Software”), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * SPDX-License-Identifier: MIT + *******************************************************************************/ +package org.eclipse.tracecompass.trace_event_logger; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.fail; + +import java.io.File; +import java.io.FileInputStream; +import java.io.FileNotFoundException; +import java.io.IOException; +import java.io.InputStream; +import java.util.logging.ErrorManager; +import java.util.logging.Filter; +import java.util.logging.Formatter; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.LogRecord; +import java.util.logging.Logger; + +import org.junit.Before; +import org.junit.Test; + +public class AsyncFileHandlerTest { + + private Logger logger; + + @Before + public void before() { + this.logger = Logger.getAnonymousLogger(); + } + + /** + * Test with simple configuration + */ + @Test + public void testConfigure() { + Logger logger = this.logger; + try (InputStream fis = new FileInputStream( + new File("./src/test/java/org/eclipse/tracecompass/trace_event_logger/res/logging.properties"))) { + LogManager manager = LogManager.getLogManager(); + manager.readConfiguration(fis); + Handler first = new AsyncFileHandler(File.createTempFile("test", ".json").getAbsolutePath()); + first.close(); + } catch (FileNotFoundException e) { + fail(e.getMessage()); + } catch (IOException e) { + fail(e.getMessage()); + } + } + + /** + * Test Bad configuration + */ + @Test(expected = IllegalArgumentException.class) + public void testBadConfigure() { + Logger logger = this.logger; + try (InputStream fis = new FileInputStream( + new File("./src/test/java/org/eclipse/tracecompass/trace_event_logger/res/badlogging.properties"))) { + LogManager manager = LogManager.getLogManager(); + manager.readConfiguration(fis); + String prop = manager.getProperty("org.eclipse.tracecompass.trace_event_logger.SnapshotHandler.maxEvents"); + assertNotNull(prop); + Handler other = new AsyncFileHandler(); + fail("should have failed above"); + } catch (FileNotFoundException e) { + fail(e.getMessage()); + } catch (IOException e) { + fail(e.getMessage()); + } + } + + /** + * Test the getters and setters. They pass everything to the filehandler. + * + * @throws SecurityException + * @throws IOException + */ + @Test + public void testGetterSetters() throws SecurityException, IOException { + File test = File.createTempFile("test", ".json"); + AsyncFileHandler toTest = new AsyncFileHandler(test.getAbsolutePath()); + toTest.setEncoding("UTF-8"); + assertEquals("UTF-8", toTest.getEncoding()); + Filter f = new Filter() { + @Override + public boolean isLoggable(LogRecord record) { + return false; + } + }; + toTest.setFilter(f); + assertEquals(f, toTest.getFilter()); + toTest.setLevel(Level.CONFIG); + assertEquals(Level.CONFIG, toTest.getLevel()); + ErrorManager em = new ErrorManager(); + toTest.setErrorManager(em); + assertEquals(em, toTest.getErrorManager()); + Formatter fmt = new Formatter() { + @Override + public String format(LogRecord record) { + // TODO Auto-generated method stub + return null; + } + }; + toTest.setFormatter(fmt); + assertEquals(fmt, toTest.getFormatter()); + } + +} diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java b/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java index 396e66b..50f2a9b 100644 --- a/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/SnapshotTest.java @@ -24,15 +24,21 @@ package org.eclipse.tracecompass.trace_event_logger; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; import java.io.File; +import java.io.FileInputStream; +import java.io.FileNotFoundException; import java.io.FileReader; import java.io.IOException; +import java.io.InputStream; import java.util.logging.Handler; import java.util.logging.Level; +import java.util.logging.LogManager; import java.util.logging.Logger; -import java.util.logging.StreamHandler; import org.junit.After; import org.junit.Before; @@ -46,12 +52,21 @@ public class SnapshotTest { private Logger logger; - private StreamHandler streamHandler; + private SnapshotHandler streamHandler; + /** + * Default ctor + */ public SnapshotTest() { // Do nothing } + /** + * Setup function + * + * @throws SecurityException won't happen + * @throws IOException won't happen + */ @Before public void before() throws SecurityException, IOException { logger = Logger.getAnonymousLogger(); @@ -64,6 +79,9 @@ public void before() throws SecurityException, IOException { streamHandler.setLevel(Level.ALL); } + /** + * Test something too fast for the snapshot + */ @Test public void fastTest() { Logger logger = this.logger; @@ -73,8 +91,10 @@ public void fastTest() { logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "", 0L, 'E', "Bla")); streamHandler.flush(); } - + /** + * Test malformed events + */ @Test public void badTest() { Logger logger = this.logger; @@ -85,6 +105,12 @@ public void badTest() { streamHandler.flush(); } + /** + * Test an actual snapshot + * + * @throws InterruptedException won't happen + * @throws IOException won't happen + */ @Test public void slowTest() throws InterruptedException, IOException { Logger logger = this.logger; @@ -102,10 +128,91 @@ public void slowTest() throws InterruptedException, IOException { try (FileReader fr = new FileReader(input)) { char[] data = new char[(int) input.length()]; fr.read(data); - assertEquals("[\"a\",\n" + "\"b\",\n" + "\"c\",\n" + "\"d\",\n" + "\"e\",\n" + "\"f\",\n" + "\"g\"]", String.valueOf(data)); + assertEquals("[\"a\",\n" + "\"b\",\n" + "\"c\",\n" + "\"d\",\n" + "\"e\",\n" + "\"f\",\n" + "\"g\"]", + String.valueOf(data)); } } + /** + * Test disabling the snapshotter + */ + @Test + public void testEnableDisable() { + Logger logger = this.logger; + assertNotNull(logger); + assertTrue(streamHandler.isEnabled()); + streamHandler.setEnabled(false); + assertFalse(streamHandler.isEnabled()); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"a\"", 10000000001L, 'a', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"b\"", 20000000000L, 'B', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"c\"", 30000000000L, 'c', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"d\"", 40000000000L, 'd', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"e\"", 50000000000L, 'e', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"f\"", 60000000000L, 'f', "Bla")); + logger.log(new LogUtils.TraceEventLogRecord(Level.INFO, () -> "\"g\"", 70000000000L, 'E', "Bla")); + streamHandler.flush(); + File input = new File("request-10000001.json"); + assertFalse(input.exists()); + } + + /** + * Test with simple configuration + */ + @Test + public void testConfigure() { + Logger logger = this.logger; + try (InputStream fis = new FileInputStream( + new File("./src/test/java/org/eclipse/tracecompass/trace_event_logger/res/logging.properties"))) { + LogManager manager = LogManager.getLogManager(); + manager.readConfiguration(fis); + Handler first = new SnapshotHandler(); + first.close(); + } catch (FileNotFoundException e) { + fail(e.getMessage()); + } catch (IOException e) { + fail(e.getMessage()); + } + } + + /** + * Test with simple bad config, should still be "OK" + * + * @throws IOException won't happen + * @throws SecurityException won't happen + */ + @Test + public void testSimpleBadConfigure() throws SecurityException, IOException { + Logger logger = this.logger; + SnapshotHandler first = new SnapshotHandler(-1); + assertNotNull(first); + first.publish(null); + + } + + /** + * Test with bad configuration + */ + @Test + public void testBadConfigure() { + Logger logger = this.logger; + try (InputStream fis = new FileInputStream( + new File("./src/test/java/org/eclipse/tracecompass/trace_event_logger/res/badlogging.properties"))) { + LogManager manager = LogManager.getLogManager(); + manager.readConfiguration(fis); + String prop = manager.getProperty("org.eclipse.tracecompass.trace_event_logger.SnapshotHandler.maxEvents"); + assertNotNull(prop); + Handler first = new SnapshotHandler(); + first.close(); + } catch (FileNotFoundException e) { + fail(e.getMessage()); + } catch (IOException e) { + fail(e.getMessage()); + } + } + + /** + * Tear down + */ @After public void after() { logger.removeHandler(streamHandler); diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/res/badlogging.properties b/src/test/java/org/eclipse/tracecompass/trace_event_logger/res/badlogging.properties new file mode 100644 index 0000000..65d9024 --- /dev/null +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/res/badlogging.properties @@ -0,0 +1,8 @@ +handlers= org.eclipse.tracecompass.trace_event_logger.SnapshotHandler, org.eclipse.tracecompass.trace_event_logger.AsyncFileHandler + +org.eclipse.tracecompass.trace_event_logger.SnapshotHandler.maxEvents = -1 +org.eclipse.tracecompass.trace_event_logger.SnapshotHandler.timeout = -1 +org.eclipse.tracecompass.trace_event_logger.SnapshotHandler.filePath = +org.eclipse.tracecompass.trace_event_logger.AsyncFileHandler.maxSize = -1 +org.eclipse.tracecompass.trace_event_logger.AsyncFileHandler.queueDepth = -1 +org.eclipse.tracecompass.trace_event_logger.AsyncFileHandler.flushRate = -1 diff --git a/src/test/java/org/eclipse/tracecompass/trace_event_logger/res/logging.properties b/src/test/java/org/eclipse/tracecompass/trace_event_logger/res/logging.properties new file mode 100644 index 0000000..86a58c1 --- /dev/null +++ b/src/test/java/org/eclipse/tracecompass/trace_event_logger/res/logging.properties @@ -0,0 +1 @@ +handlers= org.eclipse.tracecompass.trace_event_logger.SnapshotHandler, org.eclipse.tracecompass.trace_event_logger.AsyncFileHandler \ No newline at end of file From 22f67898f66d4cf3ca8f948191f3ef17e48fdb7a Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Wed, 24 Jan 2024 20:57:18 -0500 Subject: [PATCH 10/10] Bump version to 0.0.3-Snapshot Signed-off-by: Matthew Khouzam --- pom.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pom.xml b/pom.xml index 4486047..7a79a32 100644 --- a/pom.xml +++ b/pom.xml @@ -6,7 +6,7 @@ org.eclipse.tracecompass trace-event-logger - 0.0.1-SNAPSHOT + 0.0.3-SNAPSHOT trace-event-logger