From ada4d36bb6ca0c208881a0c1d528fa3f4cb03bcc Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Fri, 12 Apr 2019 08:41:17 -0500 Subject: Bug 546380 - Add bundleStartTime trace option This new option not only records the time to load and call BundleActivator.start but also the complete time to start a bundle including resolving and firing bundle events Change-Id: I70bc48ca3bfbe08d33a159d7add0164df8bcfa76 Signed-off-by: Thomas Watson --- bundles/org.eclipse.osgi/.options | 6 +++++- .../container/src/org/eclipse/osgi/container/Module.java | 15 ++++++++++++--- .../src/org/eclipse/osgi/container/ModuleContainer.java | 2 ++ .../src/org/eclipse/osgi/internal/debug/Debug.java | 5 +++++ 4 files changed, 24 insertions(+), 4 deletions(-) diff --git a/bundles/org.eclipse.osgi/.options b/bundles/org.eclipse.osgi/.options index 13b000fcb..8e606f05f 100644 --- a/bundles/org.eclipse.osgi/.options +++ b/bundles/org.eclipse.osgi/.options @@ -20,8 +20,12 @@ org.eclipse.osgi/debug/security=false org.eclipse.osgi/debug/startlevel=false # Prints out package admin service debug information org.eclipse.osgi/debug/packageadmin=false -# Prints out timing information for bundle activation +# Prints out timing information for loading and calling BundleActivator.start org.eclipse.osgi/debug/bundleTime=false +# Prints out total time for starting a bundle which includes: +# - loading and calling BundleActivator.start +# - other time spent resolving bundles and firing bundle events to listeners +org.eclipse.osgi/debug/bundleStartTime=false # Debug the loading of message bundles org.eclipse.osgi/debug/messageBundles=false # Debug the object pool additions diff --git a/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/Module.java b/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/Module.java index 86d902e07..3d6cfbf5b 100644 --- a/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/Module.java +++ b/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/Module.java @@ -388,7 +388,12 @@ public abstract class Module implements BundleReference, BundleStartLevel, Compa * @throws BundleException if an errors occurs while starting */ public void start(StartOptions... options) throws BundleException { - revisions.getContainer().checkAdminPermission(getBundle(), AdminPermission.EXECUTE); + ModuleContainer container = getContainer(); + long startTime = 0; + if (container.DEBUG_BUNDLE_START_TIME) { + startTime = System.nanoTime(); + } + container.checkAdminPermission(getBundle(), AdminPermission.EXECUTE); if (options == null) { options = new StartOptions[0]; } @@ -415,7 +420,7 @@ public abstract class Module implements BundleReference, BundleStartLevel, Compa } checkFragment(); persistStartOptions(options); - if (getStartLevel() > getRevisions().getContainer().getStartLevel()) { + if (getStartLevel() > container.getStartLevel()) { if (StartOptions.TRANSIENT.isContained(options)) { // it is an error to attempt to transient start a bundle without its start level met throw new BundleException(Msg.Module_Transient_StartError, BundleException.START_TRANSIENT_ERROR); @@ -432,7 +437,7 @@ public abstract class Module implements BundleReference, BundleStartLevel, Compa unlockStateChange(ModuleEvent.STARTED); lockedStarted = false; try { - report = getRevisions().getContainer().resolve(Collections.singletonList(this), true); + report = container.resolve(Collections.singletonList(this), true); } finally { lockStateChange(ModuleEvent.STARTED); lockedStarted = true; @@ -473,6 +478,10 @@ public abstract class Module implements BundleReference, BundleStartLevel, Compa if (!EnumSet.of(ModuleEvent.STARTED, ModuleEvent.LAZY_ACTIVATION, ModuleEvent.STOPPED).contains(event)) throw new IllegalStateException("Wrong event type: " + event); //$NON-NLS-1$ publishEvent(event); + // only print bundleTime information if we actually fired an event for this bundle + if (container.DEBUG_BUNDLE_START_TIME) { + Debug.println(TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime) + "ms for total start time of " + this); //$NON-NLS-1$ + } } if (startError != null) { diff --git a/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleContainer.java b/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleContainer.java index e51ef84e8..0b63d1a46 100644 --- a/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleContainer.java +++ b/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleContainer.java @@ -132,6 +132,7 @@ public final class ModuleContainer implements DebugOptionsListener { private final boolean autoStartOnResolve; boolean DEBUG_MONITOR_LAZY = false; + boolean DEBUG_BUNDLE_START_TIME = false; /** * Constructs a new container with the specified adaptor, module database. @@ -1554,6 +1555,7 @@ public final class ModuleContainer implements DebugOptionsListener { frameworkStartLevel.setDebugOptions(); if (options != null) { this.DEBUG_MONITOR_LAZY = options.getBooleanOption(Debug.OPTION_MONITOR_LAZY, false); + this.DEBUG_BUNDLE_START_TIME = options.getBooleanOption(Debug.OPTION_DEBUG_BUNDLE_START_TIME, false); } } diff --git a/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/internal/debug/Debug.java b/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/internal/debug/Debug.java index 5b153f25e..645b99bb0 100644 --- a/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/internal/debug/Debug.java +++ b/bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/internal/debug/Debug.java @@ -38,6 +38,11 @@ public class Debug implements DebugOptionsListener { * Bundle time Debug option key. */ public static final String OPTION_DEBUG_BUNDLE_TIME = ECLIPSE_OSGI + "/debug/bundleTime"; //$NON-NLS-1$ + + /** + * Bundle start time Debug option key. + */ + public static final String OPTION_DEBUG_BUNDLE_START_TIME = ECLIPSE_OSGI + "/debug/bundleStartTime"; //$NON-NLS-1$ /** * Loader Debug option key. */ -- cgit v1.2.3