search

cqframework / cql-engine

Clinical Quality Language Evaluation Engine
Apache License 2.0
62 stars 45 forks source link

Enhancement to enable trace for evaluator debugging #16

Closed nkarip closed 7 years ago

nkarip commented 7 years ago

Currently very difficult to debug ELM scripts when expression result is not as expected, especially with deep nested expressions. Request enhancement for trace level logging within each evaluator that logs 1. entry into the evaluator and 2. exit from the evaluator with string representation of result of execution.

c-schuler commented 7 years ago

Have a simple version of trace logging implemented: https://github.com/DBCG/cql_engine/commit/ccd7ea68c0256530a01311b15f43cc08547f195a. Get the 1.2.16-SNAPSHOT of the engine.

Example usage:

context.setEnableTraceLogging(true); // tells the engine to log the evaluation path 

// Do evaluations
...

String report = context.getTrace()

At the moment, this only logs the incoming operands and the outgoing result. The generated trace is like a stack trace, i.e. most recent evaluations are displayed first.

Let me know if this suits your needs.

nkarip commented 7 years ago

I'm getting an exception, partial stack trace below.

java.lang.NullPointerException at org.opencds.cqf.cql.runtime.Concept.toString(Concept.java:57) at org.opencds.cqf.cql.execution.TraceExecution.logTrace(TraceExecution.java:51) at org.opencds.cqf.cql.execution.Context.logTrace(Context.java:69) at org.opencds.cqf.cql.elm.execution.ToConceptEvaluator.evaluate(ToConceptEvaluator.java:39) at org.opencds.cqf.cql.elm.execution.InValueSetEvaluator.evaluate(InValueSetEvaluator.java:106)

We've actually seen a similar issue before in issue #15, using the example below. If the property operand evaluates to null, then the left hand operand of InValueSet is a Concept object with a single null code entry in getCodes(). This is causing the error in the toString operation when it tries to execute code.toString() on that null entry. I wonder if the ToConcept evaluator should be modified to not add null codes?

`

`

c-schuler commented 7 years ago

Okay. Pull in latest 1.2.16-SNAPSHOT. ToConcept was missing a null check...

nkarip commented 7 years ago

That fixed the exception. The trace output is very helpful, but it's a little difficult to follow the path of execution. For the future, it might be easier to follow if the output has the same nested hierarchy as the ELM. Something like the following (using the example ELM copied above) -

Start InValueSet Start ToConcept Start Property End Property result=".." Start ValueSetRef End ValueSetRef result=".." End ToConcept result=".." End InValueSet result=".."

c-schuler commented 7 years ago

I will continue to improve the trace output as you described. I am going to close this issue.

Please post additional feature requests for trace output as its own issue. Easier for me and others to track that way.

Thanks! =)