From 54353f8fce7605b6dd7e777c1bbfa9685487c989 Mon Sep 17 00:00:00 2001 From: Grahame Grieve Date: Wed, 25 Sep 2024 05:15:49 -0400 Subject: [PATCH] Add more logging for too costly validation --- .../expansion/ValueSetExpander.java | 26 +++++------ .../TerminologyOperationContext.java | 22 +++++++++- .../validation/ValueSetValidator.java | 44 ++++++++++++------- 3 files changed, 60 insertions(+), 32 deletions(-) diff --git a/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/expansion/ValueSetExpander.java b/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/expansion/ValueSetExpander.java index 7e1cfbbf7..82fd94efd 100644 --- a/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/expansion/ValueSetExpander.java +++ b/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/expansion/ValueSetExpander.java @@ -188,7 +188,7 @@ public class ValueSetExpander extends ValueSetProcessBase { private ValueSetExpansionContainsComponent addCode(WorkingContext wc, String system, String code, String display, String dispLang, ValueSetExpansionContainsComponent parent, List designations, Parameters expParams, boolean isAbstract, boolean inactive, List filters, boolean noInactive, boolean deprecated, List vsProp, List csProps, CodeSystem cs, List expProps, List csExtList, List vsExtList, ValueSetExpansionComponent exp) throws ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("addCode"+code); if (filters != null && !filters.isEmpty() && !filterContainsCode(filters, system, code, exp)) return null; @@ -447,7 +447,7 @@ public class ValueSetExpander extends ValueSetProcessBase { } private void addCodeAndDescendents(WorkingContext wc, ValueSetExpansionContainsComponent focus, ValueSetExpansionContainsComponent parent, Parameters expParams, List filters, boolean noInactive, List vsProps, ValueSet vsSrc, ValueSetExpansionComponent exp) throws FHIRException, ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("addCodeAndDescendents"); focus.checkNoModifiers("Expansion.contains", "expanding"); ValueSetExpansionContainsComponent np = null; for (String code : getCodesForConcept(focus, expParams)) { @@ -497,7 +497,7 @@ public class ValueSetExpander extends ValueSetProcessBase { private void addCodeAndDescendents(WorkingContext wc, CodeSystem cs, String system, ConceptDefinitionComponent def, ValueSetExpansionContainsComponent parent, Parameters expParams, List filters, ConceptDefinitionComponent exclusion, ConceptFilter filterFunc, boolean noInactive, List vsProps, List otherFilters, ValueSetExpansionComponent exp) throws FHIRException, ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("addCodeAndDescendents"); def.checkNoModifiers("Code in Code System", "expanding"); if (exclusion != null) { if (exclusion.getCode().equals(def.getCode())) @@ -528,7 +528,7 @@ public class ValueSetExpander extends ValueSetProcessBase { private void excludeCodeAndDescendents(WorkingContext wc, CodeSystem cs, String system, ConceptDefinitionComponent def, Parameters expParams, List filters, ConceptDefinitionComponent exclusion, ConceptFilter filterFunc, List otherFilters, ValueSetExpansionComponent exp) throws FHIRException, ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("excludeCodeAndDescendents"); def.checkNoModifiers("Code in Code System", "expanding"); if (exclusion != null) { if (exclusion.getCode().equals(def.getCode())) @@ -596,7 +596,7 @@ public class ValueSetExpander extends ValueSetProcessBase { } private void excludeCodes(WorkingContext wc, ConceptSetComponent exc, Parameters expParams, ValueSetExpansionComponent exp, ValueSet vs) throws FHIRException, FileNotFoundException, ETooCostly, IOException { - opContext.deadCheck(); + opContext.deadCheck("excludeCodes"); exc.checkNoModifiers("Compose.exclude", "expanding"); if (exc.hasSystem() && exc.getConcept().size() == 0 && exc.getFilter().size() == 0) { wc.getExcludeSystems().add(exc.getSystem()); @@ -639,7 +639,7 @@ public class ValueSetExpander extends ValueSetProcessBase { } private void excludeCodes(WorkingContext wc, ValueSetExpansionComponent expand) { - opContext.deadCheck(); + opContext.deadCheck("excludeCodes"); for (ValueSetExpansionContainsComponent c : expand.getContains()) { excludeCode(wc, c.getSystem(), c.getCode()); } @@ -959,7 +959,7 @@ public class ValueSetExpander extends ValueSetProcessBase { } public void copyExpansion(WorkingContext wc,List list) { - opContext.deadCheck(); + opContext.deadCheck("copyExpansion"); for (ValueSetExpansionContainsComponent cc : list) { ValueSetExpansionContainsComponent n = new ValueSet.ValueSetExpansionContainsComponent(); n.setSystem(cc.getSystem()); @@ -988,7 +988,7 @@ public class ValueSetExpander extends ValueSetProcessBase { private int copyImportContains(List list, ValueSetExpansionContainsComponent parent, Parameters expParams, List filter, boolean noInactive, List vsProps, ValueSet vsSrc, ValueSetExpansionComponent exp) throws FHIRException, ETooCostly { int count = 0; - opContext.deadCheck(); + opContext.deadCheck("copyImportContains"); for (ValueSetExpansionContainsComponent c : list) { c.checkNoModifiers("Imported Expansion in Code System", "expanding"); ValueSetExpansionContainsComponent np = addCode(dwc, c.getSystem(), c.getCode(), c.getDisplay(), vsSrc.getLanguage(), parent, null, expParams, c.getAbstract(), c.getInactive(), @@ -1002,7 +1002,7 @@ public class ValueSetExpander extends ValueSetProcessBase { } private void includeCodes(ConceptSetComponent inc, ValueSetExpansionComponent exp, Parameters expParams, boolean heirarchical, boolean noInactive, List extensions, ValueSet valueSet) throws ETooCostly, FileNotFoundException, IOException, FHIRException, CodeSystemProviderExtension { - opContext.deadCheck(); + opContext.deadCheck("includeCodes"); inc.checkNoModifiers("Compose.include", "expanding"); List imports = new ArrayList(); for (CanonicalType imp : inc.getValueSet()) { @@ -1033,7 +1033,7 @@ public class ValueSetExpander extends ValueSetProcessBase { } private void doServerIncludeCodes(ConceptSetComponent inc, boolean heirarchical, ValueSetExpansionComponent exp, List imports, Parameters expParams, List extensions, boolean noInactive, List vsProps) throws FHIRException, CodeSystemProviderExtension, ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("doServerIncludeCodes"); CodeSystemProvider csp = CodeSystemProvider.factory(inc.getSystem()); if (csp != null) { csp.includeCodes(inc, heirarchical, exp, imports, expParams, extensions, noInactive, vsProps); @@ -1075,7 +1075,7 @@ public class ValueSetExpander extends ValueSetProcessBase { public void doInternalIncludeCodes(ConceptSetComponent inc, ValueSetExpansionComponent exp, Parameters expParams, List imports, CodeSystem cs, boolean noInactive, Resource vsSrc) throws NoTerminologyServiceException, TerminologyServiceException, FHIRException, ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("doInternalIncludeCodes"); if (cs == null) { if (context.isNoTerminologyServer()) throw failTSE("Unable to find code system " + inc.getSystem().toString()); @@ -1160,7 +1160,7 @@ public class ValueSetExpander extends ValueSetProcessBase { private void processFilter(ConceptSetComponent inc, ValueSetExpansionComponent exp, Parameters expParams, List imports, CodeSystem cs, boolean noInactive, ConceptSetFilterComponent fc, WorkingContext wc, List filters, boolean exclude) throws ETooCostly { - opContext.deadCheck(); + opContext.deadCheck("processFilter"); if ("concept".equals(fc.getProperty()) && fc.getOp() == FilterOperator.ISA) { // special: all codes in the target code system under the value ConceptDefinitionComponent def = getConceptForCode(cs.getConcept(), fc.getValue()); @@ -1213,7 +1213,7 @@ public class ValueSetExpander extends ValueSetProcessBase { if (isNotBlank(def.getDisplay()) && isNotBlank(fc.getValue())) { if (def.getDisplay().contains(fc.getValue()) && passesOtherFilters(filters, cs, def.getCode())) { for (String code : getCodesForConcept(def, expParams)) { - opContext.deadCheck(); + opContext.deadCheck("processFilter2"); if (exclude) { excludeCode(wc, inc.getSystem(), code); } else { diff --git a/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/utilities/TerminologyOperationContext.java b/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/utilities/TerminologyOperationContext.java index d4b6234eb..5ac1cd591 100644 --- a/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/utilities/TerminologyOperationContext.java +++ b/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/utilities/TerminologyOperationContext.java @@ -7,6 +7,7 @@ import org.hl7.fhir.exceptions.TerminologyServiceException; import org.hl7.fhir.r5.context.IWorkerContext; import org.hl7.fhir.r5.model.OperationOutcome.IssueType; import org.hl7.fhir.r5.terminologies.utilities.TerminologyOperationContext.TerminologyServiceProtectionException; +import org.hl7.fhir.utilities.Utilities; import org.hl7.fhir.utilities.i18n.I18nConstants; import org.hl7.fhir.utilities.validation.ValidationOptions; @@ -38,11 +39,14 @@ public class TerminologyOperationContext { public static boolean debugging = java.lang.management.ManagementFactory.getRuntimeMXBean().getInputArguments().toString().indexOf("-agentlib:jdwp") > 0; private static final int EXPANSION_DEAD_TIME_SECS = 60; private long deadTime; + private int nestCount = 0; + private long startTime; private List contexts = new ArrayList<>(); private IWorkerContext worker; private boolean original; private ValidationOptions options; private String name; + private List notes = new ArrayList<>(); public TerminologyOperationContext(IWorkerContext worker, ValidationOptions options, String name) { super(); @@ -50,6 +54,7 @@ public class TerminologyOperationContext { this.original = true; this.options = options; this.name = name; + this.startTime = System.currentTimeMillis(); if (EXPANSION_DEAD_TIME_SECS == 0 || debugging) { deadTime = 0; @@ -62,6 +67,7 @@ public class TerminologyOperationContext { super(); this.options = options; this.name = name; + this.startTime = System.currentTimeMillis(); } public TerminologyOperationContext copy() { @@ -69,11 +75,20 @@ public class TerminologyOperationContext { ret.worker = worker; ret.contexts.addAll(contexts); ret.deadTime = deadTime; + ret.notes = notes; + ret.startTime = startTime; + ret.nestCount = nestCount + 1; return ret; } - public void deadCheck() { + public void deadCheck(String note) { + note(note); if (deadTime != 0 && System.currentTimeMillis() > deadTime) { + System.out.println(); + System.out.println("Operation took too long - longer than "+(deadTime - startTime)+"ms"); + for (String s : notes) { + System.out.println(s); + } throw new TerminologyServiceProtectionException(worker.formatMessage(I18nConstants.VALUESET_TOO_COSTLY_TIME, contexts.get(0), EXPANSION_DEAD_TIME_SECS, name+" (local)"), TerminologyServiceErrorClass.TOO_COSTLY, IssueType.TOOCOSTLY); } } @@ -93,5 +108,8 @@ public class TerminologyOperationContext { return options; } - + public void note(String s) { + s = Utilities.padLeft("", ' ', nestCount)+" "+(System.currentTimeMillis() - startTime)+" "+s; + notes.add(s); + } } diff --git a/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/validation/ValueSetValidator.java b/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/validation/ValueSetValidator.java index c811be7be..159c7eb69 100644 --- a/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/validation/ValueSetValidator.java +++ b/org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/terminologies/validation/ValueSetValidator.java @@ -175,11 +175,15 @@ public class ValueSetValidator extends ValueSetProcessBase { } private void analyseValueSet() { + opContext.note("analyse"); if (valueset != null) { + opContext.note("vs = "+valueset.getVersionedUrl()); opContext.seeContext(valueset.getVersionedUrl()); for (Extension s : valueset.getExtensionsByUrl(ExtensionConstants.EXT_VSSUPPLEMENT)) { requiredSupplements.add(s.getValue().primitiveValue()); } + } else { + opContext.note("vs = null"); } altCodeParams.seeParameters(expansionProfile); @@ -187,17 +191,18 @@ public class ValueSetValidator extends ValueSetProcessBase { if (localContext != null) { if (valueset != null) { for (ConceptSetComponent i : valueset.getCompose().getInclude()) { - analyseComponent(i); + analyseComponent(i, "inc"+i); } for (ConceptSetComponent i : valueset.getCompose().getExclude()) { - analyseComponent(i); + analyseComponent(i, "exc"+i); } } } + opContext.note("analysed"); } - private void analyseComponent(ConceptSetComponent i) { - opContext.deadCheck(); + private void analyseComponent(ConceptSetComponent i, String name) { + opContext.deadCheck("analyse Component "+name); if (i.getSystemElement().hasExtension(ToolingExtensions.EXT_VALUESET_SYSTEM)) { String ref = i.getSystemElement().getExtensionString(ToolingExtensions.EXT_VALUESET_SYSTEM); if (ref.startsWith("#")) { @@ -219,7 +224,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } public ValidationResult validateCode(String path, CodeableConcept code) throws FHIRException { - opContext.deadCheck(); + opContext.deadCheck("validate "+code.toString()); checkValueSetOptions(); // first, we validate the codings themselves @@ -509,7 +514,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } public ValidationResult validateCode(String path, Coding code) throws FHIRException { - opContext.deadCheck(); + opContext.deadCheck("validate "+code.toString()); checkValueSetOptions(); String warningMessage = null; @@ -841,7 +846,7 @@ public class ValueSetValidator extends ValueSetProcessBase { private ValidationResult findCodeInExpansion(Coding code, List contains) { for (ValueSetExpansionContainsComponent containsComponent: contains) { - opContext.deadCheck(); + opContext.deadCheck("findCodeInExpansion"); if (containsComponent.getSystem().equals(code.getSystem()) && containsComponent.getCode().equals(code.getCode())) { ConceptDefinitionComponent ccd = new ConceptDefinitionComponent(); ccd.setCode(containsComponent.getCode()); @@ -868,7 +873,7 @@ public class ValueSetValidator extends ValueSetProcessBase { private boolean checkExpansion(Coding code, List contains, VersionInfo vi) { for (ValueSetExpansionContainsComponent containsComponent: contains) { - opContext.deadCheck(); + opContext.deadCheck("checkExpansion: "+code.toString()); if (containsComponent.hasSystem() && containsComponent.hasCode() && containsComponent.getSystem().equals(code.getSystem()) && containsComponent.getCode().equals(code.getCode())) { vi.setExpansionVersion(containsComponent.getVersion()); return true; @@ -925,7 +930,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } for (ConceptDefinitionDesignationComponent ds : cc.getDesignation()) { - opContext.deadCheck(); + opContext.deadCheck("validateCode1 "+ds.toString()); if (isOkLanguage(ds.getLanguage())) { b.append("'"+ds.getValue()+"' ("+ds.getLanguage()+")"); if (code.getDisplay().equalsIgnoreCase(ds.getValue())) { @@ -947,7 +952,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } } for (ConceptReferenceDesignationComponent ds : vs.getCc().getDesignation()) { - opContext.deadCheck(); + opContext.deadCheck("validateCode2 "+ds.toString()); if (isOkLanguage(ds.getLanguage())) { b.append("'"+ds.getValue()+"'"); if (code.getDisplay().equalsIgnoreCase(ds.getValue())) { @@ -1052,7 +1057,7 @@ public class ValueSetValidator extends ValueSetProcessBase { return null; // if it has an expansion for (ValueSetExpansionContainsComponent exp : valueset.getExpansion().getContains()) { - opContext.deadCheck(); + opContext.deadCheck("findValueSetRef "+exp.toString()); if (system.equals(exp.getSystem()) && code.equals(exp.getCode())) { ConceptReferenceComponent cc = new ConceptReferenceComponent(); cc.setDisplay(exp.getDisplay()); @@ -1091,7 +1096,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } private ConceptDefinitionComponent findCodeInConcept(ConceptDefinitionComponent concept, String code, boolean caseSensitive, AlternateCodesProcessingRules altCodeRules) { - opContext.deadCheck(); + opContext.deadCheck("findCodeInConcept: "+code.toString()+", "+concept.toString()); if (code.equals(concept.getCode())) { return concept; } @@ -1164,7 +1169,7 @@ public class ValueSetValidator extends ValueSetProcessBase { int i = 0; for (ConceptSetComponent vsi : valueset.getCompose().getInclude()) { - opContext.deadCheck(); + opContext.deadCheck("scanForCodeInValueSet: "+code.toString()); if (scanForCodeInValueSetInclude(code, sys, problems, i, vsi)) { return true; } @@ -1284,7 +1289,7 @@ public class ValueSetValidator extends ValueSetProcessBase { */ private boolean checkSystems(List contains, String code, Set systems, List problems) { for (ValueSetExpansionContainsComponent c: contains) { - opContext.deadCheck(); + opContext.deadCheck("checkSystems "+code.toString()); if (c.getCode().equals(code)) { systems.add(c.getSystem()); } @@ -1298,7 +1303,7 @@ public class ValueSetValidator extends ValueSetProcessBase { if (valueset == null) { return null; } - opContext.deadCheck(); + opContext.deadCheck("codeInValueSet: "+system+"#"+code); checkCanonical(info.getIssues(), path, valueset, valueset); Boolean result = false; VersionInfo vi = new VersionInfo(this); @@ -1333,7 +1338,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } private Boolean inComponent(String path, ConceptSetComponent vsi, int vsiIndex, String system, String version, String code, boolean only, ValidationProcessInfo info) throws FHIRException { - opContext.deadCheck(); + opContext.deadCheck("inComponent "+vsiIndex); boolean ok = true; if (vsi.hasValueSet()) { @@ -1382,6 +1387,7 @@ public class ValueSetValidator extends ValueSetProcessBase { vs.setUrl(valueset.getUrl()+"--"+vsiIndex); vs.setVersion(valueset.getVersion()); vs.getCompose().addInclude(vsi); + opContext.deadCheck("hit server "+vs.getVersionedUrl()); ValidationResult res = context.validateCode(options.withNoClient(), new Coding(system, code, null), vs); if (res.getErrorClass() == TerminologyServiceErrorClass.UNKNOWN || res.getErrorClass() == TerminologyServiceErrorClass.CODESYSTEM_UNSUPPORTED || res.getErrorClass() == TerminologyServiceErrorClass.VALUESET_UNSUPPORTED) { if (info != null && res.getErrorClass() == TerminologyServiceErrorClass.CODESYSTEM_UNSUPPORTED) { @@ -1391,16 +1397,20 @@ public class ValueSetValidator extends ValueSetProcessBase { info.addIssue(makeIssue(IssueSeverity.WARNING, IssueType.UNKNOWN, path, msg, OpIssueCode.NotFound, null)); for (ConceptReferenceComponent cc : vsi.getConcept()) { if (cc.getCode().equals(code)) { + opContext.deadCheck("server true"); return true; } } } info.setErr(TerminologyServiceErrorClass.CODESYSTEM_UNSUPPORTED); + opContext.deadCheck("server codesystem unsupported"); return null; } + opContext.deadCheck("server not found"); return false; } if (res.getErrorClass() == TerminologyServiceErrorClass.NOSERVICE) { + opContext.deadCheck("server no server"); throw new NoTerminologyServiceException(); } return res.isOk(); @@ -1581,7 +1591,7 @@ public class ValueSetValidator extends ValueSetProcessBase { } public boolean validateCodeInConceptList(String code, CodeSystem def, List list, AlternateCodesProcessingRules altCodeRules) { - opContext.deadCheck(); + opContext.deadCheck("validateCodeInConceptList"); if (def.hasUserData("tx.cs.special")) { return ((SpecialCodeSystem) def.getUserData("tx.cs.special")).findConcept(new Coding().setCode(code)) != null; } else if (def.getCaseSensitive()) {