Prepare tests for perf improvements (MID-5539)

Evolveum · Aug 7, 2019 · aad4568 · aad4568
1 parent 95eb6f6
commit aad4568
Show file tree

Hide file tree

Showing 23 changed files with 1,108 additions and 62 deletions.
diff --git a/...rc/main/java/com/evolveum/midpoint/schema/statistics/CachePerformanceInformationUtil.java b/...rc/main/java/com/evolveum/midpoint/schema/statistics/CachePerformanceInformationUtil.java
@@ -98,4 +98,8 @@ public static String format(CachesPerformanceInformationType information) {
 		}
 		return sb.toString();
 	}
+
+	public static String format(Map<String, CachePerformanceCollector.CacheData> performanceMap) {
+		return performanceMap != null ? format(toCachesPerformanceInformationType(performanceMap)) : "";
+	}
 }
diff --git a/...common/src/main/java/com/evolveum/midpoint/model/common/util/ProfilingModelInspector.java b/...common/src/main/java/com/evolveum/midpoint/model/common/util/ProfilingModelInspector.java
@@ -27,7 +27,6 @@
 import com.evolveum.midpoint.model.api.context.ModelProjectionContext;
 import com.evolveum.midpoint.model.api.context.ModelState;
 import com.evolveum.midpoint.model.api.util.ClockworkInspector;
-import com.evolveum.midpoint.model.common.util.ProfilingModelInspector.PartRuntime;
 import com.evolveum.midpoint.prism.PrismObject;
 import com.evolveum.midpoint.prism.delta.ObjectDelta;
 import com.evolveum.midpoint.repo.api.RepositoryPerformanceMonitor;
@@ -184,6 +183,7 @@ public <F extends ObjectType> void projectorFinish(ModelContext<F> context) {
 		lastLensContext = context;
 	}
 
+	@SuppressWarnings("unchecked")
 	public <F extends ObjectType> ModelContext<F> getLastLensContext() {
 		return lastLensContext;
 	}
@@ -195,15 +195,11 @@ public <F extends ObjectType> void afterMappingEvaluation(ModelContext<F> contex
 		projectorMappingTotalCount++;
 	}
 
