diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/AreaRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/AreaRenderer.java index b1e032b4375..f3154422892 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/AreaRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/AreaRenderer.java @@ -225,6 +225,7 @@ private void ensureComposite(MArea areaModel, List stacks) { } private void synchCTFState(MArea areaModel) { + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; List stacks = findDirectStacks(areaModel); int count = 0; for (MPartStack stack : stacks) { @@ -239,6 +240,10 @@ private void synchCTFState(MArea areaModel) { } else { ensureComposite(areaModel, stacks); } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H12_AREA_SYNCH_CTF, _t0, + "stacks=" + stacks.size() + " rendered=" + count); //$NON-NLS-1$ //$NON-NLS-2$ + } } private List findDirectStacks(MPartSashContainer root) { diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRenderer.java index 397a6d0199f..b468dfab177 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRenderer.java @@ -1142,6 +1142,9 @@ private void unlinkMenu(MMenu menu) { } private void scheduleManagerUpdate(IContributionManager mgr) { + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.count(RendererPerfTracer.H06_MENU_SCHEDULE_UPDATE, mgr.getClass().getSimpleName()); + } // Bug 467000: Avoid repeatedly updating menu managers // This workaround is opt-in for 4.5 boolean workaroundEnabled = Boolean.getBoolean("eclipse.workaround.bug467000"); //$NON-NLS-1$ diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRendererFilter.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRendererFilter.java index 8b7459008a9..75b9a336868 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRendererFilter.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/MenuManagerRendererFilter.java @@ -160,6 +160,8 @@ public static void updateElementVisibility(final MMenu menuModel, MenuManagerRenderer renderer, MenuManager menuManager, final IEclipseContext evalContext, final int recurseLevel, boolean updateEnablement) { + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; + int contextCreationCount = 0; final ExpressionContext exprContext = new ExpressionContext(evalContext); HashSet records = new HashSet<>(); for (MMenuElement element : menuModel.getChildren()) { @@ -187,6 +189,7 @@ public static void updateElementVisibility(final MMenu menuModel, EHandlerService handlerService = evalContext .get(EHandlerService.class); if (cmd != null && handlerService != null) { + contextCreationCount++; final IEclipseContext staticContext = EclipseContextFactory .create(MMRF_STATIC_CONTEXT); ContributionsAnalyzer.populateModelInterfaces(item, @@ -206,6 +209,7 @@ public static void updateElementVisibility(final MMenu menuModel, ((MItem) element).setEnabled(ici.isEnabled()); } } else if (updateEnablement && element instanceof MDirectMenuItem contrib) { + contextCreationCount++; if (contrib.getObject() == null) { IContributionFactory icf = evalContext .get(IContributionFactory.class); @@ -234,6 +238,10 @@ public static void updateElementVisibility(final MMenu menuModel, } } } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H07_MENU_CONTEXT_PER_ITEM, _t0, + "children=" + menuModel.getChildren().size() + " ctxCreated=" + contextCreationCount); //$NON-NLS-1$ //$NON-NLS-2$ + } } private void cleanUp(final Menu menu) { diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/PerspectiveStackRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/PerspectiveStackRenderer.java index f6d17c75c51..66490509960 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/PerspectiveStackRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/PerspectiveStackRenderer.java @@ -102,10 +102,15 @@ protected void showTab(MUIElement tabElement) { // Move any other controls to 'limbo' Control[] kids = psComp.getChildren(); Shell limbo = (Shell) context.get("limbo"); //$NON-NLS-1$ + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; for (Control child : kids) { if (child != ctrl) { child.setParent(limbo); } } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H11_LIMBO_REPARENT, _t0, + "children=" + kids.length); //$NON-NLS-1$ + } } } diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/RendererPerfTracer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/RendererPerfTracer.java new file mode 100644 index 00000000000..8abd9ea3b45 --- /dev/null +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/RendererPerfTracer.java @@ -0,0 +1,273 @@ +/******************************************************************************* + * Copyright (c) 2026 Contributors to the Eclipse Foundation + * + * 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 + *******************************************************************************/ +package org.eclipse.e4.ui.workbench.renderers.swt; + +import java.io.BufferedWriter; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.nio.file.StandardOpenOption; +import java.util.ArrayList; +import java.util.Collections; +import java.util.Comparator; +import java.util.List; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentLinkedQueue; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; + +/** + * Lightweight performance tracer for renderer hotspots. + *

+ * Output file defaults to {@code $HOME/renderer-perf-trace.csv} and can be + * overridden with {@code -Declipse.renderer.perf.trace.file=}. A + * companion summary file is written next to the CSV with suffix + * {@code .summary.txt} when the JVM shuts down. + *

+ * The CSV format is: + * {@code timestamp_ms,hotspot_id,duration_ns,detail} + *

+ * Trace records are queued lock-free on the producer side and drained by a + * single daemon flusher thread every 500 ms. The flusher holds one open + * {@link BufferedWriter} for the lifetime of the JVM; a shutdown hook drains + * the queue, writes the summary, and closes the writer so the last events + * are not lost. + */ +public final class RendererPerfTracer { + + /** Master switch. Always enabled in this debug build. */ + public static final boolean ENABLED = true; + + // Hotspot IDs matching the items in docs/performance.md. + // H08 is intentionally unused: an earlier draft reserved it for a + // ContentProvider hotspot that turned out to be negligible during analysis. + public static final String H01_FIND_ACTIVE_ELEMENTS = "H01_findActiveElements"; //$NON-NLS-1$ + public static final String H02_FIND_PLACEHOLDERS_LABEL = "H02_findPlaceholders_label"; //$NON-NLS-1$ + public static final String H02_FIND_PLACEHOLDERS_ITEM = "H02_findPlaceholders_item"; //$NON-NLS-1$ + public static final String H03_TOOLBAR_UPDATE_WIDGET = "H03_toolbar_updateWidget"; //$NON-NLS-1$ + public static final String H04_DIRTY_ALL_SELECTOR = "H04_dirty_allSelector"; //$NON-NLS-1$ + public static final String H05_TOOL_ITEM_UPDATER = "H05_toolItemUpdater"; //$NON-NLS-1$ + public static final String H06_MENU_SCHEDULE_UPDATE = "H06_menu_scheduleUpdate"; //$NON-NLS-1$ + public static final String H07_MENU_CONTEXT_PER_ITEM = "H07_menu_contextPerItem"; //$NON-NLS-1$ + public static final String H09_WBW_FIND_STACKS = "H09_wbw_findStacks"; //$NON-NLS-1$ + public static final String H10A_SHOWTAB_LAZY = "H10a_showTab_lazyCreate"; //$NON-NLS-1$ + public static final String H10B_SHOWTAB_REPARENT = "H10b_showTab_reparent"; //$NON-NLS-1$ + public static final String H11_LIMBO_REPARENT = "H11_limbo_reparent"; //$NON-NLS-1$ + public static final String H12_AREA_SYNCH_CTF = "H12_area_synchCTF"; //$NON-NLS-1$ + public static final String H13_TOOLCTRL_STARTUP_SCAN = "H13_toolCtrl_startupScan"; //$NON-NLS-1$ + public static final String H14_RAT_UNCOALESCED = "H14_runAndTrack_uncoalesced"; //$NON-NLS-1$ + public static final String W1_SASH_SYNC_LAYOUT = "W1_sash_syncLayout_win"; //$NON-NLS-1$ + + private static final ConcurrentLinkedQueue QUEUE = new ConcurrentLinkedQueue<>(); + private static final Map STATS = new ConcurrentHashMap<>(); + private static final Path OUTPUT_FILE; + private static final Path SUMMARY_FILE; + private static final long START_TIME = System.nanoTime(); + private static final Object WRITER_LOCK = new Object(); + private static final BufferedWriter WRITER; + private static final ScheduledExecutorService FLUSHER; + + static { + String fileProp = System.getProperty("eclipse.renderer.perf.trace.file"); //$NON-NLS-1$ + if (fileProp != null) { + OUTPUT_FILE = Path.of(fileProp); + } else { + OUTPUT_FILE = Path.of(System.getProperty("user.home"), "renderer-perf-trace.csv"); //$NON-NLS-1$ //$NON-NLS-2$ + } + SUMMARY_FILE = Path.of(OUTPUT_FILE.toString() + ".summary.txt"); //$NON-NLS-1$ + BufferedWriter writer = null; + if (ENABLED) { + try { + writer = Files.newBufferedWriter(OUTPUT_FILE, + StandardOpenOption.CREATE, + StandardOpenOption.TRUNCATE_EXISTING); + writer.write("timestamp_ms,hotspot_id,duration_ns,detail\n"); //$NON-NLS-1$ + writer.flush(); + } catch (IOException e) { + System.err.println("RendererPerfTracer: failed to open " + OUTPUT_FILE + ": " + e); //$NON-NLS-1$ //$NON-NLS-2$ + writer = null; + } + } + WRITER = writer; + + FLUSHER = Executors.newSingleThreadScheduledExecutor(r -> { + Thread t = new Thread(r, "RendererPerfTracer-Flusher"); //$NON-NLS-1$ + t.setDaemon(true); + return t; + }); + if (ENABLED && WRITER != null) { + FLUSHER.scheduleWithFixedDelay(RendererPerfTracer::flush, 500, 500, TimeUnit.MILLISECONDS); + Runtime.getRuntime().addShutdownHook( + new Thread(RendererPerfTracer::shutdown, "RendererPerfTracer-Shutdown")); //$NON-NLS-1$ + } + } + + private RendererPerfTracer() { + } + + /** Capture start time. Call this at the beginning of the hotspot. */ + public static long begin() { + return System.nanoTime(); + } + + /** + * Record a trace event. + * + * @param hotspotId one of the H* or W* constants + * @param startNano value returned by {@link #begin()} + * @param detail short context string (e.g., element count, class name). + * May be {@code null}. + */ + public static void trace(String hotspotId, long startNano, String detail) { + long durationNs = System.nanoTime() - startNano; + long elapsedMs = (System.nanoTime() - START_TIME) / 1_000_000L; + String line = elapsedMs + "," + hotspotId + "," + durationNs + "," //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ + + (detail != null ? detail : "") + "\n"; //$NON-NLS-1$ //$NON-NLS-2$ + QUEUE.add(line); + STATS.computeIfAbsent(hotspotId, k -> new HotspotStats()).recordTimed(durationNs); + } + + /** + * Record a count-only event (no duration). + * + * @param hotspotId one of the H* or W* constants + * @param detail short context string + */ + public static void count(String hotspotId, String detail) { + long elapsedMs = (System.nanoTime() - START_TIME) / 1_000_000L; + String line = elapsedMs + "," + hotspotId + ",0," //$NON-NLS-1$ //$NON-NLS-2$ + + (detail != null ? detail : "") + "\n"; //$NON-NLS-1$ //$NON-NLS-2$ + QUEUE.add(line); + STATS.computeIfAbsent(hotspotId, k -> new HotspotStats()).recordCountOnly(); + } + + private static void flush() { + synchronized (WRITER_LOCK) { + if (WRITER == null) { + return; + } + try { + String line; + while ((line = QUEUE.poll()) != null) { + WRITER.write(line); + } + WRITER.flush(); + } catch (IOException e) { + // Silently drop. Tracing must not break the workbench. + } + } + } + + private static void shutdown() { + FLUSHER.shutdown(); + try { + FLUSHER.awaitTermination(1, TimeUnit.SECONDS); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + flush(); + writeSummary(); + synchronized (WRITER_LOCK) { + if (WRITER != null) { + try { + WRITER.close(); + } catch (IOException e) { + // ignore + } + } + } + } + + private static void writeSummary() { + long elapsedMs = (System.nanoTime() - START_TIME) / 1_000_000L; + double elapsedMin = elapsedMs / 60_000.0; + List> entries = new ArrayList<>(STATS.entrySet()); + entries.sort(Comparator.>comparingLong( + e -> e.getValue().totalNanos.get()).reversed()); + + StringBuilder sb = new StringBuilder(4096); + sb.append("Renderer Performance Trace Summary\n"); //$NON-NLS-1$ + sb.append("==================================\n\n"); //$NON-NLS-1$ + sb.append(String.format("Session duration: %.2f s%n", elapsedMs / 1000.0)); //$NON-NLS-1$ + long totalEvents = entries.stream().mapToLong(e -> e.getValue().count.get()).sum(); + sb.append(String.format("Total events: %d%n%n", totalEvents)); //$NON-NLS-1$ + + sb.append(String.format("%-36s %8s %10s %10s %10s %10s%n", //$NON-NLS-1$ + "Hotspot", "Count", "Calls/min", "Total ms", "Max ms", "P95 ms")); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$ //$NON-NLS-5$ //$NON-NLS-6$ + sb.append(String.format("%-36s %8s %10s %10s %10s %10s%n", //$NON-NLS-1$ + "-------", "-----", "---------", "--------", "------", "------")); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$ //$NON-NLS-5$ //$NON-NLS-6$ + for (Map.Entry e : entries) { + HotspotStats s = e.getValue(); + long count = s.count.get(); + double callsPerMin = elapsedMin > 0 ? count / elapsedMin : 0; + if (s.isCountOnly()) { + sb.append(String.format("%-36s %8d %10.1f %10s %10s %10s%n", //$NON-NLS-1$ + e.getKey(), count, callsPerMin, "-", "-", "-")); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ + } else { + double totalMs = s.totalNanos.get() / 1_000_000.0; + double maxMs = s.maxNanos.get() / 1_000_000.0; + double p95Ms = s.percentileNanos(95) / 1_000_000.0; + sb.append(String.format("%-36s %8d %10.1f %10.2f %10.2f %10.2f%n", //$NON-NLS-1$ + e.getKey(), count, callsPerMin, totalMs, maxMs, p95Ms)); + } + } + try { + Files.writeString(SUMMARY_FILE, sb.toString(), + StandardOpenOption.CREATE, StandardOpenOption.TRUNCATE_EXISTING); + } catch (IOException e) { + System.err.println("RendererPerfTracer: failed to write " + SUMMARY_FILE + ": " + e); //$NON-NLS-1$ //$NON-NLS-2$ + } + } + + private static final class HotspotStats { + final AtomicLong count = new AtomicLong(); + final AtomicLong totalNanos = new AtomicLong(); + final AtomicLong maxNanos = new AtomicLong(); + final List durationsNanos = Collections.synchronizedList(new ArrayList<>()); + + void recordTimed(long nanos) { + count.incrementAndGet(); + totalNanos.addAndGet(nanos); + maxNanos.accumulateAndGet(nanos, Math::max); + durationsNanos.add(nanos); + } + + void recordCountOnly() { + count.incrementAndGet(); + } + + boolean isCountOnly() { + return durationsNanos.isEmpty() && count.get() > 0; + } + + long percentileNanos(int percentile) { + List snapshot; + synchronized (durationsNanos) { + if (durationsNanos.isEmpty()) { + return 0; + } + snapshot = new ArrayList<>(durationsNanos); + } + Collections.sort(snapshot); + int idx = (int) Math.ceil(percentile / 100.0 * snapshot.size()) - 1; + if (idx < 0) { + idx = 0; + } + if (idx >= snapshot.size()) { + idx = snapshot.size() - 1; + } + return snapshot.get(idx); + } + } +} diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/SashRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/SashRenderer.java index ac2dddbe35d..eca9ff4f026 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/SashRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/SashRenderer.java @@ -84,7 +84,11 @@ protected void forceLayout(MElementContainer pscModel) { return; } } + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; s.layout(true, true); + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.W1_SASH_SYNC_LAYOUT, _t0, null); + } } else { s.requestLayout(); } diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/StackRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/StackRenderer.java index 8eb9c4494d9..2d865fdcae6 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/StackRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/StackRenderer.java @@ -477,7 +477,12 @@ void subscribeTopicUILabelChanged(@UIEventTopic(UIEvents.UILabel.TOPIC_ALL) Even // Do we have any stacks with place holders for the element // that's changed? MWindow win = modelService.getTopLevelWindowFor(part); + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; List refs = modelService.findElements(win, null, MPlaceholder.class, null); + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H02_FIND_PLACEHOLDERS_LABEL, _t0, + "refs=" + (refs != null ? refs.size() : 0)); //$NON-NLS-1$ + } if (refs != null) { for (MPlaceholder ref : refs) { if (ref.getRef() != part) { @@ -656,8 +661,13 @@ void subscribeTopicActivateChanged(@UIEventTopic(UIEvents.UILifeCycle.ACTIVATE) MPartStack pStack = (MPartStack) (partParent instanceof MPartStack ? partParent : null); + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; List activeElements = modelService.findElements(modelService.getTopLevelWindowFor(newActivePart), null, MUIElement.class, singletonList(CSSConstants.CSS_ACTIVE_CLASS)); + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H01_FIND_ACTIVE_ELEMENTS, _t0, + "found=" + activeElements.size()); //$NON-NLS-1$ + } for (MUIElement element : activeElements) { if (element instanceof MPartStack && element != pStack) { styleElement(element, false); @@ -1146,7 +1156,12 @@ public CTabItem findItemForPart(MPart part) { return null; } + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; List refs = modelService.findElements(win, null, MPlaceholder.class); + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H02_FIND_PLACEHOLDERS_ITEM, _t0, + "refs=" + (refs != null ? refs.size() : 0)); //$NON-NLS-1$ + } if (refs != null) { for (MPlaceholder ref : refs) { if (ref.getRef() != part) { @@ -1471,6 +1486,7 @@ private boolean closePart(Widget widget) { @Override protected void showTab(MUIElement element) { + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; super.showTab(element); // an invisible element won't have the correct widget hierarchy @@ -1485,10 +1501,11 @@ protected void showTab(MUIElement element) { tabItem = findItemForPart(element, element.getParent()); } Control ctrl = (Control) element.getWidget(); + boolean lazyCreate = (ctrl == null); if (ctrl != null && ctrl.getParent() != tabFolder) { ctrl.setParent(tabFolder); tabItem.setControl(ctrl); - } else if (element.getWidget() == null) { + } else if (lazyCreate) { Control tabCtrl = (Control) renderer.createGui(element); tabItem.setControl(tabCtrl); } @@ -1506,6 +1523,10 @@ protected void showTab(MUIElement element) { // Show the new state adjustTopRight(tabFolder); + if (RendererPerfTracer.ENABLED) { + String id = lazyCreate ? RendererPerfTracer.H10A_SHOWTAB_LAZY : RendererPerfTracer.H10B_SHOWTAB_REPARENT; + RendererPerfTracer.trace(id, _t0, element.getClass().getSimpleName()); + } } protected void showMenu(ToolItem item) { diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolBarManagerRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolBarManagerRenderer.java index a6b71cabbb7..9d6764a6b83 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolBarManagerRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolBarManagerRenderer.java @@ -295,6 +295,9 @@ private void subscribeTopicUpdateChildren(@UIEventTopic(ElementContainer.TOPIC_C @Optional private void subscribeTopicDirtyChanged( @SuppressWarnings("unused") @UIEventTopic(UIEvents.Dirtyable.TOPIC_DIRTY) Event eventData) { + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.count(RendererPerfTracer.H04_DIRTY_ALL_SELECTOR, null); + } getUpdater().updateContributionItems(ALL_SELECTOR); } @@ -515,6 +518,10 @@ public boolean changed(IEclipseContext context) { return false; } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.count(RendererPerfTracer.H14_RAT_UNCOALESCED, + toolbarModel.getElementId()); + } record.updateVisibility(parentContext.getActiveLeaf()); runExternalCode(() -> { updateToolbar(toolbarModel, manager); @@ -733,11 +740,15 @@ private void updateToolbar(final MToolBar toolbarModel, final ToolBarManager man } private void updateWidget(ToolBarManager manager) { + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; manager.update(true); ToolBar toolbar = manager.getControl(); if (toolbar != null && !toolbar.isDisposed()) { toolbar.requestLayout(); } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H03_TOOLBAR_UPDATE_WIDGET, _t0, null); + } } @Override diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolControlRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolControlRenderer.java index 60d9528e2a0..21a8fe114c4 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolControlRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolControlRenderer.java @@ -218,6 +218,7 @@ private void subscribeTopicTagsChanged( @Optional private void subscribeTopicAppStartup( @SuppressWarnings("unused") @UIEventTopic(UIEvents.UILifeCycle.APP_STARTUP_COMPLETE) Event event) { + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; List toolControls = modelService.findElements( application, null, MToolControl.class, null); for (MToolControl toolControl : toolControls) { @@ -226,6 +227,10 @@ private void subscribeTopicAppStartup( toolControl.setVisible(false); } } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H13_TOOLCTRL_STARTUP_SCAN, _t0, + "found=" + toolControls.size()); //$NON-NLS-1$ + } } private void createToolControlMenu(final MToolControl toolControl, diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolItemUpdater.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolItemUpdater.java index 9f888cb2f46..f794167bda9 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolItemUpdater.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/ToolItemUpdater.java @@ -47,11 +47,14 @@ void removeItem(AbstractContributionItem item) { } public void updateContributionItems(Selector selector) { + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; boolean doRunNow = false; + int matchCount = 0; for (final AbstractContributionItem ci : itemsToCheck) { if (ci.getModel() != null && ci.getModel().getParent() != null) { if (selector.select(ci.getModel())) { itemsToUpdateLater.add(ci); + matchCount++; if (timestampOfEarliestQueuedUpdate == 0) { timestampOfEarliestQueuedUpdate = System.nanoTime(); } @@ -76,6 +79,10 @@ public void updateContributionItems(Selector selector) { if (doRunNow) { run(); } + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H05_TOOL_ITEM_UPDATER, _t0, + "total=" + itemsToCheck.size() + " matched=" + matchCount); //$NON-NLS-1$ //$NON-NLS-2$ + } } @Override diff --git a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/WBWRenderer.java b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/WBWRenderer.java index c47c15ea4ff..25010dadf0f 100644 --- a/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/WBWRenderer.java +++ b/bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/WBWRenderer.java @@ -591,8 +591,14 @@ private void updateNonFocusState(int event, MWindow win) { return; } + long _t0 = RendererPerfTracer.ENABLED ? RendererPerfTracer.begin() : 0; List stacks = modelService.findElements(perspective, null, MPartStack.class, singletonList(CSSConstants.CSS_ACTIVE_CLASS)); + if (RendererPerfTracer.ENABLED) { + RendererPerfTracer.trace(RendererPerfTracer.H09_WBW_FIND_STACKS, _t0, + "event=" + (event == SWT.Activate ? "Activate" : "Deactivate") //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ + + " found=" + stacks.size()); //$NON-NLS-1$ + } if (stacks.isEmpty()) { return; } diff --git a/docs/performance.md b/docs/performance.md new file mode 100644 index 00000000000..5d2aa313d6a --- /dev/null +++ b/docs/performance.md @@ -0,0 +1,260 @@ +# Renderer Performance Improvements + +This document catalogs performance opportunities discovered in the +`org.eclipse.e4.ui.workbench.renderers.swt` bundle, ranked by measured impact +from IDE sessions recorded with the `RendererPerfTracer` instrumentation on the +branch `wip-adding-performance-trace-code`. + +## Methodology + +Trace data is collected by the always-on `RendererPerfTracer` utility compiled +into the bundle on this branch. Each instrumented hotspot writes a CSV row +(`timestamp_ms, hotspot_id, duration_ns, detail`) to +`$HOME/renderer-perf-trace.csv`. On JVM shutdown the tracer also writes a +companion `renderer-perf-trace.csv.summary.txt` file with count, total ms, +max ms, p95 ms, and calls/min per hotspot, aggregated deterministically at the +source (no external script, no LLM summarization step). + +All numbers in this document should be produced from that summary file or +directly from the CSV. + +### Environment + +Fill these in when publishing new trace results so sessions are comparable: + +- Eclipse build (commit sha of `eclipse.platform.ui` branch) +- JDK version and vendor +- Operating system and version +- Display resolution and scale factor +- Workload description (what was opened, switched, resized, saved) +- Whether the first N seconds after startup are included or excluded + +### Cold start vs steady state + +The first few seconds after startup dominate several hotspots (H10, H13, +initial H12) and should be reported separately from steady-state interaction +so that the ranking does not conflate one-off startup cost with recurring +overhead. A simple convention: split the trace at the first user-initiated +event, or at a fixed boundary such as 10 s. + +## Trace Sessions + +| Property | Session 1 (baseline) | Session 2 (2026-04-16) | +|-----------------------|---------------------:|------------------------:| +| Duration | ~120 s | 92.23 s | +| Trace events | 1,286 | 1,808 | +| Total hotspot time | ~2,170 ms | 2,824 ms | +| Cold start separated? | No | No | + +Session 1 and Session 2 pre-date the new summary pipeline. Both were +summarized by an external language model, and at least one anomaly +(an inflated H09 total relative to per-call averages) is visible in the raw +numbers. Future sessions should use the tracer's own `summary.txt` output. + +## Measurement Summary + +Sorted by Session 2 total time descending. Session 1 values in parentheses +for comparison. + +| Rank | Hotspot | Count | Total ms | Max ms | P95 ms | Verdict | +|------|---------------------------------------------|----------:|--------------:|--------------:|-------:|------------------------------------| +| 1 | H10 `showTab` (now split into H10a lazy / H10b reparent) | 8 (9) | **1,817** (1,566) | 1,209 (977) | 901 | Tail dominated by H10a cold first-show; `setRedraw` fix tried and reverted | +| 2 | H07 per-item context creation in menu show | 403 (227)| **954** (568) | 373 (262) | 1.2 | Top unfixed priority (see caveat) | +| 3 | H03 unbatched `updateWidget` / `requestLayout` | 155 (115)| **25** (16) | 6.3 (3.1) | 0.76 | Low per call; new 6 ms spike | +| 4 | H05 `ToolItemUpdater` linear scan | 309 (238)| **22** (17) | 3.3 (3.4) | 0.09 | Low; 12 items | +| 5 | H09 `findElements` on window activate/deactivate | 9 (54) | **1.9**\* (1.1) | 0.15 (0.14) | 0.04 | Negligible | +| 6 | H01 `findElements` for active CSS class | 19 (30) | **1.5** (2.4) | 0.23 (0.24) | 0.19 | Negligible | +| 7 | H02 `findElements` for placeholders | 22+2 (21) | **1.5+0.3** (1.9) | 0.24 (0.23) | 0.09 | Negligible | +| 8 | H06 unbatched `scheduleManagerUpdate` | 753 (537)| 0 (count only)| n/a | n/a | Fix (753 fires in 92 s, 490/min) | +| 9 | H14 uncoalesced `RunAndTrack` callbacks | 39 (51) | 0 (count only)| n/a | n/a | Low volume | +| 10 | H04 dirty-flag `ALL_SELECTOR` update | not reported in sessions 1/2 | count only | n/a | n/a | Add to next session's summary | +| 11 | H13 full model scan at startup | 1 (1) | 0.15 (0.2) | 0.15 (0.17) | n/a | One-time | +| 12 | H12 `synchCTFState` recursive walk | 2 (2) | 0.11 (0.1) | 0.10 (0.1) | n/a | Negligible | +| 13 | H11 limbo reparenting | 1 (1) | 0.09 (0.2) | 0.09 (0.2) | n/a | Single event | + +\* H09 total is inconsistent with per-call averages in the raw CSV. Suspected +language-model summarization artifact; individual calls remain sub-ms. This +is one of the reasons the next session should use the tracer's built-in +summary. + +**Key finding (unchanged):** H10 and H07 account for roughly 98 percent of all +measured renderer overhead in these two sessions (64 percent and 34 percent +respectively). The `findElements` tree scans (H01, H02, H09) remain fast in +practice at current model sizes. + +### Notable ranking changes from Session 1 + +- H07 moved closer to H10. Total time rose 68 percent (568 ms to 954 ms) with + call count nearly doubling (227 to 403), consistent with heavier menu + interaction in Session 2. With the H10 `setRedraw` fix ruled out, H07 is + now the top actionable hotspot. +- H03 showed a new 6 ms spike (up from 3.1 ms max). Still a low total (25 ms) + but worth monitoring; could indicate layout cascading when multiple toolbar + items update in quick succession. +- H06 frequency rose from 537 calls in ~120 s (268/min) to 753 calls in 92 s + (490/min). The zero-duration measurement confirms these are trigger-only + probes, but the rising cadence reinforces the case for enabling batching. +- H09 count dropped sharply (54 to 9) because Session 2 involved fewer window + activate and deactivate cycles. Time remains negligible. + +### High-frequency hotspots (more than 100 calls per minute) + +| Hotspot | Calls/min (Session 2) | Calls/min (Session 1) | +|-------------------------------|----------------------:|----------------------:| +| H06 `scheduleManagerUpdate` | 490 | 268 | +| H07 menu `contextPerItem` | 262 | 113 | +| H05 `toolItemUpdater` | 201 | 119 | +| H03 `updateWidget` | 101 | 58 | + +H06 is zero-duration (trigger probe) but its 490 calls per minute means 490 +synchronous `mgr.update(false)` walks per minute when batching is off. + +--- + +## Fix Status + +### H10: `showTab` `setRedraw` batching (abandoned) + +A candidate fix on `wip-fix-showTab-setRedraw-batching` wrapped the `showTab` +body in `setRedraw(false)` and `setRedraw(true)` on the target `CTabFolder`. +It was merged into an aggregator build and measured. Result: **the fix did +not help and was reverted**. + +| Metric | No fix | Always batch | Reparent-only batch | +|-------------------|-------:|-------------:|--------------------:| +| Avg ms per call | 24.6 | 34.0 | 54.2 | +| P95 ms | 124 | 99 | 137 | +| Max ms | 695 | 1,087 | 1,462 | + +Why it did not work: the tail in every recorded session (max 695 ms to +1,462 ms, P95 98 ms to 137 ms) is dominated by one or two very expensive +calls per session. Those calls happen on the **lazy-create path** inside +`showTab`, where `renderer.createGui(element)` constructs a new editor or +view and its initial layout. `setRedraw(true)` on exit forces that paint to +happen synchronously inside the method, which inflates worst-case time +rather than reducing it. On the reparent path (switching to an already +rendered tab) the common case is already in the single-digit ms range, so +there is no meaningful time for batching to eliminate. + +### Revised instrumentation (this branch) + +Because the lazy-create path and the reparent path have different cost +profiles and different causes, H10 has been split into two probes: + +- `H10a_showTab_lazyCreate`: `showTab` calls where `element.getWidget()` + is null and `renderer.createGui` is invoked. Expect a long right-tail + governed by editor/view construction cost. +- `H10b_showTab_reparent`: `showTab` calls where the widget already + exists and is being reparented or reselected. Expect low single-digit ms + and stable P95. + +Next session should report the two probes separately. `H10a` is not +actionable via `setRedraw` batching. `H10b` is the one to watch if we want +evidence that batching might help steady-state switching (though the +measurements so far suggest it does not). + +--- + +## Priority 1: per-item Eclipse context creation during menu show (H07) + +**954 ms total; 34 percent of all hotspot time (up from 26 percent).** + +**Location:** `MenuManagerRendererFilter.updateVisibility(...)` (private +helper invoked from the public `updateElementVisibility` entry point). + +`updateVisibility` fired 403 times in 92 seconds. The method iterates over +`menuModel.getChildren()` and for each `MHandledMenuItem` or `MDirectMenuItem` +performs work that includes creating and disposing an `IEclipseContext`. + +**Top 5 slowest H07 events (Session 2):** + +| Elapsed (ms) | Duration (ms) | Detail | +|-------------:|--------------:|-------------------------------| +| 2,803 | 373 | children=18, ctxCreated=0 | +| 2,800 | 367 | children=18, ctxCreated=0 | +| 19,057 | 63 | children=30, ctxCreated=2 | +| 19,049 | 49 | children=48, ctxCreated=0 | +| 19,043 | 24 | children=12, ctxCreated=0 | + +**Caveat on the previously recommended fix.** An earlier draft of this +document proposed a shared scratch `IEclipseContext` reused across iterations, +based on the assumption that per-item context allocation dominated. The two +worst recorded calls (373 ms and 367 ms) both show `ctxCreated=0`, meaning +no contexts were created on that path. Allocation is therefore **not** the +dominant cost for the tail, and the scratch-context refactor is not +guaranteed to help. The actual hot code on the `ctxCreated=0` path is the +enablement evaluation loop around `ContributionsAnalyzer.populateModelInterfaces`, +the expression evaluation via `ExpressionContext`, and the handler service +lookups for each child. Root cause needs attribution (e.g., JFR or async +profiler) before committing to a fix shape. + +--- + +## Priority 2: unbatched `scheduleManagerUpdate` (H06) + +**753 calls in 92 s (490/min); count-only, not time-measured.** + +**Location:** `MenuManagerRenderer.scheduleManagerUpdate(IContributionManager)`. + +The batching mechanism introduced for bug 467000 is disabled by default via +the system property `eclipse.workaround.bug467000`. Without it, each call +performs an immediate `mgr.update(false)`, walking and reconciling the widget +tree synchronously. Frequency rose 83 percent between sessions. + +**Recommendation:** enable batching unconditionally and remove the system +property guard. This is both a local fix (H06 in this doc) and a workaround +for an unresolved SWT gap (see "Cross-platform batching gaps" below). + +--- + +## Lower Priority Items + +### `updateWidget` / `requestLayout` (H03) + +25 ms total across 155 calls. Average remains low (about 162 us) but max +jumped from 3.1 ms to 6.3 ms. The new spike warrants investigation; likely a +layout cascade when multiple toolbar items update in quick succession. + +### `ToolItemUpdater` linear scan (H05) + +22 ms total across 309 calls. Still only 12 toolbar items registered. +Numbers track linearly with session activity. Switching the backing +collection to `LinkedHashSet` is a preventive measure, not a current +bottleneck. + +### `findElements` tree scans (H01, H02, H09) + +All three combined: 5.2 ms across 52 calls (down from 5.4 ms across 103 +calls). Remain negligible at current model sizes. + +--- + +## Cross-platform batching gaps + +### Menu manager batching guarded by bug-467000 system property (H06 / W2) + +**Location:** `MenuManagerRenderer.scheduleManagerUpdate(IContributionManager)`. +**Eclipse Bug:** [467000](https://bugs.eclipse.org/bugs/show_bug.cgi?id=467000) + +SWT `Menu` does not support deferred or coalesced updates, forcing each +`MenuManager.update(false)` to immediately reconcile the widget tree (753 +times in Session 2, up from 537). + +**What SWT should fix:** provide a built-in batching mechanism for menu +updates. + +## Platform-Specific SWT Workarounds + +### W-1. Synchronous `layout(true, true)` on Windows in `SashRenderer` + +**Location:** `SashRenderer.forceLayout(...)`. +**SWT Bug:** [558392](https://bugs.eclipse.org/bugs/show_bug.cgi?id=558392) + +On Windows, `forceLayout()` uses `sashForm.layout(true, true)`, a +synchronous, recursive full layout, instead of the asynchronous +`requestLayout()` used on other platforms. Not triggered in either Linux +trace session, but expected to be the dominant hotspot on Windows based on +code analysis. + +**What SWT should fix:** `Composite.requestLayout()` must correctly schedule +a deferred layout on Windows.