Expose the permutation data through the felix resolver logger

Currently it is not really possible to write a test that asserts
something about the complexity of a problem that the resolver has
performed. This has the risk of undetected performance regressions but
also means performance improvements can not be easily investigated. Also
in general code (like for example console commands) it could be useful
to gather some statistics.

This now adds two new methods to the logger, one that is performing a
log each time when a permutation is added or processed to either log
this by the caller or perform any statistics on them.

bundles/org.eclipse.osgi.tests/src/org/eclipse/osgi/tests/container/TestModuleContainer.java

@@ -78,6 +78,7 @@
 import org.eclipse.osgi.internal.debug.Debug;
 import org.eclipse.osgi.internal.framework.EquinoxConfiguration;
 import org.eclipse.osgi.report.resolution.ResolutionReport;
+import org.eclipse.osgi.report.resolution.ResolutionReport.ResolutionStatistics;
 import org.eclipse.osgi.tests.container.dummys.DummyCollisionHook;
 import org.eclipse.osgi.tests.container.dummys.DummyContainerAdaptor;
 import org.eclipse.osgi.tests.container.dummys.DummyDebugOptions;
@@ -1981,20 +1982,20 @@ public void testUses4() throws BundleException, IOException {
 	 */
 	@Test
 	public void testUses5Importer() throws BundleException, IOException {
-		doTestUses5("uses.k.importer.MF");
+		doTestUses5("uses.k.importer.MF", 3);
 	}
 
 	@Test
 	public void testUses5ReqCap() throws BundleException, IOException {
-		doTestUses5("uses.k.reqCap.MF");
+		doTestUses5("uses.k.reqCap.MF", 3);
 	}
 
 	@Test
 	public void testUses5Requirer() throws BundleException, IOException {
-		doTestUses5("uses.k.requirer.MF");
+		doTestUses5("uses.k.requirer.MF", 3);
 	}
 
-	public void doTestUses5(String kManifest) throws BundleException, IOException {
+	public void doTestUses5(String kManifest, int max) throws BundleException, IOException {
 		DummyContainerAdaptor adaptor = createDummyAdaptor();
 		ModuleContainer container = adaptor.getContainer();
 
@@ -2006,12 +2007,13 @@ public void doTestUses5(String kManifest) throws BundleException, IOException {
 		Module uses_m_conflict1 = installDummyModule("uses.m.conflict1.MF", "m.conflict1", container);
 		Module uses_m_conflict2 = installDummyModule("uses.m.conflict2.MF", "m.conflict2", container);
 
-		container.resolve(null, false);
+		ResolutionReport report = container.resolve(null, false);
 
 		assertEquals("k should resolve.", State.RESOLVED, uses_k.getState());
 		assertEquals("l should resolve.", State.RESOLVED, uses_l.getState());
 		assertEquals("m.conflict1 should resolve.", State.RESOLVED, uses_m_conflict1.getState());
 		assertEquals("m.conflict2 should resolve.", State.RESOLVED, uses_m_conflict2.getState());
+		assertNotMoreThanPermutationCreated(report, max);
 	}
 
 	@Test
@@ -3929,14 +3931,32 @@ public void testSubstitutionWithMoreThan2Providers() throws BundleException, IOE
 				"osgi.ee; osgi.ee=JavaSE; version:List<Version>=\"1.3, 1.4, 1.5, 1.6, 1.7\"", //
 				container);
 		ResolutionReport report = container.resolve(Arrays.asList(systemBundle), true);
-		assertNull("Failed to resolve test.", report.getResolutionException());
+		assertSucessfulWith(report, 1);
 
 		List<Module> modules = new ArrayList<>();
 		for (String manifest : HTTPCOMPS_AND_EATHER) {
 			modules.add(installDummyModule(manifest, manifest, container));
 		}
 		report = container.resolve(modules, true);
+		assertSucessfulWith(report, 115);
+	}
+
+	protected void assertSucessfulWith(ResolutionReport report, int maxTotalPermutations) {
 		assertNull("Failed to resolve test.", report.getResolutionException());
+		assertNotMoreThanPermutationCreated(report, maxTotalPermutations);
+	}
+
+	protected void assertNotMoreThanPermutationCreated(ResolutionReport report, int maxTotal) {
+		if (report instanceof ResolutionStatistics) {
+			ResolutionStatistics statistics = (ResolutionStatistics) report;
+			int totalPermutations = statistics.getTotalPermutations();
+			if (totalPermutations > maxTotal) {
+				fail("Maximum of " + maxTotal + " permutations expected but was " + totalPermutations + " ("
+						+ statistics.getProcessedPermutations() + " processed).");
+			}
+			return;
+		}
+		fail("Report does not provide performance statistics!");
 	}
 
 	@Test

bundles/org.eclipse.osgi/.settings/.api_filters

@@ -0,0 +1,11 @@
+<?xml version="1.0" encoding="UTF-8" standalone="no"?>
+<component id="org.eclipse.osgi" version="2">
+    <resource path="supplement/src/org/eclipse/osgi/report/resolution/ResolutionReport.java" type="org.eclipse.osgi.report.resolution.ResolutionReport">
+        <filter id="403853384">
+            <message_arguments>
+                <message_argument value="@noimplement"/>
+                <message_argument value="org.eclipse.osgi.report.resolution.ResolutionReport"/>
+            </message_arguments>
+        </filter>
+    </resource>
+</component>

bundles/org.eclipse.osgi/META-INF/MANIFEST.MF

@@ -36,7 +36,7 @@ Export-Package: org.eclipse.core.runtime.adaptor;x-friends:="org.eclipse.core.ru
  org.eclipse.osgi.internal.signedcontent;x-internal:=true,
  org.eclipse.osgi.internal.url;x-internal:=true,
  org.eclipse.osgi.launch;version="1.1";uses:="org.osgi.framework,org.osgi.framework.launch,org.osgi.framework.connect",
- org.eclipse.osgi.report.resolution;version="1.0";uses:="org.osgi.service.resolver,org.osgi.resource",
+ org.eclipse.osgi.report.resolution;version="1.1.0";uses:="org.osgi.service.resolver,org.osgi.resource",
  org.eclipse.osgi.service.datalocation;version="1.4.0",
  org.eclipse.osgi.service.debug;version="1.2",
  org.eclipse.osgi.service.environment;version="1.4",
@@ -107,7 +107,7 @@ Bundle-Activator: org.eclipse.osgi.internal.framework.SystemBundleActivator
 Bundle-Description: %systemBundle
 Bundle-Copyright: %copyright
 Bundle-Vendor: %eclipse.org
-Bundle-Version: 3.19.100.qualifier
+Bundle-Version: 3.20.0.qualifier
 Bundle-Localization: systembundle
 Bundle-DocUrl: http://www.eclipse.org
 Eclipse-ExtensibleAPI: true

bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleContainer.java

@@ -38,7 +38,6 @@
 import java.util.concurrent.atomic.AtomicReference;
 import java.util.concurrent.locks.ReentrantLock;
 import java.util.concurrent.locks.ReentrantReadWriteLock;
-
 import org.eclipse.osgi.container.Module.StartOptions;
 import org.eclipse.osgi.container.Module.State;
 import org.eclipse.osgi.container.Module.StopOptions;
@@ -651,7 +650,7 @@ public ResolutionReport resolve(Collection<Module> triggers, boolean triggersMan
 	private ResolutionReport resolve(Collection<Module> triggers, boolean triggersMandatory, boolean restartTriggers) {
 		if (isRefreshingSystemModule()) {
 			return new ModuleResolutionReport(null, Collections.emptyMap(),
-					new ResolutionException("Unable to resolve while shutting down the framework.")); //$NON-NLS-1$
+					new ResolutionException("Unable to resolve while shutting down the framework."), -1, -1, -1); //$NON-NLS-1$
 		}
 		ResolutionReport report = null;
 		try (ResolutionLock.Permits resolutionPermits = _resolutionLock.acquire(1)) {
@@ -664,15 +663,16 @@ private ResolutionReport resolve(Collection<Module> triggers, boolean triggersMa
 						if (be.getType() == BundleException.REJECTED_BY_HOOK
 								|| be.getType() == BundleException.STATECHANGE_ERROR) {
 							return new ModuleResolutionReport(null, Collections.emptyMap(),
-									new ResolutionException(be));
+									new ResolutionException(be), -1, -1, -1);
 						}
 					}
 					throw e;
 				}
 			} while (report == null);
 		} catch (ResolutionLockException e) {
 			return new ModuleResolutionReport(null, Collections.emptyMap(),
-					new ResolutionException("Timeout acquiring lock for resolution", e, Collections.emptyList())); //$NON-NLS-1$
+					new ResolutionException("Timeout acquiring lock for resolution", e, Collections.emptyList()), -1, //$NON-NLS-1$
+					-1, -1);
 		}
 		return report;
 	}
