Skip to content

Commit

Permalink
TestOperationPerf story test
Browse files Browse the repository at this point in the history
  • Loading branch information
@semancik
semancik committed Feb 28, 2018
1 parent 1165497 commit 3fd7362
Show file tree
Hide file tree
Showing 22 changed files with 721 additions and 227 deletions.
16 changes: 14 additions & 2 deletions infra/schema/src/main/java/com/evolveum/midpoint/schema/internals/CachingStatistics.java
View file
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2010-2013 Evolveum
* Copyright (c) 2010-2018 Evolveum
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand All @@ -15,11 +15,14 @@
*/
package com.evolveum.midpoint.schema.internals;

import com.evolveum.midpoint.util.DebugDumpable;
import com.evolveum.midpoint.util.DebugUtil;

/**
* @author semancik
*
*/
public class CachingStatistics {
public class CachingStatistics implements DebugDumpable {

private long requests = 0;
private long hits = 0;
Expand Down Expand Up @@ -74,4 +77,13 @@ public String toString() {
return "CachingStatistics(requests=" + requests + ", hits=" + hits + ", misses=" + misses + ")";
}

@Override
public String debugDump(int indent) {
StringBuilder sb = DebugUtil.createTitleStringBuilderLn(CachingStatistics.class, indent);
DebugUtil.debugDumpWithLabelLn(sb, "requests", requests, indent);
DebugUtil.debugDumpWithLabelLn(sb, "hits", hits, indent);
DebugUtil.debugDumpWithLabel(sb, "misses", misses, indent);
return sb.toString();
}

}
46 changes: 32 additions & 14 deletions infra/schema/src/main/java/com/evolveum/midpoint/schema/internals/InternalMonitor.java
View file
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2010-2017 Evolveum
* Copyright (c) 2010-2018 Evolveum
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -49,7 +49,8 @@ public class InternalMonitor implements PrismMonitor, DebugDumpable {
private static CachingStatistics resourceCacheStats = new CachingStatistics();
private static CachingStatistics connectorCacheStats = new CachingStatistics();

private static long prismObjectCloneDurationMillis = 0;
private static boolean cloneTimingEnabled = false;
private static long prismObjectCloneDurationNanos = 0;

private static InternalInspector inspector;

Expand Down Expand Up @@ -172,32 +173,45 @@ public synchronized <O extends Objectable> void recordPrismObjectCompareCount(Pr
recordCountInternal(InternalCounters.PRISM_OBJECT_COMPARE_COUNT);
}

public static boolean isCloneTimingEnabled() {
return cloneTimingEnabled;
}

public static void setCloneTimingEnabled(boolean cloneTimingEnabled) {
InternalMonitor.cloneTimingEnabled = cloneTimingEnabled;
}

public static long getPrismObjectCloneDurationMillis() {
return prismObjectCloneDurationMillis;
return prismObjectCloneDurationNanos;
}

public static void setPrismObjectCloneDurationMillis(long prismObjectCloneDurationMillis) {
InternalMonitor.prismObjectCloneDurationMillis = prismObjectCloneDurationMillis;
public static void setPrismObjectCloneDurationMillis(long prismObjectCloneDurationNanos) {
InternalMonitor.prismObjectCloneDurationNanos = prismObjectCloneDurationNanos;
}

@Override
public <O extends Objectable> void beforeObjectClone(PrismObject<O> orig) {
if (!cloneTimingEnabled) {
return;
}
LOGGER.trace("MONITOR prism object clone start: {}", orig);
if (!orig.isImmutable()) {
orig.setUserData(CLONE_START_TIMESTAMP_KEY, System.currentTimeMillis());
orig.setUserData(CLONE_START_TIMESTAMP_KEY, System.nanoTime());
}
}

@Override
public synchronized <O extends Objectable> void afterObjectClone(PrismObject<O> orig, PrismObject<O> clone) {
long count = recordCountInternal(InternalCounters.PRISM_OBJECT_CLONE_COUNT);
Object cloneStartObject = orig.getUserData(CLONE_START_TIMESTAMP_KEY);
if (cloneStartObject != null && cloneStartObject instanceof Long) {
long cloneDurationMillis = System.currentTimeMillis() - (Long)cloneStartObject;
prismObjectCloneDurationMillis += cloneDurationMillis;
LOGGER.debug("MONITOR prism object clone end: {} (duration {} ms)", orig, cloneDurationMillis);
} else {
LOGGER.debug("MONITOR prism object clone end: {}", orig);
if (cloneTimingEnabled) {
Object cloneStartObject = orig.getUserData(CLONE_START_TIMESTAMP_KEY);
if (cloneStartObject != null && cloneStartObject instanceof Long) {
long cloneDurationNanos = System.nanoTime() - (Long)cloneStartObject;
prismObjectCloneDurationNanos += cloneDurationNanos;
LOGGER.debug("MONITOR prism object clone end: {} (duration {} ns)", orig, cloneDurationNanos);
} else {
LOGGER.debug("MONITOR prism object clone end: {}", orig);
}
}
if (isTrace(InternalCounters.PRISM_OBJECT_CLONE_COUNT)) {
traceOperation("prism object clone", null, count, false);
Expand Down Expand Up @@ -257,7 +271,11 @@ public static String debugDumpStatic(int indent) {
sb.append("\n");
DebugUtil.debugDumpWithLabel(sb, trace.getLabel(), isTrace(trace), indent + 2);
}
// TODO
sb.append("\n");
DebugUtil.debugDumpWithLabelLn(sb, "cloneTimingEnabled", cloneTimingEnabled, indent + 1);
DebugUtil.debugDumpWithLabelLn(sb, "prismObjectCloneDuration", (prismObjectCloneDurationNanos/1000000)+" ms (" + prismObjectCloneDurationNanos + " ns)", indent + 1);
DebugUtil.debugDumpWithLabelLn(sb, "resourceCacheStats", resourceCacheStats, indent + 1);
DebugUtil.debugDumpWithLabel(sb, "connectorCacheStats", connectorCacheStats, indent + 1);
return sb.toString();
}
}
42 changes: 18 additions & 24 deletions model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/Clockwork.java
View file
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2010-2017 Evolveum
* Copyright (c) 2010-2018 Evolveum
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -150,6 +150,7 @@ public class Clockwork {
@Autowired private OperationalDataManager metadataManager;
@Autowired private ContextFactory contextFactory;
@Autowired private Migrator migrator;
@Autowired private ClockworkMedic medic;

@Autowired(required = false)
private HookRegistry hookRegistry;
Expand All @@ -158,15 +159,7 @@ public class Clockwork {
@Qualifier("cacheRepositoryService")
private transient RepositoryService repositoryService;

private LensDebugListener debugListener;

public LensDebugListener getDebugListener() {
return debugListener;
}

public void setDebugListener(LensDebugListener debugListener) {
this.debugListener = debugListener;
}


private static final int DEFAULT_MAX_CLICKS = 200;

Expand Down Expand Up @@ -404,8 +397,8 @@ public <F extends ObjectType> HookOperationMode click(LensContext<F> context, Ta
// DO NOT CHECK CONSISTENCY of the context here. The context may not be fresh and consistent yet. Project will fix
// that. Check consistency afterwards (and it is also checked inside projector several times).

if (context.getDebugListener() == null) {
context.setDebugListener(debugListener);
if (context.getInspector() == null) {
context.setInspector(medic.getClockworkInspector());
}

try {
Expand All @@ -419,9 +412,7 @@ public <F extends ObjectType> HookOperationMode click(LensContext<F> context, Ta

ModelState state = context.getState();
if (state == ModelState.INITIAL) {
if (debugListener != null) {
debugListener.beforeSync(context);
}
medic.clockworkStart(context);
metadataManager.setRequestMetadataInContext(context, now, task);
context.getStats().setRequestTimestamp(now);
// We need to do this BEFORE projection. If we would do that after projection
Expand Down Expand Up @@ -455,7 +446,7 @@ public <F extends ObjectType> HookOperationMode click(LensContext<F> context, Ta
authorizeContextRequest(context, task, result);
}

LensUtil.traceContext(LOGGER, "CLOCKWORK (" + state + ")", "before processing", true, context, false);
medic.traceContext(LOGGER, "CLOCKWORK (" + state + ")", "before processing", true, context, false);
if (InternalsConfig.consistencyChecks) {
try {
context.checkConsistence();
Expand All @@ -481,9 +472,7 @@ public <F extends ObjectType> HookOperationMode click(LensContext<F> context, Ta
break;
case FINAL:
HookOperationMode mode = processFinal(context, task, result);
if (debugListener != null) {
debugListener.afterSync(context);
}
medic.clockworkFinish(context);
return mode;
}
result.recomputeStatus();
Expand Down Expand Up @@ -611,27 +600,32 @@ private void evaluateScriptingHook(LensContext context, HookType hookType,
LOGGER.trace("Finished evaluation of {}", shortDesc);
}

private <F extends ObjectType> void switchState(LensContext<F> context, ModelState newState) {
medic.clockworkStateSwitch(context, newState);
context.setState(newState);
}

private <F extends ObjectType> void processInitialToPrimary(LensContext<F> context, Task task, OperationResult result) {
// Context loaded, nothing special do. Bump state to PRIMARY.
context.setState(ModelState.PRIMARY);
switchState(context, ModelState.PRIMARY);
}

private <F extends ObjectType> void processPrimaryToSecondary(LensContext<F> context, Task task, OperationResult result) {
// Nothing to do now. The context is already recomputed.
context.setState(ModelState.SECONDARY);
switchState(context, ModelState.SECONDARY);
}

private <F extends ObjectType> void processSecondary(LensContext<F> context, Task task, OperationResult result)
throws ObjectAlreadyExistsException, ObjectNotFoundException, SchemaException, CommunicationException, ConfigurationException,
SecurityViolationException, ExpressionEvaluationException, PolicyViolationException, PreconditionViolationException {
if (context.getExecutionWave() > context.getMaxWave() + 1) {
context.setState(ModelState.FINAL);
switchState(context, ModelState.FINAL);
return;
}

Holder<Boolean> restartRequestedHolder = new Holder<>();

LensUtil.partialExecute("execution",
medic.partialExecute("execution",
() -> {
boolean restartRequested = changeExecutor.executeChanges(context, task, result);
restartRequestedHolder.setValue(restartRequested);
Expand All @@ -654,7 +648,7 @@ private <F extends ObjectType> void processSecondary(LensContext<F> context, Tas
// explicitly rot context?
}

LensUtil.traceContext(LOGGER, "CLOCKWORK (" + context.getState() + ")", "change execution", false, context, false);
medic.traceContext(LOGGER, "CLOCKWORK (" + context.getState() + ")", "change execution", false, context, false);
}

/**
Expand Down
21 changes: 15 additions & 6 deletions ...nt/model/impl/lens/LensDebugListener.java → ...t/model/impl/lens/ClockworkInspector.java
View file
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2010-2015 Evolveum
* Copyright (c) 2010-2018 Evolveum
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand All @@ -15,6 +15,7 @@
*/
package com.evolveum.midpoint.model.impl.lens;

import com.evolveum.midpoint.model.api.context.ModelState;
import com.evolveum.midpoint.model.common.mapping.Mapping;
import com.evolveum.midpoint.xml.ns._public.common.common_3.ObjectType;

Expand All @@ -28,15 +29,23 @@
* @author Radovan Semancik
*
*/
public interface LensDebugListener {
public interface ClockworkInspector {

public <F extends ObjectType> void beforeSync(LensContext<F> context);
<F extends ObjectType> void clockworkStart(LensContext<F> context);

<F extends ObjectType> void clockworkStateSwitch(LensContext<F> contextBefore, ModelState newState);

public <F extends ObjectType> void afterSync(LensContext<F> context);
<F extends ObjectType> void clockworkFinish(LensContext<F> context);

public <F extends ObjectType> void beforeProjection(LensContext<F> context);
<F extends ObjectType> void projectorStart(LensContext<F> context);

void projectorComponentSkip(String componentName);

void projectorComponentStart(String componentName);

void projectorComponentFinish(String componentName);

public <F extends ObjectType> void afterProjection(LensContext<F> context);
<F extends ObjectType> void projectorFinish(LensContext<F> context);

/**
* May be used to gather profiling data, etc.
Expand Down

0 comments on commit 3fd7362

Please sign in to comment.