common: Add JUL logging to TraceCompass

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<String> 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 <gbastien+lttng@versatic.net>
Signed-off-by: Alexandre Montplaisir <alexmonthy@efficios.com>
Reviewed-on: https://git.eclipse.org/r/71819
Reviewed-by: Hudson CI

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 d006a9dd68a10e218e4e71a7a167e48ce0b17025..580d813dd2f13805f4a64422110858b9b5042f8f 100644 (file)
--- 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 (file)
index 0000000..60a0a33
--- /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 (file)
index 0000000..2774f3c
--- /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 (file)
index 0000000..eabac72
--- /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 197c2c979c6295362b0122064cc1636b36342aee..e9ab7b250f5322ab8c8d2737ca0a48b79c5e6fd7 100644 (file)
--- 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<ITmfTrace, ITmfStateSystem> 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<List<ITmfStateInterval>> fullStates, @Nullable List<ITmfStateInterval> 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 3c6619064b0ba10dbc6897026b5271748e3d9be3..6b0650fd7374444d5412152f3829b083f9854c69 100644 (file)
--- 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<ILinkEvent> events = getLinkList(getZoomStartTime(), getZoomEndTime(), getResolution(), getMonitor());
+
             /* Refresh the view-specific markers when zooming */
+            fLogger.config(() -> "[TimeGraphView:ZoomThreadGettingMarkers]"); //$NON-NLS-1$
             List<IMarkerEvent> 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$
             }
         });
     }