Skip to content

Commit

Permalink
Improve getVersion performance + reporting
Browse files Browse the repository at this point in the history 
- getVersion is now fulfilled from global cache, if possible
- model audit operations are recorded
- cache usage is reported better
- hasConflict is reported (it was not)
  • Loading branch information
@mederly
mederly committed Jun 25, 2019
1 parent 19ab9b3 commit a8a4232
Show file tree
Hide file tree
Showing 12 changed files with 386 additions and 95 deletions.
26 changes: 26 additions & 0 deletions infra/schema/src/main/java/com/evolveum/midpoint/schema/result/OperationResult.java
View file
Expand Up @@ -92,6 +92,7 @@ public class OperationResult implements Serializable, DebugDumpable, ShortDumpab
public static final String CONTEXT_ITEM = "item";
public static final String CONTEXT_TASK = "task";
public static final String CONTEXT_RESOURCE = "resource";
public static final String CONTEXT_REASON = "reason";

public static final String PARAM_OID = "oid";
public static final String PARAM_NAME = "name";
Expand Down Expand Up @@ -145,6 +146,14 @@ public class OperationResult implements Serializable, DebugDumpable, ShortDumpab

private final List<TraceType> traces = new ArrayList<>();

// Caller can specify the reason of the operation invocation.
// (Normally, the reason is known from the parent opResult; but it might be an overkill to create operation result
// only to specify the reason.)
//
// Use of this attribute assumes that the callee will ALWAYS create OperationResult as its first step.
// TODO reconsider ... it looks like a really ugly hack
private transient String callerReason;

