From b128f1ecfa15874af855f9ba715a5128cd7eb8c2 Mon Sep 17 00:00:00 2001 From: Lars Vogel Date: Thu, 30 Jul 2026 14:40:14 +0200 Subject: [PATCH] Make builder tracing work and switchable at runtime MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Per-builder tracing existed as org.eclipse.core.resources/perf/builders but never worked. ResourceStats kept the in-progress PerformanceStats in a single static field, so parallel builders overwrote each other's start time, and startRun(context) mutated the context of that shared instance, which is part of its hashCode and so corrupted its key in the global stats map. Each start now returns a handle that the matching end consumes, and the duration is recorded through addRun, which leaves the shared context alone. Enablement is no longer frozen at startup: core.runtime updates PerformanceStats.ENABLED from a debug options listener, and the resources flags are refreshed from the listener core.resources already had. Because a bundle is only notified about its own options, the resources flags track just perf/* of core.resources and read the global flag separately. The threshold is now the shortest duration still reported, so 0 reports every occurrence to listeners without writing to the performance log. core.runtime also contributes an org.eclipse.ui.trace.traceComponents component, like core.jobs and core.resources do, so its perf options can be set from the Tracing preference page instead of only from a launch configuration. Assisted-by: multiple AI agents and layers of automated tooling 🤖 --- .../org.eclipse.core.resources/.options | 3 +- .../core/internal/events/BuildManager.java | 33 ++-- .../internal/events/NotificationManager.java | 15 +- .../core/internal/events/ResourceStats.java | 153 +++++++++------ .../localstore/FileSystemResourceManager.java | 23 +-- .../core/internal/resources/SaveManager.java | 29 ++- .../eclipse/core/internal/utils/Policy.java | 3 + .../META-INF/MANIFEST.MF | 1 + .../internal/builders/AllBuilderTests.java | 1 + .../internal/builders/BuilderTracingTest.java | 181 ++++++++++++++++++ .../plugin.properties | 1 + .../org.eclipse.core.runtime/plugin.xml | 11 ++ .../internal/runtime/InternalPlatform.java | 14 ++ .../runtime/PerformanceStatsProcessor.java | 28 +-- .../core/runtime/PerformanceStats.java | 110 +++++------ 15 files changed, 417 insertions(+), 189 deletions(-) create mode 100644 resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/BuilderTracingTest.java diff --git a/resources/bundles/org.eclipse.core.resources/.options b/resources/bundles/org.eclipse.core.resources/.options index 04239fc4e0e..b0f12d9cb2b 100644 --- a/resources/bundles/org.eclipse.core.resources/.options +++ b/resources/bundles/org.eclipse.core.resources/.options @@ -3,7 +3,8 @@ # Turn on debugging for the org.eclipse.core.resources plugin. org.eclipse.core.resources/debug=false -# Monitor builders and gather time statistics etc. +# Monitor builders and trace if a single builder run takes longer than the specified time in milliseconds. +# A value of 0 gathers statistics for every builder run without writing any of them to the log. org.eclipse.core.resources/perf/builders=10000 # Monitor resource change listeners and gather time statistics etc. diff --git a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/BuildManager.java b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/BuildManager.java index 170f4d33de5..8454e7ea89c 100644 --- a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/BuildManager.java +++ b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/BuildManager.java @@ -210,7 +210,6 @@ public ISchedulingRule getRule(int kind, Map args) { private final Object builderInitializationLock = new Object(); //used for debug/trace timing - private long timeStamp = -1; private long overallTimeStamp = -1; private final Workspace workspace; @@ -262,6 +261,7 @@ private void basicBuild(int trigger, IncrementalProjectBuilder builder, Map 0 + && duration > ResourceStats.TRACE_BUILDERS_THRESHOLD) { + String message = "Builder " + toString(builder) + " took " + duration + " ms for " + debugTrigger(trigger); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ + Policy.log(IStatus.INFO, message, null); + } + if (Policy.DEBUG_BUILD_INVOKING) { + Policy.debug("Builder finished: " + toString(builder) + " time: " + duration + "ms"); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ } - Policy.debug("Builder finished: " + toString(builder) + " time: " + (System.currentTimeMillis() - timeStamp) + "ms"); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ - timeStamp = -1; } /** @@ -1232,14 +1237,14 @@ private void hookEndBuild(int trigger) { * Hook for adding trace options and debug information at the start of a build. * This hook is called before each builder instance is called. */ - private void hookStartBuild(IncrementalProjectBuilder builder, int trigger) { - if (ResourceStats.TRACE_BUILDERS) { - ResourceStats.startBuild(builder); + private ResourceStats.Run hookStartBuild(IncrementalProjectBuilder builder, int trigger) { + if (!ResourceStats.isTracingBuilders() && !Policy.DEBUG_BUILD_INVOKING) { + return null; } if (Policy.DEBUG_BUILD_INVOKING) { - timeStamp = System.currentTimeMillis(); Policy.debug("Invoking (" + debugTrigger(trigger) + ") on builder: " + toString(builder)); //$NON-NLS-1$ //$NON-NLS-2$ } + return ResourceStats.isTracingBuilders() ? ResourceStats.startBuild(builder) : ResourceStats.startTiming(); } /** diff --git a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/NotificationManager.java b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/NotificationManager.java index 017afaec0c3..0db8311e532 100644 --- a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/NotificationManager.java +++ b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/NotificationManager.java @@ -139,7 +139,7 @@ public NotificationManager(Workspace workspace) { public void addListener(IResourceChangeListener listener, int eventMask) { listeners.add(listener, eventMask); - if (ResourceStats.TRACE_LISTENERS) { + if (ResourceStats.isTracingListeners()) { ResourceStats.listenerAdded(listener); } } @@ -325,9 +325,7 @@ private void notify(ResourceChangeListenerList.ListenerEntry[] resourceListeners for (ListenerEntry resourceListener : resourceListeners) { if ((type & resourceListener.eventMask) != 0) { final IResourceChangeListener listener = resourceListener.listener; - if (ResourceStats.TRACE_LISTENERS) { - ResourceStats.startNotify(listener); - } + ResourceStats.Run run = ResourceStats.isTracingListeners() ? ResourceStats.startNotify(listener) : null; SafeRunner.run(new ISafeRunnable() { @Override public void handleException(Throwable e) { @@ -342,9 +340,7 @@ public void run() throws Exception { listener.resourceChanged(event); } }); - if (ResourceStats.TRACE_LISTENERS) { - ResourceStats.endNotify(); - } + ResourceStats.end(run); } } } finally { @@ -356,9 +352,8 @@ public void run() throws Exception { public void removeListener(IResourceChangeListener listener) { listeners.remove(listener); - if (ResourceStats.TRACE_LISTENERS) { - ResourceStats.listenerRemoved(listener); - } + // unconditional, so that no stale entry survives if tracing was switched off meanwhile + ResourceStats.listenerRemoved(listener); } /** diff --git a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/ResourceStats.java b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/ResourceStats.java index a77390dd735..26faaa51576 100644 --- a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/ResourceStats.java +++ b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/events/ResourceStats.java @@ -1,5 +1,5 @@ /******************************************************************************* - * Copyright (c) 2000, 2005 IBM Corporation and others. + * Copyright (c) 2000, 2026 IBM Corporation and others. * * This program and the accompanying materials * are made available under the terms of the Eclipse Public License 2.0 @@ -26,10 +26,14 @@ * a builder running, an editor opening, etc. */ public class ResourceStats { + /** - * The event that is currently occurring, maybe null + * A single timed occurrence of a traced event, passed from a + * start... method to {@link ResourceStats#end(Run)}. */ - private static PerformanceStats currentStats; + public record Run(PerformanceStats stats, String context, long startTime) { + } + //performance event names public static final String EVENT_BUILDERS = ResourcesPlugin.PI_RESOURCES + "/perf/builders"; //$NON-NLS-1$ public static final String EVENT_LISTENERS = ResourcesPlugin.PI_RESOURCES + "/perf/listeners"; //$NON-NLS-1$ @@ -37,59 +41,95 @@ public class ResourceStats { public static final String EVENT_SNAPSHOT = ResourcesPlugin.PI_RESOURCES + "/perf/snapshot"; //$NON-NLS-1$ public static final String EVENT_REFRESH = ResourcesPlugin.PI_RESOURCES + "/perf/refresh"; //$NON-NLS-1$ - //performance event enablement - public static boolean TRACE_BUILDERS = PerformanceStats.isEnabled(ResourceStats.EVENT_BUILDERS); - public static boolean TRACE_LISTENERS = PerformanceStats.isEnabled(ResourceStats.EVENT_LISTENERS); - public static boolean TRACE_SAVE_PARTICIPANTS = PerformanceStats.isEnabled(ResourceStats.EVENT_SAVE_PARTICIPANTS); - public static boolean TRACE_SNAPSHOT = PerformanceStats.isEnabled(ResourceStats.EVENT_SNAPSHOT); - public static boolean TRACE_REFRESH = PerformanceStats.isEnabled(ResourceStats.EVENT_REFRESH); - public static int TRACE_REFRESH_THRESHOLD; - static { - String option = Platform.getDebugOption(ResourceStats.EVENT_REFRESH); - if (option != null) { - try { - TRACE_REFRESH_THRESHOLD = Integer.parseInt(option); - } catch (NumberFormatException e) { - TRACE_REFRESH_THRESHOLD = 0; - } - } + /* + * Whether the debug option of the event is set. Only this bundle's own options, + * since a debug options listener is not notified about another bundle's; the + * global perf flag is read separately through PerformanceStats.ENABLED. + */ + private static volatile boolean optionBuilders = isOptionSet(EVENT_BUILDERS); + private static volatile boolean optionListeners = isOptionSet(EVENT_LISTENERS); + private static volatile boolean optionSaveParticipants = isOptionSet(EVENT_SAVE_PARTICIPANTS); + private static volatile boolean optionSnapshot = isOptionSet(EVENT_SNAPSHOT); + private static volatile boolean optionRefresh = isOptionSet(EVENT_REFRESH); + + //durations above which an occurrence is reported to the log, in milliseconds + public static volatile int TRACE_BUILDERS_THRESHOLD = threshold(EVENT_BUILDERS); + public static volatile int TRACE_REFRESH_THRESHOLD = threshold(EVENT_REFRESH); + + /** + * Re-reads the tracing options, so that tracing can be switched at runtime. + */ + public static void optionsChanged() { + optionBuilders = isOptionSet(EVENT_BUILDERS); + optionListeners = isOptionSet(EVENT_LISTENERS); + optionSaveParticipants = isOptionSet(EVENT_SAVE_PARTICIPANTS); + optionSnapshot = isOptionSet(EVENT_SNAPSHOT); + optionRefresh = isOptionSet(EVENT_REFRESH); + TRACE_BUILDERS_THRESHOLD = threshold(EVENT_BUILDERS); + TRACE_REFRESH_THRESHOLD = threshold(EVENT_REFRESH); } - public static void endBuild() { - if (currentStats != null) { - currentStats.endRun(); - } - currentStats = null; + public static boolean isTracingBuilders() { + return PerformanceStats.ENABLED && optionBuilders; } - public static void endNotify() { - if (currentStats != null) { - currentStats.endRun(); - } - currentStats = null; + public static boolean isTracingListeners() { + return PerformanceStats.ENABLED && optionListeners; } - public static void endSave() { - if (currentStats != null) { - currentStats.endRun(); - } - currentStats = null; + public static boolean isTracingSaveParticipants() { + return PerformanceStats.ENABLED && optionSaveParticipants; + } + + public static boolean isTracingSnapshot() { + return PerformanceStats.ENABLED && optionSnapshot; } - public static void endSnapshot() { - if (currentStats != null) { - currentStats.endRun(); + public static boolean isTracingRefresh() { + return PerformanceStats.ENABLED && optionRefresh; + } + + private static boolean isOptionSet(String event) { + String option = Platform.getDebugOption(event); + return option != null && !"false".equalsIgnoreCase(option) && !"-1".equalsIgnoreCase(option); //$NON-NLS-1$ //$NON-NLS-2$ + } + + private static int threshold(String event) { + String option = Platform.getDebugOption(event); + if (option == null) { + return 0; } - currentStats = null; + try { + return Integer.parseInt(option.trim()); + } catch (NumberFormatException e) { + return 0; + } + } + + private static Run start(String event, Object blame, String context) { + return new Run(PerformanceStats.getStats(event, blame), context, System.currentTimeMillis()); } - public static PerformanceStats endRefresh() { - if (currentStats != null) { - currentStats.endRun(); + /** + * Starts a run that is only timed, not recorded as a performance event. + */ + public static Run startTiming() { + return new Run(null, null, System.currentTimeMillis()); + } + + /** + * Records the given run and returns its duration in milliseconds, or -1 if + * there was no run. + */ + public static long end(Run run) { + if (run == null) { + return -1; + } + long duration = System.currentTimeMillis() - run.startTime(); + if (run.stats() != null) { + run.stats().addRun(duration, run.context()); } - PerformanceStats stats = currentStats; - currentStats = null; - return stats; + return duration; } /** @@ -110,29 +150,24 @@ public static void listenerRemoved(IResourceChangeListener listener) { } } - public static void startBuild(IncrementalProjectBuilder builder) { - currentStats = PerformanceStats.getStats(EVENT_BUILDERS, builder); - currentStats.startRun(builder.getProject().getName()); + public static Run startBuild(IncrementalProjectBuilder builder) { + return start(EVENT_BUILDERS, builder, builder.getProject().getName()); } - public static void startNotify(IResourceChangeListener listener) { - currentStats = PerformanceStats.getStats(EVENT_LISTENERS, listener); - currentStats.startRun(); + public static Run startNotify(IResourceChangeListener listener) { + return start(EVENT_LISTENERS, listener, null); } - public static void startSnapshot() { - currentStats = PerformanceStats.getStats(EVENT_SNAPSHOT, ResourcesPlugin.getWorkspace()); - currentStats.startRun(); + public static Run startSnapshot() { + return start(EVENT_SNAPSHOT, ResourcesPlugin.getWorkspace(), null); } - public static void startSave(ISaveParticipant participant) { - currentStats = PerformanceStats.getStats(EVENT_SAVE_PARTICIPANTS, participant); - currentStats.startRun(); + public static Run startSave(ISaveParticipant participant) { + return start(EVENT_SAVE_PARTICIPANTS, participant, null); } - public static void startRefresh(IResource resource) { - currentStats = PerformanceStats.getStats(EVENT_REFRESH, resource); - currentStats.startRun(); + public static Run startRefresh(IResource resource) { + return start(EVENT_REFRESH, resource, null); } } diff --git a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/localstore/FileSystemResourceManager.java b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/localstore/FileSystemResourceManager.java index e1d3fff3a8e..487593b91b3 100644 --- a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/localstore/FileSystemResourceManager.java +++ b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/localstore/FileSystemResourceManager.java @@ -73,7 +73,6 @@ import org.eclipse.core.runtime.IStatus; import org.eclipse.core.runtime.MultiStatus; import org.eclipse.core.runtime.OperationCanceledException; -import org.eclipse.core.runtime.PerformanceStats; import org.eclipse.core.runtime.Platform; import org.eclipse.core.runtime.SubMonitor; import org.eclipse.core.runtime.preferences.IEclipsePreferences.IPreferenceChangeListener; @@ -1075,26 +1074,16 @@ public boolean refresh(IResource target, int depth, boolean updateAliases, IProg if (!target.isAccessible()) { return false; } - boolean result; - if (ResourceStats.TRACE_REFRESH) { - ResourceStats.startRefresh(target); - } + ResourceStats.Run run = ResourceStats.isTracingRefresh() ? ResourceStats.startRefresh(target) : null; try { - result = refreshResource(target, depth, updateAliases, monitor); + return refreshResource(target, depth, updateAliases, monitor); } finally { - if (ResourceStats.TRACE_REFRESH) { - PerformanceStats stats = ResourceStats.endRefresh(); - if (stats != null) { - long runningTime = stats.getRunningTime(); - if (runningTime > ResourceStats.TRACE_REFRESH_THRESHOLD) { - String message = "Refresh on " + target.getFullPath() + " took " + runningTime + " ms"; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ - Policy.log(IStatus.INFO, message, null); - } - stats.reset(); - } + long duration = ResourceStats.end(run); + if (duration > ResourceStats.TRACE_REFRESH_THRESHOLD) { + String message = "Refresh on " + target.getFullPath() + " took " + duration + " ms"; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ + Policy.log(IStatus.INFO, message, null); } } - return result; case IResource.FOLDER : case IResource.FILE : return refreshResource(target, depth, updateAliases, monitor); diff --git a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/resources/SaveManager.java b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/resources/SaveManager.java index 96d15a2702a..e718b62f705 100644 --- a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/resources/SaveManager.java +++ b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/resources/SaveManager.java @@ -458,18 +458,15 @@ protected void executeLifecycle(int lifecycle, ISaveParticipant participant, Sav case PREPARE_TO_SAVE : participant.prepareToSave(context); break; - case SAVING : + case SAVING : { + ResourceStats.Run run = ResourceStats.isTracingSaveParticipants() ? ResourceStats.startSave(participant) : null; try { - if (ResourceStats.TRACE_SAVE_PARTICIPANTS) { - ResourceStats.startSave(participant); - } participant.saving(context); } finally { - if (ResourceStats.TRACE_SAVE_PARTICIPANTS) { - ResourceStats.endSave(); - } + ResourceStats.end(run); } break; + } case DONE_SAVING : participant.doneSaving(context); break; @@ -523,10 +520,8 @@ protected String[] getSaveParticipantPluginIds() { * Hooks the end of a save operation, for debugging and performance * monitoring purposes. */ - private void hookEndSave(int kind, IProject project, long start) { - if (ResourceStats.TRACE_SNAPSHOT && kind == ISaveContext.SNAPSHOT) { - ResourceStats.endSnapshot(); - } + private void hookEndSave(int kind, IProject project, long start, ResourceStats.Run run) { + ResourceStats.end(run); if (Policy.DEBUG_SAVE) { String endMessage = null; switch (kind) { @@ -550,9 +545,10 @@ private void hookEndSave(int kind, IProject project, long start) { * Hooks the start of a save operation, for debugging and performance * monitoring purposes. */ - private void hookStartSave(int kind, Project project) { - if (ResourceStats.TRACE_SNAPSHOT && kind == ISaveContext.SNAPSHOT) { - ResourceStats.startSnapshot(); + private ResourceStats.Run hookStartSave(int kind, Project project) { + ResourceStats.Run run = null; + if (ResourceStats.isTracingSnapshot() && kind == ISaveContext.SNAPSHOT) { + run = ResourceStats.startSnapshot(); } if (Policy.DEBUG_SAVE) { switch (kind) { @@ -567,6 +563,7 @@ private void hookStartSave(int kind, Project project) { break; } } + return run; } /** @@ -1276,7 +1273,7 @@ public IStatus save(int kind, boolean keepConsistencyWhenCanceled, Project proje try { workspace.prepareOperation(rule, monitor); workspace.beginOperation(false); - hookStartSave(kind, project); + ResourceStats.Run snapshotRun = hookStartSave(kind, project); long start = System.currentTimeMillis(); Map contexts = computeSaveContexts(getSaveParticipantPluginIds(), kind, project); broadcastLifecycle(PREPARE_TO_SAVE, contexts, warnings, Policy.subMonitorFor(monitor, 1)); @@ -1353,7 +1350,7 @@ public IStatus save(int kind, boolean keepConsistencyWhenCanceled, Project proje //this must be done after committing save contexts to update participant save numbers saveMasterTable(kind); broadcastLifecycle(DONE_SAVING, contexts, warnings, Policy.subMonitorFor(monitor, 1)); - hookEndSave(kind, project, start); + hookEndSave(kind, project, start, snapshotRun); return warnings; } catch (CoreException e) { broadcastLifecycle(ROLLBACK, contexts, warnings, Policy.subMonitorFor(monitor, 1)); diff --git a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/utils/Policy.java b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/utils/Policy.java index 97a3c093cff..85c3ccdbcd7 100644 --- a/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/utils/Policy.java +++ b/resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/utils/Policy.java @@ -15,6 +15,7 @@ import java.io.PrintWriter; import java.io.StringWriter; +import org.eclipse.core.internal.events.ResourceStats; import org.eclipse.core.resources.ResourcesPlugin; import org.eclipse.core.runtime.*; import org.eclipse.core.runtime.jobs.Job; @@ -67,6 +68,8 @@ public void optionsChanged(DebugOptions options) { DEBUG_SAVE_TREE = DEBUG && options.getBooleanOption(ResourcesPlugin.PI_RESOURCES + "/save/tree", false); //$NON-NLS-1$ DEBUG_STRINGS = DEBUG && options.getBooleanOption(ResourcesPlugin.PI_RESOURCES + "/strings", false); //$NON-NLS-1$ + + ResourceStats.optionsChanged(); } }; diff --git a/resources/tests/org.eclipse.core.tests.resources/META-INF/MANIFEST.MF b/resources/tests/org.eclipse.core.tests.resources/META-INF/MANIFEST.MF index e7c73a23e09..f4c074d7ad0 100644 --- a/resources/tests/org.eclipse.core.tests.resources/META-INF/MANIFEST.MF +++ b/resources/tests/org.eclipse.core.tests.resources/META-INF/MANIFEST.MF @@ -35,6 +35,7 @@ Require-Bundle: org.eclipse.core.resources, org.eclipse.core.runtime, org.eclipse.pde.junit.runtime;bundle-version="3.5.0" Import-Package: org.assertj.core.api, + org.eclipse.osgi.service.debug, org.junit.jupiter.api;version="[5.14.0,6.0.0)", org.junit.jupiter.api.extension;version="[5.14.0,6.0.0)", org.junit.jupiter.api.function;version="[5.14.0,6.0.0)", diff --git a/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/AllBuilderTests.java b/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/AllBuilderTests.java index 98b0b6b52ac..11dd0448679 100644 --- a/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/AllBuilderTests.java +++ b/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/AllBuilderTests.java @@ -27,6 +27,7 @@ BuilderEventTest.class, // BuilderNatureTest.class, // BuilderTest.class, // + BuilderTracingTest.class, // ComputeProjectOrderTest.class, // CustomBuildTriggerTest.class, // EmptyDeltaTest.class, // diff --git a/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/BuilderTracingTest.java b/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/BuilderTracingTest.java new file mode 100644 index 00000000000..d71fd8a7e50 --- /dev/null +++ b/resources/tests/org.eclipse.core.tests.resources/src/org/eclipse/core/tests/internal/builders/BuilderTracingTest.java @@ -0,0 +1,181 @@ +/******************************************************************************* + * Copyright (c) 2026 Vogella GmbH and others. + * + * This program and the accompanying materials + * are made available under the terms of the Eclipse Public License 2.0 + * which accompanies this distribution, and is available at + * https://www.eclipse.org/legal/epl-2.0/ + * + * SPDX-License-Identifier: EPL-2.0 + * + * Contributors: + * Vogella GmbH - initial API and implementation + *******************************************************************************/ +package org.eclipse.core.tests.internal.builders; + +import static org.eclipse.core.resources.ResourcesPlugin.getWorkspace; +import static org.eclipse.core.tests.resources.ResourceTestUtil.createTestMonitor; +import static org.eclipse.core.tests.resources.ResourceTestUtil.setAutoBuilding; +import static org.eclipse.core.tests.resources.ResourceTestUtil.updateProjectDescription; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import java.util.Arrays; +import java.util.LinkedHashMap; +import java.util.Map; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; +import java.util.function.BooleanSupplier; +import org.eclipse.core.internal.events.ResourceStats; +import org.eclipse.core.resources.IProject; +import org.eclipse.core.resources.IncrementalProjectBuilder; +import org.eclipse.core.runtime.CoreException; +import org.eclipse.core.runtime.PerformanceStats; +import org.eclipse.core.runtime.PerformanceStats.PerformanceListener; +import org.eclipse.core.tests.resources.util.WorkspaceResetExtension; +import org.eclipse.osgi.service.debug.DebugOptions; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; +import org.osgi.framework.BundleContext; +import org.osgi.framework.FrameworkUtil; +import org.osgi.framework.ServiceReference; + +/** + * Tests that builder tracing can be switched on at runtime and then attributes + * build time to the individual builder and project. + */ +@ExtendWith(WorkspaceResetExtension.class) +public class BuilderTracingTest { + + private static final String EVENT_BUILDERS = "org.eclipse.core.resources/perf/builders"; + private static final String OPTION_PERF = "org.eclipse.core.runtime/perf"; + private static final String OPTION_PERF_SUCCESS = "org.eclipse.core.runtime/perf/success"; + + private DebugOptions debugOptions; + private ServiceReference debugOptionsReference; + private boolean debugWasEnabled; + private boolean tracingWasEnabled; + private final Map replacedOptions = new LinkedHashMap<>(); + + @BeforeEach + public void setUp() { + BundleContext context = FrameworkUtil.getBundle(BuilderTracingTest.class).getBundleContext(); + debugOptionsReference = context.getServiceReference(DebugOptions.class); + debugOptions = context.getService(debugOptionsReference); + debugWasEnabled = debugOptions.isDebugEnabled(); + tracingWasEnabled = ResourceStats.isTracingBuilders(); + for (String option : Arrays.asList(OPTION_PERF, OPTION_PERF_SUCCESS, EVENT_BUILDERS)) { + replacedOptions.put(option, debugOptions.getOption(option)); + } + PerformanceStats.clear(); + } + + @AfterEach + public void tearDown() throws InterruptedException { + if (debugWasEnabled) { + replacedOptions.forEach((option, value) -> { + if (value == null) { + debugOptions.removeOption(option); + } else { + debugOptions.setOption(option, value); + } + }); + } else { + // disabling debug discards all options that were set + debugOptions.setDebugEnabled(false); + } + waitUntil(() -> ResourceStats.isTracingBuilders() == tracingWasEnabled, + "builder tracing was not restored to its previous state"); + PerformanceStats.clear(); + FrameworkUtil.getBundle(BuilderTracingTest.class).getBundleContext().ungetService(debugOptionsReference); + } + + /** + * Debug options listeners are notified asynchronously, so a change to the + * options only takes effect a moment later. + */ + private static void waitUntil(BooleanSupplier condition, String message) throws InterruptedException { + long deadline = System.currentTimeMillis() + 30_000; + while (!condition.getAsBoolean() && System.currentTimeMillis() < deadline) { + Thread.sleep(10); + } + assertTrue(condition.getAsBoolean(), message); + } + + private void enableBuilderTracing() throws InterruptedException { + debugOptions.setDebugEnabled(true); + debugOptions.setOption(OPTION_PERF, "true"); + debugOptions.setOption(OPTION_PERF_SUCCESS, "true"); + // a threshold of 0 records every builder run, not just the slow ones + debugOptions.setOption(EVENT_BUILDERS, "0"); + waitUntil(() -> ResourceStats.isTracingBuilders(), "builder tracing did not take effect"); + } + + private IProject createProjectWithSortBuilder(String name) throws CoreException { + IProject project = getWorkspace().getRoot().getProject(name); + setAutoBuilding(false); + project.create(createTestMonitor()); + project.open(createTestMonitor()); + updateProjectDescription(project).addingCommand(SortBuilder.BUILDER_NAME).withTestBuilderId(name).apply(); + return project; + } + + @Test + public void testTracingFollowsDebugOptionsAtRuntime() throws InterruptedException { + // start from a known state, the suite may run with tracing already enabled + debugOptions.setOption(OPTION_PERF, "false"); + waitUntil(() -> !PerformanceStats.ENABLED, "tracing could not be switched off"); + assertFalse(PerformanceStats.isEnabled(EVENT_BUILDERS), "tracing should start out disabled"); + + enableBuilderTracing(); + assertTrue(PerformanceStats.ENABLED, "the global tracing flag should follow the debug option"); + assertTrue(PerformanceStats.isEnabled(EVENT_BUILDERS), "builder tracing should be enabled"); + + debugOptions.setOption(OPTION_PERF, "false"); + assertFalse(PerformanceStats.isEnabled(EVENT_BUILDERS), "builder tracing should be disabled again"); + waitUntil(() -> !PerformanceStats.ENABLED, "the global tracing flag should be switched off again"); + } + + @Test + public void testBuildIsAttributedToBuilderAndProject() throws Exception { + IProject project = createProjectWithSortBuilder("tracedProject"); + enableBuilderTracing(); + + getWorkspace().build(IncrementalProjectBuilder.FULL_BUILD, createTestMonitor()); + + assertTrue(Arrays.stream(PerformanceStats.getAllStats()) + .anyMatch(stats -> EVENT_BUILDERS.equals(stats.getEvent()) + && stats.getBlameString().contains(SortBuilder.class.getSimpleName()) + && project.getName().equals(stats.getContext())), + "expected a builder event blaming " + SortBuilder.class.getSimpleName() + " on " + project.getName() + + " but got " + Arrays.toString(PerformanceStats.getAllStats())); + } + + @Test + public void testListenerIsNotifiedAboutEveryBuilderRun() throws Exception { + IProject project = createProjectWithSortBuilder("listenedProject"); + // two runs of the same builder on the same project share event, blame and + // context, so a processor that coalesces occurrences would only report one + CountDownLatch reported = new CountDownLatch(2); + PerformanceListener listener = new PerformanceListener() { + @Override + public void eventFailed(PerformanceStats event, long duration) { + if (EVENT_BUILDERS.equals(event.getEvent()) && project.getName().equals(event.getContext())) { + reported.countDown(); + } + } + }; + + enableBuilderTracing(); + PerformanceStats.addListener(listener); + try { + getWorkspace().build(IncrementalProjectBuilder.FULL_BUILD, createTestMonitor()); + getWorkspace().build(IncrementalProjectBuilder.FULL_BUILD, createTestMonitor()); + assertTrue(reported.await(30, TimeUnit.SECONDS), "listener was not notified about every builder run"); + } finally { + PerformanceStats.removeListener(listener); + } + } +} diff --git a/runtime/bundles/org.eclipse.core.runtime/plugin.properties b/runtime/bundles/org.eclipse.core.runtime/plugin.properties index b41bdc67472..a8950f1eaab 100644 --- a/runtime/bundles/org.eclipse.core.runtime/plugin.properties +++ b/runtime/bundles/org.eclipse.core.runtime/plugin.properties @@ -15,3 +15,4 @@ pluginName = Core Runtime providerName = Eclipse.org shutdownHook = Shutdown Hook preferencesName=Preferences +traceComponentLabel = Platform Core Runtime diff --git a/runtime/bundles/org.eclipse.core.runtime/plugin.xml b/runtime/bundles/org.eclipse.core.runtime/plugin.xml index ceaa752beff..cb2a9989b35 100644 --- a/runtime/bundles/org.eclipse.core.runtime/plugin.xml +++ b/runtime/bundles/org.eclipse.core.runtime/plugin.xml @@ -2,4 +2,15 @@ + + + + + + diff --git a/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/InternalPlatform.java b/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/InternalPlatform.java index e4ba969794e..16a767f81a0 100644 --- a/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/InternalPlatform.java +++ b/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/InternalPlatform.java @@ -44,6 +44,7 @@ import org.eclipse.core.runtime.ILogListener; import org.eclipse.core.runtime.IPath; import org.eclipse.core.runtime.IProduct; +import org.eclipse.core.runtime.PerformanceStats; import org.eclipse.core.runtime.Platform; import org.eclipse.core.runtime.Plugin; import org.eclipse.core.runtime.RegistryFactory; @@ -64,6 +65,7 @@ import org.eclipse.osgi.framework.log.FrameworkLog; import org.eclipse.osgi.service.datalocation.Location; import org.eclipse.osgi.service.debug.DebugOptions; +import org.eclipse.osgi.service.debug.DebugOptionsListener; import org.eclipse.osgi.service.environment.EnvironmentInfo; import org.eclipse.osgi.service.resolver.PlatformAdmin; import org.osgi.framework.Bundle; @@ -150,6 +152,7 @@ public final class InternalPlatform { private ServiceRegistration legacyPreferencesService = null; private ServiceRegistration customPreferencesService = null; + private ServiceRegistration debugOptionsListenerService = null; private ServiceTracker environmentTracker = null; private ServiceTracker logTracker = null; @@ -772,9 +775,20 @@ private void startServices() { customPreferencesService = context.registerService(IProductPreferencesService.class, new ProductPreferencesService(), new Hashtable<>()); legacyPreferencesService = context.registerService(ILegacyPreferences.class, new InitLegacyPreferences(), new Hashtable<>()); + + Hashtable debugProperties = new Hashtable<>(2); + debugProperties.put(DebugOptions.LISTENER_SYMBOLICNAME, Platform.PI_RUNTIME); + debugOptionsListenerService = context.registerService(DebugOptionsListener.class, options -> { + initializeDebugFlags(); + PerformanceStats.ENABLED = options.getBooleanOption(Platform.PI_RUNTIME + "/perf", false); //$NON-NLS-1$ + }, debugProperties); } private void stopServices() { + if (debugOptionsListenerService != null) { + debugOptionsListenerService.unregister(); + debugOptionsListenerService = null; + } if (legacyPreferencesService != null) { legacyPreferencesService.unregister(); legacyPreferencesService = null; diff --git a/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/PerformanceStatsProcessor.java b/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/PerformanceStatsProcessor.java index 2b7ccd31297..41f7d1eee5d 100644 --- a/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/PerformanceStatsProcessor.java +++ b/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/internal/runtime/PerformanceStatsProcessor.java @@ -39,10 +39,13 @@ public class PerformanceStatsProcessor extends Job { private final ArrayList changes = new ArrayList<>(); /** - * Event failures that have occurred but have not yet been broadcast. - * Maps (PerformanceStats -> Long). + * Event failures that have occurred but have not yet been broadcast, one + * entry per occurrence. */ - private final HashMap failures = new HashMap<>(); + private record Failure(PerformanceStats stats, long elapsed) { + } + + private final ArrayList failures = new ArrayList<>(); /** * Event listeners. @@ -77,13 +80,16 @@ public static void changed(PerformanceStats stats) { * @param pluginId The id of the plugin that declared the blame object, or * null * @param elapsed The elapsed time for this failure + * @param log Whether to write the failure to the performance log as well */ - public static void failed(PerformanceStats stats, String pluginId, long elapsed) { + public static void failed(PerformanceStats stats, String pluginId, long elapsed, boolean log) { synchronized (instance) { - instance.failures.put(stats, Long.valueOf(elapsed)); + instance.failures.add(new Failure(stats, elapsed)); } instance.schedule(SCHEDULE_DELAY); - instance.logFailure(stats, pluginId, elapsed); + if (log) { + instance.logFailure(stats, pluginId, elapsed); + } } /* @@ -194,13 +200,11 @@ private void logFailure(PerformanceStats stats, String pluginId, long elapsed) { @Override protected IStatus run(IProgressMonitor monitor) { PerformanceStats[] events; - PerformanceStats[] failedEvents; - Long[] failedTimes; + Failure[] failedEvents; synchronized (this) { events = changes.toArray(new PerformanceStats[changes.size()]); changes.clear(); - failedEvents = failures.keySet().toArray(new PerformanceStats[failures.size()]); - failedTimes = failures.values().toArray(new Long[failures.size()]); + failedEvents = failures.toArray(new Failure[failures.size()]); failures.clear(); } @@ -209,8 +213,8 @@ protected IStatus run(IProgressMonitor monitor) { if (events.length > 0) { listener.eventsOccurred(events); } - for (int j = 0; j < failedEvents.length; j++) { - listener.eventFailed(failedEvents[j], failedTimes[j].longValue()); + for (Failure failure : failedEvents) { + listener.eventFailed(failure.stats(), failure.elapsed()); } } schedule(SCHEDULE_DELAY); diff --git a/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/runtime/PerformanceStats.java b/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/runtime/PerformanceStats.java index f3d0eafe39a..603b756e565 100644 --- a/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/runtime/PerformanceStats.java +++ b/runtime/bundles/org.eclipse.core.runtime/src/org/eclipse/core/runtime/PerformanceStats.java @@ -96,9 +96,10 @@ public void eventsOccurred(PerformanceStats[] event) { private static final PerformanceStats EMPTY_STATS = new PerformanceStats("", ""); //$NON-NLS-1$ //$NON-NLS-2$ /** - * Constant indicating whether or not tracing is enabled + * Indicates whether or not tracing is enabled. Follows the + * org.eclipse.core.runtime/perf debug option and changes with it. */ - public static final boolean ENABLED; + public static volatile boolean ENABLED; /** * A constant indicating that the timer has not been started. @@ -111,17 +112,6 @@ public void eventsOccurred(PerformanceStats[] event) { private final static Map statMap = Collections.synchronizedMap(new HashMap<>()); - /** - * Maximum allowed durations for each event. - * Maps String (event name) -> Long (threshold) - */ - private final static Map thresholdMap = Collections.synchronizedMap(new HashMap<>()); - - /** - * Whether non-failure statistics should be retained. - */ - private static final boolean TRACE_SUCCESS; - /** * An identifier that can be used to figure out who caused the event. This is * typically a string representation of the object whose code was running when @@ -170,8 +160,14 @@ public void eventsOccurred(PerformanceStats[] event) { static { ENABLED = InternalPlatform.getDefault().getBooleanOption(Platform.PI_RUNTIME + "/perf", false);//$NON-NLS-1$ - //turn these on by default if the global trace flag is turned on - TRACE_SUCCESS = InternalPlatform.getDefault().getBooleanOption(Platform.PI_RUNTIME + "/perf/success", ENABLED); //$NON-NLS-1$ + } + + /** + * Returns whether non-failure statistics should be retained. On by default + * once the global trace flag is on. + */ + private static boolean isTraceSuccess() { + return InternalPlatform.getDefault().getBooleanOption(Platform.PI_RUNTIME + "/perf/success", ENABLED); //$NON-NLS-1$ } /** @@ -182,9 +178,7 @@ public void eventsOccurred(PerformanceStats[] event) { * @see #removeListener(PerformanceStats.PerformanceListener) */ public static void addListener(PerformanceListener listener) { - if (ENABLED) { - PerformanceStatsProcessor.addListener(listener); - } + PerformanceStatsProcessor.addListener(listener); } /** @@ -222,16 +216,11 @@ public static PerformanceStats getStats(String eventName, Object blameObject) { return EMPTY_STATS; } PerformanceStats newStats = new PerformanceStats(eventName, blameObject); - if (!TRACE_SUCCESS) { + if (!isTraceSuccess()) { return newStats; } //use existing stats object if available - PerformanceStats oldStats = statMap.get(newStats); - if (oldStats != null) { - return oldStats; - } - statMap.put(newStats, newStats); - return newStats; + return statMap.computeIfAbsent(newStats, key -> newStats); } /** @@ -239,8 +228,8 @@ public static PerformanceStats getStats(String eventName, Object blameObject) { *

