Skip to content

Commit cc60b7f

Browse files
vogellavogella
committed
Add StartupTrace instrumentation to platform startup paths
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. When the CSV is first created, an AI analysis prompt is written 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 (used to capture instantaneous events like 'startup complete' where the timestamp matters, not a duration) 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.
1 parent b885e3b commit cc60b7f

6 files changed

Lines changed: 471 additions & 0 deletions

File tree

‎resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/resources/SaveManager.java‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,7 @@
6666
import org.eclipse.core.internal.localstore.SafeChunkyOutputStream;
6767
import org.eclipse.core.internal.localstore.SafeFileInputStream;
6868
import org.eclipse.core.internal.localstore.SafeFileOutputStream;
69+
import org.eclipse.core.internal.runtime.StartupTrace;
6970
import org.eclipse.core.internal.utils.IStringPoolParticipant;
7071
import org.eclipse.core.internal.utils.Messages;
7172
import org.eclipse.core.internal.utils.Policy;
@@ -790,6 +791,7 @@ protected void resetSnapshots(IResource resource) throws CoreException {
790791
* which were open when it was last saved.
791792
*/
792793
protected void restore(IProgressMonitor monitor) throws CoreException {
794+
long tRestore = StartupTrace.begin();
793795
if (Policy.DEBUG_RESTORE) {
794796
Policy.debug("Restore workspace: starting..."); //$NON-NLS-1$
795797
}
@@ -804,29 +806,44 @@ protected void restore(IProgressMonitor monitor) throws CoreException {
804806
String msg = Messages.resources_startupProblems;
805807
MultiStatus problems = new MultiStatus(ResourcesPlugin.PI_RESOURCES, IResourceStatus.FAILED_READ_METADATA, msg, null);
806808

809+
long t;
810+
t = StartupTrace.begin();
807811
restoreMasterTable();
812+
StartupTrace.record("SaveManager.restore/restoreMasterTable", t); //$NON-NLS-1$
808813
// restore the saved tree and overlay the snapshots if any
814+
t = StartupTrace.begin();
809815
restoreTree(Policy.subMonitorFor(monitor, 10));
816+
StartupTrace.record("SaveManager.restore/restoreTree", t); //$NON-NLS-1$
817+
t = StartupTrace.begin();
810818
restoreSnapshots(Policy.subMonitorFor(monitor, 10));
819+
StartupTrace.record("SaveManager.restore/restoreSnapshots", t); //$NON-NLS-1$
811820

812821
// tolerate failure for non-critical information
813822
// if startup fails, the entire workspace is shot
823+
t = StartupTrace.begin();
814824
try {
815825
restoreMarkers(workspace.getRoot(), false, Policy.subMonitorFor(monitor, 10));
816826
} catch (CoreException e) {
817827
problems.merge(e.getStatus());
818828
}
829+
StartupTrace.record("SaveManager.restore/restoreMarkers", t); //$NON-NLS-1$
830+
t = StartupTrace.begin();
819831
try {
820832
restoreSyncInfo(workspace.getRoot(), Policy.subMonitorFor(monitor, 10));
821833
} catch (CoreException e) {
822834
problems.merge(e.getStatus());
823835
}
836+
StartupTrace.record("SaveManager.restore/restoreSyncInfo", t); //$NON-NLS-1$
824837
// restore meta info last because it might close a project if its description is not readable
838+
t = StartupTrace.begin();
825839
restoreMetaInfo(problems, Policy.subMonitorFor(monitor, 10));
840+
StartupTrace.record("SaveManager.restore/restoreMetaInfo", t); //$NON-NLS-1$
841+
t = StartupTrace.begin();
826842
IProject[] roots = workspace.getRoot().getProjects(IContainer.INCLUDE_HIDDEN);
827843
for (IProject root : roots) {
828844
((Project) root).startup();
829845
}
846+
StartupTrace.record("SaveManager.restore/project.startup(all)", t); //$NON-NLS-1$
830847
if (!problems.isOK()) {
831848
Policy.log(problems);
832849
}
@@ -835,6 +852,7 @@ protected void restore(IProgressMonitor monitor) throws CoreException {
835852
}
836853
} finally {
837854
monitor.done();
855+
StartupTrace.record("SaveManager.restore(total)", tRestore); //$NON-NLS-1$
838856
}
839857
if (Policy.DEBUG_RESTORE) {
840858
Policy.debug("Restore workspace: " + (System.currentTimeMillis() - start) + "ms"); //$NON-NLS-1$ //$NON-NLS-2$
@@ -923,7 +941,9 @@ protected void restoreMarkers(IResource resource, boolean generateDeltas, IProgr
923941
MarkerManager markerManager = workspace.getMarkerManager();
924942
// when restoring a project, only load markers if it is open
925943
if (resource.isAccessible()) {
944+
long tRoot = StartupTrace.begin();
926945
markerManager.restore(resource, generateDeltas, monitor);
946+
StartupTrace.record("SaveManager.restore/restoreMarkers/readSnapshot", tRoot); //$NON-NLS-1$
927947
}
928948

929949
// if we have the workspace root then restore markers for its projects
@@ -934,11 +954,13 @@ protected void restoreMarkers(IResource resource, boolean generateDeltas, IProgr
934954
return;
935955
}
936956
IProject[] projects = ((IWorkspaceRoot) resource).getProjects(IContainer.INCLUDE_HIDDEN);
957+
long tLoop = StartupTrace.begin();
937958
for (IProject project : projects) {
938959
if (project.isAccessible()) {
939960
markerManager.restore(project, generateDeltas, monitor);
940961
}
941962
}
963+
StartupTrace.record("SaveManager.restore/restoreMarkers/readDelta(count=" + projects.length + ")", tLoop); //$NON-NLS-1$ //$NON-NLS-2$
942964
if (Policy.DEBUG_RESTORE_MARKERS) {
943965
Policy.debug("Restore Markers for workspace: " + (System.currentTimeMillis() - start) + "ms"); //$NON-NLS-1$ //$NON-NLS-2$
944966
}
@@ -977,6 +999,7 @@ protected void restoreMetaInfo(MultiStatus problems, IProgressMonitor monitor) {
977999
}
9781000
long start = System.currentTimeMillis();
9791001
IProject[] roots = workspace.getRoot().getProjects(IContainer.INCLUDE_HIDDEN);
1002+
long tLoop = StartupTrace.begin();
9801003
for (IProject root : roots) {
9811004
//fatal to throw exceptions during startup
9821005
try {
@@ -986,6 +1009,7 @@ protected void restoreMetaInfo(MultiStatus problems, IProgressMonitor monitor) {
9861009
problems.merge(new ResourceStatus(IResourceStatus.FAILED_READ_METADATA, root.getFullPath(), message, e));
9871010
}
9881011
}
1012+
StartupTrace.record("SaveManager.restore/restoreMetaInfo/loadMetaInfo(count=" + roots.length + ")", tLoop); //$NON-NLS-1$ //$NON-NLS-2$
9891013
if (Policy.DEBUG_RESTORE_METAINFO) {
9901014
Policy.debug("Restore workspace metainfo: " + (System.currentTimeMillis() - start) + "ms"); //$NON-NLS-1$ //$NON-NLS-2$
9911015
}
@@ -1160,8 +1184,12 @@ protected void restoreTree(IProgressMonitor monitor) throws CoreException {
11601184
savedStates = Collections.synchronizedMap(new HashMap<>(10));
11611185
return;
11621186
}
1187+
long tOpen = StartupTrace.begin();
11631188
try (DataInputStream input = new DataInputStream(new SafeFileInputStream(treeLocation.toOSString(), tempLocation.toOSString(), TREE_BUFFER_SIZE))) {
1189+
StartupTrace.record("SaveManager.restore/restoreTree/open DataInputStream", tOpen); //$NON-NLS-1$
1190+
long tRead = StartupTrace.begin();
11641191
WorkspaceTreeReader.getReader(workspace, input.readInt()).readTree(input, monitor);
1192+
StartupTrace.record("SaveManager.restore/restoreTree/readTree (ElementTreeReader)", tRead); //$NON-NLS-1$
11651193
} catch (Exception e) { // "Unknown format" is passed as ResourceException
11661194
String msg = NLS.bind(Messages.resources_readMeta, treeLocation.toOSString());
11671195
throw new ResourceException(IResourceStatus.FAILED_READ_METADATA, treeLocation, msg, e);

‎resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/internal/resources/Workspace.java‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,7 @@
6565
import org.eclipse.core.internal.refresh.RefreshManager;
6666
import org.eclipse.core.internal.resources.ComputeProjectOrder.Digraph;
6767
import org.eclipse.core.internal.resources.ComputeProjectOrder.VertexOrder;
68+
import org.eclipse.core.internal.runtime.StartupTrace;
6869
import org.eclipse.core.internal.utils.BitMask;
6970
import org.eclipse.core.internal.utils.Messages;
7071
import org.eclipse.core.internal.utils.Policy;
@@ -2342,6 +2343,7 @@ protected long nextNodeId() {
23422343
* @see ResourcesPlugin#getWorkspace()
23432344
*/
23442345
public IStatus open(IProgressMonitor monitor) throws CoreException {
2346+
long tOpen = StartupTrace.begin();
23452347
if (!localMetaArea.hasSavedWorkspace()) {
23462348
localMetaArea.createMetaArea();
23472349
}
@@ -2359,29 +2361,42 @@ public IStatus open(IProgressMonitor monitor) throws CoreException {
23592361

23602362
// Set explicit workspace encoding if no projects exist in the workspace
23612363
if (!localMetaArea.hasSavedProjects()) {
2364+
long tEnc = StartupTrace.begin();
23622365
setExplicitWorkspaceEncoding();
2366+
StartupTrace.record("Workspace.open/setExplicitWorkspaceEncoding", tEnc); //$NON-NLS-1$
23632367
}
2368+
long tPrefOrder = StartupTrace.begin();
23642369
initializePreferenceLookupOrder();
2370+
StartupTrace.record("Workspace.open/initializePreferenceLookupOrder", tPrefOrder); //$NON-NLS-1$
23652371

23662372
// create root location
23672373
localMetaArea.locationFor(getRoot()).toFile().mkdirs();
23682374

2375+
long tStartup = StartupTrace.begin();
23692376
startup(new NullProgressMonitor());
2377+
StartupTrace.record("Workspace.open/startup", tStartup); //$NON-NLS-1$
23702378
// restart the notification manager so it is initialized with the right tree
2379+
long tNotif = StartupTrace.begin();
23712380
notificationManager.startup(null);
2381+
StartupTrace.record("Workspace.open/notificationManager.startup(restart)", tNotif); //$NON-NLS-1$
23722382
openFlag = true;
23732383
if (crashed || refreshRequested()) {
2384+
long tRefresh = StartupTrace.begin();
23742385
try {
23752386
refreshManager.refresh(getRoot());
23762387
} catch (RuntimeException e) {
2388+
StartupTrace.record("Workspace.open/crashRecoveryRefresh", tRefresh); //$NON-NLS-1$
2389+
StartupTrace.record("Workspace.open", tOpen); //$NON-NLS-1$
23772390
//don't fail entire open if refresh failed, just report as warning
23782391
return new ResourceStatus(IResourceStatus.INTERNAL_ERROR, IPath.ROOT,
23792392
Messages.resources_errorMultiRefresh, e);
23802393
}
2394+
StartupTrace.record("Workspace.open/crashRecoveryRefresh", tRefresh); //$NON-NLS-1$
23812395
}
23822396
//finally register a string pool participant
23832397
stringPoolJob = new StringPoolJob();
23842398
stringPoolJob.addStringPoolParticipant(saveManager, getRoot());
2399+
StartupTrace.record("Workspace.open", tOpen); //$NON-NLS-1$
23852400
return Status.OK_STATUS;
23862401
}
23872402

@@ -2654,45 +2669,76 @@ public String[] sortNatureSet(String[] natureIds) {
26542669
* Starts all the workspace manager classes.
26552670
*/
26562671
protected void startup(IProgressMonitor monitor) throws CoreException {
2672+
long tAll = StartupTrace.begin();
26572673
// ensure the tree is locked during the startup notification
26582674
try {
2675+
long t;
2676+
t = StartupTrace.begin();
26592677
_workManager = new WorkManager(this);
26602678
_workManager.startup(null);
2679+
StartupTrace.record("Workspace.startup/WorkManager", t); //$NON-NLS-1$
2680+
t = StartupTrace.begin();
26612681
fileSystemManager = new FileSystemResourceManager(this);
26622682
fileSystemManager.startup(monitor);
2683+
StartupTrace.record("Workspace.startup/FileSystemResourceManager", t); //$NON-NLS-1$
2684+
t = StartupTrace.begin();
26632685
pathVariableManager = new PathVariableManager();
26642686
pathVariableManager.startup(null);
2687+
StartupTrace.record("Workspace.startup/PathVariableManager", t); //$NON-NLS-1$
2688+
t = StartupTrace.begin();
26652689
natureManager = new NatureManager(this);
26662690
natureManager.startup(null);
2691+
StartupTrace.record("Workspace.startup/NatureManager", t); //$NON-NLS-1$
2692+
t = StartupTrace.begin();
26672693
filterManager = new FilterTypeManager();
26682694
filterManager.startup(null);
2695+
StartupTrace.record("Workspace.startup/FilterTypeManager", t); //$NON-NLS-1$
2696+
t = StartupTrace.begin();
26692697
buildManager = new BuildManager(this, getWorkManager().getLock());
26702698
buildManager.startup(null);
2699+
StartupTrace.record("Workspace.startup/BuildManager", t); //$NON-NLS-1$
2700+
t = StartupTrace.begin();
26712701
notificationManager = new NotificationManager(this);
26722702
notificationManager.startup(null);
2703+
StartupTrace.record("Workspace.startup/NotificationManager", t); //$NON-NLS-1$
2704+
t = StartupTrace.begin();
26732705
markerManager = new MarkerManager(this);
26742706
markerManager.startup(null);
2707+
StartupTrace.record("Workspace.startup/MarkerManager", t); //$NON-NLS-1$
2708+
t = StartupTrace.begin();
26752709
synchronizer = new Synchronizer(this);
26762710
saveManager = new SaveManager(this);
26772711
saveManager.startup(null);
2712+
StartupTrace.record("Workspace.startup/SaveManager", t); //$NON-NLS-1$
2713+
t = StartupTrace.begin();
26782714
propertyManager = new PropertyManager2(this);
26792715
propertyManager.startup(monitor);
2716+
StartupTrace.record("Workspace.startup/PropertyManager2", t); //$NON-NLS-1$
2717+
t = StartupTrace.begin();
26802718
charsetManager = new CharsetManager(this);
26812719
charsetManager.startup(null);
2720+
StartupTrace.record("Workspace.startup/CharsetManager", t); //$NON-NLS-1$
2721+
t = StartupTrace.begin();
26822722
contentDescriptionManager = new ContentDescriptionManager(this);
26832723
contentDescriptionManager.startup(null);
2724+
StartupTrace.record("Workspace.startup/ContentDescriptionManager", t); //$NON-NLS-1$
26842725
//must start after save manager, because (read) access to tree is needed
26852726
//must start after other managers to avoid potential cyclic dependency on uninitialized managers (see bug 316182)
26862727
//must start before alias manager (see bug 94829)
2728+
t = StartupTrace.begin();
26872729
refreshManager = new RefreshManager(this);
26882730
refreshManager.startup(null);
2731+
StartupTrace.record("Workspace.startup/RefreshManager", t); //$NON-NLS-1$
26892732
//must start at the end to avoid potential cyclic dependency on other uninitialized managers (see bug 369177)
2733+
t = StartupTrace.begin();
26902734
aliasManager = new AliasManager(this);
26912735
aliasManager.startup(null);
2736+
StartupTrace.record("Workspace.startup/AliasManager", t); //$NON-NLS-1$
26922737
} finally {
26932738
//unlock tree even in case of failure, otherwise shutdown will also fail
26942739
treeLocked = null;
26952740
_workManager.postWorkspaceStartup();
2741+
StartupTrace.record("Workspace.startup(total)", tAll); //$NON-NLS-1$
26962742
}
26972743
}
26982744

‎resources/bundles/org.eclipse.core.resources/src/org/eclipse/core/resources/ResourcesPlugin.java‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
import java.util.Hashtable;
2626
import java.util.List;
2727
import org.eclipse.core.internal.resources.Workspace;
28+
import org.eclipse.core.internal.runtime.StartupTrace;
2829
import org.eclipse.core.internal.utils.Messages;
2930
import org.eclipse.core.internal.utils.Policy;
3031
import org.eclipse.core.runtime.CoreException;
@@ -549,20 +550,28 @@ public void stop(BundleContext context) throws Exception {
549550
*/
550551
@Override
551552
public void start(BundleContext context) throws Exception {
553+
long tTotal = StartupTrace.begin();
554+
long tSuper = StartupTrace.begin();
552555
super.start(context);
556+
StartupTrace.record("ResourcesPlugin.start/super.start", tSuper); //$NON-NLS-1$
553557
workspaceInitCustomizer = new WorkspaceInitCustomizer(context);
554558
// register debug options listener
559+
long tDbg = StartupTrace.begin();
555560
Hashtable<String, String> properties = new Hashtable<>(2);
556561
properties.put(DebugOptions.LISTENER_SYMBOLICNAME, PI_RESOURCES);
557562
debugRegistration = context.registerService(DebugOptionsListener.class, Policy.RESOURCES_DEBUG_OPTIONS_LISTENER,
558563
properties);
564+
StartupTrace.record("ResourcesPlugin.start/registerDebugOptions", tDbg); //$NON-NLS-1$
559565
instanceLocationTracker = new ServiceTracker<>(context,
560566
context.createFilter(String.format("(&%s(%s=*))", Location.INSTANCE_FILTER, //$NON-NLS-1$
561567
Location.SERVICE_PROPERTY_URL)),
562568
workspaceInitCustomizer);
563569
plugin = this; // must before open the tracker, as this can cause the registration of the
564570
// workspace and this might trigger code that calls the static method then.
571+
long tOpen = StartupTrace.begin();
565572
instanceLocationTracker.open();
573+
StartupTrace.record("ResourcesPlugin.start/openInstanceLocationTracker", tOpen); //$NON-NLS-1$
574+
StartupTrace.record("ResourcesPlugin.start (total)", tTotal); //$NON-NLS-1$
566575
}
567576

568577
private final class WorkspaceInitCustomizer implements ServiceTrackerCustomizer<Location, Workspace> {
@@ -579,20 +588,26 @@ public Workspace addingService(ServiceReference<Location> reference) {
579588
if (workspace != null) {
580589
return null; // there can only be one workspace right now...
581590
}
591+
long tLoc = StartupTrace.begin();
582592
Location location = context.getService(reference);
593+
StartupTrace.record("ResourcesPlugin.start/openInstanceLocationTracker/open instance Location", tLoc); //$NON-NLS-1$
583594
if (location == null) {
584595
return null; // we can't use that service...
585596
}
586597
// the workspace is accessible from now on, this is because some plugins require
587598
// access to it in the early startup phase
599+
long tCtor = StartupTrace.begin();
588600
workspace = new Workspace();
601+
StartupTrace.record("ResourcesPlugin.start/openInstanceLocationTracker/new Workspace", tCtor); //$NON-NLS-1$
589602
IStatus result;
590603
try {
591604
result = workspace.open(null);
592605
if (!result.isOK()) {
593606
getLog().log(result);
594607
}
608+
long tReg = StartupTrace.begin();
595609
workspaceRegistration = context.registerService(IWorkspace.class, workspace, null);
610+
StartupTrace.record("ResourcesPlugin.start/openInstanceLocationTracker/register workspace with platform", tReg); //$NON-NLS-1$
596611
return workspace;
597612
} catch (CoreException e) {
598613
getLog().log(e.getStatus());

0 commit comments

Comments
 (0)