Instrument workspace/runtime startup with StartupTrace#4
Conversation
There was a problem hiding this comment.
Code Review
This pull request introduces performance instrumentation using the StartupTrace utility across key initialization and restoration methods in SaveManager, Workspace, and InternalPlatform. The review feedback identifies several opportunities to improve the robustness of this instrumentation, specifically by using try-finally blocks to ensure that trace records are captured even when exceptions occur. Additionally, there is a recommendation to maintain consistent naming conventions for trace identifiers in InternalPlatform to match the patterns used in other components.
| StartupTrace.record("Workspace.open/crashRecoveryRefresh", tRefresh); //$NON-NLS-1$ | ||
| StartupTrace.record("Workspace.open", tOpen); //$NON-NLS-1$ | ||
| //don't fail entire open if refresh failed, just report as warning | ||
| return new ResourceStatus(IResourceStatus.INTERNAL_ERROR, IPath.ROOT, | ||
| Messages.resources_errorMultiRefresh, e); | ||
| } | ||
| StartupTrace.record("Workspace.open/crashRecoveryRefresh", tRefresh); //$NON-NLS-1$ |
There was a problem hiding this comment.
The recording of the Workspace.open and Workspace.open/crashRecoveryRefresh spans is inconsistent and contains duplication.
tOpenis recorded manually in theRuntimeExceptioncatch block (line 2389) and at the end of the method (line 2399), but it is missed if aCoreExceptionis thrown earlier (e.g., duringstartup()at line 2376).tRefreshis recorded twice: once in the catch block (line 2388) and once after the try block (line 2394).
Consider wrapping the method body in a try-finally block for tOpen, and using a try-finally for the refresh logic. This ensures all spans are recorded regardless of how the method exits, matching the robust pattern used in SaveManager.restore() and Workspace.startup().
| long tStart = StartupTrace.begin(); | ||
| this.context = runtimeContext; | ||
| this.fwkWiring = runtimeContext.getBundle(Constants.SYSTEM_BUNDLE_LOCATION).adapt(FrameworkWiring.class); | ||
| long tTrackers = StartupTrace.begin(); | ||
| openOSGiTrackers(); | ||
| StartupTrace.record("InternalPlatform.start/openOSGiTrackers", tTrackers); //$NON-NLS-1$ | ||
| splashEnded = false; | ||
| long tCmdLine = StartupTrace.begin(); | ||
| processCommandLine(getEnvironmentInfoService().getNonFrameworkArgs()); | ||
| StartupTrace.record("InternalPlatform.start/processCommandLine", tCmdLine); //$NON-NLS-1$ | ||
| long tDebug = StartupTrace.begin(); | ||
| initializeDebugFlags(); | ||
| StartupTrace.record("InternalPlatform.start/initializeDebugFlags", tDebug); //$NON-NLS-1$ | ||
| initialized = true; | ||
| stopped = false; | ||
| long tAuth = StartupTrace.begin(); | ||
| initializeAuthorizationHandler(); | ||
| StartupTrace.record("InternalPlatform.start/initializeAuthorizationHandler", tAuth); //$NON-NLS-1$ | ||
| long tSsl = StartupTrace.begin(); | ||
| initializeSSLContext(); | ||
| StartupTrace.record("InternalPlatform.start/initializeSSLContext", tSsl); //$NON-NLS-1$ | ||
| long tSvc = StartupTrace.begin(); | ||
| startServices(); | ||
| StartupTrace.record("InternalPlatform.start/startServices", tSvc); //$NON-NLS-1$ | ||
| StartupTrace.record("InternalPlatform.start", tStart); //$NON-NLS-1$ |
There was a problem hiding this comment.
The InternalPlatform.start span is only recorded at the very end of the method. If an unchecked exception occurs during startup, the trace will be lost. For better reliability in profiling, consider wrapping the method body in a try-finally block to ensure StartupTrace.record is always called, consistent with the implementation in SaveManager.restore().
| private void openOSGiTrackers() { | ||
| long t; | ||
| t = StartupTrace.begin(); | ||
| instanceLocation = createOpenTracker(Location.INSTANCE_FILTER); | ||
| StartupTrace.record("openOSGiTrackers/instanceLocation", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| userLocation = createOpenTracker(Location.USER_FILTER); | ||
| StartupTrace.record("openOSGiTrackers/userLocation", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| configurationLocation = createOpenTracker(Location.CONFIGURATION_FILTER); | ||
| StartupTrace.record("openOSGiTrackers/configurationLocation", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| installLocation = createOpenTracker(Location.INSTALL_FILTER); | ||
| StartupTrace.record("openOSGiTrackers/installLocation", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| logTracker = createOpenTracker(FrameworkLog.class); | ||
| StartupTrace.record("openOSGiTrackers/FrameworkLog", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| platformTracker = createOpenTracker(PlatformAdmin.class); | ||
| StartupTrace.record("openOSGiTrackers/PlatformAdmin", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| contentTracker = createOpenTracker(IContentTypeManager.class); | ||
| StartupTrace.record("openOSGiTrackers/IContentTypeManager", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| preferencesTracker = createOpenTracker(IPreferencesService.class); | ||
| StartupTrace.record("openOSGiTrackers/IPreferencesService", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| groupProviderTracker = createOpenTracker("(objectClass=" + IBundleGroupProvider.class.getName() + ")"); //$NON-NLS-1$ //$NON-NLS-2$ | ||
| StartupTrace.record("openOSGiTrackers/IBundleGroupProvider", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| logReaderTracker = createOpenTracker(ExtendedLogReaderService.class); | ||
| StartupTrace.record("openOSGiTrackers/ExtendedLogReaderService", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| extendedLogTracker = createOpenTracker(ExtendedLogService.class); | ||
| StartupTrace.record("openOSGiTrackers/ExtendedLogService", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| environmentTracker = createOpenTracker(EnvironmentInfo.class); | ||
| StartupTrace.record("openOSGiTrackers/EnvironmentInfo", t); //$NON-NLS-1$ | ||
| t = StartupTrace.begin(); | ||
| debugTracker = createOpenTracker(DebugOptions.class); | ||
| StartupTrace.record("openOSGiTrackers/DebugOptions", t); //$NON-NLS-1$ | ||
| } |
There was a problem hiding this comment.
The trace names in openOSGiTrackers are missing the InternalPlatform. class prefix. This is inconsistent with the naming convention used in other instrumented areas like Workspace.startup/... and SaveManager.restore/.... Adding the prefix will make the trace logs more consistent and easier to aggregate.
private void openOSGiTrackers() {
long t;
t = StartupTrace.begin();
instanceLocation = createOpenTracker(Location.INSTANCE_FILTER);
StartupTrace.record("InternalPlatform.openOSGiTrackers/instanceLocation", t); //$NON-NLS-1$
t = StartupTrace.begin();
userLocation = createOpenTracker(Location.USER_FILTER);
StartupTrace.record("InternalPlatform.openOSGiTrackers/userLocation", t); //$NON-NLS-1$
t = StartupTrace.begin();
configurationLocation = createOpenTracker(Location.CONFIGURATION_FILTER);
StartupTrace.record("InternalPlatform.openOSGiTrackers/configurationLocation", t); //$NON-NLS-1$
t = StartupTrace.begin();
installLocation = createOpenTracker(Location.INSTALL_FILTER);
StartupTrace.record("InternalPlatform.openOSGiTrackers/installLocation", t); //$NON-NLS-1$
t = StartupTrace.begin();
logTracker = createOpenTracker(FrameworkLog.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/FrameworkLog", t); //$NON-NLS-1$
t = StartupTrace.begin();
platformTracker = createOpenTracker(PlatformAdmin.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/PlatformAdmin", t); //$NON-NLS-1$
t = StartupTrace.begin();
contentTracker = createOpenTracker(IContentTypeManager.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/IContentTypeManager", t); //$NON-NLS-1$
t = StartupTrace.begin();
preferencesTracker = createOpenTracker(IPreferencesService.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/IPreferencesService", t); //$NON-NLS-1$
t = StartupTrace.begin();
groupProviderTracker = createOpenTracker("(objectClass=" + IBundleGroupProvider.class.getName() + ")"); //$NON-NLS-1$ //$NON-NLS-2$
StartupTrace.record("InternalPlatform.openOSGiTrackers/IBundleGroupProvider", t); //$NON-NLS-1$
t = StartupTrace.begin();
logReaderTracker = createOpenTracker(ExtendedLogReaderService.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/ExtendedLogReaderService", t); //$NON-NLS-1$
t = StartupTrace.begin();
extendedLogTracker = createOpenTracker(ExtendedLogService.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/ExtendedLogService", t); //$NON-NLS-1$
t = StartupTrace.begin();
environmentTracker = createOpenTracker(EnvironmentInfo.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/EnvironmentInfo", t); //$NON-NLS-1$
t = StartupTrace.begin();
debugTracker = createOpenTracker(DebugOptions.class);
StartupTrace.record("InternalPlatform.openOSGiTrackers/DebugOptions", t); //$NON-NLS-1$
}669bc7f to
300881a
Compare
Delete the local copy at org.eclipse.e4.ui.internal.workbench.StartupTrace and switch all call sites to the platform-provided class introduced by vogella/eclipse.platform#4, so workbench and platform bundles share one run file and one RUN_ID in ~/.eclipse/startup-trace.csv. Each affected bundle already Require-Bundles org.eclipse.core.runtime, so no MANIFEST changes are needed. Discouraged-access is set to warning in the workbench bundles, so no @SuppressWarnings is required either.
The class Javadoc claimed "There are currently five different types of resource change events" but the bullet list immediately below it enumerates six (PRE_BUILD, POST_BUILD, POST_CHANGE, PRE_CLOSE, PRE_DELETE, PRE_REFRESH). The count drifted when PRE_REFRESH was added and would drift again whenever a new type is introduced, so replace the count with "The following types of resource change events are reported:".
Two complementary tracers, both writing CSV summaries on JVM shutdown, so we can measure where Workbench startup and renderer execution 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 RUN_ID. 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. RendererPerfTracer is always active in this debug build and writes to ~/renderer-perf-trace.csv (configurable via -Declipse.renderer.perf.trace.file=<path>). 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.
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=<path>). 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.
cc60b7f to
de2afcd
Compare
Adds org.eclipse.core.internal.runtime.StartupTrace, a java-only, always-on span recorder that drains buffered entries to ~/.eclipse/startup-trace.csv on a 2-second periodic daemon, on explicit flush() calls, and on a JVM shutdown hook. Prints a diagnostic line on every successful write and a top-40 cumulative-time summary at shutdown. Single shared queue and runId across every caller, so contributions from any bundle that Require-Bundles core.runtime land in one CSV per run. The class lives in core.runtime rather than equinox.common so that its inclusion in the built jar is not defeated by Tycho baseline-replace. The CSV is truncated and rewritten on the first flush of each JVM, so every Eclipse startup produces a fresh single-run file. The trace also freezes when StartupTrace.mark(END_OF_STARTUP_MARK) is recorded: the periodic daemon is stopped, the queue is drained one last time, and all further begin/record/mark calls become no-ops. The eclipse.platform.ui follow-up emits this checkpoint once control returns to the SWT event loop, so the CSV contains only startup activity, not steady-state. When the CSV is first written, an AI analysis prompt is emitted above the column header (each line prefixed with '# ' so the body is still filterable as 'grep -v ^# startup-trace.csv'). The prompt instructs a large-context model (e.g. Gemini) to fold the raw rows into a per-run Markdown summary suitable as input for a second AI doing bottleneck analysis: top phases, hot leaves, parent-vs-children gaps, outliers, and cross-run variance. Lets the file be copy-pasted directly into the AI engine without any extra context. API: - StartupTrace.begin() / record(name, t0) for timed spans - StartupTrace.mark(name) for zero-duration checkpoints - StartupTrace.END_OF_STARTUP_MARK sentinel: passing this name to mark() freezes the trace Instrumented call sites: - InternalPlatform.start with sub-spans for openOSGiTrackers (one per ServiceTracker.open), processCommandLine, initializeDebugFlags, initializeAuthorizationHandler, initializeSSLContext (TrustManager init, KeyManager init, SSLContext.getDefault), startServices. - ResourcesPlugin.start (total) with sub-spans for super.start, registerDebugOptions, openInstanceLocationTracker. The tracker span is further sub-divided into open instance Location, new Workspace, and register workspace with platform. - Workspace.open with sub-spans for setExplicitWorkspaceEncoding, initializePreferenceLookupOrder, inner startup, notification-manager restart, and crash-recovery refresh. - Workspace.startup: individual span per manager (WorkManager, FileSystemResourceManager, PathVariableManager, NatureManager, FilterTypeManager, BuildManager, NotificationManager, MarkerManager, SaveManager, PropertyManager2, CharsetManager, ContentDescriptionManager, RefreshManager, AliasManager). - SaveManager.restore with sub-spans for restoreMasterTable, restoreTree (open DataInputStream, readTree), restoreSnapshots, restoreMarkers (readSnapshot, per-project readDelta loop), restoreSyncInfo, restoreMetaInfo (per-project loadMetaInfo loop), and the per-project Project.startup loop. Local-only; not intended for upstream merge.
de2afcd to
dade073
Compare
Summary
Adds
StartupTrace.begin/recordspans around the key platform startup paths so local profiling builds can attribute startup cost to individual phases instead of estimating from code inspection.Instrumented phases
Workspace.open(total) with sub-spans forsetExplicitWorkspaceEncoding,initializePreferenceLookupOrder, innerstartup, notification-manager restart, and crash-recovery refresh.Workspace.startup— an individual span per manager (WorkManager,FileSystemResourceManager,PathVariableManager,NatureManager,FilterTypeManager,BuildManager,NotificationManager,MarkerManager,SaveManager,PropertyManager2,CharsetManager,ContentDescriptionManager,RefreshManager,AliasManager) plus a total span.SaveManager.restore— sub-spans forrestoreMasterTable,restoreTree,restoreSnapshots,restoreMarkers,restoreSyncInfo,restoreMetaInfo, and the per-projectProject.startuploop.InternalPlatform.start— total + sub-spans foropenOSGiTrackers,processCommandLine,initializeDebugFlags,initializeAuthorizationHandler,initializeSSLContext,startServices.openOSGiTrackers— an individual span per each of the 13ServiceTracker.opencalls.Dependency
Requires
org.eclipse.core.internal.runtime.StartupTraceinorg.eclipse.equinox.common. See the companion PR in vogella/equinox. Until that bundle is installed into the local target platform, this branch will not compile downstream bundles via-Pbuild-individual-bundles(Tycho's baseline-replace silently substitutes upstream artifacts).Scope
Local-only tracing build. Not intended for upstream merge.
Test plan
~/.eclipse/startup-trace.csvcontains rows from Workspace/SaveManager/InternalPlatform under a singlerunId.