Bug 546380 - Add bundleStartTime trace optionI20190417-1800I20190416-1800I20190415-1800I20190415-0300I20190414-1800I20190414-0210I20190413-1800I20190412-1800

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 <tjwatson@us.ibm.com>

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.
 	 */