From fb155075cbc666903334695d17203e829edac8c1 Mon Sep 17 00:00:00 2001 From: Lars Vogel Date: Mon, 18 May 2026 15:45:37 +0200 Subject: [PATCH] Add opt-in startup and renderer performance tracing Three layers of tracing emit CSV summaries on JVM shutdown, so we can measure where Workbench startup, renderer execution, and runtime UI events actually spend time. StartupTrace (opt-in via -Declipse.startup.trace=true) reuses the shared StartupTrace from org.eclipse.core.internal.runtime so workbench and platform bundles share one ~/.eclipse/startup-trace.csv and one runId. Instrumentation points cover Workbench.init phases, E4 application bootstrap, ResourceHandler, ModelAssembler, IDEApplication.start, and the first-touch of context functions in WorkbenchPlugin (PerspectiveRegistry, ViewRegistry, ActionSetRegistry, IntroRegistry, PreferenceManager, ThemeRegistry, WorkingSetManager, WorkingSetRegistry, EditorRegistry). With the property unset the cost is one static-final boolean read per call site. The same StartupTrace channel also captures runtime UI hotspots: - DisplayEventProbe installs SWT.PreEvent/SWT.PostEvent listeners on the workbench Display and records any event whose dispatch exceeds 16 ms, keyed by SWT event type (Paint, Selection, MouseDown, etc.). - WorkbenchLabelProvider.getText/getImage are bracketed so cumulative label-provider cost shows up per viewer refresh. - AbstractCSSEngine.applyStyles records the outermost call (depth counter avoids inflating the CSV with every recursive child). RendererPerfTracer is always active in this debug build and writes to ~/renderer-perf-trace.csv (configurable via -Declipse.renderer.perf.trace.file=). It covers 14 hotspots across AreaRenderer, MenuManagerRenderer, MenuManagerRendererFilter, PerspectiveStackRenderer, SashRenderer, StackRenderer, ToolBarManagerRenderer, ToolControlRenderer, ToolItemUpdater, and WBWRenderer, with a persistent writer, shutdown hook, and daemon flusher. The H10 showTab probe is split into separate lazy-create and reparent paths. docs/performance.md documents both tracers, the captured trace sessions, and the analysis approach. Not intended for upstream merge; depends on vogella/eclipse.platform#4 for org.eclipse.core.internal.runtime.StartupTrace. --- .../core/impl/engine/AbstractCSSEngine.java | 15 + .../workbench/renderers/swt/AreaRenderer.java | 5 + .../renderers/swt/MenuManagerRenderer.java | 3 + .../swt/MenuManagerRendererFilter.java | 8 + .../swt/PerspectiveStackRenderer.java | 5 + .../renderers/swt/RendererPerfTracer.java | 273 ++++++++++++++++++ .../workbench/renderers/swt/SashRenderer.java | 4 + .../renderers/swt/StackRenderer.java | 23 +- .../renderers/swt/ToolBarManagerRenderer.java | 11 + .../renderers/swt/ToolControlRenderer.java | 5 + .../renderers/swt/ToolItemUpdater.java | 7 + .../workbench/renderers/swt/WBWRenderer.java | 6 + .../internal/workbench/swt/E4Application.java | 87 +++++- .../ui/internal/workbench/ModelAssembler.java | 7 + .../internal/workbench/ResourceHandler.java | 23 +- .../ide/application/IDEApplication.java | 121 ++++---- .../org/eclipse/ui/internal/Workbench.java | 100 ++++++- .../eclipse/ui/internal/WorkbenchPlugin.java | 10 +- .../ui/internal/misc/DisplayEventProbe.java | 97 +++++++ .../ui/internal/registry/EditorRegistry.java | 5 + .../ui/internal/registry/ViewRegistry.java | 5 + .../ui/model/WorkbenchLabelProvider.java | 50 ++-- docs/performance.md | 260 +++++++++++++++++ 23 files changed, 1041 insertions(+), 89 deletions(-) create mode 100644 bundles/org.eclipse.e4.ui.workbench.renderers.swt/src/org/eclipse/e4/ui/workbench/renderers/swt/RendererPerfTracer.java create mode 100644 bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/misc/DisplayEventProbe.java create mode 100644 docs/performance.md diff --git a/bundles/org.eclipse.e4.ui.css.core/src/org/eclipse/e4/ui/css/core/impl/engine/AbstractCSSEngine.java b/bundles/org.eclipse.e4.ui.css.core/src/org/eclipse/e4/ui/css/core/impl/engine/AbstractCSSEngine.java index 61a74c087b3..116417b2f38 100644 --- a/bundles/org.eclipse.e4.ui.css.core/src/org/eclipse/e4/ui/css/core/impl/engine/AbstractCSSEngine.java +++ b/bundles/org.eclipse.e4.ui.css.core/src/org/eclipse/e4/ui/css/core/impl/engine/AbstractCSSEngine.java @@ -369,8 +369,23 @@ public void applyStyles(Object element, boolean applyStylesToChildNodes) { applyStyles(element, applyStylesToChildNodes, computeDefaultStyle); } + private int applyStylesDepth; + @Override public void applyStyles(Object element, boolean applyStylesToChildNodes, boolean computeDefaultStyle) { + long traceStart = applyStylesDepth == 0 ? org.eclipse.core.internal.runtime.StartupTrace.begin() : 0L; + applyStylesDepth++; + try { + applyStylesImpl(element, applyStylesToChildNodes, computeDefaultStyle); + } finally { + applyStylesDepth--; + if (applyStylesDepth == 0) { + org.eclipse.core.internal.runtime.StartupTrace.record("CSSEngine.applyStyles", traceStart); //$NON-NLS-1$ + } + } + } + + private void applyStylesImpl(Object element, boolean applyStylesToChildNodes, boolean computeDefaultStyle) { Element elt = getElement(element); if (elt == null || !isVisible(elt)) { return; 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/bundles/org.eclipse.e4.ui.workbench.swt/src/org/eclipse/e4/ui/internal/workbench/swt/E4Application.java b/bundles/org.eclipse.e4.ui.workbench.swt/src/org/eclipse/e4/ui/internal/workbench/swt/E4Application.java index e544e7744b9..87c12ef4462 100644 --- a/bundles/org.eclipse.e4.ui.workbench.swt/src/org/eclipse/e4/ui/internal/workbench/swt/E4Application.java +++ b/bundles/org.eclipse.e4.ui.workbench.swt/src/org/eclipse/e4/ui/internal/workbench/swt/E4Application.java @@ -64,6 +64,7 @@ import org.eclipse.e4.ui.internal.workbench.ResourceHandler; import org.eclipse.e4.ui.internal.workbench.SelectionAggregator; import org.eclipse.e4.ui.internal.workbench.SelectionServiceImpl; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.e4.ui.internal.workbench.URIHelper; import org.eclipse.e4.ui.internal.workbench.WorkbenchLogger; import org.eclipse.e4.ui.model.application.MAddon; @@ -140,6 +141,7 @@ public Display getApplicationDisplay() { @Override public Object start(IApplicationContext applicationContext) throws Exception { + long tStart = StartupTrace.begin(); // set the display name before the Display is // created to ensure the app name is used in any // platform menus, etc. See @@ -148,7 +150,9 @@ public Object start(IApplicationContext applicationContext) throws Exception { if (product != null && product.getName() != null) { Display.setAppName(product.getName()); } + long tDisp = StartupTrace.begin(); Display display = getApplicationDisplay(); + StartupTrace.record("E4Application.start/getApplicationDisplay", tDisp); //$NON-NLS-1$ Location instanceLocation = null; try { E4Workbench workbench = createE4Workbench(applicationContext, display); @@ -160,11 +164,15 @@ public Object start(IApplicationContext applicationContext) throws Exception { // place it off so it's not visible shell.setLocation(0, 10000); } - if (!checkInstanceLocation(instanceLocation, shell, workbench.getContext())) { + long tCheck = StartupTrace.begin(); + boolean ok = checkInstanceLocation(instanceLocation, shell, workbench.getContext()); + StartupTrace.record("E4Application.start/checkInstanceLocation", tCheck); //$NON-NLS-1$ + if (!ok) { return EXIT_OK; } // Create and run the UI (if any) + StartupTrace.record("E4Application.start (pre-createAndRunUI)", tStart); //$NON-NLS-1$ workbench.createAndRunUI(workbench.getApplication()); saveModel(); @@ -210,9 +218,12 @@ public void saveModel() { } public E4Workbench createE4Workbench(IApplicationContext applicationContext, final Display display) { + long tTotal = StartupTrace.begin(); args = (String[]) applicationContext.getArguments().get(IApplicationContext.APPLICATION_ARGS); + long tCtx = StartupTrace.begin(); IEclipseContext appContext = createDefaultContext(); + StartupTrace.record("E4Application.createE4Workbench/createDefaultContext", tCtx); //$NON-NLS-1$ appContext.set(Display.class, display); appContext.set(Realm.class, DisplayRealm.getRealm(display)); appContext.set(UISynchronize.class, new DisplayUISynchronize(display)); @@ -227,6 +238,7 @@ public E4Workbench createE4Workbench(IApplicationContext applicationContext, fin // Install the life-cycle manager for this session if there's one // defined + long tLc = StartupTrace.begin(); Optional lifeCycleURI = getArgValue(IWorkbench.LIFE_CYCLE_URI_ARG, applicationContext, false); lifeCycleURI.ifPresent(lifeCycleURIValue -> { lcManager = factory.create(lifeCycleURIValue, appContext); @@ -235,6 +247,7 @@ public E4Workbench createE4Workbench(IApplicationContext applicationContext, fin ContextInjectionFactory.invoke(lcManager, PostContextCreate.class, appContext, null); } }); + StartupTrace.record("E4Application.createE4Workbench/lifecycle manager (PostContextCreate)", tLc); //$NON-NLS-1$ Optional forcedPerspectiveId = getArgValue(PERSPECTIVE_ARG_NAME, applicationContext, false); forcedPerspectiveId.ifPresent(forcedPerspectiveIdValue -> appContext.set(E4Workbench.FORCED_PERSPECTIVE_ID, @@ -246,7 +259,9 @@ public E4Workbench createE4Workbench(IApplicationContext applicationContext, fin } // Create the app model and its context + long tModel = StartupTrace.begin(); MApplication appModel = loadApplicationModel(applicationContext, appContext); + StartupTrace.record("E4Application.createE4Workbench/loadApplicationModel", tModel); //$NON-NLS-1$ appModel.setContext(appContext); boolean isRtl = ((Window.getDefaultOrientation() & SWT.RIGHT_TO_LEFT) != 0); @@ -263,21 +278,34 @@ public E4Workbench createE4Workbench(IApplicationContext applicationContext, fin appContext.set(MApplication.class, appModel); // adds basic services to the contexts + long tSvc = StartupTrace.begin(); initializeServices(appModel); + StartupTrace.record("E4Application.createE4Workbench/initializeServices", tSvc); //$NON-NLS-1$ // let the life cycle manager add to the model if (lcManager != null) { + long tLc2 = StartupTrace.begin(); ContextInjectionFactory.invoke(lcManager, ProcessAdditions.class, appContext, null); ContextInjectionFactory.invoke(lcManager, ProcessRemovals.class, appContext, null); + StartupTrace.record("E4Application.createE4Workbench/lifecycle ProcessAdditions+Removals", tLc2); //$NON-NLS-1$ } // Create the addons + long tAddons = StartupTrace.begin(); + long tQuery = StartupTrace.begin(); IEclipseContext addonStaticContext = EclipseContextFactory.create(); - for (MAddon addon : appModel.getAddons()) { + List addons = appModel.getAddons(); + StartupTrace.record("create addons/query extension registry", tQuery); //$NON-NLS-1$ + long tInstantiate = StartupTrace.begin(); + int addonCount = 0; + for (MAddon addon : addons) { addonStaticContext.set(MAddon.class, addon); Object obj = factory.create(addon.getContributionURI(), appContext, addonStaticContext); addon.setObject(obj); + addonCount++; } + StartupTrace.record("create addons/instantiate addons (count=" + addonCount + ")", tInstantiate); //$NON-NLS-1$ //$NON-NLS-2$ + StartupTrace.record("E4Application.createE4Workbench/create addons", tAddons); //$NON-NLS-1$ // Parse out parameters from both the command line and/or the product // definition (if any) and put them in the context @@ -287,7 +315,9 @@ public E4Workbench createE4Workbench(IApplicationContext applicationContext, fin }); + long tCss = StartupTrace.begin(); setCSSContextVariables(applicationContext, appContext); + StartupTrace.record("E4Application.createE4Workbench/setCSSContextVariables", tCss); //$NON-NLS-1$ Optional rendererFactoryURI = getArgValue(E4Workbench.RENDERER_FACTORY_URI, applicationContext, false); rendererFactoryURI.ifPresent(rendererFactoryURIValue -> { @@ -300,7 +330,11 @@ public E4Workbench createE4Workbench(IApplicationContext applicationContext, fin // Instantiate the Workbench (which is responsible for // 'running' the UI (if any)... - return workbench = new E4Workbench(appModel, appContext); + long tCtor = StartupTrace.begin(); + E4Workbench wb = new E4Workbench(appModel, appContext); + StartupTrace.record("E4Application.createE4Workbench/new E4Workbench(ctor)", tCtor); //$NON-NLS-1$ + StartupTrace.record("E4Application.createE4Workbench (total)", tTotal); //$NON-NLS-1$ + return workbench = wb; } private void setCSSContextVariables(IApplicationContext applicationContext, IEclipseContext context) { @@ -378,10 +412,14 @@ private MApplication loadApplicationModel(IApplicationContext appContext, IEclip IContributionFactory factory = eclipseContext.get(IContributionFactory.class); + long tHandler = StartupTrace.begin(); handler = (IModelResourceHandler) factory.create(resourceHandler, eclipseContext); + StartupTrace.record("loadApplicationModel/create IModelResourceHandler", tHandler); //$NON-NLS-1$ eclipseContext.set(IModelResourceHandler.class, handler); + long tLoad = StartupTrace.begin(); Resource resource = handler.loadMostRecentModel(); + StartupTrace.record("loadApplicationModel/handler.loadMostRecentModel (XMI parse)", tLoad); //$NON-NLS-1$ return (MApplication) resource.getContents().get(0); } @@ -509,21 +547,37 @@ public void stop() { // TODO This should go into a different bundle public static IEclipseContext createDefaultHeadlessContext() { + long tCreate = StartupTrace.begin(); IEclipseContext serviceContext = E4Workbench.getServiceContext(); + StartupTrace.record("createDefaultContext/EclipseContextFactory.create", tCreate); //$NON-NLS-1$ + long tCore = StartupTrace.begin(); + long coreCifNs = 0L; + int coreCifCount = 0; IExtensionRegistry registry = RegistryFactory.getRegistry(); ExceptionHandler exceptionHandler = new ExceptionHandler(); serviceContext.set(IContributionFactory.class, new ReflectionContributionFactory()); serviceContext.set(IExceptionHandler.class, exceptionHandler); serviceContext.set(IExtensionRegistry.class, registry); - serviceContext.set(Adapter.class, ContextInjectionFactory.make(EclipseAdapter.class, serviceContext)); + long tCif1 = StartupTrace.begin(); + EclipseAdapter adapter = ContextInjectionFactory.make(EclipseAdapter.class, serviceContext); + coreCifNs += System.nanoTime() - tCif1; + coreCifCount++; + serviceContext.set(Adapter.class, adapter); // No default log provider available if (serviceContext.get(ILoggerProvider.class) == null) { - serviceContext.set(ILoggerProvider.class, - ContextInjectionFactory.make(DefaultLoggerProvider.class, serviceContext)); + long tCif2 = StartupTrace.begin(); + DefaultLoggerProvider loggerProvider = ContextInjectionFactory.make(DefaultLoggerProvider.class, serviceContext); + coreCifNs += System.nanoTime() - tCif2; + coreCifCount++; + serviceContext.set(ILoggerProvider.class, loggerProvider); } + StartupTrace.record( + "createDefaultContext/register core services/ContextInjectionFactory.make (count=" + coreCifCount + ")", //$NON-NLS-1$ //$NON-NLS-2$ + System.nanoTime() - coreCifNs); + StartupTrace.record("createDefaultContext/register core services", tCore); //$NON-NLS-1$ return serviceContext; } @@ -532,12 +586,25 @@ public static IEclipseContext createDefaultHeadlessContext() { public static IEclipseContext createDefaultContext() { IEclipseContext serviceContext = createDefaultHeadlessContext(); + + long tUi = StartupTrace.begin(); + long uiCifNs = 0L; + int uiCifCount = 0; final IEclipseContext appContext = serviceContext.createChild("WorkbenchContext"); //$NON-NLS-1$ // make application context available for dependency injection under the E4Application.APPLICATION_CONTEXT_KEY key appContext.set(IWorkbench.APPLICATION_CONTEXT_KEY, appContext); - appContext.set(Logger.class, ContextInjectionFactory.make(WorkbenchLogger.class, appContext)); - appContext.set(EModelService.class, ContextInjectionFactory.make(ModelServiceImpl.class, appContext)); + long tCif3 = StartupTrace.begin(); + WorkbenchLogger logger = ContextInjectionFactory.make(WorkbenchLogger.class, appContext); + uiCifNs += System.nanoTime() - tCif3; + uiCifCount++; + appContext.set(Logger.class, logger); + + long tCif4 = StartupTrace.begin(); + ModelServiceImpl modelService = ContextInjectionFactory.make(ModelServiceImpl.class, appContext); + uiCifNs += System.nanoTime() - tCif4; + uiCifCount++; + appContext.set(EModelService.class, modelService); appContext.set(EPlaceholderResolver.class, new PlaceholderResolver()); // setup for commands and handlers @@ -571,6 +638,10 @@ public void setClassnameAndId(Object widget, String classname, String id) { // translation initializeLocalization(appContext); + StartupTrace.record( + "createDefaultContext/register UI services/ContextInjectionFactory.make (count=" + uiCifCount + ")", //$NON-NLS-1$ //$NON-NLS-2$ + System.nanoTime() - uiCifNs); + StartupTrace.record("createDefaultContext/register UI services", tUi); //$NON-NLS-1$ return appContext; } diff --git a/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ModelAssembler.java b/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ModelAssembler.java index 581e1243588..a7928583b53 100644 --- a/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ModelAssembler.java +++ b/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ModelAssembler.java @@ -41,6 +41,7 @@ import java.util.concurrent.atomic.AtomicReference; import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.core.runtime.IConfigurationElement; import org.eclipse.core.runtime.IExtension; import org.eclipse.core.runtime.IExtensionPoint; @@ -314,11 +315,17 @@ public void processModel(boolean initial) { IExtension[] extensions = new ExtensionsSort().sort(extPoint.getExtensions()); // run processors which are marked to run before fragments + long tProcBefore = StartupTrace.begin(); runProcessors(extensions, initial, false); + StartupTrace.record("handler.loadMostRecentModel/processor.process", tProcBefore); //$NON-NLS-1$ // process fragments (and resolve imports) + long tFrag = StartupTrace.begin(); processFragments(extensions, initial); + StartupTrace.record("handler.loadMostRecentModel/fragments.process", tFrag); //$NON-NLS-1$ // run processors which are marked to run after fragments + long tProcAfter = StartupTrace.begin(); runProcessors(extensions, initial, true); + StartupTrace.record("handler.loadMostRecentModel/processor.process", tProcAfter); //$NON-NLS-1$ } // once we are done, any further handling in the tracker can't be initial diff --git a/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ResourceHandler.java b/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ResourceHandler.java index e763473da1f..7ec02987848 100644 --- a/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ResourceHandler.java +++ b/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/ResourceHandler.java @@ -31,6 +31,7 @@ import java.util.Collections; import java.util.HashMap; import java.util.Map; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.core.runtime.URIUtil; import org.eclipse.e4.core.contexts.ContextInjectionFactory; import org.eclipse.e4.core.contexts.IEclipseContext; @@ -139,6 +140,7 @@ private boolean hasTopLevelWindows(Resource applicationResource) { @Override public Resource loadMostRecentModel() { + long tResolve = StartupTrace.begin(); File workbenchData = null; URI restoreLocation = null; @@ -160,10 +162,13 @@ public Resource loadMostRecentModel() { // boolean restore = restoreLastModified > lastApplicationModification; boolean restore = restoreLastModified > 0; boolean initialModel; + StartupTrace.record("handler.loadMostRecentModel/resolve applicationXMI URI", tResolve); //$NON-NLS-1$ resource = null; if (restore && saveAndRestore) { - resource = loadResource(restoreLocation); + long tDeltas = StartupTrace.begin(); + resource = loadResource(restoreLocation, "handler.loadMostRecentModel/merge deltas"); //$NON-NLS-1$ + StartupTrace.record("handler.loadMostRecentModel/merge deltas (if persisted state exists)", tDeltas); //$NON-NLS-1$ // If the saved model does not have any top-level windows, Eclipse will exit // immediately, so throw out the persisted state and reinitialize with the defaults. if (!hasTopLevelWindows(resource)) { @@ -175,7 +180,9 @@ public Resource loadMostRecentModel() { } } if (resource == null) { - Resource applicationResource = loadResource(applicationDefinitionInstance); + long tLoad = StartupTrace.begin(); + Resource applicationResource = loadResource(applicationDefinitionInstance, null); + StartupTrace.record("handler.loadMostRecentModel/load default model (XMIResource.load)", tLoad); //$NON-NLS-1$ MApplication theApp = (MApplication) applicationResource.getContents().get(0); resource = createResourceWithApp(theApp); context.set(E4Workbench.NO_SAVED_MODEL_FOUND, Boolean.TRUE); @@ -257,10 +264,14 @@ private File getBaseLocation() { } // Ensures that even models with error are loaded! - private Resource loadResource(URI uri) { + private Resource loadResource(URI uri, String tracePhasePrefix) { Resource resource; try { + long tLoad = StartupTrace.begin(); resource = getResource(uri); + if (tracePhasePrefix != null) { + StartupTrace.record(tracePhasePrefix + "/load delta resource", tLoad); //$NON-NLS-1$ + } } catch (Exception e) { // TODO We could use diagnostics for better analyzing the error logger.error(e, "Unable to load resource " + uri); //$NON-NLS-1$ @@ -270,13 +281,19 @@ private Resource loadResource(URI uri) { // TODO once we switch from deltas, we only need this once on the default model? String contributorURI = URIHelper.EMFtoPlatform(uri); if (contributorURI != null) { + long tApply = StartupTrace.begin(); + int count = 0; TreeIterator it = EcoreUtil.getAllContents(resource.getContents()); while (it.hasNext()) { EObject o = it.next(); if (o instanceof MApplicationElement) { ((MApplicationElement) o).setContributorURI(contributorURI); + count++; } } + if (tracePhasePrefix != null) { + StartupTrace.record(tracePhasePrefix + "/apply delta (count=" + count + ")", tApply); //$NON-NLS-1$ //$NON-NLS-2$ + } } return resource; } diff --git a/bundles/org.eclipse.ui.ide.application/src/org/eclipse/ui/internal/ide/application/IDEApplication.java b/bundles/org.eclipse.ui.ide.application/src/org/eclipse/ui/internal/ide/application/IDEApplication.java index 77bb2dbda2c..8caeadf235c 100644 --- a/bundles/org.eclipse.ui.ide.application/src/org/eclipse/ui/internal/ide/application/IDEApplication.java +++ b/bundles/org.eclipse.ui.ide.application/src/org/eclipse/ui/internal/ide/application/IDEApplication.java @@ -34,6 +34,7 @@ import java.util.Map; import java.util.Properties; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.core.runtime.IConfigurationElement; import org.eclipse.core.runtime.IExecutableExtension; import org.eclipse.core.runtime.IProduct; @@ -148,68 +149,77 @@ public IDEApplication() { @Override public Object start(IApplicationContext appContext) throws Exception { - // Suspend the job manager to prevent background jobs from running. This - // is done to reduce resource contention during startup. - // The job manager will be resumed by the - // IDEWorkbenchAdvisor.postStartup method. - Job.getJobManager().suspend(); + long tStart = StartupTrace.begin(); + try { + // Suspend the job manager to prevent background jobs from running. This + // is done to reduce resource contention during startup. + // The job manager will be resumed by the + // IDEWorkbenchAdvisor.postStartup method. + Job.getJobManager().suspend(); - Display display = createDisplay(); + Display display = createDisplay(); - initializeDefaultTheme(display); + long tProduct = StartupTrace.begin(); + initializeDefaultTheme(display); - // processor must be created before we start event loop - DelayedEventsProcessor processor = new DelayedEventsProcessor(display); + // processor must be created before we start event loop + DelayedEventsProcessor processor = new DelayedEventsProcessor(display); - try { + try { - // look and see if there's a splash shell we can parent off of - Shell shell = WorkbenchPlugin.getSplashShell(display); - if (shell != null) { - // should should set the icon and message for this shell to be the - // same as the chooser dialog - this will be the guy that lives in - // the task bar and without these calls you'd have the default icon - // with no message. - shell.setText(ChooseWorkspaceDialog.getWindowTitle()); - shell.setImages(Window.getDefaultImages()); - } + // look and see if there's a splash shell we can parent off of + Shell shell = WorkbenchPlugin.getSplashShell(display); + if (shell != null) { + // should should set the icon and message for this shell to be the + // same as the chooser dialog - this will be the guy that lives in + // the task bar and without these calls you'd have the default icon + // with no message. + shell.setText(ChooseWorkspaceDialog.getWindowTitle()); + shell.setImages(Window.getDefaultImages()); + } + StartupTrace.record("IDEApplication.start/initializeProduct", tProduct); //$NON-NLS-1$ + + long tCheck = StartupTrace.begin(); + Object instanceLocationCheck = checkInstanceLocation(shell, appContext.getArguments()); + StartupTrace.record("IDEApplication.start/checkInstanceLocation", tCheck); //$NON-NLS-1$ + if (instanceLocationCheck != null) { + WorkbenchPlugin.unsetSplashShell(display); + return instanceLocationCheck; + } - Object instanceLocationCheck = checkInstanceLocation(shell, appContext.getArguments()); - if (instanceLocationCheck != null) { - WorkbenchPlugin.unsetSplashShell(display); - return instanceLocationCheck; - } + // Reset early dark theme styling before the workbench starts; + // the ThemeEngine will apply the correct theme from here on. + resetEarlyDarkTheme(display); + + // create the workbench with this advisor and run it until it exits + // N.B. createWorkbench remembers the advisor, and also registers + // the workbench globally so that all UI plug-ins can find it using + // PlatformUI.getWorkbench() or AbstractUIPlugin.getWorkbench() + int returnCode = PlatformUI.createAndRunWorkbench(display, + new IDEWorkbenchAdvisor(processor)); + + // the workbench doesn't support relaunch yet (bug 61809) so + // for now restart is used, and exit data properties are checked + // here to substitute in the relaunch return code if needed + if (returnCode != PlatformUI.RETURN_RESTART) { + return EXIT_OK; + } - // Reset early dark theme styling before the workbench starts; - // the ThemeEngine will apply the correct theme from here on. - resetEarlyDarkTheme(display); - - // create the workbench with this advisor and run it until it exits - // N.B. createWorkbench remembers the advisor, and also registers - // the workbench globally so that all UI plug-ins can find it using - // PlatformUI.getWorkbench() or AbstractUIPlugin.getWorkbench() - int returnCode = PlatformUI.createAndRunWorkbench(display, - new IDEWorkbenchAdvisor(processor)); - - // the workbench doesn't support relaunch yet (bug 61809) so - // for now restart is used, and exit data properties are checked - // here to substitute in the relaunch return code if needed - if (returnCode != PlatformUI.RETURN_RESTART) { - return EXIT_OK; + // if the exit code property has been set to the relaunch code, then + // return that code now, otherwise this is a normal restart + return EXIT_RELAUNCH.equals(Integer.getInteger(Workbench.PROP_EXIT_CODE)) ? EXIT_RELAUNCH + : EXIT_RESTART; + } finally { + if (display != null) { + display.dispose(); + } + Location instanceLoc = Platform.getInstanceLocation(); + if (instanceLoc != null) { + instanceLoc.release(); + } } - - // if the exit code property has been set to the relaunch code, then - // return that code now, otherwise this is a normal restart - return EXIT_RELAUNCH.equals(Integer.getInteger(Workbench.PROP_EXIT_CODE)) ? EXIT_RELAUNCH - : EXIT_RESTART; } finally { - if (display != null) { - display.dispose(); - } - Location instanceLoc = Platform.getInstanceLocation(); - if (instanceLoc != null) { - instanceLoc.release(); - } + StartupTrace.record("IDEApplication.start (total)", tStart); //$NON-NLS-1$ } } @@ -532,6 +542,8 @@ private static boolean isDevLaunchMode(Map args) { */ private URL promptForWorkspace(Shell shell, ChooseWorkspaceData launchData, boolean force) { + long tPrompt = StartupTrace.begin(); + try { URL url = null; do { @@ -586,6 +598,9 @@ private URL promptForWorkspace(Shell shell, ChooseWorkspaceData launchData, } return url; } while (true); + } finally { + StartupTrace.record("IDEApplication.start/promptForWorkspace", tPrompt); //$NON-NLS-1$ + } } /** diff --git a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/Workbench.java b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/Workbench.java index 71910c2c7b1..593aa3e5d56 100644 --- a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/Workbench.java +++ b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/Workbench.java @@ -226,6 +226,7 @@ import org.eclipse.ui.internal.menus.WorkbenchMenuService; import org.eclipse.ui.internal.misc.Policy; import org.eclipse.ui.internal.misc.StatusUtil; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.ui.internal.misc.UIStats; import org.eclipse.ui.internal.model.ContributionService; import org.eclipse.ui.internal.progress.ProgressManager; @@ -579,6 +580,7 @@ public static Workbench getInstance() { * IWorkbench.restart}; other values reserved for future use */ public static int createAndRunWorkbench(final Display display, final WorkbenchAdvisor advisor) { + long tOuter = StartupTrace.begin(); final int[] returnCode = new int[1]; Realm.runWithDefault(DisplayRealm.getRealm(display), () -> { boolean showProgress = PrefUtil.getAPIPreferenceStore() @@ -592,7 +594,9 @@ public static int createAndRunWorkbench(final Display display, final WorkbenchAd System.setProperty(org.eclipse.e4.ui.workbench.IWorkbench.XMI_URI_ARG, "org.eclipse.ui.workbench/LegacyIDE.e4xmi"); //$NON-NLS-1$ + long tGetApp = StartupTrace.begin(); Object obj = getApplication(Platform.getCommandLineArgs()); + StartupTrace.record("createAndRunWorkbench/getApplication", tGetApp); //$NON-NLS-1$ IPreferenceStore store = WorkbenchPlugin.getDefault().getPreferenceStore(); if (!store.isDefault(IPreferenceConstants.LAYOUT_DIRECTION)) { @@ -600,13 +604,17 @@ public static int createAndRunWorkbench(final Display display, final WorkbenchAd Window.setDefaultOrientation(orientation); } if (obj instanceof E4Application e4app) { + long tE4Wb = StartupTrace.begin(); E4Workbench e4Workbench = e4app.createE4Workbench(getApplicationContext(), display); + StartupTrace.record("createAndRunWorkbench/E4Application.createE4Workbench", tE4Wb); //$NON-NLS-1$ MApplication appModel = e4Workbench.getApplication(); IEclipseContext context = e4Workbench.getContext(); // create the workbench instance + long tCtor = StartupTrace.begin(); Workbench workbench = new Workbench(display, advisor, appModel, context); + StartupTrace.record("createAndRunWorkbench/new Workbench(ctor)", tCtor); //$NON-NLS-1$ Dictionary properties = new Hashtable<>(); properties.put(Constants.SERVICE_RANKING, Integer.valueOf(Integer.MAX_VALUE - 1)); @@ -667,7 +675,9 @@ public void update() { setSearchContribution(appModel, true); // run the legacy workbench once + long tRunUI = StartupTrace.begin(); returnCode[0] = workbench.runUI(); + StartupTrace.record("createAndRunWorkbench/workbench.runUI", tRunUI); //$NON-NLS-1$ if (AUTOSCALE_ADAPTATION.isMonitorSpecificScalingDisabledForIncompatibility()) { display.asyncExec(() -> { @@ -681,6 +691,8 @@ public void update() { if (serviceListener.get() != null) { WorkbenchPlugin.getDefault().getBundleContext().removeServiceListener(serviceListener.get()); } + StartupTrace.mark("startup.complete (marker)"); //$NON-NLS-1$ + scheduleStartupTraceAutoExit(display); e4Workbench.createAndRunUI(e4Workbench.getApplication()); } if (returnCode[0] != PlatformUI.RETURN_UNSTARTABLE) { @@ -698,9 +710,38 @@ public void update() { } } }); + StartupTrace.record("createAndRunWorkbench (outer total)", tOuter); //$NON-NLS-1$ return returnCode[0]; } + /** + * If the {@code startup.trace.autoExitSeconds} system property is set to a + * positive integer, schedule a graceful workbench close after that many + * seconds. Used for unattended batch collection of startup traces; no-op + * if the property is unset or invalid. + */ + private static void scheduleStartupTraceAutoExit(Display display) { + String raw = System.getProperty("startup.trace.autoExitSeconds"); //$NON-NLS-1$ + if (raw == null) { + return; + } + int seconds; + try { + seconds = Integer.parseInt(raw.trim()); + } catch (NumberFormatException ignored) { + return; + } + if (seconds <= 0) { + return; + } + display.timerExec(seconds * 1000, () -> { + if (!PlatformUI.getWorkbench().isClosing()) { + PlatformUI.getWorkbench().close(); + } + }); + System.err.println("[StartupTrace] auto-exit scheduled in " + seconds + "s"); //$NON-NLS-1$ //$NON-NLS-2$ + } + private static void setSearchContribution(MApplication app, boolean enabled) { for (MTrimContribution contribution : app.getTrimContributions()) { if ("org.eclipse.ui.ide.application.trimcontribution.QuickAccess".contains(contribution //$NON-NLS-1$ @@ -760,6 +801,7 @@ static Object getApplication(@SuppressWarnings("unused") String[] args) { * @return the display */ public static Display createDisplay() { + long tTotal = StartupTrace.begin(); // setup the application name used by SWT to lookup resources on some platforms String applicationName = System.getProperty("eclipse.appName", WorkbenchPlugin.getDefault().getAppName()); //$NON-NLS-1$ if (applicationName != null) { @@ -769,6 +811,7 @@ public static Display createDisplay() { AUTOSCALE_ADAPTATION.setRescaleAtRuntimePropertyFromPreference(); // create the display + long tNew = StartupTrace.begin(); Display newDisplay = Display.getCurrent(); if (newDisplay == null) { if (Policy.DEBUG_SWT_GRAPHICS || Policy.DEBUG_SWT_DEBUG) { @@ -784,6 +827,9 @@ public static Display createDisplay() { newDisplay = new Display(); } } + StartupTrace.record("Workbench.createDisplay/new Display", tNew); //$NON-NLS-1$ + + org.eclipse.ui.internal.misc.DisplayEventProbe.install(newDisplay); // workaround for 1GEZ9UR and 1GF07HN newDisplay.setWarnings(false); @@ -792,8 +838,11 @@ public static Display createDisplay() { // than the JobManager. Thread.currentThread().setPriority(Math.min(Thread.MAX_PRIORITY, Thread.NORM_PRIORITY + 1)); + long tImg = StartupTrace.begin(); initializeImages(); + StartupTrace.record("Workbench.createDisplay/initializeImages (window icons)", tImg); //$NON-NLS-1$ + StartupTrace.record("Workbench.createDisplay (total)", tTotal); //$NON-NLS-1$ return newDisplay; } @@ -1724,6 +1773,7 @@ public ILocalWorkingSetManager createLocalWorkingSetManager() { * @return true if init succeeded. */ private boolean init() { + long tInit = StartupTrace.begin(); // setup debug mode if required. if (WorkbenchPlugin.getDefault().isDebugging()) { WorkbenchPlugin.DEBUG = true; @@ -1751,7 +1801,9 @@ public void runWithException() { // Initialize the activity support. + long t = StartupTrace.begin(); activityHelper = ActivityPersistanceHelper.getInstance(); + StartupTrace.record("Workbench.init/ActivityPersistanceHelper.getInstance", t); //$NON-NLS-1$ StartupThreading.runWithoutExceptions(new StartupRunnable() { @Override @@ -1767,8 +1819,12 @@ public void runWithException() { introDescriptor = (IntroDescriptor) introRegistry.getIntroForProduct(product.getId()); } } + t = StartupTrace.begin(); initializeDefaultServices(); + StartupTrace.record("Workbench.init/initializeDefaultServices", t); //$NON-NLS-1$ + t = StartupTrace.begin(); initializeFonts(); + StartupTrace.record("Workbench.init/initializeFonts", t); //$NON-NLS-1$ initializeApplicationColors(); // now that the workbench is sufficiently initialized, let the advisor @@ -1777,7 +1833,9 @@ public void runWithException() { @Override public void runWithException() { + long t2 = StartupTrace.begin(); advisor.internalBasicInitialize(getWorkbenchConfigurer()); + StartupTrace.record("Workbench.init/advisor.internalBasicInitialize", t2); //$NON-NLS-1$ } }); @@ -1804,26 +1862,36 @@ public void runWithException() { // attempt to restore a previous workbench state try { UIStats.start(UIStats.RESTORE_WORKBENCH, "Workbench"); //$NON-NLS-1$ + long tRestore = StartupTrace.begin(); final boolean bail[] = new boolean[1]; StartupThreading.runWithoutExceptions(new StartupRunnable() { @Override public void runWithException() throws Throwable { + long t2 = StartupTrace.begin(); advisor.preStartup(); + StartupTrace.record("Workbench.init/advisor.preStartup", t2); //$NON-NLS-1$ // TODO compat: open the windows here/instantiate the model // TODO compat: instantiate the WW around the model initializationDone = true; - if (isClosing() || !advisor.openWindows()) { - // if (isClosing()) { + if (isClosing()) { bail[0] = true; + } else { + if (!advisor.openWindows()) { + bail[0] = true; + } } + long t4 = StartupTrace.begin(); restoreWorkbenchState(); + StartupTrace.record("Workbench.init/restoreWorkbenchState", t4); //$NON-NLS-1$ } }); + StartupTrace.record("Workbench.init/restore+openWindows (total)", tRestore); //$NON-NLS-1$ if (bail[0]) { + StartupTrace.record("Workbench.init (total, bailed)", tInit); //$NON-NLS-1$ return false; } @@ -1831,6 +1899,7 @@ public void runWithException() throws Throwable { UIStats.end(UIStats.RESTORE_WORKBENCH, this, "Workbench"); //$NON-NLS-1$ } + StartupTrace.record("Workbench.init (total)", tInit); //$NON-NLS-1$ return true; } @@ -2333,8 +2402,10 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); Command.DEBUG_COMMAND_EXECUTION = Policy.DEBUG_COMMANDS; commandManager = e4Context.get(CommandManager.class); + StartupTrace.record("initializeDefaultServices/commandManager", t); //$NON-NLS-1$ } }); @@ -2343,8 +2414,9 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); commandService[0] = initializeCommandService(e4Context); - + StartupTrace.record("initializeDefaultServices/initializeCommandService", t); //$NON-NLS-1$ } }); @@ -2352,12 +2424,16 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); ContextManager.DEBUG = Policy.DEBUG_CONTEXTS; contextManager = e4Context.get(ContextManager.class); + StartupTrace.record("initializeDefaultServices/contextManager", t); //$NON-NLS-1$ } }); + long tCxs = StartupTrace.begin(); IContextService cxs = ContextInjectionFactory.make(ContextService.class, e4Context); + StartupTrace.record("initializeDefaultServices/ContextService.make", tCxs); //$NON-NLS-1$ final IContextService contextService = cxs; @@ -2365,6 +2441,7 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); contextManager.addContextManagerListener(contextManagerEvent -> { if (contextManagerEvent.isContextChanged()) { String id = contextManagerEvent.getContextId(); @@ -2375,6 +2452,7 @@ public void runWithException() { }); EContextService ecs = e4Context.get(EContextService.class); ecs.activateContext(IContextService.CONTEXT_ID_DIALOG_AND_WINDOW); + StartupTrace.record("initializeDefaultServices/contextManager listener+activate", t); //$NON-NLS-1$ } }); @@ -2386,21 +2464,27 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); BindingManager.DEBUG = Policy.DEBUG_KEY_BINDINGS; bindingManager = e4Context.get(BindingManager.class); bindingService[0] = ContextInjectionFactory.make(BindingService.class, e4Context); + StartupTrace.record("initializeDefaultServices/bindingManager+bindingService", t); //$NON-NLS-1$ } }); // bindingService[0].readRegistryAndPreferences(commandService[0]); serviceLocator.registerService(IBindingService.class, bindingService[0]); + long tCmdImg = StartupTrace.begin(); final CommandImageManager commandImageManager = new CommandImageManager(); final CommandImageService commandImageService = new CommandImageService(commandImageManager, commandService[0]); commandImageService.readRegistry(); + StartupTrace.record("initializeDefaultServices/commandImageService.readRegistry", tCmdImg); //$NON-NLS-1$ serviceLocator.registerService(ICommandImageService.class, commandImageService); + long tMenuCtor = StartupTrace.begin(); final WorkbenchMenuService menuService = new WorkbenchMenuService(serviceLocator, e4Context); + StartupTrace.record("initializeDefaultServices/new WorkbenchMenuService", tMenuCtor); //$NON-NLS-1$ serviceLocator.registerService(IMenuService.class, menuService); // the service must be registered before it is initialized - its @@ -2410,7 +2494,9 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); menuService.readRegistry(); + StartupTrace.record("initializeDefaultServices/menuService.readRegistry", t); //$NON-NLS-1$ } }); @@ -2427,7 +2513,10 @@ public void runWithException() { @Override public void runWithException() { // this currently instantiates all players ... sigh + long tRead = StartupTrace.begin(); sourceProviderService.readRegistry(); + StartupTrace.record("initializeDefaultServices/sourceProviderService.readRegistry", tRead); //$NON-NLS-1$ + long tAdd = StartupTrace.begin(); ISourceProvider[] sourceproviders = sourceProviderService.getSourceProviders(); for (ISourceProvider sp : sourceproviders) { evaluationService.addSourceProvider(sp); @@ -2435,6 +2524,7 @@ public void runWithException() { contextService.addSourceProvider(sp); } } + StartupTrace.record("initializeDefaultServices/register source providers", tAdd); //$NON-NLS-1$ } }); @@ -2464,13 +2554,17 @@ public void runWithException() { @Override public void runWithException() { + long t = StartupTrace.begin(); handlerService[0] = new LegacyHandlerService(e4Context); e4Context.set(IHandlerService.class, handlerService[0]); handlerService[0].readRegistry(); + StartupTrace.record("initializeDefaultServices/handlerService.readRegistry", t); //$NON-NLS-1$ } }); workbenchContextSupport = new WorkbenchContextSupport(this, contextManager); + long tCmdResolver = StartupTrace.begin(); initializeCommandResolver(); + StartupTrace.record("initializeDefaultServices/initializeCommandResolver", tCmdResolver); //$NON-NLS-1$ bindingManager.addBindingManagerListener(bindingManagerListener); diff --git a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/WorkbenchPlugin.java b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/WorkbenchPlugin.java index 1d4037a9d08..87455743e0f 100644 --- a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/WorkbenchPlugin.java +++ b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/WorkbenchPlugin.java @@ -58,6 +58,7 @@ import org.eclipse.ui.internal.help.HelpServiceImpl; import org.eclipse.ui.internal.intro.IIntroRegistry; import org.eclipse.ui.internal.intro.IntroRegistry; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.ui.internal.misc.StatusUtil; import org.eclipse.ui.internal.operations.WorkbenchOperationSupport; import org.eclipse.ui.internal.progress.ProgressManager; @@ -1253,7 +1254,9 @@ public Object compute(IEclipseContext context, String contextKey) { @Override public Object compute(IEclipseContext context, String contextKey) { if (viewRegistry == null) { + long t = StartupTrace.begin(); viewRegistry = ContextInjectionFactory.make(ViewRegistry.class, e4Context); + StartupTrace.record("ContextFunction.compute/ViewRegistry (first touch)", t); //$NON-NLS-1$ } return viewRegistry; } @@ -1324,7 +1327,6 @@ public Object compute(IEclipseContext context, String contextKey) { PlatformUI.getWorkbench()); registryReader.loadFromRegistry(Platform.getExtensionRegistry()); preferenceManager.addPages(registryReader.getTopLevelNodes()); - } return preferenceManager; } @@ -1343,9 +1345,11 @@ public Object compute(IEclipseContext context, String contextKey) { @Override public Object compute(IEclipseContext context, String contextKey) { if (themeRegistry == null) { + long t = StartupTrace.begin(); themeRegistry = new ThemeRegistry(); ThemeRegistryReader reader = new ThemeRegistryReader(); reader.readThemes(Platform.getExtensionRegistry(), themeRegistry); + StartupTrace.record("ContextFunction.compute/ThemeRegistry (first touch)", t); //$NON-NLS-1$ } return themeRegistry; } @@ -1354,8 +1358,10 @@ public Object compute(IEclipseContext context, String contextKey) { @Override public Object compute(IEclipseContext context, String contextKey) { if (workingSetManager == null) { + long t = StartupTrace.begin(); workingSetManager = new WorkingSetManager(bundleContext); workingSetManager.restoreState(); + StartupTrace.record("ContextFunction.compute/WorkingSetManager (first touch)", t); //$NON-NLS-1$ } return workingSetManager; } @@ -1374,7 +1380,9 @@ public Object compute(IEclipseContext context, String contextKey) { @Override public Object compute(IEclipseContext context, String contextKey) { if (editorRegistry == null) { + long t = StartupTrace.begin(); editorRegistry = new EditorRegistry(Platform.getContentTypeManager()); + StartupTrace.record("ContextFunction.compute/EditorRegistry (first touch)", t); //$NON-NLS-1$ } return editorRegistry; } diff --git a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/misc/DisplayEventProbe.java b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/misc/DisplayEventProbe.java new file mode 100644 index 00000000000..d38b2520226 --- /dev/null +++ b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/misc/DisplayEventProbe.java @@ -0,0 +1,97 @@ +/******************************************************************************* + * 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.ui.internal.misc; + +import java.util.concurrent.atomic.AtomicBoolean; +import org.eclipse.core.internal.runtime.StartupTrace; +import org.eclipse.swt.SWT; +import org.eclipse.swt.widgets.Display; + +/** + * Installs SWT.PreEvent / SWT.PostEvent listeners on the workbench Display so + * each dispatched UI event is bracketed and recorded in StartupTrace. Events + * shorter than {@link #THRESHOLD_NS} are dropped to avoid CSV blow-up; only + * outliers are reported, identified by SWT event type. + * + * Local-only debug instrumentation. NOT FOR UPSTREAM MERGE. + */ +public final class DisplayEventProbe { + + /** Below this duration an event is considered uninteresting and skipped. */ + private static final long THRESHOLD_NS = 16_000_000L; // 16 ms (one 60 Hz frame) + + private static final AtomicBoolean INSTALLED = new AtomicBoolean(); + private static long currentEventStartNs; + + private DisplayEventProbe() { + } + + /** Installs the listeners once; subsequent calls are no-ops. */ + public static void install(Display display) { + if (!StartupTrace.ENABLED || display == null || display.isDisposed()) { + return; + } + if (!INSTALLED.compareAndSet(false, true)) { + return; + } + display.addListener(SWT.PreEvent, e -> currentEventStartNs = System.nanoTime()); + display.addListener(SWT.PostEvent, e -> { + long start = currentEventStartNs; + if (start == 0L) { + return; + } + currentEventStartNs = 0L; + long elapsed = System.nanoTime() - start; + if (elapsed >= THRESHOLD_NS) { + StartupTrace.record("DisplayEvent." + eventName(e.type), start); //$NON-NLS-1$ + } + }); + } + + private static String eventName(int type) { + return switch (type) { + case SWT.Paint -> "Paint"; //$NON-NLS-1$ + case SWT.Resize -> "Resize"; //$NON-NLS-1$ + case SWT.Selection -> "Selection"; //$NON-NLS-1$ + case SWT.DefaultSelection -> "DefaultSelection"; //$NON-NLS-1$ + case SWT.MouseDown -> "MouseDown"; //$NON-NLS-1$ + case SWT.MouseUp -> "MouseUp"; //$NON-NLS-1$ + case SWT.MouseMove -> "MouseMove"; //$NON-NLS-1$ + case SWT.MouseWheel -> "MouseWheel"; //$NON-NLS-1$ + case SWT.MouseDoubleClick -> "MouseDoubleClick"; //$NON-NLS-1$ + case SWT.MouseEnter -> "MouseEnter"; //$NON-NLS-1$ + case SWT.MouseExit -> "MouseExit"; //$NON-NLS-1$ + case SWT.MouseHover -> "MouseHover"; //$NON-NLS-1$ + case SWT.KeyDown -> "KeyDown"; //$NON-NLS-1$ + case SWT.KeyUp -> "KeyUp"; //$NON-NLS-1$ + case SWT.Traverse -> "Traverse"; //$NON-NLS-1$ + case SWT.FocusIn -> "FocusIn"; //$NON-NLS-1$ + case SWT.FocusOut -> "FocusOut"; //$NON-NLS-1$ + case SWT.Activate -> "Activate"; //$NON-NLS-1$ + case SWT.Deactivate -> "Deactivate"; //$NON-NLS-1$ + case SWT.Show -> "Show"; //$NON-NLS-1$ + case SWT.Hide -> "Hide"; //$NON-NLS-1$ + case SWT.Close -> "Close"; //$NON-NLS-1$ + case SWT.Modify -> "Modify"; //$NON-NLS-1$ + case SWT.Verify -> "Verify"; //$NON-NLS-1$ + case SWT.Move -> "Move"; //$NON-NLS-1$ + case SWT.Expand -> "Expand"; //$NON-NLS-1$ + case SWT.Collapse -> "Collapse"; //$NON-NLS-1$ + case SWT.SetData -> "SetData"; //$NON-NLS-1$ + case SWT.MeasureItem -> "MeasureItem"; //$NON-NLS-1$ + case SWT.PaintItem -> "PaintItem"; //$NON-NLS-1$ + case SWT.EraseItem -> "EraseItem"; //$NON-NLS-1$ + case SWT.MenuDetect -> "MenuDetect"; //$NON-NLS-1$ + case SWT.Dispose -> "Dispose"; //$NON-NLS-1$ + default -> "type" + type; //$NON-NLS-1$ + }; + } +} diff --git a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/EditorRegistry.java b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/EditorRegistry.java index 022f2652142..abd89d2e4db 100644 --- a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/EditorRegistry.java +++ b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/EditorRegistry.java @@ -76,6 +76,7 @@ import org.eclipse.ui.internal.WorkbenchImages; import org.eclipse.ui.internal.WorkbenchMessages; import org.eclipse.ui.internal.WorkbenchPlugin; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.ui.internal.editorsupport.ComponentSupport; import org.eclipse.ui.internal.misc.ExternalProgramImageDescriptor; import org.eclipse.ui.internal.misc.ProgramImageDescriptor; @@ -610,14 +611,18 @@ private void addSystemEditors(Map map) { * overrides. */ private void initializeFromStorage() { + long tTotal = StartupTrace.begin(); typeEditorMappings = new EditorMap(); extensionImages = new HashMap<>(); // Get editors from the registry + long tRead = StartupTrace.begin(); EditorRegistryReader registryReader = new EditorRegistryReader(); registryReader.addEditors(this); + StartupTrace.record("EditorRegistry.initializeFromStorage/addEditors (registry read)", tRead); //$NON-NLS-1$ sortInternalEditors(); rebuildInternalEditorMap(); + StartupTrace.record("EditorRegistry.initializeFromStorage (total)", tTotal); //$NON-NLS-1$ IPreferenceStore store = PlatformUI.getPreferenceStore(); String defaultEditors = store.getString(IPreferenceConstants.DEFAULT_EDITORS); diff --git a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/ViewRegistry.java b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/ViewRegistry.java index cd955cd7ef8..195542f95f8 100644 --- a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/ViewRegistry.java +++ b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/internal/registry/ViewRegistry.java @@ -38,6 +38,7 @@ import org.eclipse.ui.IWorkbench; import org.eclipse.ui.activities.WorkbenchActivityHelper; import org.eclipse.ui.internal.IWorkbenchConstants; +import org.eclipse.core.internal.runtime.StartupTrace; import org.eclipse.ui.internal.e4.compatibility.CompatibilityPart; import org.eclipse.ui.internal.menus.MenuHelper; import org.eclipse.ui.part.ViewPart; @@ -88,6 +89,7 @@ public class ViewRegistry implements IViewRegistry { @PostConstruct void postConstruct() { + long tTotal = StartupTrace.begin(); IExtensionPoint point = extensionRegistry.getExtensionPoint("org.eclipse.ui.views"); //$NON-NLS-1$ for (IExtension extension : point.getExtensions()) { // find the category first @@ -110,6 +112,7 @@ void postConstruct() { categories.put(miscCategory.getId(), new ViewCategory(miscCategory.getId(), miscCategory.getLabel())); } + long tPass2 = StartupTrace.begin(); for (IExtension extension : point.getExtensions()) { for (IConfigurationElement element : extension.getConfigurationElements()) { if (element.getName().equals(IWorkbenchRegistryConstants.TAG_VIEW)) { @@ -120,6 +123,8 @@ void postConstruct() { } } } + StartupTrace.record("ViewRegistry.postConstruct/pass2 views", tPass2); //$NON-NLS-1$ + StartupTrace.record("ViewRegistry.postConstruct (total)", tTotal); //$NON-NLS-1$ } private void createDescriptor(IConfigurationElement element, boolean e4View) { diff --git a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/model/WorkbenchLabelProvider.java b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/model/WorkbenchLabelProvider.java index f37396a31c8..1e9f7b85d85 100644 --- a/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/model/WorkbenchLabelProvider.java +++ b/bundles/org.eclipse.ui.workbench/eclipseui/org/eclipse/ui/model/WorkbenchLabelProvider.java @@ -170,20 +170,25 @@ private ResourceManager getResourceManager() { @Override public final Image getImage(Object element) { - // obtain the base image by querying the element - IWorkbenchAdapter adapter = getAdapter(element); - if (adapter == null) { - return null; - } - ImageDescriptor descriptor = adapter.getImageDescriptor(element); - if (descriptor == null) { - return null; - } + long t = org.eclipse.core.internal.runtime.StartupTrace.begin(); + try { + // obtain the base image by querying the element + IWorkbenchAdapter adapter = getAdapter(element); + if (adapter == null) { + return null; + } + ImageDescriptor descriptor = adapter.getImageDescriptor(element); + if (descriptor == null) { + return null; + } - // add any annotations to the image descriptor - descriptor = decorateImage(descriptor, element); + // add any annotations to the image descriptor + descriptor = decorateImage(descriptor, element); - return getResourceManager().get(descriptor); + return getResourceManager().get(descriptor); + } finally { + org.eclipse.core.internal.runtime.StartupTrace.record("WorkbenchLabelProvider.getImage", t); //$NON-NLS-1$ + } } /** @@ -231,15 +236,20 @@ protected Styler getDecorationStyle(Object element) { @Override public final String getText(Object element) { - // query the element for its label - IWorkbenchAdapter adapter = getAdapter(element); - if (adapter == null) { - return ""; //$NON-NLS-1$ - } - String label = adapter.getLabel(element); + long t = org.eclipse.core.internal.runtime.StartupTrace.begin(); + try { + // query the element for its label + IWorkbenchAdapter adapter = getAdapter(element); + if (adapter == null) { + return ""; //$NON-NLS-1$ + } + String label = adapter.getLabel(element); - // return the decorated label - return decorateText(label, element); + // return the decorated label + return decorateText(label, element); + } finally { + org.eclipse.core.internal.runtime.StartupTrace.record("WorkbenchLabelProvider.getText", t); //$NON-NLS-1$ + } } @Override 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.