diff --git a/Src/java/engine-fhir/src/test/kotlin/org/opencds/cqf/cql/engine/fhir/data/TestCqlEngineRelatedContextSupport.kt b/Src/java/engine-fhir/src/test/kotlin/org/opencds/cqf/cql/engine/fhir/data/TestCqlEngineRelatedContextSupport.kt index ec009f3af..27c74801e 100644 --- a/Src/java/engine-fhir/src/test/kotlin/org/opencds/cqf/cql/engine/fhir/data/TestCqlEngineRelatedContextSupport.kt +++ b/Src/java/engine-fhir/src/test/kotlin/org/opencds/cqf/cql/engine/fhir/data/TestCqlEngineRelatedContextSupport.kt @@ -91,7 +91,7 @@ internal class TestCqlEngineRelatedContextSupport : FhirExecutionTestBase() { private fun evaluate( cqlEngine: CqlEngine, expression: String, - initialContext: Pair?, + initialContext: Pair?, ): Any? { val evaluateResult = cqlEngine diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/ExpressionRefEvaluator.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/ExpressionRefEvaluator.kt index d3d7befb8..f67ba7f24 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/ExpressionRefEvaluator.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/ExpressionRefEvaluator.kt @@ -15,9 +15,11 @@ object ExpressionRefEvaluator { try { val def = Libraries.resolveExpressionRef(expressionRef.name, state.getCurrentLibrary()!!) - state.pushActivationFrame(def, def.context) + state.pushActivationFrame(def, def.context!!) try { - return visitor.visitExpressionDef(def, state) + val result = visitor.visitExpressionDef(def, state) + state.storeIntermediateResultForTracing(result) + return result } finally { state.popActivationFrame() } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/FunctionRefEvaluator.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/FunctionRefEvaluator.kt index 28296442c..aef258627 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/FunctionRefEvaluator.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/elm/executing/FunctionRefEvaluator.kt @@ -48,12 +48,14 @@ object FunctionRefEvaluator { } else { // Establish activation frame with the function // definition being evaluated. - state.pushActivationFrame(functionDef, functionDef.context) + state.pushActivationFrame(functionDef, functionDef.context!!) try { for (i in arguments.indices) { state.push(Variable(functionDef.operand[i].name!!).withValue(arguments[i])) } - return visitor.visitExpression(functionDef.expression!!, state) + val result = visitor.visitExpression(functionDef.expression!!, state) + state.storeIntermediateResultForTracing(result) + return result } finally { state.popActivationFrame() } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/Backtrace.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/Backtrace.kt index 5d8de7f48..fb241eaa1 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/Backtrace.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/Backtrace.kt @@ -1,189 +1,62 @@ package org.opencds.cqf.cql.engine.exception import java.util.Deque -import java.util.LinkedList -import java.util.function.Consumer -import java.util.function.Function import org.hl7.elm.r1.Expression import org.hl7.elm.r1.ExpressionDef -import org.hl7.elm.r1.FunctionDef -import org.hl7.elm.r1.OperandDef -import org.hl7.elm.r1.VersionedIdentifier import org.opencds.cqf.cql.engine.execution.State.ActivationFrame -import org.opencds.cqf.cql.engine.execution.Variable +import org.opencds.cqf.cql.engine.execution.trace.ExpressionDefTraceFrame +import org.opencds.cqf.cql.engine.execution.trace.TraceFrame /** - * A backtrace represents a stack of call-like frames from the root of an evaluation to a particular - * sub-expression, commonly a sub-expression in which an exception was thrown. - * - * @author Jan Moringen + * A backtrace represents a series of trace frames from the root of an evaluation to the + * sub-expression in which an exception was thrown. */ -class Backtrace { - /** - * Represents the evaluation of a CQL expression. - * - * @see FunctionoidFrame Subclass for functions and expression definitions. - */ - open class Frame( - /** - * Returns the expression that was being evaluated when the backtrace frame was captured. - * - * @return The expression. - */ - val expression: Expression? - ) +class Backtrace( + /** The root of the trace frame series. */ + val frame: TraceFrame +) { + override fun toString(): String { + return frame.toIndentedString(0, false) + } - /** - * Instances of this subclass of [Frame] represent the invocation of a function with specific - * arguments or the evaluation of an expression definition. - * - * In addition to the (sub)expression being evaluated, this class captures the surrounding - * function or expression definition, function arguments, local variables as well as the name - * and value of the CQL context. - */ - @Suppress("LongParameterList") - class FunctionoidFrame( - expression: Expression?, - /** - * Returns the definition in which the current expression was being evaluated when the - * backtrace frame was captured. - * - * Definitions are either direct instances of ExpressionDef which correspond to define foo: - * ... in CQL libraries or instances of FunctionDef which correspond to define function - * foo(...): ... in CQL libraries. In either case, getExpression() returns the - * sub-expression within the definition expression that was being evaluated. - * - * @return The containing definition expression. - */ - val definition: ExpressionDef?, - /** - * Returns the arguments with which the [FunctionDef] expression was invoked. - * - * Returns an empty list if the surrounding expression was an [ExpressionDef] but not a - * FunctionDef. - * - * @return A list of the [Variable]s that correspond to function call arguments. - */ - val arguments: MutableList?, - /** - * Returns the local variable bindings in the scope of expression evaluation of the frame. - * - * @return A list of the [Variable]s that correspond to local variable bindings. - */ - val localVariables: MutableList?, - /** - * Returns the name of the Library that was current during the evaluation represented by the - * frame. - * - * @return The name of the Library in context. - */ - val libraryIdentifier: VersionedIdentifier?, + companion object { /** - * Returns the name of the CQL context that was current during the evaluation represented by - * the frame. - * - * @return The name of the CQL context. + * Creates a [Backtrace] from a stack of activation frames and the expression in which the + * exception was thrown. */ - val contextName: String?, - /** - * Returns the value of the CQL context that was current during the evaluation represented - * by the frame. - * - * @return The value of the CQL context. - */ - val contextValue: Any?, - ) : Frame(expression) - - val frames: MutableList = LinkedList() + fun fromActivationFrames( + activationFrameStack: Deque, + expression: Expression, + contextValues: Map, + ): Backtrace { + val topActivationFrame = activationFrameStack.peek() - fun addFrame(frame: Frame?) { - this.frames.add(frame) - } + var frame = + TraceFrame( + topActivationFrame.library, + expression, + topActivationFrame.variables.toList().reversed(), + topActivationFrame.contextName!! to + contextValues[topActivationFrame.contextName], + ) - @Suppress("LongParameterList") - fun maybeAddFrame( - containingDefinition: ExpressionDef?, - definitionFrame: ActivationFrame?, - stack: Deque, - contextName: String?, - contextValue: Any?, - libraryIdentifier: VersionedIdentifier?, - expression: Expression?, - ) { - // When the EvaluationVisitor unwinds through - // EvaluationVisitor.visitExpression calls, every call has a - // unique expression that is being evaluated but not every - // call has a unique ActivationFrame since each - // ActivationFrame is associated with the respective innermost - // expression definition or function definition enclosing the - // expression which is being evaluated in the call. For that - // reason, this method is called for multiple expressions with - // the same surrounding ActivationFrame. If the frame at the - // end of our frame list already describes the definition or - // function that surrounds the expression for which the - // visitExpression is being unwound, everything has already - // been recorded: the innermost expression, the containing - // definition or function and all local variables and - // arguments. - if (!frames.isEmpty()) { - val currentFrame = this.frames.get(frames.size - 1) - if (currentFrame is FunctionoidFrame) { - if (currentFrame.definition === containingDefinition) { - return + for (activationFrame in activationFrameStack) { + val element = activationFrame.element + if (element is ExpressionDef) { + frame = + ExpressionDefTraceFrame( + activationFrame.library, + element, + activationFrame.variables.toList().reversed(), + activationFrame.contextName!! to + contextValues[activationFrame.contextName], + activationFrame.result, + listOf(frame), + ) } } + + return Backtrace(frame) } - // Walk the ActivationFrames from the top of the stack to the - // innermost ActivationFrame which corresponds to an - // expression or function definition which is definitionFrame. - // Variable bindings in frames closer to the top of the stack - // than definitionFrame correspond to local variables which - // where established in the scope of the top-level expression - // or function. Each variable binding in definitionFrame - // itself corresponds to either an invocation argument, if the - // frame represents a function invocation, or more local - // variables. Classify all relevant bindings into those two - // categories, mainly for more informative presentation in - // backtraces. - val arguments = mutableListOf() - val localVariables = mutableListOf() - for (frame in stack) { - if (frame === definitionFrame) { - val parameterNames: List - if (containingDefinition is FunctionDef) { - parameterNames = containingDefinition.operand.map(OperandDef::name) - } else { - parameterNames = listOf() - } - frame.variables.forEach( - Consumer { variable -> - if (parameterNames.contains(variable!!.name)) { - arguments.add(variable) - } else { - localVariables.add(variable) - } - } - ) - arguments.sortWith( - Comparator.comparing( - Function { argument -> parameterNames.indexOf(argument!!.name) } - ) - ) - break - } else { - localVariables.addAll(frame.variables) - } - } - addFrame( - FunctionoidFrame( - expression, - containingDefinition, - arguments, - localVariables, - libraryIdentifier, - contextName, - contextValue, - ) - ) } } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/CqlException.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/CqlException.kt index e7de7133f..61c96bd98 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/CqlException.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/exception/CqlException.kt @@ -32,7 +32,7 @@ constructor( @Transient var sourceLocator: SourceLocator? = null - val backtrace: Backtrace = Backtrace() + var backtrace: Backtrace? = null init { this.sourceLocator = sourceLocator diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/CqlEngine.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/CqlEngine.kt index d67bff97e..8871ab19b 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/CqlEngine.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/CqlEngine.kt @@ -49,6 +49,10 @@ constructor(val environment: Environment, engineOptions: MutableSet? = // definitions and retrieves. EnableProfiling, + // Collect trace information during evaluation (expressions and function + // calls with intermediate results). Trace data can be exported after evaluation. + EnableTracing, + // Collect coverage information during execution. Coverage // data can be exported in LCOV format after execution. EnableCoverageCollection, @@ -209,7 +213,7 @@ constructor(val environment: Environment, engineOptions: MutableSet? = } } } finally { - this.state.endEvaluation() + result.trace = this.state.endEvaluation() // We are moving the evaluated resources off the stack so we can work on the next ones this.state.clearEvaluatedResources() // We are moving the library off the stack so we can work on the next one @@ -229,11 +233,12 @@ constructor(val environment: Environment, engineOptions: MutableSet? = ) { try { val action = this.state.shouldDebug(def) - state.pushActivationFrame(def, def.context) + state.pushActivationFrame(def, def.context!!) try { val value = eval() result.results[expression] = ExpressionResult(value, this.state.evaluatedResources) this.state.logDebugResult(def, value, action) + state.storeIntermediateResultForTracing(value) } finally { this.state.popActivationFrame() // this avoids spill over of evaluatedResources from previous/next diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationParams.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationParams.kt index 3843f8bb3..79a156e5a 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationParams.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationParams.kt @@ -17,7 +17,7 @@ import org.opencds.cqf.cql.engine.debug.DebugMap */ class EvaluationParams( val expressions: Map?>, - val contextParameter: Pair? = null, + val contextParameter: Pair? = null, val parameters: Map? = null, val debugMap: DebugMap? = null, val evaluationDateTime: ZonedDateTime? = null, @@ -26,7 +26,7 @@ class EvaluationParams( private val expressions = mutableMapOf?>() - var contextParameter: Pair? = null + var contextParameter: Pair? = null var parameters: Map? = null var debugMap: DebugMap? = null var evaluationDateTime: ZonedDateTime? = null diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationResult.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationResult.kt index 37b413861..9c0ccd500 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationResult.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationResult.kt @@ -1,6 +1,7 @@ package org.opencds.cqf.cql.engine.execution import org.opencds.cqf.cql.engine.debug.DebugResult +import org.opencds.cqf.cql.engine.execution.trace.Trace class EvaluationResult { /** Includes both expression results and function evaluation results. */ @@ -30,4 +31,7 @@ class EvaluationResult { } var debugResult: DebugResult? = null + + /** Trace information collected during evaluation. Only used when tracing is enabled. */ + var trace: Trace? = null } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationVisitor.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationVisitor.kt index ab6fa28ad..2628f0f28 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationVisitor.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/EvaluationVisitor.kt @@ -165,6 +165,7 @@ import org.opencds.cqf.cql.engine.elm.executing.ValueSetRefEvaluator.internalEva import org.opencds.cqf.cql.engine.elm.executing.VarianceEvaluator.variance import org.opencds.cqf.cql.engine.elm.executing.WidthEvaluator.width import org.opencds.cqf.cql.engine.elm.executing.XorEvaluator.xor +import org.opencds.cqf.cql.engine.exception.Backtrace import org.opencds.cqf.cql.engine.exception.CqlException import org.opencds.cqf.cql.engine.exception.Severity import org.opencds.cqf.cql.engine.runtime.Interval @@ -179,7 +180,7 @@ class EvaluationVisitor : BaseElmLibraryVisitor() { try { return super.visitExpression(elm, context) } catch (e: CqlException) { - maybeExtendBacktrace(e, context, elm) + maybeExtendBacktrace(e, context!!, elm) throw e } catch (e: Exception) { val exception = @@ -194,27 +195,15 @@ class EvaluationVisitor : BaseElmLibraryVisitor() { } } + /** Builds a backtrace for the exception if it does not already have one. */ private fun maybeExtendBacktrace( exception: CqlException, - context: State?, - expression: Expression?, + context: State, + expression: Expression, ) { - // If the top of the stack in state is call-like - // ActivationFrame (that is an ActivationFrame for an - // expression definition or a function definition), try to - // extend the backtrace object of exception to include that - // call. - val frame = context!!.topActivationFrame - if (frame.element is ExpressionDef) { - exception.backtrace.maybeAddFrame( - frame.element as ExpressionDef, - frame, - context.stack, - context.getCurrentContext(), - context.currentContextValue, - context.getCurrentLibrary()?.identifier, - expression, - ) + if (exception.backtrace == null) { + exception.backtrace = + Backtrace.fromActivationFrames(context.stack, expression, context.contextValues) } } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/State.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/State.kt index 15d61f3ed..81d98f017 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/State.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/State.kt @@ -15,6 +15,7 @@ import org.hl7.elm.r1.Element import org.hl7.elm.r1.ExpressionDef import org.hl7.elm.r1.Library import org.hl7.elm.r1.Retrieve +import org.hl7.elm.r1.VersionedIdentifier import org.opencds.cqf.cql.engine.debug.DebugAction import org.opencds.cqf.cql.engine.debug.DebugMap import org.opencds.cqf.cql.engine.debug.DebugResult @@ -22,6 +23,7 @@ import org.opencds.cqf.cql.engine.debug.SourceLocator import org.opencds.cqf.cql.engine.exception.CqlException import org.opencds.cqf.cql.engine.exception.Severity import org.opencds.cqf.cql.engine.execution.CqlEngine.Options +import org.opencds.cqf.cql.engine.execution.trace.Trace import org.opencds.cqf.cql.engine.runtime.DateTime import org.opencds.cqf.cql.engine.runtime.Tuple @@ -32,13 +34,16 @@ constructor( val environment: Environment, val engineOptions: MutableSet = HashSet(), ) { - class ActivationFrame( // The expression that is being evaluated in this activation - // frame. Either null for the "root" activation frame, an ExpressionDef (which can be a - // FunctionDef) - // or a Retrieve. + class ActivationFrame( + /** + * The expression that is being evaluated in this activation frame. Either null for the + * "root" activation frame, an ExpressionDef (which can be a FunctionDef) or a Retrieve. + */ var element: Element?, - var contextName: String?, // The times at which the evaluation to which this activation - // frame belongs started and ended. + /** The library containing the element being evaluated. */ + var library: VersionedIdentifier?, + var contextName: String?, + /** The time at which the evaluation to which this activation frame belongs started. */ var startTime: Long, ) { // Arguments and/or local variables of the active function @@ -48,6 +53,7 @@ constructor( // and profiling. var variables: Deque = ArrayDeque(4) + /** The time at which the evaluation to which this activation frame belongs ended. */ var endTime: Long = 0 // If the activation frame belongs to an ExpressionDef that is @@ -56,6 +62,18 @@ constructor( // taken from the cache. var isCached: Boolean = false + /** + * The result of the expression evaluation for this frame. Only used when tracing is + * enabled. + */ + var result: Any? = null + + /** + * Frames representing nested expressions, function calls, and retrieves. Only used when + * tracing is enabled. + */ + val innerActivationFrames: MutableList = mutableListOf() + override fun toString(): String { val result = StringBuilder().append("Frame{element=") if (this.element == null) { @@ -81,7 +99,7 @@ constructor( val cache: Cache = Cache() - private val currentContext = ArrayDeque() + private val currentContext = ArrayDeque() private val currentLibrary = ArrayDeque() @@ -90,7 +108,7 @@ constructor( private val evaluatedResourceStack = ArrayDeque>() val parameters = mutableMapOf() - var contextValues = mutableMapOf() + var contextValues = mutableMapOf() var evaluationZonedDateTime: ZonedDateTime? = null private set @@ -243,11 +261,22 @@ constructor( pushActivationFrame(null) } - fun endEvaluation() { + fun endEvaluation(): Trace? { assert(this.stack.size == 1) + + val trace = + if (engineOptions.contains(Options.EnableTracing)) + Trace.fromActivationFrames( + this.stack.peek().innerActivationFrames, + this.contextValues, + ) + else null + // TODO(jmoringe): maybe assert this.stack.getLast().variables.isEmpty(); // Pop (and possibly process) the root activation frame. popActivationFrame() + + return trace } fun resolveVariable(name: String?): Variable? { @@ -277,7 +306,11 @@ constructor( contextName: String?, startTime: Long = System.nanoTime(), ) { - val newActivationFrame = ActivationFrame(element, contextName, startTime) + val newActivationFrame = + ActivationFrame(element, this.getCurrentLibrary()?.identifier, contextName, startTime) + if (engineOptions.contains(Options.EnableTracing) && this.stack.isNotEmpty()) { + topActivationFrame.innerActivationFrames.add(newActivationFrame) + } this.stack.push(newActivationFrame) if (this.debugResult != null) { val profile = this.debugResult!!.profile @@ -288,7 +321,7 @@ constructor( } fun pushActivationFrame(element: Element?) { - val contextName: String? = this.currentContext.peekFirst() + val contextName = this.currentContext.peekFirst() pushActivationFrame(element, contextName) } @@ -311,6 +344,13 @@ constructor( this.stack.pop() } + /** Stores the intermediate result in the activation frame. */ + fun storeIntermediateResultForTracing(result: Any?) { + if (engineOptions.contains(Options.EnableTracing)) { + topActivationFrame.result = result + } + } + val topActivationFrame: ActivationFrame get() { val topActivationFrame = this.stack.peek() @@ -320,13 +360,13 @@ constructor( return topActivationFrame } - fun setContextValue(context: String?, contextValue: Any) { + fun setContextValue(context: String, contextValue: Any?) { val containsKey = contextValues.containsKey(context) val valueFromContextValues = contextValues[context] val valuesAreEqual = contextValue == valueFromContextValues if (!containsKey || !valuesAreEqual) { - contextValues.put(context, contextValue) + contextValues[context] = contextValue clearCacheExpressions() } } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/Variable.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/Variable.kt index cc7924766..d861da2d8 100644 --- a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/Variable.kt +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/Variable.kt @@ -1,6 +1,6 @@ package org.opencds.cqf.cql.engine.execution -class Variable(val name: String?) { +data class Variable(val name: String?) { var value: Any? = null @@ -11,8 +11,4 @@ class Variable(val name: String?) { this.value = value return this } - - override fun toString(): String { - return "Variable{name=${name}, value=${value}, isList=${isList}}" - } } diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/ExpressionDefTraceFrame.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/ExpressionDefTraceFrame.kt new file mode 100644 index 000000000..537e65694 --- /dev/null +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/ExpressionDefTraceFrame.kt @@ -0,0 +1,84 @@ +package org.opencds.cqf.cql.engine.execution.trace + +import org.hl7.elm.r1.ExpressionDef +import org.hl7.elm.r1.FunctionDef +import org.hl7.elm.r1.VersionedIdentifier +import org.opencds.cqf.cql.engine.execution.State.ActivationFrame +import org.opencds.cqf.cql.engine.execution.Variable + +/** Represents an expression def or function def that was evaluated. */ +class ExpressionDefTraceFrame( + /** The library containing the expression or function def. */ + library: VersionedIdentifier?, + /** Expression or function def. */ + expressionDef: ExpressionDef, + /** Variables in scope when the element was evaluated. */ + variables: List, + /** Context name and value. */ + context: Pair, + /** Result of evaluating the expression or function. Only used if tracing is enabled. */ + val result: Any?, + /** Inner expression and function calls. */ + val subframes: List, +) : TraceFrame(library, expressionDef, variables, context) { + override val element: ExpressionDef = expressionDef + + /** Arguments passed to the function. If the frame represents an expression, this is empty. */ + val arguments: List = + if (expressionDef is FunctionDef) { + expressionDef.operand.map { operand -> variables.find { it.name == operand.name }!! } + } else { + emptyList() + } + + /** Recursively stringifies the trace frame with indentation. */ + override fun toIndentedString(indentLevel: Int, showResults: Boolean): String { + return buildString { + append(" ".repeat(indentLevel)) + append("${library?.id ?: "?"}.${element.name}") + if (element is FunctionDef) { + append("(") + append(arguments.joinToString(", ") { "${it.name} = ${it.value}" }) + append(")") + } + if (showResults) { + append(" = $result") + } + appendLine() + + subframes.forEach { append(it.toIndentedString(indentLevel + 1, showResults)) } + } + } + + companion object { + + /** Recursively converts activation frames to trace frames. */ + fun fromActivationFrames( + activationFrames: List, + contextValues: Map, + ): List { + return activationFrames.flatMap { activationFrame -> + val subframes = + fromActivationFrames(activationFrame.innerActivationFrames, contextValues) + + val element = activationFrame.element + + // Only create trace frames for expressions and function calls + if (element is ExpressionDef) { + return@flatMap listOf( + ExpressionDefTraceFrame( + activationFrame.library, + element, + activationFrame.variables.toList().reversed(), + activationFrame.contextName!! to + contextValues[activationFrame.contextName], + activationFrame.result, + subframes, + ) + ) + } + subframes + } + } + } +} diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/Trace.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/Trace.kt new file mode 100644 index 000000000..a881a0ea8 --- /dev/null +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/Trace.kt @@ -0,0 +1,23 @@ +package org.opencds.cqf.cql.engine.execution.trace + +import org.opencds.cqf.cql.engine.execution.State + +/** Captures expression and function calls involved in evaluation with intermediate values. */ +class Trace(val frames: List) { + + override fun toString(): String { + return buildString { frames.forEach { append(it.toIndentedString(0, true)) } } + } + + companion object { + /** Creates a [Trace] from a list of activation frames. */ + fun fromActivationFrames( + activationFrames: List, + contextValues: Map, + ): Trace { + return Trace( + ExpressionDefTraceFrame.fromActivationFrames(activationFrames, contextValues) + ) + } + } +} diff --git a/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/TraceFrame.kt b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/TraceFrame.kt new file mode 100644 index 000000000..4f3de6d9b --- /dev/null +++ b/Src/java/engine/src/main/kotlin/org/opencds/cqf/cql/engine/execution/trace/TraceFrame.kt @@ -0,0 +1,26 @@ +package org.opencds.cqf.cql.engine.execution.trace + +import org.hl7.elm.r1.Element +import org.hl7.elm.r1.VersionedIdentifier +import org.opencds.cqf.cql.engine.execution.Variable + +/** Represents an ELM element that was evaluated. */ +open class TraceFrame( + /** The library containing the element. */ + val library: VersionedIdentifier?, + /** The ELM element represented by the frame. */ + open val element: Element, + /** Variables in scope when the element was evaluated. */ + val variables: List, + /** Context name and value. */ + val context: Pair, +) { + /** Stringifies the trace frame with indentation. */ + open fun toIndentedString(indentLevel: Int, showResults: Boolean): String { + return buildString { + append(" ".repeat(indentLevel)) + append(element::class.simpleName) + appendLine() + } + } +} diff --git a/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/BacktraceTest.kt b/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/BacktraceTest.kt index b5322bc6a..56cf5ad93 100644 --- a/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/BacktraceTest.kt +++ b/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/BacktraceTest.kt @@ -1,219 +1,92 @@ package org.opencds.cqf.cql.engine.execution -import org.hamcrest.Description -import org.hamcrest.MatcherAssert -import org.hamcrest.Matchers -import org.hamcrest.TypeSafeMatcher -import org.hl7.elm.r1.ExpressionDef -import org.hl7.elm.r1.FunctionDef +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertFailsWith +import kotlin.test.assertIs +import kotlin.test.assertNotNull +import org.hl7.elm.r1.Message import org.hl7.elm.r1.VersionedIdentifier -import org.junit.jupiter.api.Assertions -import org.junit.jupiter.api.Test -import org.opencds.cqf.cql.engine.exception.Backtrace.FunctionoidFrame import org.opencds.cqf.cql.engine.exception.CqlException +import org.opencds.cqf.cql.engine.execution.trace.ExpressionDefTraceFrame +import org.opencds.cqf.cql.engine.execution.trace.TraceFrame -internal class BacktraceTest : CqlTestBase() { - internal class FunctionMatcher(private val expectedName: String?) : - TypeSafeMatcher() { - override fun matchesSafely(functionDefinition: FunctionDef): Boolean { - return functionDefinition.name == expectedName - } - - override fun describeTo(description: Description) { - description.appendText("a function named ").appendValue(expectedName) - } - - companion object { - fun isFunction(expectedName: String?): FunctionMatcher { - return FunctionMatcher(expectedName) - } - } - } - - internal class ExpressionDefinitionMatcher(private val expectedName: String?) : - TypeSafeMatcher() { - override fun matchesSafely(expressionDefinition: ExpressionDef): Boolean { - return expressionDefinition.name == expectedName - } - - override fun describeTo(description: Description) { - description.appendText("an expression definition named ").appendValue(expectedName) - } - - companion object { - fun isExpressionDefinition(expectedName: String?): ExpressionDefinitionMatcher { - return ExpressionDefinitionMatcher(expectedName) - } - } - } - - internal class VariableMatcher( - private val expectedName: String?, - private val expectedValue: Any?, - ) : TypeSafeMatcher() { - override fun matchesSafely(variable: Variable): Boolean { - return variable.name == expectedName && variable.value == expectedValue - } - - override fun describeTo(description: Description) { - description - .appendText("an argument with name ") - .appendValue(expectedName) - .appendText(" and value ") - .appendValue(expectedValue) - } - - companion object { - fun isVariable(expectedName: String?, expectedValue: Any?): VariableMatcher { - return VariableMatcher(expectedName, expectedValue) - } - } - } - - internal class VersionedIdentifierMatcher( - private val expectedId: String?, - private val expectedVersion: String?, - ) : TypeSafeMatcher() { - override fun matchesSafely(vi: VersionedIdentifier): Boolean { - return true - } - - override fun describeTo(description: Description) { - description - .appendText("a library id") - .appendValue(expectedId) - .appendText("a library version") - .appendValue(expectedVersion) - } - - companion object { - fun isVersionedIdentifier( - expectedId: String?, - expectedVersion: String?, - ): VersionedIdentifierMatcher { - return VersionedIdentifierMatcher(expectedId, expectedVersion) - } - } - } - - internal class ContextMatcher( - private val expectedName: String?, - private val expectedValue: Any?, - ) : TypeSafeMatcher() { - override fun matchesSafely(frame: FunctionoidFrame): Boolean { - return frame.contextName == expectedName && frame.contextValue == expectedValue - } - - override fun describeTo(description: Description) { - description - .appendText("a context with name ") - .appendValue(expectedName) - .appendText(" and value ") - .appendValue(expectedValue) - } - - companion object { - fun hasContext(expectedName: String?, expectedValue: Any?): ContextMatcher { - return ContextMatcher(expectedName, expectedValue) - } - } - } +class BacktraceTest : CqlTestBase() { @Test - fun backtrace_smoke() { - try { - engine.evaluate { library("BacktraceTest") }.onlyResultOrThrow - Assertions.fail("Expected exception but none was thrown") - } catch (e: CqlException) { - MatcherAssert.assertThat(e.backtrace, Matchers.notNullValue()) - val backtrace = e.backtrace - val frames = backtrace.frames - MatcherAssert.assertThat(frames, Matchers.hasSize(3)) - // Frame 1 - val frame1 = frames!![0] - MatcherAssert.assertThat(frame1, Matchers.instanceOf(FunctionoidFrame::class.java)) - val frame1Functionoid = frame1 as FunctionoidFrame - val definition1 = frame1Functionoid.definition - MatcherAssert.assertThat(definition1, Matchers.instanceOf(FunctionDef::class.java)) - MatcherAssert.assertThat( - definition1 as FunctionDef?, - FunctionMatcher.isFunction("F"), - ) - MatcherAssert.assertThat( - frame1Functionoid.arguments, - Matchers.contains(VariableMatcher.isVariable("X", 3)), - ) - MatcherAssert.assertThat( - frame1Functionoid.localVariables, - Matchers.containsInAnyOrder( - VariableMatcher.isVariable("A", 7), - VariableMatcher.isVariable("_", 1), - ), - ) - MatcherAssert.assertThat( - frame1Functionoid.libraryIdentifier, - VersionedIdentifierMatcher.isVersionedIdentifier( - "BacktraceTest", - expectedVersion = null, - ), - ) - MatcherAssert.assertThat( - frame1Functionoid, - ContextMatcher.hasContext("Unfiltered", null), - ) - // Frame 2 - val frame2 = frames[1] - MatcherAssert.assertThat(frame2, Matchers.instanceOf(FunctionoidFrame::class.java)) - val frame2Functionoid = frame2 as FunctionoidFrame - val definition2 = frame2Functionoid.definition - MatcherAssert.assertThat(definition2, Matchers.instanceOf(FunctionDef::class.java)) - MatcherAssert.assertThat( - definition2 as FunctionDef?, - FunctionMatcher.isFunction("G"), - ) - MatcherAssert.assertThat( - frame2Functionoid.arguments, - Matchers.contains( - VariableMatcher.isVariable("Y", 2), - VariableMatcher.isVariable("Z", "hi"), - ), - ) - MatcherAssert.assertThat(frame2Functionoid.localVariables, Matchers.empty()) - MatcherAssert.assertThat( - frame2Functionoid.libraryIdentifier, - VersionedIdentifierMatcher.isVersionedIdentifier( - "BacktraceTest", - expectedVersion = null, - ), - ) - MatcherAssert.assertThat( - frame2Functionoid, - ContextMatcher.hasContext("Unfiltered", null), - ) - MatcherAssert.assertThat(frame2Functionoid.contextValue, Matchers.equalTo(null)) - // Frame 3 - val frame3 = frames[2] - MatcherAssert.assertThat(frame3, Matchers.instanceOf(FunctionoidFrame::class.java)) - val frame3Functionoid = frame3 as FunctionoidFrame - val definition3 = frame3Functionoid.definition - MatcherAssert.assertThat(definition3, Matchers.instanceOf(ExpressionDef::class.java)) - MatcherAssert.assertThat( - definition3, - ExpressionDefinitionMatcher.isExpressionDefinition("E2"), - ) - MatcherAssert.assertThat(frame3Functionoid.arguments, Matchers.empty()) - MatcherAssert.assertThat(frame3Functionoid.localVariables, Matchers.empty()) - MatcherAssert.assertThat( - frame3Functionoid.libraryIdentifier, - VersionedIdentifierMatcher.isVersionedIdentifier( - "BacktraceTest", - expectedVersion = null, - ), - ) - MatcherAssert.assertThat( - frame3Functionoid, - ContextMatcher.hasContext("Unfiltered", null), - ) - } + @Suppress("LongMethod") + fun backtraceSmoke() { + val cqlException = + assertFailsWith { + engine.evaluate { library("BacktraceTest") }.onlyResultOrThrow + } + val backtrace = cqlException.backtrace + assertNotNull(backtrace) + + val libraryIdentifier = VersionedIdentifier().withId("BacktraceTest") + + val e2Frame = backtrace.frame + assertIs(e2Frame) + assertEquals("E2", e2Frame.element.name) + assertEquals(emptyList(), e2Frame.arguments) + assertEquals(emptyList(), e2Frame.variables) + assertEquals(libraryIdentifier, e2Frame.library) + assertEquals("Unfiltered" to null, e2Frame.context) + + val gFrame = e2Frame.subframes.single() + assertIs(gFrame) + assertEquals("G", gFrame.element.name) + assertEquals( + listOf(Variable("Y").withValue(2), Variable("Z").withValue("hi")), + gFrame.arguments, + ) + assertEquals( + listOf(Variable("Y").withValue(2), Variable("Z").withValue("hi")), + gFrame.variables, + ) + assertEquals(libraryIdentifier, gFrame.library) + assertEquals("Unfiltered" to null, gFrame.context) + + val fFrame = gFrame.subframes.single() + assertIs(fFrame) + assertEquals("F", fFrame.element.name) + assertEquals(listOf(Variable("X").withValue(3)), fFrame.arguments) + assertEquals( + listOf( + Variable("X").withValue(3), + Variable("_").withValue(1), + Variable("A").withValue(7), + ), + fFrame.variables, + ) + assertEquals(libraryIdentifier, fFrame.library) + assertEquals("Unfiltered" to null, fFrame.context) + + val messageFrame = fFrame.subframes.single() + assertIs(messageFrame) + val messageElement = messageFrame.element + assertIs(messageElement) + assertEquals( + listOf( + Variable("X").withValue(3), + Variable("_").withValue(1), + Variable("A").withValue(7), + ), + messageFrame.variables, + ) + assertEquals(libraryIdentifier, messageFrame.library) + assertEquals("Unfiltered" to null, messageFrame.context) + + assertEquals( + """ + BacktraceTest.E2 + BacktraceTest.G(Y = 2, Z = hi) + BacktraceTest.F(X = 3) + Message + + """ + .trimIndent(), + backtrace.toString(), + ) } } diff --git a/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/trace/TraceTest.kt b/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/trace/TraceTest.kt new file mode 100644 index 000000000..884d584e1 --- /dev/null +++ b/Src/java/engine/src/test/kotlin/org/opencds/cqf/cql/engine/execution/trace/TraceTest.kt @@ -0,0 +1,92 @@ +package org.opencds.cqf.cql.engine.execution.trace + +import kotlin.test.assertEquals +import org.hl7.elm.r1.ExpressionDef +import org.hl7.elm.r1.FunctionDef +import org.hl7.elm.r1.OperandDef +import org.hl7.elm.r1.Retrieve +import org.hl7.elm.r1.VersionedIdentifier +import org.junit.jupiter.api.Test +import org.opencds.cqf.cql.engine.execution.CqlEngine +import org.opencds.cqf.cql.engine.execution.CqlTestBase +import org.opencds.cqf.cql.engine.execution.State +import org.opencds.cqf.cql.engine.execution.Variable + +class TraceTest : CqlTestBase() { + + /** + * Generates a trace from a tree of activation frames that conceptually represents the + * evaluation of the following CQL: + * + * library Lib1 + * context Patient + * define function func1(a Integer): a + 1 + * define expr1: func1(Length([Encounter]) + 2) * 3 + * + * Activation frames are also created for retrieves, but these should not appear in the trace. + */ + @Test + fun traceOutput() { + val libraryIdentifier = VersionedIdentifier().withId("Lib1") + val contextName = "Patient" + + val retrieveActivationFrame = + State.ActivationFrame(Retrieve(), libraryIdentifier, contextName, 0) + // Starting with a patient with 4 encounters + retrieveActivationFrame.result = listOf(1, 2, 3, 4) + + val func1ActivationFrame = + State.ActivationFrame( + FunctionDef().withName("func1").withOperand(listOf(OperandDef().withName("a"))), + libraryIdentifier, + contextName, + 0, + ) + func1ActivationFrame.variables.push(Variable("a").withValue(6)) + func1ActivationFrame.result = 7 + + val expr1ActivationFrame = + State.ActivationFrame( + ExpressionDef().withName("expr1"), + libraryIdentifier, + contextName, + 0, + ) + expr1ActivationFrame.innerActivationFrames.add(retrieveActivationFrame) + expr1ActivationFrame.innerActivationFrames.add(func1ActivationFrame) + expr1ActivationFrame.result = 21 + + val trace = + Trace.fromActivationFrames(listOf(expr1ActivationFrame), mapOf("Patient" to null)) + + assertEquals( + """ + Lib1.expr1 = 21 + Lib1.func1(a = 6) = 7 + + """ + .trimIndent(), + trace.toString(), + ) + } + + @Test + fun engineOption() { + engine.state.engineOptions.add(CqlEngine.Options.EnableTracing) + val rv = engine.evaluate { library("TraceTest") } + val result = rv.results.values.first() + assertEquals( + """ + TraceTest.expr1 = 2 + TraceTest.expr2 = 19 + TraceTest.func2(b = 5) = 19 + TraceTest.func1(a = 7) = 8 + TraceTest.func1(a = 8) = 9 + TraceTest.expr1 = 2 + + """ + .trimIndent(), + result.trace.toString(), + ) + } +} diff --git a/Src/java/engine/src/test/resources/org/opencds/cqf/cql/engine/execution/TraceTest.cql b/Src/java/engine/src/test/resources/org/opencds/cqf/cql/engine/execution/TraceTest.cql new file mode 100644 index 000000000..f1391f86e --- /dev/null +++ b/Src/java/engine/src/test/resources/org/opencds/cqf/cql/engine/execution/TraceTest.cql @@ -0,0 +1,9 @@ +library TraceTest + +define function func1(a Integer): a + 1 + +define expr1: 2 + +define function func2(b Integer): func1(b + 2) + func1(b + 3) + expr1 + +define expr2: func2(5)