@@ -1341,7 +1341,7 @@ public ResolutionReport refresh(Collection<Module> initial) {
 		if (!isRefreshingSystemModule()) {
 			return resolve(refreshTriggers, false, true);
 		}
-		return new ModuleResolutionReport(null, null, null);
+		return new ModuleResolutionReport(null, null, null, -1, -1, -1);
 	}
 
 	/**

bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleResolutionReport.java

@@ -49,8 +49,10 @@ public void addEntry(Resource resource, Entry.Type type, Object data) {
 			entries.add(new EntryImpl(type, data));
 		}
 
-		public ModuleResolutionReport build(Map<Resource, List<Wire>> resolutionResult, ResolutionException cause) {
-			return new ModuleResolutionReport(resolutionResult, resourceToEntries, cause);
+		public ModuleResolutionReport build(Map<Resource, List<Wire>> resolutionResult, ResolutionException cause,
+				int totalPerm, int processedPerm, int usesPerm) {
+			return new ModuleResolutionReport(resolutionResult, resourceToEntries, cause, totalPerm, processedPerm,
+					usesPerm);
 		}
 	}
 
@@ -77,9 +79,15 @@ public Type getType() {
 	private final Map<Resource, List<Entry>> entries;
 	private final ResolutionException resolutionException;
 	private final Map<Resource, List<Wire>> resolutionResult;
+	private int totalPerm;
+	private int processedPerm;
+	private int usesPerm;
 
 	ModuleResolutionReport(Map<Resource, List<Wire>> resolutionResult, Map<Resource, List<Entry>> entries,
-			ResolutionException cause) {
+			ResolutionException cause, int totalPerm, int processedPerm, int usesPerm) {
+		this.totalPerm = totalPerm;
+		this.processedPerm = processedPerm;
+		this.usesPerm = usesPerm;
 		this.entries = entries == null ? Collections.emptyMap() : Collections.unmodifiableMap(new HashMap<>(entries));
 		this.resolutionResult = resolutionResult == null ? Collections.emptyMap()
 				: Collections.unmodifiableMap(resolutionResult);
@@ -176,4 +184,19 @@ private static void printResolutionEntry(StringBuilder result, String prepend, R
 	public String getResolutionReportMessage(Resource resource) {
 		return getResolutionReport0(null, (ModuleRevision) resource, getEntries(), null);
 	}
+
+	@Override
+	public int getTotalPermutations() {
+		return totalPerm;
+	}
+
+	@Override
+	public int getProcessedPermutations() {
+		return processedPerm;
+	}
+
+	@Override
+	public int getUsesPermutations() {
+		return usesPerm;
+	}
 }

bundles/org.eclipse.osgi/container/src/org/eclipse/osgi/container/ModuleResolver.java

@@ -37,7 +37,10 @@
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicReference;
+import java.util.function.ToIntFunction;
+import java.util.stream.Collectors;
 import org.apache.felix.resolver.Logger;
+import org.apache.felix.resolver.PermutationType;
 import org.apache.felix.resolver.ResolutionError;
 import org.apache.felix.resolver.ResolverImpl;
 import org.eclipse.osgi.container.ModuleRequirement.DynamicModuleRequirement;
@@ -89,11 +92,13 @@ final class ModuleResolver {
 	private static final String OPTION_USES = OPTION_RESOLVER + "/uses"; //$NON-NLS-1$
 	private static final String OPTION_WIRING = OPTION_RESOLVER + "/wiring"; //$NON-NLS-1$
 	private static final String OPTION_REPORT = OPTION_RESOLVER + "/report"; //$NON-NLS-1$
+	private static final String OPTION_PERMUTATION = OPTION_RESOLVER + "/permutation"; //$NON-NLS-1$
 
 	boolean DEBUG_ROOTS = false;
 	boolean DEBUG_PROVIDERS = false;
 	boolean DEBUG_HOOKS = false;
 	boolean DEBUG_USES = false;
+	boolean DEBUG_PERMUTATIONS = false;
 	boolean DEBUG_WIRING = false;
 	boolean DEBUG_REPORT = false;
 
@@ -115,6 +120,7 @@ void setDebugOptions() {
 		DEBUG_USES = debugAll || options.getBooleanOption(OPTION_USES, false);
 		DEBUG_WIRING = debugAll || options.getBooleanOption(OPTION_WIRING, false);
 		DEBUG_REPORT = debugAll || options.getBooleanOption(OPTION_REPORT, false);
+		DEBUG_PERMUTATIONS = debugAll || options.getBooleanOption(OPTION_PERMUTATION, false);
 	}
 
 	static final Collection<String> NON_PAYLOAD_CAPABILITIES = Arrays.asList(IdentityNamespace.IDENTITY_NAMESPACE);
@@ -470,6 +476,9 @@ class ResolveProcess extends ResolveContext implements Comparator<Capability>, E
 
 		class ResolveLogger extends Logger {
 			private Map<Resource, ResolutionException> errors = null;
+			public int totalPerm;
+			public int processedPerm;
+			public int usesPerm;
 
 			public ResolveLogger() {
 				super(DEBUG_USES ? Logger.LOG_DEBUG : 0);
@@ -510,6 +519,27 @@ protected void doLog(int level, String msg, Throwable throwable) {
 						+ (throwable != null ? (TAB + TAB + throwable.getMessage()) : "")); //$NON-NLS-1$
 			}
 
+			@Override
+			public void logPermutationAdded(PermutationType type, ToIntFunction<PermutationType> remaining) {
+				totalPerm++;
+				if (type == PermutationType.USES) {
+					usesPerm++;
+				}
+			}
+
+			PermutationType[] permutationTypes = PermutationType.values();
+
+			@Override
+			public void logProcessPermutation(PermutationType type, ToIntFunction<PermutationType> remaining) {
+				processedPerm++;
+				if (DEBUG_PERMUTATIONS) {
+					Debug.println(
+							"RESOLVER: Process " + type + " permutation remaining: " + SEPARATOR + TAB //$NON-NLS-1$ //$NON-NLS-2$
+									+ Arrays.stream(permutationTypes).map(t -> t + ": " + remaining.applyAsInt(t)) //$NON-NLS-1$
+											.collect(Collectors.joining(SEPARATOR + TAB)));
+				}
+			}
+
 		}
 
 		private final ModuleResolutionReport.Builder reportBuilder = new ModuleResolutionReport.Builder();
@@ -918,7 +948,7 @@ ModuleResolutionReport resolve() {
 						BundleException be = (BundleException) e.getCause();
 						if (be.getType() == BundleException.REJECTED_BY_HOOK) {
 							return new ModuleResolutionReport(null, Collections.emptyMap(),
-									new ResolutionException(be));
+									new ResolutionException(be), -1, -1, -1);
 						}
 					}
 					throw e;
@@ -962,7 +992,7 @@ ModuleResolutionReport resolve() {
 					if (DEBUG_WIRING) {
 						printWirings(result);
 					}
-					report = reportBuilder.build(result, re);
+					report = reportBuilder.build(result, re, logger.totalPerm, logger.processedPerm, logger.usesPerm);
 					if (DEBUG_REPORT) {
 						if (report.getResolutionException() != null) {
 							Debug.printStackTrace(report.getResolutionException());

bundles/org.eclipse.osgi/felix/src/org/apache/felix/resolver/Candidates.java

@@ -22,7 +22,6 @@
 import java.util.Map.Entry;
 import java.util.concurrent.atomic.AtomicBoolean;
 
-import org.apache.felix.resolver.ResolverImpl.PermutationType;
 import org.apache.felix.resolver.ResolverImpl.ResolveSession;
 import org.apache.felix.resolver.reason.ReasonException;
 import org.apache.felix.resolver.util.*;

bundles/org.eclipse.osgi/felix/src/org/apache/felix/resolver/Logger.java

@@ -18,6 +18,7 @@
  */
 package org.apache.felix.resolver;
 
