|
| 1 | +/******************************************************************************* |
| 2 | + * Copyright (c) 2026 Contributors to the Eclipse Foundation |
| 3 | + * |
| 4 | + * This program and the accompanying materials |
| 5 | + * are made available under the terms of the Eclipse Public License 2.0 |
| 6 | + * which accompanies this distribution, and is available at |
| 7 | + * https://www.eclipse.org/legal/epl-2.0/ |
| 8 | + * |
| 9 | + * SPDX-License-Identifier: EPL-2.0 |
| 10 | + *******************************************************************************/ |
| 11 | +package org.eclipse.e4.ui.workbench.renderers.swt; |
| 12 | + |
| 13 | +import java.io.BufferedWriter; |
| 14 | +import java.io.IOException; |
| 15 | +import java.nio.file.Files; |
| 16 | +import java.nio.file.Path; |
| 17 | +import java.nio.file.StandardOpenOption; |
| 18 | +import java.util.ArrayList; |
| 19 | +import java.util.Collections; |
| 20 | +import java.util.Comparator; |
| 21 | +import java.util.List; |
| 22 | +import java.util.Map; |
| 23 | +import java.util.concurrent.ConcurrentHashMap; |
| 24 | +import java.util.concurrent.ConcurrentLinkedQueue; |
| 25 | +import java.util.concurrent.Executors; |
| 26 | +import java.util.concurrent.ScheduledExecutorService; |
| 27 | +import java.util.concurrent.TimeUnit; |
| 28 | +import java.util.concurrent.atomic.AtomicLong; |
| 29 | + |
| 30 | +/** |
| 31 | + * Lightweight performance tracer for renderer hotspots. |
| 32 | + * <p> |
| 33 | + * Output file defaults to {@code $HOME/renderer-perf-trace.csv} and can be |
| 34 | + * overridden with {@code -Declipse.renderer.perf.trace.file=<path>}. A |
| 35 | + * companion summary file is written next to the CSV with suffix |
| 36 | + * {@code .summary.txt} when the JVM shuts down. |
| 37 | + * <p> |
| 38 | + * The CSV format is: |
| 39 | + * {@code timestamp_ms,hotspot_id,duration_ns,detail} |
| 40 | + * <p> |
| 41 | + * Trace records are queued lock-free on the producer side and drained by a |
| 42 | + * single daemon flusher thread every 500 ms. The flusher holds one open |
| 43 | + * {@link BufferedWriter} for the lifetime of the JVM; a shutdown hook drains |
| 44 | + * the queue, writes the summary, and closes the writer so the last events |
| 45 | + * are not lost. |
| 46 | + */ |
| 47 | +public final class RendererPerfTracer { |
| 48 | + |
| 49 | + /** Master switch. Always enabled in this debug build. */ |
| 50 | + public static final boolean ENABLED = true; |
| 51 | + |
| 52 | + // Hotspot IDs matching the items in docs/performance.md. |
| 53 | + // H08 is intentionally unused: an earlier draft reserved it for a |
| 54 | + // ContentProvider hotspot that turned out to be negligible during analysis. |
| 55 | + public static final String H01_FIND_ACTIVE_ELEMENTS = "H01_findActiveElements"; //$NON-NLS-1$ |
| 56 | + public static final String H02_FIND_PLACEHOLDERS_LABEL = "H02_findPlaceholders_label"; //$NON-NLS-1$ |
| 57 | + public static final String H02_FIND_PLACEHOLDERS_ITEM = "H02_findPlaceholders_item"; //$NON-NLS-1$ |
| 58 | + public static final String H03_TOOLBAR_UPDATE_WIDGET = "H03_toolbar_updateWidget"; //$NON-NLS-1$ |
| 59 | + public static final String H04_DIRTY_ALL_SELECTOR = "H04_dirty_allSelector"; //$NON-NLS-1$ |
| 60 | + public static final String H05_TOOL_ITEM_UPDATER = "H05_toolItemUpdater"; //$NON-NLS-1$ |
| 61 | + public static final String H06_MENU_SCHEDULE_UPDATE = "H06_menu_scheduleUpdate"; //$NON-NLS-1$ |
| 62 | + public static final String H07_MENU_CONTEXT_PER_ITEM = "H07_menu_contextPerItem"; //$NON-NLS-1$ |
| 63 | + public static final String H09_WBW_FIND_STACKS = "H09_wbw_findStacks"; //$NON-NLS-1$ |
| 64 | + public static final String H10A_SHOWTAB_LAZY = "H10a_showTab_lazyCreate"; //$NON-NLS-1$ |
| 65 | + public static final String H10B_SHOWTAB_REPARENT = "H10b_showTab_reparent"; //$NON-NLS-1$ |
| 66 | + public static final String H11_LIMBO_REPARENT = "H11_limbo_reparent"; //$NON-NLS-1$ |
| 67 | + public static final String H12_AREA_SYNCH_CTF = "H12_area_synchCTF"; //$NON-NLS-1$ |
| 68 | + public static final String H13_TOOLCTRL_STARTUP_SCAN = "H13_toolCtrl_startupScan"; //$NON-NLS-1$ |
| 69 | + public static final String H14_RAT_UNCOALESCED = "H14_runAndTrack_uncoalesced"; //$NON-NLS-1$ |
| 70 | + public static final String W1_SASH_SYNC_LAYOUT = "W1_sash_syncLayout_win"; //$NON-NLS-1$ |
| 71 | + |
| 72 | + private static final ConcurrentLinkedQueue<String> QUEUE = new ConcurrentLinkedQueue<>(); |
| 73 | + private static final Map<String, HotspotStats> STATS = new ConcurrentHashMap<>(); |
| 74 | + private static final Path OUTPUT_FILE; |
| 75 | + private static final Path SUMMARY_FILE; |
| 76 | + private static final long START_TIME = System.nanoTime(); |
| 77 | + private static final Object WRITER_LOCK = new Object(); |
| 78 | + private static final BufferedWriter WRITER; |
| 79 | + private static final ScheduledExecutorService FLUSHER; |
| 80 | + |
| 81 | + static { |
| 82 | + String fileProp = System.getProperty("eclipse.renderer.perf.trace.file"); //$NON-NLS-1$ |
| 83 | + if (fileProp != null) { |
| 84 | + OUTPUT_FILE = Path.of(fileProp); |
| 85 | + } else { |
| 86 | + OUTPUT_FILE = Path.of(System.getProperty("user.home"), "renderer-perf-trace.csv"); //$NON-NLS-1$ //$NON-NLS-2$ |
| 87 | + } |
| 88 | + SUMMARY_FILE = Path.of(OUTPUT_FILE.toString() + ".summary.txt"); //$NON-NLS-1$ |
| 89 | + BufferedWriter writer = null; |
| 90 | + if (ENABLED) { |
| 91 | + try { |
| 92 | + writer = Files.newBufferedWriter(OUTPUT_FILE, |
| 93 | + StandardOpenOption.CREATE, |
| 94 | + StandardOpenOption.TRUNCATE_EXISTING); |
| 95 | + writer.write("timestamp_ms,hotspot_id,duration_ns,detail\n"); //$NON-NLS-1$ |
| 96 | + writer.flush(); |
| 97 | + } catch (IOException e) { |
| 98 | + System.err.println("RendererPerfTracer: failed to open " + OUTPUT_FILE + ": " + e); //$NON-NLS-1$ //$NON-NLS-2$ |
| 99 | + writer = null; |
| 100 | + } |
| 101 | + } |
| 102 | + WRITER = writer; |
| 103 | + |
| 104 | + FLUSHER = Executors.newSingleThreadScheduledExecutor(r -> { |
| 105 | + Thread t = new Thread(r, "RendererPerfTracer-Flusher"); //$NON-NLS-1$ |
| 106 | + t.setDaemon(true); |
| 107 | + return t; |
| 108 | + }); |
| 109 | + if (ENABLED && WRITER != null) { |
| 110 | + FLUSHER.scheduleWithFixedDelay(RendererPerfTracer::flush, 500, 500, TimeUnit.MILLISECONDS); |
| 111 | + Runtime.getRuntime().addShutdownHook( |
| 112 | + new Thread(RendererPerfTracer::shutdown, "RendererPerfTracer-Shutdown")); //$NON-NLS-1$ |
| 113 | + } |
| 114 | + } |
| 115 | + |
| 116 | + private RendererPerfTracer() { |
| 117 | + } |
| 118 | + |
| 119 | + /** Capture start time. Call this at the beginning of the hotspot. */ |
| 120 | + public static long begin() { |
| 121 | + return System.nanoTime(); |
| 122 | + } |
| 123 | + |
| 124 | + /** |
| 125 | + * Record a trace event. |
| 126 | + * |
| 127 | + * @param hotspotId one of the H* or W* constants |
| 128 | + * @param startNano value returned by {@link #begin()} |
| 129 | + * @param detail short context string (e.g., element count, class name). |
| 130 | + * May be {@code null}. |
| 131 | + */ |
| 132 | + public static void trace(String hotspotId, long startNano, String detail) { |
| 133 | + long durationNs = System.nanoTime() - startNano; |
| 134 | + long elapsedMs = (System.nanoTime() - START_TIME) / 1_000_000L; |
| 135 | + String line = elapsedMs + "," + hotspotId + "," + durationNs + "," //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ |
| 136 | + + (detail != null ? detail : "") + "\n"; //$NON-NLS-1$ //$NON-NLS-2$ |
| 137 | + QUEUE.add(line); |
| 138 | + STATS.computeIfAbsent(hotspotId, k -> new HotspotStats()).recordTimed(durationNs); |
| 139 | + } |
| 140 | + |
| 141 | + /** |
| 142 | + * Record a count-only event (no duration). |
| 143 | + * |
| 144 | + * @param hotspotId one of the H* or W* constants |
| 145 | + * @param detail short context string |
| 146 | + */ |
| 147 | + public static void count(String hotspotId, String detail) { |
| 148 | + long elapsedMs = (System.nanoTime() - START_TIME) / 1_000_000L; |
| 149 | + String line = elapsedMs + "," + hotspotId + ",0," //$NON-NLS-1$ //$NON-NLS-2$ |
| 150 | + + (detail != null ? detail : "") + "\n"; //$NON-NLS-1$ //$NON-NLS-2$ |
| 151 | + QUEUE.add(line); |
| 152 | + STATS.computeIfAbsent(hotspotId, k -> new HotspotStats()).recordCountOnly(); |
| 153 | + } |
| 154 | + |
| 155 | + private static void flush() { |
| 156 | + synchronized (WRITER_LOCK) { |
| 157 | + if (WRITER == null) { |
| 158 | + return; |
| 159 | + } |
| 160 | + try { |
| 161 | + String line; |
| 162 | + while ((line = QUEUE.poll()) != null) { |
| 163 | + WRITER.write(line); |
| 164 | + } |
| 165 | + WRITER.flush(); |
| 166 | + } catch (IOException e) { |
| 167 | + // Silently drop. Tracing must not break the workbench. |
| 168 | + } |
| 169 | + } |
| 170 | + } |
| 171 | + |
| 172 | + private static void shutdown() { |
| 173 | + FLUSHER.shutdown(); |
| 174 | + try { |
| 175 | + FLUSHER.awaitTermination(1, TimeUnit.SECONDS); |
| 176 | + } catch (InterruptedException e) { |
| 177 | + Thread.currentThread().interrupt(); |
| 178 | + } |
| 179 | + flush(); |
| 180 | + writeSummary(); |
| 181 | + synchronized (WRITER_LOCK) { |
| 182 | + if (WRITER != null) { |
| 183 | + try { |
| 184 | + WRITER.close(); |
| 185 | + } catch (IOException e) { |
| 186 | + // ignore |
| 187 | + } |
| 188 | + } |
| 189 | + } |
| 190 | + } |
| 191 | + |
| 192 | + private static void writeSummary() { |
| 193 | + long elapsedMs = (System.nanoTime() - START_TIME) / 1_000_000L; |
| 194 | + double elapsedMin = elapsedMs / 60_000.0; |
| 195 | + List<Map.Entry<String, HotspotStats>> entries = new ArrayList<>(STATS.entrySet()); |
| 196 | + entries.sort(Comparator.<Map.Entry<String, HotspotStats>>comparingLong( |
| 197 | + e -> e.getValue().totalNanos.get()).reversed()); |
| 198 | + |
| 199 | + StringBuilder sb = new StringBuilder(4096); |
| 200 | + sb.append("Renderer Performance Trace Summary\n"); //$NON-NLS-1$ |
| 201 | + sb.append("==================================\n\n"); //$NON-NLS-1$ |
| 202 | + sb.append(String.format("Session duration: %.2f s%n", elapsedMs / 1000.0)); //$NON-NLS-1$ |
| 203 | + long totalEvents = entries.stream().mapToLong(e -> e.getValue().count.get()).sum(); |
| 204 | + sb.append(String.format("Total events: %d%n%n", totalEvents)); //$NON-NLS-1$ |
| 205 | + |
| 206 | + sb.append(String.format("%-36s %8s %10s %10s %10s %10s%n", //$NON-NLS-1$ |
| 207 | + "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$ |
| 208 | + sb.append(String.format("%-36s %8s %10s %10s %10s %10s%n", //$NON-NLS-1$ |
| 209 | + "-------", "-----", "---------", "--------", "------", "------")); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$ //$NON-NLS-5$ //$NON-NLS-6$ |
| 210 | + for (Map.Entry<String, HotspotStats> e : entries) { |
| 211 | + HotspotStats s = e.getValue(); |
| 212 | + long count = s.count.get(); |
| 213 | + double callsPerMin = elapsedMin > 0 ? count / elapsedMin : 0; |
| 214 | + if (s.isCountOnly()) { |
| 215 | + sb.append(String.format("%-36s %8d %10.1f %10s %10s %10s%n", //$NON-NLS-1$ |
| 216 | + e.getKey(), count, callsPerMin, "-", "-", "-")); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ |
| 217 | + } else { |
| 218 | + double totalMs = s.totalNanos.get() / 1_000_000.0; |
| 219 | + double maxMs = s.maxNanos.get() / 1_000_000.0; |
| 220 | + double p95Ms = s.percentileNanos(95) / 1_000_000.0; |
| 221 | + sb.append(String.format("%-36s %8d %10.1f %10.2f %10.2f %10.2f%n", //$NON-NLS-1$ |
| 222 | + e.getKey(), count, callsPerMin, totalMs, maxMs, p95Ms)); |
| 223 | + } |
| 224 | + } |
| 225 | + try { |
| 226 | + Files.writeString(SUMMARY_FILE, sb.toString(), |
| 227 | + StandardOpenOption.CREATE, StandardOpenOption.TRUNCATE_EXISTING); |
| 228 | + } catch (IOException e) { |
| 229 | + System.err.println("RendererPerfTracer: failed to write " + SUMMARY_FILE + ": " + e); //$NON-NLS-1$ //$NON-NLS-2$ |
| 230 | + } |
| 231 | + } |
| 232 | + |
| 233 | + private static final class HotspotStats { |
| 234 | + final AtomicLong count = new AtomicLong(); |
| 235 | + final AtomicLong totalNanos = new AtomicLong(); |
| 236 | + final AtomicLong maxNanos = new AtomicLong(); |
| 237 | + final List<Long> durationsNanos = Collections.synchronizedList(new ArrayList<>()); |
| 238 | + |
| 239 | + void recordTimed(long nanos) { |
| 240 | + count.incrementAndGet(); |
| 241 | + totalNanos.addAndGet(nanos); |
| 242 | + maxNanos.accumulateAndGet(nanos, Math::max); |
| 243 | + durationsNanos.add(nanos); |
| 244 | + } |
| 245 | + |
| 246 | + void recordCountOnly() { |
| 247 | + count.incrementAndGet(); |
| 248 | + } |
| 249 | + |
| 250 | + boolean isCountOnly() { |
| 251 | + return durationsNanos.isEmpty() && count.get() > 0; |
| 252 | + } |
| 253 | + |
| 254 | + long percentileNanos(int percentile) { |
| 255 | + List<Long> snapshot; |
| 256 | + synchronized (durationsNanos) { |
| 257 | + if (durationsNanos.isEmpty()) { |
| 258 | + return 0; |
| 259 | + } |
| 260 | + snapshot = new ArrayList<>(durationsNanos); |
| 261 | + } |
| 262 | + Collections.sort(snapshot); |
| 263 | + int idx = (int) Math.ceil(percentile / 100.0 * snapshot.size()) - 1; |
| 264 | + if (idx < 0) { |
| 265 | + idx = 0; |
| 266 | + } |
| 267 | + if (idx >= snapshot.size()) { |
| 268 | + idx = snapshot.size() - 1; |
| 269 | + } |
| 270 | + return snapshot.get(idx); |
| 271 | + } |
| 272 | + } |
| 273 | +} |
0 commit comments