-	private void recordProjectorPartTime(ModelState state, String componenetName, Long start, Long finish) {
-		List<PartRuntime> partList = projectorPartMap.get(state);
-		if (partList == null) {
-			partList = new ArrayList<>();
-			projectorPartMap.put(state, partList);
-		}
-		PartRuntime partRuntime = findPartRuntime(partList, componenetName);
+	private void recordProjectorPartTime(ModelState state, String componentName, Long start, Long finish) {
+		List<PartRuntime> partList = projectorPartMap.computeIfAbsent(state, k -> new ArrayList<>());
+		PartRuntime partRuntime = findPartRuntime(partList, componentName);
 		if (partRuntime == null) {
-			partRuntime = new PartRuntime(componenetName);
+			partRuntime = new PartRuntime(componentName);
 			partList.add(partRuntime);
 		}
 		if (start != null) {
@@ -267,7 +263,7 @@ private void dumpState(StringBuilder sb, ModelState state, int indent) {
 		if (runtimes == null) {
 			return;
 		}
-		DebugUtil.debugDumpWithLabelLn(sb, state.toString(), runtimes==null?null:runtimes.etimeStr(), indent + 2);
+		DebugUtil.debugDumpWithLabelLn(sb, state.toString(), runtimes.etimeStr(), indent + 2);
 		Runtimes projectorRuntimes = projectorTimes.get(state);
 		if (projectorRuntimes != null) {
 			DebugUtil.debugDumpWithLabelLn(sb, "projector", projectorRuntimes.etimeStr(), indent + 3);

diff --git a/...del-test/src/main/java/com/evolveum/midpoint/model/test/AbstractModelIntegrationTest.java b/...del-test/src/main/java/com/evolveum/midpoint/model/test/AbstractModelIntegrationTest.java
@@ -50,11 +50,13 @@
 import com.evolveum.midpoint.prism.delta.*;
 import com.evolveum.midpoint.prism.equivalence.EquivalenceStrategy;
 import com.evolveum.midpoint.prism.path.*;
+import com.evolveum.midpoint.repo.api.perf.PerformanceInformation;
 import com.evolveum.midpoint.schema.*;
 import com.evolveum.midpoint.schema.result.OperationResultStatus;
 import com.evolveum.midpoint.schema.util.*;
 import com.evolveum.midpoint.schema.statistics.StatisticsUtil;
 import com.evolveum.midpoint.task.api.TaskDebugUtil;
+import com.evolveum.midpoint.test.asserter.*;
 import com.evolveum.midpoint.util.*;
 import com.evolveum.midpoint.xml.ns._public.common.common_3.*;
 import org.apache.commons.lang.StringUtils;
@@ -153,15 +155,6 @@
 import com.evolveum.midpoint.test.DummyAuditService;
 import com.evolveum.midpoint.test.DummyResourceContoller;
 import com.evolveum.midpoint.test.IntegrationTestTools;
-import com.evolveum.midpoint.test.asserter.ArchetypePolicyAsserter;
-import com.evolveum.midpoint.test.asserter.DummyAccountAsserter;
-import com.evolveum.midpoint.test.asserter.DummyGroupAsserter;
-import com.evolveum.midpoint.test.asserter.FocusAsserter;
-import com.evolveum.midpoint.test.asserter.OrgAsserter;
-import com.evolveum.midpoint.test.asserter.ResourceAsserter;
-import com.evolveum.midpoint.test.asserter.RoleAsserter;
-import com.evolveum.midpoint.test.asserter.ShadowAsserter;
-import com.evolveum.midpoint.test.asserter.UserAsserter;
 import com.evolveum.midpoint.test.util.MidPointAsserts;
 import com.evolveum.midpoint.test.util.TestUtil;
 import com.evolveum.midpoint.util.exception.CommonException;
@@ -5796,6 +5789,14 @@ protected UserAsserter<Void> assertUser(String oid, String message) throws Objec
 		PrismObject<UserType> user = getUser(oid);
 		return assertUser(user, message);
 	}
+	protected RepoOpAsserter createRepoOpAsserter(PerformanceInformation performanceInformation, String details) {
+		return new RepoOpAsserter(performanceInformation, details);
+	}
+
+	protected RepoOpAsserter createRepoOpAsserter(String details) {
+		PerformanceInformation repoPerformanceInformation = repositoryService.getPerformanceMonitor().getThreadLocalPerformanceInformation();
+		return new RepoOpAsserter(repoPerformanceInformation, details);
+	}
 
 	protected UserAsserter<Void> assertUser(PrismObject<UserType> user, String message) throws ObjectNotFoundException, SchemaException, SecurityViolationException, CommunicationException, ConfigurationException, ExpressionEvaluationException {
 		UserAsserter<Void> asserter = UserAsserter.forUser(user, message);

diff --git a/...pi/src/main/java/com/evolveum/midpoint/repo/api/perf/OperationPerformanceInformation.java b/...pi/src/main/java/com/evolveum/midpoint/repo/api/perf/OperationPerformanceInformation.java
@@ -17,14 +17,15 @@
 package com.evolveum.midpoint.repo.api.perf;
 
 import com.evolveum.midpoint.util.ShortDumpable;
+import com.evolveum.midpoint.util.exception.SystemException;
 import com.evolveum.midpoint.xml.ns._public.common.common_3.RepositoryOperationPerformanceInformationType;
 
 import java.util.Locale;
 
 /**
  *  Experimental.
  */
-public class OperationPerformanceInformation implements ShortDumpable {
+public class OperationPerformanceInformation implements ShortDumpable, Cloneable {
 
 	private int invocationCount;
 	private int executionCount;
@@ -132,4 +133,12 @@ private String percent(long value, long base) {
 			return "NaN%";
 		}
 	}
+
+	public OperationPerformanceInformation clone() {
+		try {
+			return (OperationPerformanceInformation) super.clone();
+		} catch (CloneNotSupportedException e) {
+			throw new SystemException(e);
+		}
+	}
 }
diff --git a/repo/repo-api/src/main/java/com/evolveum/midpoint/repo/api/perf/PerformanceInformation.java b/repo/repo-api/src/main/java/com/evolveum/midpoint/repo/api/perf/PerformanceInformation.java
@@ -24,11 +24,15 @@
 /**
  *
  */
-public interface PerformanceInformation extends DebugDumpable {
+public interface PerformanceInformation extends DebugDumpable, Cloneable {
 
 	void clear();
 
 	Map<String, OperationPerformanceInformation> getAllData();
 
 	RepositoryPerformanceInformationType toRepositoryPerformanceInformationType();
+
+	int getInvocationCount(String operation);
+
+	PerformanceInformation clone();
 }
diff --git a/.../repo-sql-impl/src/main/java/com/evolveum/midpoint/repo/sql/SqlRepositoryServiceImpl.java b/.../repo-sql-impl/src/main/java/com/evolveum/midpoint/repo/sql/SqlRepositoryServiceImpl.java
@@ -199,13 +199,11 @@ public <T extends ObjectType> PrismObject<T> getObject(Class<T> type, String oid
 
         PrismObject<T> object = null;
         try {
-
-		    PrismObject<T> attemptobject = executeAttempts(oid, OP_GET_OBJECT, type, "getting",
-				    subResult, () -> objectRetriever.getObjectAttempt(type, oid, options, subResult)
-		    );
-		    object = attemptobject;
-		    invokeConflictWatchers((w) -> w.afterGetObject(attemptobject));
-
+            // "objectLocal" is here just to provide effectively final variable for the lambda below
+		    PrismObject<T> objectLocal = executeAttempts(oid, OP_GET_OBJECT, type, "getting",
+				    subResult, () -> objectRetriever.getObjectAttempt(type, oid, options, subResult));
+            object = objectLocal;
+		    invokeConflictWatchers((w) -> w.afterGetObject(objectLocal));
         } finally {
         	OperationLogger.logGetObject(type, oid, options, object, subResult);
         }

diff --git a/...ql-impl/src/main/java/com/evolveum/midpoint/repo/sql/perf/PerformanceInformationImpl.java b/...ql-impl/src/main/java/com/evolveum/midpoint/repo/sql/perf/PerformanceInformationImpl.java
@@ -75,4 +75,31 @@ public String debugDump(int indent) {
 		}
 		return sb.toString();
 	}
+
+	@Override
+	public int getInvocationCount(String operation) {
+		OperationPerformanceInformation info = operationMap.get(operation);
+		if (info != null) {
+			return info.getInvocationCount();
+		} else if (operation.contains(".")) {
+			return 0;       // we expect only single level of aggregation
+		} else {
+			String prefix = operation + ".";
+			int rv = 0;
+			for (Map.Entry<String, OperationPerformanceInformation> entry : operationMap.entrySet()) {
+				if (entry.getKey().startsWith(prefix)) {
+					rv += entry.getValue().getInvocationCount();
+				}
+			}
+			return rv;
+		}
+	}
+
+	@SuppressWarnings("MethodDoesntCallSuperMethod")
+	@Override
+	public PerformanceInformation clone() {
+		PerformanceInformationImpl clone = new PerformanceInformationImpl();
+		operationMap.forEach((op, opPerfInfo) -> clone.operationMap.put(op, opPerfInfo.clone()));
+		return clone;
+	}
 }
diff --git a/repo/repo-test-util/src/main/java/com/evolveum/midpoint/test/AbstractIntegrationTest.java b/repo/repo-test-util/src/main/java/com/evolveum/midpoint/test/AbstractIntegrationTest.java
@@ -1802,6 +1802,29 @@ protected Task createTask(String operationName) {
 		return task;
 	}
 
+	protected Task createTracedTask(String operationName) {
+		Task task = createTask(operationName);
+		task.addTracingRequest(TracingRootType.CLOCKWORK_RUN);
+		task.setTracingProfile(new TracingProfileType()
+				.collectLogEntries(true)
+				.createRepoObject(false)        // to avoid influencing repo statistics
+//				.beginLoggingOverride()
+//					.beginLevelOverride()
+//						.logger("org.hibernate.SQL")
+//						.level(LoggingLevelType.TRACE)
+//					.<LoggingOverrideType>end()
+//					.beginLevelOverride()
+//						.logger("org.hibernate.type")
+//						.level(LoggingLevelType.TRACE)
+//					.<LoggingOverrideType>end()
+//				.<TracingProfileType>end()
+				.beginTracingTypeProfile()
+					.level(TracingLevelType.NORMAL)
+				.<TracingProfileType>end()
+				.fileNamePattern("trace %{timestamp} %{testNameShort} %{focusName} %{milliseconds}"));
+		return task;
+	}
+
 	protected void assertSuccess(OperationResult result) {
 		if (result.isUnknown()) {
 			result.computeStatus();

diff --git a/repo/repo-test-util/src/main/java/com/evolveum/midpoint/test/asserter/AbstractAsserter.java b/repo/repo-test-util/src/main/java/com/evolveum/midpoint/test/asserter/AbstractAsserter.java
@@ -130,4 +130,10 @@ protected <T> void copySetupTo(AbstractAsserter<T> other) {
 		other.setProtector(this.getProtector());
 		other.setClock(this.getClock());
 	}
+
+	protected void assertMinMax(String message, int expectedMin, int expectedMax, int value) {
+		if (value < expectedMin || value > expectedMax) {
+			fail(message + ": expected " + expectedMin + "-" + expectedMax + ", real value is " + value);
+		}
+	}
 }
diff --git a/repo/repo-test-util/src/main/java/com/evolveum/midpoint/test/asserter/RepoOpAsserter.java b/repo/repo-test-util/src/main/java/com/evolveum/midpoint/test/asserter/RepoOpAsserter.java
@@ -0,0 +1,59 @@
+/*
+ * Copyright (c) 2010-2019 Evolveum
+ *
+ * Licensed 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 com.evolveum.midpoint.test.asserter;
+
+import com.evolveum.midpoint.repo.api.perf.PerformanceInformation;
+import com.evolveum.midpoint.schema.statistics.RepositoryPerformanceInformationUtil;
+import com.evolveum.midpoint.test.IntegrationTestTools;
+
+import static org.testng.AssertJUnit.assertEquals;
+
+/**
+ *  Asserter that checks repository operation counts.
+ *  EXPERIMENTAL
+ */
+public class RepoOpAsserter extends AbstractAsserter<Void> {
+
+    private final PerformanceInformation repoPerformanceInformation;
+
+    public RepoOpAsserter(PerformanceInformation repoPerformanceInformation, String details) {
+        super(details);
+        this.repoPerformanceInformation = repoPerformanceInformation.clone();       // cloning to gather current state
+    }
+
+    public RepoOpAsserter assertOp(String operation, int expected) {
+        assertEquals("Wrong number of invocations of " + operation, expected, repoPerformanceInformation.getInvocationCount(operation));
+        return this;
+    }
+
+    public RepoOpAsserter assertOp(String operation, int expectedMin, int expectedMax) {
+        assertMinMax("Wrong number of invocations of " + operation, expectedMin, expectedMax,
+                repoPerformanceInformation.getInvocationCount(operation));
+        return this;
+    }
+
+    @Override
+    protected String desc() {
+        return getDetails();
+    }
+
+    public RepoOpAsserter display() {
+        IntegrationTestTools.display(desc(),
+                RepositoryPerformanceInformationUtil.format(repoPerformanceInformation.toRepositoryPerformanceInformationType()));
+        return this;
+    }
+}
diff --git a/testing/story/src/test/java/com/evolveum/midpoint/testing/story/AbstractStoryTest.java b/testing/story/src/test/java/com/evolveum/midpoint/testing/story/AbstractStoryTest.java
@@ -22,12 +22,17 @@
 import com.evolveum.midpoint.prism.path.ItemPath;
 import com.evolveum.midpoint.prism.query.ObjectQuery;
 import com.evolveum.midpoint.prism.util.PrismUtil;
+import com.evolveum.midpoint.repo.api.perf.PerformanceInformation;
+import com.evolveum.midpoint.repo.api.perf.PerformanceMonitor;
 import com.evolveum.midpoint.schema.SearchResultList;
 import com.evolveum.midpoint.schema.constants.ObjectTypes;
 import com.evolveum.midpoint.schema.result.OperationResult;
+import com.evolveum.midpoint.schema.statistics.CachePerformanceInformationUtil;
+import com.evolveum.midpoint.schema.statistics.RepositoryPerformanceInformationUtil;
 import com.evolveum.midpoint.schema.util.ObjectTypeUtil;
 import com.evolveum.midpoint.task.api.Task;
 import com.evolveum.midpoint.util.DOMUtil;
+import com.evolveum.midpoint.util.caching.CachePerformanceCollector;
 import com.evolveum.midpoint.util.exception.ObjectAlreadyExistsException;
 import com.evolveum.midpoint.util.exception.SchemaException;
 import com.evolveum.midpoint.xml.ns._public.common.common_3.*;
@@ -186,6 +191,41 @@ protected Map<String, CaseWorkItemType> sortByOriginalAssignee(Collection<CaseWo
 		workItems.forEach(wi -> rv.put(wi.getOriginalAssigneeRef().getOid(), wi));
 		return rv;
 	}
-	//endregion
+    //endregion
 
+	protected PerformanceMonitor getRepoPerformanceMonitor() {
+		return repositoryService.getPerformanceMonitor();
+	}
+
+	protected void resetGlobalCachePerformanceCollector() {
+		CachePerformanceCollector.INSTANCE.clear();
+	}
+
+	protected void dumpGlobalCachePerformanceData(String testName) {
+		display("Cache performance data for " + testName + " (got from cache performance collector)", CachePerformanceCollector.INSTANCE);
+	}
+
+	protected void dumpThreadLocalCachePerformanceData(String testName) {
+		dumpCachePerformanceData(testName, CachePerformanceCollector.INSTANCE.getThreadLocalPerformanceMap());
+	}
+
+	protected void resetThreadLocalPerformanceData() {
+		getRepoPerformanceMonitor().startThreadLocalPerformanceInformationCollection();
+		CachePerformanceCollector.INSTANCE.startThreadLocalPerformanceInformationCollection();
+	}
+
+	protected PerformanceInformation dumpThreadLocalPerformanceData(String testName) {
+		PerformanceInformation performanceInformation = getRepoPerformanceMonitor().getThreadLocalPerformanceInformation();
+		dumpRepoPerformanceData("Repo operations for " + testName, performanceInformation);
+		dumpCachePerformanceData(testName, CachePerformanceCollector.INSTANCE.getThreadLocalPerformanceMap());
+		return performanceInformation;
+	}
+
+	protected void dumpRepoPerformanceData(String label, PerformanceInformation performanceInformation) {
+		display(label, RepositoryPerformanceInformationUtil.format(performanceInformation.toRepositoryPerformanceInformationType()));
+	}
+
+	protected void dumpCachePerformanceData(String label, Map<String, CachePerformanceCollector.CacheData> performanceMap) {
+		display(label, CachePerformanceInformationUtil.format(performanceMap));
+	}
 }