From 4de98699f218c81e5bdc74bfe01b771408950eb2 Mon Sep 17 00:00:00 2001 From: Matthew Khouzam Date: Thu, 6 Feb 2025 18:07:39 -0500 Subject: [PATCH] Add MxBeans logging to the logger Brings monitoring support to the trace event logger. Signed-off-by: Matthew Khouzam --- README.md | 13 +- .../traceeventlogger/LogUtils.java | 4 + .../beans/ITraceEventLoggerBean.java | 82 ++++++++++++ .../beans/TraceEventLoggerBean.java | 120 ++++++++++++++++++ .../beans/TraceEventLoggerManager.java | 83 ++++++++++++ 5 files changed, 297 insertions(+), 5 deletions(-) create mode 100644 src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/ITraceEventLoggerBean.java create mode 100644 src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerBean.java create mode 100644 src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerManager.java diff --git a/README.md b/README.md index af89509..ade5dda 100644 --- a/README.md +++ b/README.md @@ -143,6 +143,8 @@ While one could open the traces in their favorite text editor, results are bette python3 jsonify.py LOG_FILE log.json ``` +Another option would be to add the `-DenableMonitoring=true` flag to enable the JMX beans counters. These can be read using VisualVM or jconsole. + [Video tutorial](https://www.youtube.com/watch?v=YCdzmcpOrK4) ## Performance @@ -150,11 +152,12 @@ python3 jsonify.py LOG_FILE log.json On an Intel i5-1145G7 @ 2.60GHz with an NVME hard drive, using an `AsyncFileHandler` instead of the classic `FileHandler` leads to events being logged from 45 us/event (`FileHandler`) to 1.1 us/event (`AsyncFileHandler`). In other words, `AsyncFileHandler` can write 900k events in the time it takes FileHandler to write 22k events One could also take advantage of the cache effect. If the data is not saturating the IO, speed is even higher. -| Action | Overhead | -|------------------|---------:| -| Instrumentation | 72 ns | -| AsyncFileHandler | 1100 ns | -| FileHandler | 45000 ns | +| Action | Overhead | +|--------------------------------|---------:| +| Instrumentation | 72 ns | +| AsyncFileHandler | 1100 ns | +| FileHandler | 45000 ns | +| Beans-Enabled AsyncFileHandler | 1400 ns | ## Design Philosophy diff --git a/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java b/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java index 34d2b6a..a92d866 100644 --- a/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java +++ b/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java @@ -39,6 +39,8 @@ import java.util.logging.LogRecord; import java.util.logging.Logger; +import org.eclipse.tracecompass.traceeventlogger.beans.TraceEventLoggerManager; + /** * Logger helper * @@ -296,6 +298,7 @@ public void close() { return appendArgs(sb, fData).append('}').toString(); }; fLogger.log(new TraceEventLogRecord(fLevel, msgSupplier, time, phase, fThreadId)); + TraceEventLoggerManager.getInstance().update(fLabel, time - fTime); } } @@ -586,6 +589,7 @@ public void close() { return sb.toString(); }; fLogger.log(new LogUtils.TraceEventLogRecord(fLevel, msgSupplier, time, phase, fThreadId)); + TraceEventLoggerManager.getInstance().update(fLabel, time - fTime); } } diff --git a/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/ITraceEventLoggerBean.java b/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/ITraceEventLoggerBean.java new file mode 100644 index 0000000..fe5f253 --- /dev/null +++ b/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/ITraceEventLoggerBean.java @@ -0,0 +1,82 @@ +/******************************************************************************* + * Copyright (c) 2025 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.traceeventlogger.beans; + +import javax.management.MXBean; + +/** + * Trace Event Logger Monitor MXBean interface. Needed to publish MXBeans. + * + * An MXBean is a managed java object that uses Java Management (JMX) to publish + * information. MXBeans have a pre-defined datatype, and in this case will be + * SimpleTypes. This allows the value to be easily plotted. + * + * @author Matthew Khouzam + */ +@MXBean +public interface ITraceEventLoggerBean { + + /** + * Get the observed element name + * + * @return the observed element name + */ + String getObservedElementName(); + + /** + * Get the mean (average) time + * + * @return the average time + */ + double getMeanTime(); + + /** + * Get the total (sum) time + * + * @return the sum time + */ + long getTotalTime(); + + /** + * Get the number of times (count) the element is added + * + * @return the count of elements added + */ + long getCount(); + + /** + * Get the minimum time + * + * @return the minimum time + */ + long getMinTime(); + + /** + * Get the maximum time + * + * @return the maximum time + */ + long getMaxTime(); +} diff --git a/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerBean.java b/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerBean.java new file mode 100644 index 0000000..aed4652 --- /dev/null +++ b/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerBean.java @@ -0,0 +1,120 @@ +/******************************************************************************* + * Copyright (c) 2025 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.traceeventlogger.beans; + +import java.lang.management.ManagementFactory; +import java.util.LongSummaryStatistics; +import java.util.logging.Level; +import java.util.logging.Logger; + +import javax.management.JMException; +import javax.management.MBeanServer; +import javax.management.NotificationBroadcasterSupport; +import javax.management.ObjectName; + +/** + * Trace Event Logger internal bean. + * + * A bean is a java standard object to publish information. + * + * Used to publish performance metrics and KPIs, can be seen with tools such as + * visualvm and jconsole. + * + * This class is internal, it should not be extended or made into API. + * + * @author Matthew Khouzam + */ +public final class TraceEventLoggerBean extends NotificationBroadcasterSupport implements ITraceEventLoggerBean { + + private final LongSummaryStatistics fStats = new LongSummaryStatistics(); + private final String fLabel; + + /** + * Constructor + * + * @param label + * the name of the bean, colons (':') will be replaced with + * hyphens ('-') + */ + public TraceEventLoggerBean(String label) { + fLabel = label; + /** + * Override potentially finer logging for these, as this breaks the + * resulting JSON trace file. This happens upon @{link + * ManagementFactory} use below. Use the default @{link Level.FINE}, + * which doesn't output any such breaking strings. Finer logging for + * this package isn't necessary anyway here. + */ + Logger.getLogger("javax.management").setLevel(Level.FINE); //$NON-NLS-1$ NOSONAR + MBeanServer mbs = ManagementFactory.getPlatformMBeanServer(); + String beanName = "org.eclipse.tracecompass.log:type=TraceEventLoggerBean,name=" + label.replace(':', '-'); //$NON-NLS-1$ + try { + ObjectName name = new ObjectName(beanName); + mbs.registerMBean(this, name); + } catch (JMException e) { + java.util.logging.Logger.getAnonymousLogger().log(Level.WARNING, "Cannot create bean", e); //$NON-NLS-1$ + } + } + + @Override + public String getObservedElementName() { + return fLabel; + } + + @Override + public double getMeanTime() { + return fStats.getAverage(); + } + + @Override + public long getMinTime() { + return fStats.getMin(); + } + + @Override + public long getMaxTime() { + return fStats.getMax(); + } + + @Override + public long getTotalTime() { + return fStats.getSum(); + } + + @Override + public long getCount() { + return fStats.getCount(); + } + + /** + * Accept a long to aggregate + * + * @param value + * the value to aggregate + */ + public void accept(long value) { + fStats.accept(value); + } +} diff --git a/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerManager.java b/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerManager.java new file mode 100644 index 0000000..01448f2 --- /dev/null +++ b/src/main/java/org/eclipse/tracecompass/traceeventlogger/beans/TraceEventLoggerManager.java @@ -0,0 +1,83 @@ +/******************************************************************************* + * Copyright (c) 2025 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.traceeventlogger.beans; +import java.util.LinkedHashMap; +import java.util.Map; + +/** + * Trace Event Logger Monitor, shows the state of every scoped logger + * + * Use the {@link #update(String, long)} method to publish a new value + * + * @author Matthew Khouzam + */ +public final class TraceEventLoggerManager { + + private final Map fCounters = new LinkedHashMap<>(); + + /** + * Instance, internal, do not use + */ + private static TraceEventLoggerManager sInstance = null; + + private boolean fEnabled = false; + + /** + * Constructor + */ + private TraceEventLoggerManager() { + String loggingProperty = System.getProperty("enableMonitoring", "false"); //$NON-NLS-1$ //$NON-NLS-2$ + + // Convert to boolean + fEnabled = Boolean.parseBoolean(loggingProperty); + } + + /** + * Update a value + * + * @param label + * the label to update + * @param value + * the value to update for a given label + */ + public synchronized void update(String label, long value) { + if (fEnabled) { + fCounters.computeIfAbsent(label, TraceEventLoggerBean::new).accept(value); + } + } + + /** + * Get the instance of the manager + * + * @return the manager + */ + public static synchronized TraceEventLoggerManager getInstance() { + TraceEventLoggerManager instance = sInstance; + if (instance == null) { + instance = new TraceEventLoggerManager(); + sInstance = instance; + } + return instance; + } +}