Add more logging for too costly validation

This commit is contained in:
Grahame Grieve 2024-09-25 05:15:49 -04:00
parent 004d367340
commit 54353f8fce
3 changed files with 60 additions and 32 deletions

View File

@ -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<ConceptDefinitionDesignationComponent> designations, Parameters expParams,
boolean isAbstract, boolean inactive, List<ValueSet> filters, boolean noInactive, boolean deprecated, List<ValueSetExpansionPropertyComponent> vsProp,
List<ConceptPropertyComponent> csProps, CodeSystem cs, List<org.hl7.fhir.r5.model.ValueSet.ConceptPropertyComponent> expProps, List<Extension> csExtList, List<Extension> 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<ValueSet> filters, boolean noInactive, List<ValueSetExpansionPropertyComponent> 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<ValueSet> filters,
ConceptDefinitionComponent exclusion, ConceptFilter filterFunc, boolean noInactive, List<ValueSetExpansionPropertyComponent> vsProps, List<WorkingContext> 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<ValueSet> filters,
ConceptDefinitionComponent exclusion, ConceptFilter filterFunc, List<WorkingContext> 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<ValueSetExpansionContainsComponent> 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<ValueSetExpansionContainsComponent> list, ValueSetExpansionContainsComponent parent, Parameters expParams, List<ValueSet> filter, boolean noInactive, List<ValueSetExpansionPropertyComponent> 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<Extension> extensions, ValueSet valueSet) throws ETooCostly, FileNotFoundException, IOException, FHIRException, CodeSystemProviderExtension {
opContext.deadCheck();
opContext.deadCheck("includeCodes");
inc.checkNoModifiers("Compose.include", "expanding");
List<ValueSet> imports = new ArrayList<ValueSet>();
for (CanonicalType imp : inc.getValueSet()) {
@ -1033,7 +1033,7 @@ public class ValueSetExpander extends ValueSetProcessBase {
}
private void doServerIncludeCodes(ConceptSetComponent inc, boolean heirarchical, ValueSetExpansionComponent exp, List<ValueSet> imports, Parameters expParams, List<Extension> extensions, boolean noInactive, List<ValueSetExpansionPropertyComponent> 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<ValueSet> 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<ValueSet> imports, CodeSystem cs, boolean noInactive,
ConceptSetFilterComponent fc, WorkingContext wc, List<WorkingContext> 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 {

View File

@ -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<String> contexts = new ArrayList<>();
private IWorkerContext worker;
private boolean original;
private ValidationOptions options;
private String name;
private List<String> 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);
}
}

View File

@ -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<ValueSetExpansionContainsComponent> 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<ValueSetExpansionContainsComponent> 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<ValueSetExpansionContainsComponent> contains, String code, Set<String> systems, List<StringWithCode> 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<ConceptDefinitionComponent> 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()) {