From 47c79d9566541f5a30244b5d7569a8a893859d59 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Genevi=C3=A8ve=20Bastien?= Date: Tue, 14 Jun 2016 11:19:06 -0400 Subject: [PATCH] common: Add JUL logging to TraceCompass MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Logging allows to add tracepoints at various places in the code, and at runtime enable log handlers for specific components to produce log files that can then be analyzed by various tools... like Trace Compass! This patch is a first suggestion for adding logging facility to TraceCompass. Here is the suggested approach: * Logging has a small overhead, so they should have a negligible performance impact performance if they are not overly used. * Logging must be explicitly enabled at runtime by setting a parameter to true: -Dorg.eclipse.tracecompass.logging=true in the vmargs * Each class should have their own logger, using the class's full name (canonical name). It is thus easy to filter which classes to log using per logger name. For example, logging org.eclipse.tracecompass.tmf will log all loggers that start with o.e.t.tmf.* * Abstract classes should use their concrete class's name, to match the log statements to their concrete component. * The TraceCompassLog class contains a wrapper methods to retrieve loggers. Calling it makes sure that the main logger's level has been set and the default values set by java (info level with ConsoleLogger) are not used. * What is non-negligible in logging is often the message being logged. To be meaningful, the message will often add parameters concatenated to a string and that can be very costly. Messages should be lazily constructed using the logging statements taking Supplier in parameter. For example: LOGGER.log(() -> "My msg " + param1 + " " + param2); * Log levels, handlers, etc can be controlled via a configuration file set in the vmargs: -Djava.util.logging.config.file=/path/to/logger.properties. An example logger.properties file can be found here: https://wiki.eclipse.org/Swordfish_Documentation:_Turning_On_Logging * To help logging trace parsing, the log strings should have the following format: [EventName:MayContainSemiColon] paramName1=param1, paramName2=param2 Change-Id: Ia6cde4256799705a9f13c71b70576eb09cc3d427 Signed-off-by: Geneviève Bastien Signed-off-by: Alexandre Montplaisir Reviewed-on: https://git.eclipse.org/r/71819 Reviewed-by: Hudson CI --- .../META-INF/MANIFEST.MF | 3 +- .../annotations/java/util/logging/Logger.eea | 5 ++ .../common/core/log/TraceCompassLog.java | 70 +++++++++++++++++++ .../common/core/log/package-info.java | 11 +++ .../AbstractStateSystemTimeGraphView.java | 12 ++++ .../timegraph/AbstractTimeGraphView.java | 28 ++++++++ 6 files changed, 128 insertions(+), 1 deletion(-) create mode 100644 common/org.eclipse.tracecompass.common.core/annotations/java/util/logging/Logger.eea create mode 100644 common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/TraceCompassLog.java create mode 100644 common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/package-info.java diff --git a/common/org.eclipse.tracecompass.common.core/META-INF/MANIFEST.MF b/common/org.eclipse.tracecompass.common.core/META-INF/MANIFEST.MF index d006a9dd68..580d813dd2 100644 --- a/common/org.eclipse.tracecompass.common.core/META-INF/MANIFEST.MF +++ b/common/org.eclipse.tracecompass.common.core/META-INF/MANIFEST.MF @@ -2,7 +2,7 @@ Manifest-Version: 1.0 Bundle-ManifestVersion: 2 Bundle-Name: %Bundle-Name Bundle-Vendor: %Bundle-Vendor -Bundle-Version: 2.0.0.qualifier +Bundle-Version: 2.1.0.qualifier Bundle-Localization: plugin Bundle-SymbolicName: org.eclipse.tracecompass.common.core;singleton:=true Bundle-Activator: org.eclipse.tracecompass.internal.common.core.Activator @@ -13,5 +13,6 @@ Require-Bundle: org.eclipse.core.runtime, Export-Package: org.eclipse.tracecompass.common.core, org.eclipse.tracecompass.common.core.collect, org.eclipse.tracecompass.common.core.format, + org.eclipse.tracecompass.common.core.log, org.eclipse.tracecompass.internal.common.core;x-internal:=true Import-Package: com.google.common.collect diff --git a/common/org.eclipse.tracecompass.common.core/annotations/java/util/logging/Logger.eea b/common/org.eclipse.tracecompass.common.core/annotations/java/util/logging/Logger.eea new file mode 100644 index 0000000000..60a0a33208 --- /dev/null +++ b/common/org.eclipse.tracecompass.common.core/annotations/java/util/logging/Logger.eea @@ -0,0 +1,5 @@ +class java/util/logging/Logger +getLogger + (Ljava/lang/String;)Ljava/util/logging/Logger; + (Ljava/lang/String;)L1java/util/logging/Logger; + \ No newline at end of file diff --git a/common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/TraceCompassLog.java b/common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/TraceCompassLog.java new file mode 100644 index 0000000000..2774f3cf89 --- /dev/null +++ b/common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/TraceCompassLog.java @@ -0,0 +1,70 @@ +/******************************************************************************* + * Copyright (c) 2016 École Polytechnique de Montréal + * + * All rights reserved. This program and the accompanying materials are + * made available under the terms of the Eclipse Public License v1.0 which + * accompanies this distribution, and is available at + * http://www.eclipse.org/legal/epl-v10.html + *******************************************************************************/ + +package org.eclipse.tracecompass.common.core.log; + +import java.util.logging.Level; +import java.util.logging.Logger; + +/** + * Utility class containing methods to support logging in Trace Compass + * + * @author Geneviève Bastien + * @since 2.1 + */ +public final class TraceCompassLog { + + private static final String LOGGING_PROPERTY = "org.eclipse.tracecompass.logging"; //$NON-NLS-1$ + private static final Logger TC_PARENT_LOGGER = Logger.getLogger("org.eclipse.tracecompass"); //$NON-NLS-1$ + + static { + /* + * If Logging is not enabled, to avoid java's default parameters, we set + * the main TraceCompass logger to not use its parent's logs and set the + * level at OFF + */ + String loggingProperty = System.getProperty(LOGGING_PROPERTY); + if (!"true".equals(loggingProperty)) { //$NON-NLS-1$ + TC_PARENT_LOGGER.setUseParentHandlers(false); + TC_PARENT_LOGGER.setLevel(Level.OFF); + } + } + + private TraceCompassLog() { + } + + /** + * Get a logger by name. Calling this method instead of directly + * {@link Logger#getLogger(String)} insures that the main Trace Compass + * logger has been initialized to default value instead of using java's + * default parameters. + * + * @param name + * The name of the logger to get. It is advised to use something + * like {@link Class#getCanonicalName()}, as it will use the full + * path of the logged class and the logging can be controlled for + * its parent as well. + * @return The logger + */ + public static Logger getLogger(String name) { + return Logger.getLogger(name); + } + + /** + * Get a logger for a class + * + * @param clazz + * The class to get a logger for + * @return The logger + */ + public static Logger getLogger(Class clazz) { + return Logger.getLogger(clazz.getName()); + } + +} diff --git a/common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/package-info.java b/common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/package-info.java new file mode 100644 index 0000000000..eabac721ad --- /dev/null +++ b/common/org.eclipse.tracecompass.common.core/src/org/eclipse/tracecompass/common/core/log/package-info.java @@ -0,0 +1,11 @@ +/******************************************************************************* + * Copyright (c) 2016 École Polytechnique de Montréal and others + * + * All rights reserved. This program and the accompanying materials + * are made available under the terms of the Eclipse Public License v1.0 + * which accompanies this distribution, and is available at + * http://www.eclipse.org/legal/epl-v10.html + *******************************************************************************/ + +@org.eclipse.jdt.annotation.NonNullByDefault +package org.eclipse.tracecompass.common.core.log; diff --git a/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractStateSystemTimeGraphView.java b/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractStateSystemTimeGraphView.java index 197c2c979c..e9ab7b250f 100644 --- a/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractStateSystemTimeGraphView.java +++ b/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractStateSystemTimeGraphView.java @@ -19,10 +19,12 @@ import java.util.HashMap; import java.util.List; import java.util.Map; import java.util.concurrent.CopyOnWriteArrayList; +import java.util.logging.Logger; import org.eclipse.core.runtime.IProgressMonitor; import org.eclipse.jdt.annotation.NonNull; import org.eclipse.jdt.annotation.Nullable; +import org.eclipse.tracecompass.common.core.log.TraceCompassLog; import org.eclipse.tracecompass.statesystem.core.ITmfStateSystem; import org.eclipse.tracecompass.statesystem.core.exceptions.StateSystemDisposedException; import org.eclipse.tracecompass.statesystem.core.interval.ITmfStateInterval; @@ -62,6 +64,9 @@ public abstract class AbstractStateSystemTimeGraphView extends AbstractTimeGraph /** The trace to state system multi map */ private final Multimap fTraceSSMap = HashMultimap.create(); + /** Instance-specific logger, which will use the concrete class's name */ + private final Logger fLogger = TraceCompassLog.getLogger(getClass()); + // ------------------------------------------------------------------------ // Classes // ------------------------------------------------------------------------ @@ -117,6 +122,8 @@ public abstract class AbstractStateSystemTimeGraphView extends AbstractTimeGraph getTimeGraphViewer().setLinks(links); getTimeGraphViewer().setMarkers(markers); }); + } else { + fLogger.info(() -> "[TimeGraphView:ZoomThreadCanceled]"); //$NON-NLS-1$ } } @@ -142,15 +149,19 @@ public abstract class AbstractStateSystemTimeGraphView extends AbstractTimeGraph queryFullStates(ss, start, end, resolution, monitor, new IQueryHandler() { @Override public void handle(@NonNull List> fullStates, @Nullable List prevFullState) { + fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingStates]"); //$NON-NLS-1$ if (!fullRange) { for (TimeGraphEntry entry : entryList) { zoom(checkNotNull(entry), ss, fullStates, prevFullState, monitor); } } /* Refresh the arrows when zooming */ + fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingLinks]"); //$NON-NLS-1$ links.addAll(getLinkList(ss, fullStates, prevFullState, monitor)); /* Refresh the view-specific markers when zooming */ + fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingMarkers]"); //$NON-NLS-1$ markers.addAll(getViewMarkerList(ss, fullStates, prevFullState, monitor)); + fLogger.config(() -> "[TimeGraphView:ZoomThreadDone]"); //$NON-NLS-1$ } }); refresh(); @@ -170,6 +181,7 @@ public abstract class AbstractStateSystemTimeGraphView extends AbstractTimeGraph } for (TimeGraphEntry child : entry.getChildren()) { if (monitor.isCanceled()) { + fLogger.info(() -> "[TimeGraphView:ZoomThreadCanceled]"); //$NON-NLS-1$ return; } zoom(child, ss, fullStates, prevFullState, monitor); diff --git a/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractTimeGraphView.java b/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractTimeGraphView.java index 3c6619064b..6b0650fd73 100644 --- a/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractTimeGraphView.java +++ b/tmf/org.eclipse.tracecompass.tmf.ui/src/org/eclipse/tracecompass/tmf/ui/views/timegraph/AbstractTimeGraphView.java @@ -28,6 +28,7 @@ import java.util.Map; import java.util.Set; import java.util.concurrent.CopyOnWriteArrayList; import java.util.concurrent.atomic.AtomicInteger; +import java.util.logging.Logger; import java.util.regex.Matcher; import java.util.regex.Pattern; @@ -78,6 +79,7 @@ import org.eclipse.swt.widgets.Menu; import org.eclipse.swt.widgets.Shell; import org.eclipse.swt.widgets.Tree; import org.eclipse.swt.widgets.TreeColumn; +import org.eclipse.tracecompass.common.core.log.TraceCompassLog; import org.eclipse.tracecompass.internal.tmf.ui.Activator; import org.eclipse.tracecompass.tmf.core.resources.ITmfMarker; import org.eclipse.tracecompass.tmf.core.signal.TmfSelectionRangeUpdatedSignal; @@ -142,6 +144,9 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA private static final Pattern RGBA_PATTERN = Pattern.compile("RGBA \\{(\\d+), (\\d+), (\\d+), (\\d+)\\}"); //$NON-NLS-1$ + /** Instance-specific logger, which will use the concrete class's name */ + private final Logger fLogger = TraceCompassLog.getLogger(getClass()); + /** * Redraw state enum */ @@ -697,10 +702,14 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA @Override public void run() { + fLogger.info(() -> "[TimeGraphView:BuildThreadStart] trace=" + fBuildTrace.getName()); //$NON-NLS-1$ + buildEntryList(fBuildTrace, fParentTrace, fMonitor); synchronized (fBuildThreadMap) { fBuildThreadMap.remove(fBuildTrace); } + + fLogger.info(() -> "[TimeGraphView:BuildThreadEnd]"); //$NON-NLS-1$ } public void cancel() { @@ -773,8 +782,12 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA @Override public final void run() { + fLogger.info(() -> "[TimeGraphView:ZoomThreadStart] start=" + fZoomStartTime + ", end=" + fZoomEndTime); //$NON-NLS-1$ //$NON-NLS-2$ + doRun(); fDirty.decrementAndGet(); + + fLogger.info(() -> "[TimeGraphView:ZoomThreadEnd]"); //$NON-NLS-1$ } /** @@ -812,8 +825,11 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA @Override public void doRun() { + fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingStates]"); //$NON-NLS-1$ + for (TimeGraphEntry entry : fZoomEntryList) { if (getMonitor().isCanceled()) { + fLogger.info(() -> "[TimeGraphView:ZoomThreadCanceled]"); //$NON-NLS-1$ return; } if (entry == null) { @@ -822,8 +838,11 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA zoom(entry, getMonitor()); } /* Refresh the arrows when zooming */ + fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingLinks]"); //$NON-NLS-1$ List events = getLinkList(getZoomStartTime(), getZoomEndTime(), getResolution(), getMonitor()); + /* Refresh the view-specific markers when zooming */ + fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingMarkers]"); //$NON-NLS-1$ List markers = new ArrayList<>(getViewMarkerList(getZoomStartTime(), getZoomEndTime(), getResolution(), getMonitor())); /* Refresh the trace-specific markers when zooming */ markers.addAll(getTraceMarkerList(getZoomStartTime(), getZoomEndTime(), getResolution(), getMonitor())); @@ -1566,6 +1585,9 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA fViewContext.put(fTrace, new ViewContext(fCurrentSortColumn, fSortDirection, fTimeGraphWrapper.getSelection())); } fTrace = trace; + + fLogger.info(() -> "[TimeGraphView:LoadingTrace] trace=" + trace.getName()); //$NON-NLS-1$ + restoreViewContext(); fEditorFile = TmfTraceManager.getInstance().getTraceEditorFile(trace); synchronized (fEntryListMap) { @@ -1787,10 +1809,12 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA * Refresh the display */ protected void refresh() { + fLogger.info(() -> "[TimeGraphView:RefreshRequested]"); //$NON-NLS-1$ final boolean zoomThread = Thread.currentThread() instanceof ZoomThread; TmfUiRefreshHandler.getInstance().queueUpdate(this, new Runnable() { @Override public void run() { + fLogger.info(() -> "[TimeGraphView:RefreshStart]"); //$NON-NLS-1$ if (fTimeGraphWrapper.isDisposed()) { return; } @@ -1875,6 +1899,7 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA startZoomThread(startTime, endTime); } fDirty.decrementAndGet(); + fLogger.info(() -> "[TimeGraphView:RefreshEnd]"); //$NON-NLS-1$ } }); } @@ -1891,9 +1916,11 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA return; } } + fLogger.info(() -> "[TimeGraphView:RedrawRequested]"); //$NON-NLS-1$ Display.getDefault().asyncExec(new Runnable() { @Override public void run() { + fLogger.info(() -> "[TimeGraphView:RedrawStart]"); //$NON-NLS-1$ if (fTimeGraphWrapper.isDisposed()) { return; } @@ -1907,6 +1934,7 @@ public abstract class AbstractTimeGraphView extends TmfView implements ITmfTimeA fRedrawState = State.IDLE; } } + fLogger.info(() -> "[TimeGraphView:RedrawEnd]"); //$NON-NLS-1$ } }); } -- 2.34.1