/**
* Reference to an asynchronous operation that can be used to retrieve
* the status of the running operation. This may be a task identifier,
Expand Down Expand Up @@ -223,10 +232,18 @@ public OperationResult build() {
building = false;
if (futureParent != null) {
futureParent.addSubresult(this);
recordCallerReason(futureParent);
}
return this;
}

private void recordCallerReason(OperationResult parent) {
if (parent.getCallerReason() != null) {
addContext(CONTEXT_REASON, parent.getCallerReason());
parent.setCallerReason(null);
}
}

private static void recordStart(OperationResult result, String operation, Object[] arguments) {
result.invocationRecord = OperationInvocationRecord.create(operation, arguments);
result.invocationId = result.invocationRecord.getInvocationId();
Expand Down Expand Up @@ -264,6 +281,7 @@ public static OperationResult createProfiled(String operation, Object[] argument

private OperationResult createSubresult(String operation, boolean minor, boolean profiled, Object[] arguments) {
OperationResult subresult = new OperationResult(operation);
subresult.recordCallerReason(this);
addSubresult(subresult);
if (profiled) {
recordStart(subresult, operation, arguments);
Expand Down Expand Up @@ -2166,4 +2184,12 @@ public List<TraceType> getTraces() {
public List<String> getQualifiers() {
return qualifiers;
}

public String getCallerReason() {
return callerReason;
}

public void setCallerReason(String callerReason) {
this.callerReason = callerReason;
}
}
131 changes: 124 additions & 7 deletions infra/schema/src/main/resources/xml/ns/public/common/common-model-context-3.xsd
View file
Expand Up @@ -960,7 +960,22 @@
</xsd:documentation>
</xsd:annotation>
</xsd:element>
<xsd:element name="cacheUse" type="tns:CacheUseTraceType" minOccurs="0">
<xsd:element name="cacheUse" type="xsd:string" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
How was the cache used?
DEPRECATED - remove!
</xsd:documentation>
</xsd:annotation>
</xsd:element>
<xsd:element name="globalCacheUse" type="tns:CacheUseTraceType" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
How was the cache used?
</xsd:documentation>
</xsd:annotation>
</xsd:element>
<xsd:element name="localCacheUse" type="tns:CacheUseTraceType" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
How was the cache used?
Expand Down Expand Up @@ -1096,10 +1111,10 @@
</xsd:complexType>
<xsd:element name="repositoryDeleteTrace" type="tns:RepositoryDeleteTraceType" />

<xsd:complexType name="RepositoryGetTraceType">
<xsd:complexType name="RepositoryGetObjectTraceType">
<xsd:annotation>
<xsd:documentation>
Trace for repository GET (getObject) operation.
Trace for repository getObject operation.
</xsd:documentation>
<xsd:appinfo>
<a:experimental>true</a:experimental>
Expand Down Expand Up @@ -1142,12 +1157,96 @@
</xsd:extension>
</xsd:complexContent>
</xsd:complexType>
<xsd:element name="repositoryGetObjectTrace" type="tns:RepositoryGetObjectTraceType" />

<xsd:complexType name="RepositoryGetTraceType">
<xsd:annotation>
<xsd:documentation>
TEMPORARY - REMOVE
</xsd:documentation>
<xsd:appinfo>
<a:experimental>true</a:experimental>
<a:container>true</a:container>
<a:since>4.0</a:since>
</xsd:appinfo>
</xsd:annotation>
<xsd:complexContent>
<xsd:extension base="tns:RepositoryGetObjectTraceType">
</xsd:extension>
</xsd:complexContent>
</xsd:complexType>
<xsd:element name="repositoryGetTrace" type="tns:RepositoryGetTraceType" />

<xsd:complexType name="RepositorySearchTraceType">
<xsd:annotation>
<xsd:documentation>
Trace for repository SEARCH (searchObjects/searchObjectsIterative) operation.
TEMPORARY - REMOVE
</xsd:documentation>
<xsd:appinfo>
<a:experimental>true</a:experimental>
<a:container>true</a:container>
<a:since>4.0</a:since>
</xsd:appinfo>
</xsd:annotation>
<xsd:complexContent>
<xsd:extension base="tns:RepositorySearchObjectsTraceType">
</xsd:extension>
</xsd:complexContent>
</xsd:complexType>
<xsd:element name="repositorySearchTrace" type="tns:RepositorySearchTraceType" />

<xsd:complexType name="RepositoryGetVersionTraceType">
<xsd:annotation>
<xsd:documentation>
Trace for repository getVersion operation.
</xsd:documentation>
<xsd:appinfo>
<a:experimental>true</a:experimental>
<a:container>true</a:container>
<a:since>4.0</a:since>
</xsd:appinfo>
</xsd:annotation>
<xsd:complexContent>
<xsd:extension base="tns:RepositoryOperationTraceType">
<xsd:sequence>
<xsd:element name="objectType" type="xsd:QName" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
Type of the object to be deleted.
</xsd:documentation>
</xsd:annotation>
</xsd:element>
<xsd:element name="oid" type="xsd:string" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
OID of the object to be deleted.
</xsd:documentation>
</xsd:annotation>
</xsd:element>
<xsd:element name="options" type="xsd:string" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
Options (stringified).
</xsd:documentation>
</xsd:annotation>
</xsd:element>
<xsd:element name="version" type="xsd:string" minOccurs="0">
<xsd:annotation>
<xsd:documentation>
Object version that was retrieved.
</xsd:documentation>
</xsd:annotation>
</xsd:element>
</xsd:sequence>
</xsd:extension>
</xsd:complexContent>
</xsd:complexType>
<xsd:element name="repositoryGetVersionTrace" type="tns:RepositoryGetVersionTraceType" />

<xsd:complexType name="RepositorySearchObjectsTraceType">
<xsd:annotation>
<xsd:documentation>
Trace for repository searchObjects/searchObjectsIterative operation.
</xsd:documentation>
<xsd:appinfo>
<a:experimental>true</a:experimental>
Expand Down Expand Up @@ -1198,7 +1297,7 @@
</xsd:extension>
</xsd:complexContent>
</xsd:complexType>
<xsd:element name="repositorySearchTrace" type="tns:RepositorySearchTraceType" />
<xsd:element name="repositorySearchObjectsTrace" type="tns:RepositorySearchObjectsTraceType" />

<xsd:complexType name="MappingEvaluationTraceType">
<xsd:annotation>
Expand Down Expand Up @@ -1240,9 +1339,27 @@
</xsd:extension>
</xsd:complexContent>
</xsd:complexType>
<xsd:element name="scriptgEvaluationTrace" type="tns:ScriptEvaluationTraceType" />
<xsd:element name="scriptEvaluationTrace" type="tns:ScriptEvaluationTraceType" />

<xsd:complexType name="CacheUseTraceType">
<xsd:annotation>
<xsd:documentation>

</xsd:documentation>
<xsd:appinfo>
<a:experimental>true</a:experimental>
<a:container>true</a:container>
<a:since>4.0</a:since>
</xsd:appinfo>
</xsd:annotation>
<xsd:sequence>
<xsd:element name="category" type="tns:CacheUseCategoryTraceType" minOccurs="0" />
<xsd:element name="comment" type="xsd:string" minOccurs="0"/>
</xsd:sequence>
</xsd:complexType>
<xsd:element name="cacheUseTrace" type="tns:CacheUseTraceType" />

<xsd:simpleType name="CacheUseTraceType">
<xsd:simpleType name="CacheUseCategoryTraceType">
<xsd:annotation>
<xsd:documentation>
How was the cache used?
Expand Down
2 changes: 1 addition & 1 deletion ...model-impl/src/main/java/com/evolveum/midpoint/model/impl/controller/AuditController.java
View file
Expand Up @@ -75,7 +75,7 @@ public class AuditController implements ModelAuditService {
@Override
public void audit(AuditEventRecord record, Task task, OperationResult result) throws SecurityViolationException, SchemaException, ObjectNotFoundException, ExpressionEvaluationException, CommunicationException, ConfigurationException {
authorize(ModelAuthorizationAction.AUDIT_RECORD, task, result);
auditHelper.audit(record, task);
auditHelper.audit(record, task, result);
}

@Override
Expand Down
4 changes: 2 additions & 2 deletions ...model-impl/src/main/java/com/evolveum/midpoint/model/impl/controller/ModelController.java
View file
Expand Up @@ -412,7 +412,7 @@ public Collection<ObjectDeltaOperation<? extends ObjectType>> executeChanges(fin
auditRecord.addDeltas(ObjectDeltaOperation.cloneDeltaCollection(deltas));
auditRecord.setTarget(ModelImplUtils.determineAuditTarget(deltas, prismContext));
// we don't know auxiliary information (resource, objectName) at this moment -- so we do nothing
auditHelper.audit(auditRecord, task);
auditHelper.audit(auditRecord, task, result);
try {
for (ObjectDelta<? extends ObjectType> delta : deltas) {
OperationResult result1 = result.createSubresult(EXECUTE_CHANGE);
Expand Down Expand Up @@ -540,7 +540,7 @@ public Collection<ObjectDeltaOperation<? extends ObjectType>> executeChanges(fin
auditRecord.setEventStage(AuditEventStage.EXECUTION);
auditRecord.getDeltas().clear();
auditRecord.getDeltas().addAll(executedDeltas);
auditHelper.audit(auditRecord, task);
auditHelper.audit(auditRecord, task, result);

task.markObjectActionExecutedBoundary();
}
Expand Down
4 changes: 2 additions & 2 deletions model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/Clockwork.java
View file
Expand Up @@ -1241,7 +1241,7 @@ private <F extends ObjectType> void processClockworkException(LensContext<F> con
//
// We provide "result" here just for completeness - if any of the called methods would like to record to it.
private <F extends ObjectType> void auditEvent(LensContext<F> context, AuditEventStage stage,
XMLGregorianCalendar timestamp, boolean alwaysAudit, Task task, @SuppressWarnings("unused") OperationResult result,
XMLGregorianCalendar timestamp, boolean alwaysAudit, Task task, OperationResult result,
OperationResult overallResult) throws SchemaException {

PrismObject<? extends ObjectType> primaryObject;
Expand Down Expand Up @@ -1326,7 +1326,7 @@ private <F extends ObjectType> void auditEvent(LensContext<F> context, AuditEven

addRecordMessage(auditRecord, clone.getMessage());

auditHelper.audit(auditRecord, task);
auditHelper.audit(auditRecord, task, result);

if (stage == AuditEventStage.EXECUTION) {
// We need to clean up so these deltas will not be audited again in next wave
Expand Down
4 changes: 2 additions & 2 deletions model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/security/SecurityHelper.java
View file
Expand Up @@ -117,7 +117,7 @@ private void auditLogin(@Nullable String username, @Nullable UserType user, @Not
record.setMessage(message);
storeConnectionEnvironment(record, connEnv);

auditHelper.audit(record, task);
auditHelper.audit(record, task, new OperationResult(SecurityHelper.class.getName() + ".auditLogin"));
}

@Override
Expand All @@ -127,7 +127,7 @@ public void auditLogout(ConnectionEnvironment connEnv, Task task) {
record.setTimestamp(System.currentTimeMillis());
record.setOutcome(OperationResultStatus.SUCCESS);
storeConnectionEnvironment(record, connEnv);
auditHelper.audit(record, task);
auditHelper.audit(record, task, new OperationResult(SecurityHelper.class.getName() + ".auditLogout"));
}

private void storeConnectionEnvironment(AuditEventRecord record, ConnectionEnvironment connEnv) {
Expand Down
26 changes: 13 additions & 13 deletions ...l-impl/src/main/java/com/evolveum/midpoint/model/impl/sync/ReconciliationTaskHandler.java
View file
Expand Up @@ -273,7 +273,7 @@ public TaskWorkBucketProcessingResult run(RunningTask localCoordinatorTask, Work
AuditEventRecord requestRecord = new AuditEventRecord(AuditEventType.RECONCILIATION, AuditEventStage.REQUEST);
requestRecord.setTarget(resource, prismContext);
requestRecord.setMessage("Stage: " + stage + ", Work bucket: " + workBucket);
auditHelper.audit(requestRecord, localCoordinatorTask);
auditHelper.audit(requestRecord, localCoordinatorTask, opResult);

try {
if (isStage(stage, Stage.FIRST) && !scanForUnfinishedOperations(localCoordinatorTask, resourceOid, reconResult, opResult)) {
Expand Down Expand Up @@ -343,6 +343,12 @@ public TaskWorkBucketProcessingResult run(RunningTask localCoordinatorTask, Work
return runResult;
}

AuditEventRecord executionRecord = new AuditEventRecord(AuditEventType.RECONCILIATION, AuditEventStage.EXECUTION);
executionRecord.setTarget(resource, prismContext);
executionRecord.setOutcome(OperationResultStatus.SUCCESS);
executionRecord.setMessage(requestRecord.getMessage());
auditHelper.audit(executionRecord, localCoordinatorTask, opResult);

opResult.computeStatus();
// This "run" is finished. But the task goes on ...
runResult.setRunResultStatus(TaskRunResultStatus.FINISHED);
Expand All @@ -352,12 +358,6 @@ public TaskWorkBucketProcessingResult run(RunningTask localCoordinatorTask, Work
LOGGER.trace("Reconciliation.run stopping, result: {}", opResult.getStatus());
}

AuditEventRecord executionRecord = new AuditEventRecord(AuditEventType.RECONCILIATION, AuditEventStage.EXECUTION);
executionRecord.setTarget(resource, prismContext);
executionRecord.setOutcome(OperationResultStatus.SUCCESS);
executionRecord.setMessage(requestRecord.getMessage());
auditHelper.audit(executionRecord, localCoordinatorTask);

long reconEndTimestamp = clock.currentTimeMillis();

long etime = reconEndTimestamp - reconStartTimestamp;
Expand Down Expand Up @@ -479,17 +479,17 @@ private void processInterruption(TaskRunResult runResult, PrismObject<ResourceTy

private void processErrorFinal(TaskRunResult runResult, String errorDesc, Exception ex,
TaskRunResultStatus runResultStatus, PrismObject<ResourceType> resource, RunningTask task, OperationResult opResult) {
AuditEventRecord executionRecord = new AuditEventRecord(AuditEventType.RECONCILIATION, AuditEventStage.EXECUTION);
executionRecord.setTarget(resource, prismContext);
executionRecord.setOutcome(OperationResultStatus.FATAL_ERROR);
executionRecord.setMessage(ex.getMessage());
auditHelper.audit(executionRecord, task, opResult);

String message = errorDesc+": "+ex.getMessage();
LOGGER.error("Reconciliation: {}-{}", new Object[]{message, ex});
opResult.recordFatalError(message, ex);
TaskHandlerUtil.appendLastFailuresInformation(OperationConstants.RECONCILIATION, task, opResult); // TODO implement more seriously
runResult.setRunResultStatus(runResultStatus);

AuditEventRecord executionRecord = new AuditEventRecord(AuditEventType.RECONCILIATION, AuditEventStage.EXECUTION);
executionRecord.setTarget(resource, prismContext);
executionRecord.setOutcome(OperationResultStatus.FATAL_ERROR);
executionRecord.setMessage(ex.getMessage());
auditHelper.audit(executionRecord , task);
}

private void processErrorPartial(TaskRunResult runResult, String errorDesc, Exception ex,
Expand Down

0 comments on commit a8a4232

Please sign in to comment.