+import java.util.function.ToIntFunction;
 import org.osgi.resource.Resource;
 
 /**
@@ -131,4 +132,29 @@ public void logUsesConstraintViolation(Resource resource, ResolutionError error)
     {
         // do nothing by default
     }
+
+	/**
+	 * Called whenever a new permutation is added by the resolver.
+	 * 
+	 * @param type      the type of the permutation
+	 * @param remaining a function that can be used to query the now current number
+	 *                  of permutation types
+	 */
+	public void logPermutationAdded(PermutationType type, ToIntFunction<PermutationType> remaining) 
+	{
+		// do nothing by default
+	}
+
+	/**
+	 * Called whenever a permutation is removed and about to be processed by the
+	 * resolver.
+	 * 
+	 * @param type      the type of permutation that will be processed
+	 * @param remaining a function that can be used to query the now current number
+	 *                  of permutation types
+	 */
+	public void logProcessPermutation(PermutationType type, ToIntFunction<PermutationType> remaining) 
+	{
+		// do nothing by default
+	}
 }

bundles/org.eclipse.osgi/felix/src/org/apache/felix/resolver/PermutationType.java

@@ -0,0 +1,24 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.felix.resolver;
+public enum PermutationType {
+    USES,
+    IMPORT,
+    SUBSTITUTE
+}