* For frequent performance events, the result of this method call should * be cached by the caller to minimize overhead when performance monitoring - * is turned off. It is not possible for enablement to change during the life - * of this invocation of the platform. + * is turned off. Enablement follows the platform debug options, so a caller + * that caches the result should refresh it when those options change. *

* * @param eventName The name of the event to determine enablement for @@ -248,7 +237,9 @@ public static PerformanceStats getStats(String eventName, Object blameObject) { * name is enabled, and false otherwise. */ public static boolean isEnabled(String eventName) { - if (!ENABLED) { + // read live rather than through ENABLED, so the answer does not depend on the + // order in which debug options listeners are notified + if (!InternalPlatform.getDefault().getBooleanOption(Platform.PI_RUNTIME + "/perf", false)) { //$NON-NLS-1$ return false; } String option = Platform.getDebugOption(eventName); @@ -287,9 +278,7 @@ public static void printStats(PrintWriter out) { * @see #addListener(PerformanceStats.PerformanceListener) */ public static void removeListener(PerformanceListener listener) { - if (ENABLED) { - PerformanceStatsProcessor.removeListener(listener); - } + PerformanceStatsProcessor.removeListener(listener); } /** @@ -340,12 +329,14 @@ public void addRun(long elapsed, String contextName) { if (!ENABLED) { return; } - runCount++; - runningTime += elapsed; - if (elapsed > getThreshold(event)) { - PerformanceStatsProcessor.failed(createFailureStats(contextName, elapsed), blamePluginId, elapsed); + record(elapsed); + // a threshold of 0 reports every occurrence to listeners without logging it, + // a positive threshold is a maximum that has to be exceeded + long threshold = getThreshold(event); + if (threshold == 0 || elapsed > threshold) { + PerformanceStatsProcessor.failed(createFailureStats(contextName, elapsed), blamePluginId, elapsed, threshold > 0); } - if (TRACE_SUCCESS) { + if (isTraceSuccess()) { PerformanceStatsProcessor.changed(this); } } @@ -358,19 +349,25 @@ public void addRun(long elapsed, String contextName) { * @return The failure stats */ private PerformanceStats createFailureStats(String contextName, long elapsed) { - PerformanceStats failedStat = new PerformanceStats(event, blame, contextName); - PerformanceStats old = statMap.get(failedStat); - if (old == null) { - statMap.put(failedStat, failedStat); - } else { - failedStat = old; - } + PerformanceStats newStats = new PerformanceStats(event, blame, contextName); + PerformanceStats failedStat = statMap.computeIfAbsent(newStats, key -> newStats); failedStat.isFailure = true; - failedStat.runCount++; - failedStat.runningTime += elapsed; + if (failedStat != this) { + // without a context the lookup returns this object, whose run was already recorded + failedStat.record(elapsed); + } return failedStat; } + /** + * Adds an occurrence to the counters. Synchronized because runs of the same + * event may end concurrently. + */ + private synchronized void record(long elapsed) { + runCount++; + runningTime += elapsed; + } + /** * Stops timing the occurrence of this event that was started by the previous * call to startRun. The event is automatically added to @@ -462,22 +459,15 @@ public long getRunningTime() { * Returns the performance threshold for this event. */ private long getThreshold(String eventName) { - Long value = thresholdMap.get(eventName); - if (value == null) { - String option = InternalPlatform.getDefault().getOption(eventName); - if (option != null) { - try { - value = Long.valueOf(option); - } catch (NumberFormatException e) { - //invalid option, just ignore - } - } - if (value == null) { - value = Long.valueOf(Long.MAX_VALUE); + String option = InternalPlatform.getDefault().getOption(eventName); + if (option != null) { + try { + return Long.parseLong(option.trim()); + } catch (NumberFormatException e) { + //invalid option, just ignore } - thresholdMap.put(eventName, value); } - return value.longValue(); + return Long.MAX_VALUE; } @Override @@ -503,7 +493,7 @@ public boolean isFailure() { /** * Resets count and running time for this particular stats event. */ - public void reset() { + public synchronized void reset() { runningTime = 0; runCount = 0; }