From 0fd6ae614d04692d5e337491da2df041ee6fcf23 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Thu, 2 May 2024 14:13:37 +0200
Subject: [PATCH 01/22] Add ILoggableExpression

---
 .../src/main/kotlin/com/smeup/rpgparser/logging/loggable.kt  | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/loggable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/loggable.kt
index 25691c1b8..b693ddb85 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/loggable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/loggable.kt
@@ -6,6 +6,11 @@ interface ILoggable {
     val loggableEntityName: String
 }
 
+interface ILoggableExpression : ILoggable {
+    override val loggableEntityName: String
+        get() = this.javaClass.simpleName
+}
+
 interface ILoggableStatement : ILoggable {
     override val loggableEntityName: String
         get() = this.javaClass.simpleName

From 41824371c25e17aae86ab3f3030a111d26216452 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Thu, 2 May 2024 14:13:57 +0200
Subject: [PATCH 02/22] Add custom loggable name to bifs

---
 .../parsing/ast/builtin_functions.kt          | 89 ++++++++++++++-----
 .../rpgparser/parsing/ast/expressions.kt      |  3 +-
 2 files changed, 67 insertions(+), 25 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/builtin_functions.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/builtin_functions.kt
index a2800022c..ded5047cb 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/builtin_functions.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/builtin_functions.kt
@@ -35,6 +35,8 @@ data class LookupExpr(
     val length: Expression? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%LOOKUP"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -47,6 +49,8 @@ data class ScanExpr(
     val length: Expression? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%SCAN"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -58,6 +62,8 @@ data class CheckExpr(
     val start: Expression? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%CHECK"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -70,6 +76,8 @@ data class TranslateExpr(
     val startPos: Expression,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%XLATE"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -80,6 +88,8 @@ data class TrimExpr(
     val charactersToTrim: Expression? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%TRIM"
     override fun render(): String {
         val toTrim = if (this.charactersToTrim != null) ": ${this.charactersToTrim.render()}" else ""
         return "%TRIM(${this.value.render()} $toTrim)"
@@ -94,7 +104,8 @@ data class TrimrExpr(
     val charactersToTrim: Expression? = null,
     override val position: Position? = null
 ) : Expression(position) {
-
+    override val loggableEntityName: String
+        get() = "%TRIMR"
     override fun render(): String {
         val toTrim = if (this.charactersToTrim != null) ": ${this.charactersToTrim.render()}" else ""
         return "%TRIMR(${this.value.render()} $toTrim)"
@@ -109,10 +120,11 @@ data class TrimlExpr(
     val charactersToTrim: Expression? = null,
     override val position: Position? = null
 ) : Expression(position) {
-
+    override val loggableEntityName: String
+        get() = "%TRIML"
     override fun render(): String {
         val toTrim = if (this.charactersToTrim != null) ": ${this.charactersToTrim.render()}" else ""
-        return "%TRIMR(${this.value.render()} $toTrim)"
+        return "%TRIML(${this.value.render()} $toTrim)"
     }
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
@@ -125,8 +137,9 @@ data class SubstExpr(
     var start: Expression,
     val length: Expression? = null,
     override val position: Position? = null
-) :
-        AssignableExpression(position) {
+) : AssignableExpression(position) {
+    override val loggableEntityName: String
+        get() = "%SUBST"
     override fun render(): String {
         val len = if (length != null) ": ${length.render()}" else ""
         return "%SUBST(${this.string.render()} : ${start.render()} $len)"
@@ -144,8 +157,9 @@ data class SubarrExpr(
     var start: Expression,
     val numberOfElements: Expression? = null,
     override val position: Position? = null
-) :
-    AssignableExpression(position) {
+) : AssignableExpression(position) {
+    override val loggableEntityName: String
+        get() = "%SUBARR"
     override fun render(): String {
         val len = if (numberOfElements != null) ": ${numberOfElements.render()}" else ""
         return "%SUBARR(${this.array.render()} : ${start.render()} $len)"
@@ -158,9 +172,9 @@ data class SubarrExpr(
 
 // %LEN
 @Serializable
-data class LenExpr(var value: Expression, override val position: Position? = null) :
-    AssignableExpression(position) {
-
+data class LenExpr(var value: Expression, override val position: Position? = null) : AssignableExpression(position) {
+    override val loggableEntityName: String
+        get() = "%LEN"
     override fun render(): String {
         return "%LEN(${this.value.render()})"
     }
@@ -179,6 +193,8 @@ data class RemExpr(
     val divisor: Expression,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%REM"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -190,6 +206,8 @@ data class DecExpr(
     val decDigits: Expression,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%DEC"
     override fun render(): String {
         return this.value.render()
     }
@@ -201,8 +219,9 @@ data class DecExpr(
 data class IntExpr(
     var value: Expression,
     override val position: Position? = null
-) :
-    Expression(position) {
+) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%INT"
     override fun render(): String = this.value.render()
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
@@ -212,16 +231,18 @@ data class IntExpr(
 data class InthExpr(
     var value: Expression,
     override val position: Position? = null
-) :
-    Expression(position) {
+) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%INTH"
     override fun render(): String = this.value.render()
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
 // %SQRT
 @Serializable
-data class SqrtExpr(var value: Expression, override val position: Position? = null) :
-        Expression(position) {
+data class SqrtExpr(var value: Expression, override val position: Position? = null) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%SQRT"
     override fun render(): String {
         return this.value.render()
     }
@@ -236,6 +257,8 @@ data class EditcExpr(
     val format: Expression,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%EDITC"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -247,6 +270,8 @@ data class EditwExpr(
     val format: Expression,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%EDITW"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -256,6 +281,8 @@ data class FoundExpr(
     var name: String? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%FOUND"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -265,6 +292,8 @@ data class EofExpr(
     var name: String? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%EOF"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -274,6 +303,8 @@ data class ParmsExpr(
     var name: String,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%PARAMS"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -283,6 +314,8 @@ data class EqualExpr(
     var name: String? = null,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%EQUAL"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -292,6 +325,8 @@ data class AbsExpr(
     var value: Expression,
     override val position: Position? = null
 ) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%ABS"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -299,6 +334,8 @@ data class AbsExpr(
 @Serializable
 data class CharExpr(var value: Expression, val format: String?, override val position: Position? = null) :
     Expression(position) {
+    override val loggableEntityName: String
+        get() = "%CHAR"
     override fun render(): String {
         return "%CHAR(${value.render()})"
     }
@@ -307,8 +344,9 @@ data class CharExpr(var value: Expression, val format: String?, override val pos
 
 // %TIMESTAMP
 @Serializable
-data class TimeStampExpr(val value: Expression?, override val position: Position? = null) :
-    Expression(position) {
+data class TimeStampExpr(val value: Expression?, override val position: Position? = null) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%TIMESTAMP"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -319,8 +357,9 @@ data class DiffExpr(
     var value2: Expression,
     val durationCode: DurationCode,
     override val position: Position? = null
-) :
-    Expression(position) {
+) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%DIFF"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -332,8 +371,9 @@ data class ReplaceExpr(
     val start: Expression? = null,
     val length: Expression? = null,
     override val position: Position? = null
-) :
-    Expression(position) {
+) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%REPLACE"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
@@ -342,8 +382,9 @@ data class ReplaceExpr(
 data class OpenExpr(
     var name: String? = null,
     override val position: Position? = null
-) :
-    Expression(position) {
+) : Expression(position) {
+    override val loggableEntityName: String
+        get() = "%OPEN"
     override fun evalWith(evaluator: Evaluator): Value = evaluator.eval(this)
 }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/expressions.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/expressions.kt
index 108b1e98d..052714c86 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/expressions.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/expressions.kt
@@ -17,6 +17,7 @@
 package com.smeup.rpgparser.parsing.ast
 
 import com.smeup.rpgparser.interpreter.*
+import com.smeup.rpgparser.logging.ILoggableExpression
 import com.strumenta.kolasu.model.Node
 import com.strumenta.kolasu.model.Position
 import com.strumenta.kolasu.model.ReferenceByName
@@ -26,7 +27,7 @@ import kotlinx.serialization.Transient
 import java.math.BigDecimal
 
 @Serializable
-abstract class Expression(@Transient override val position: Position? = null) : Node(position) {
+abstract class Expression(@Transient override val position: Position? = null) : Node(position), ILoggableExpression {
     open fun render(): String = this.javaClass.simpleName
     abstract fun evalWith(evaluator: Evaluator): Value
 }

From 09a32d5dbc825291fb2288fdea05bbf3506cd848 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Thu, 2 May 2024 14:16:51 +0200
Subject: [PATCH 03/22] Add support for time tracking based on program

---
 .../rpgparser/interpreter/InterpreterCore.kt  |   1 +
 .../interpreter/SymbolTableAction.kt          |  13 ++
 .../interpreter/internal_interpreter.kt       | 194 +++++++++---------
 .../com/smeup/rpgparser/interpreter/logs.kt   |   1 +
 .../smeup/rpgparser/interpreter/program.kt    |   5 +-
 .../interpreter/symbol_table_storaging.kt     |   3 +-
 .../logging/AnalyticsLoggingContext.kt        | 158 ++++++--------
 .../rpgparser/logging/ProgramUsageTable.kt    | 110 ++++++++++
 .../rpgparser/logging/UsageMeasurement.kt     |  27 +++
 9 files changed, 317 insertions(+), 195 deletions(-)
 create mode 100644 rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTableAction.kt
 create mode 100644 rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
 create mode 100644 rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/UsageMeasurement.kt

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/InterpreterCore.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/InterpreterCore.kt
index bb919b2d8..a3a69354c 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/InterpreterCore.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/InterpreterCore.kt
@@ -67,6 +67,7 @@ interface InterpreterCore {
     fun optimizedIntExpression(expression: Expression): () -> Long
     fun enterCondition(index: Value, end: Value, downward: Boolean): Boolean
     fun increment(dataDefinition: AbstractDataDefinition, amount: Long): Value
+    fun onInterpretationEnd()
 }
 
 internal fun ErrorEvent.pushRuntimeErrorEvent() {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTableAction.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTableAction.kt
new file mode 100644
index 000000000..d08c41e46
--- /dev/null
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTableAction.kt
@@ -0,0 +1,13 @@
+package com.smeup.rpgparser.interpreter
+
+/**
+ * Represent a type of interaction with the symbol table
+ * @see ISymbolTable
+ */
+enum class SymbolTableAction {
+    INIT,
+    LOAD,
+    STORE,
+    GET,
+    SET
+}
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
index bd6a82fa2..add07cb6e 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
@@ -21,7 +21,6 @@ import com.smeup.dbnative.file.Record
 import com.smeup.rpgparser.execution.ErrorEvent
 import com.smeup.rpgparser.execution.ErrorEventSource
 import com.smeup.rpgparser.execution.MainExecutionContext
-import com.smeup.rpgparser.logging.AnalyticsLoggingContext
 import com.smeup.rpgparser.parsing.ast.*
 import com.smeup.rpgparser.parsing.ast.AssignmentOperator.*
 import com.smeup.rpgparser.parsing.facade.SourceReference
@@ -148,17 +147,18 @@ open class InternalInterpreter(
 
     override fun dataDefinitionByName(name: String) = globalSymbolTable.dataDefinitionByName(name)
 
-    override operator fun get(data: AbstractDataDefinition) = globalSymbolTable[data]
-
-    override operator fun get(dataName: String) = globalSymbolTable[dataName]
+    override operator fun get(data: AbstractDataDefinition) = if (logsEnabled()) getWithLogging(data) else globalSymbolTable[data]
+    override operator fun get(dataName: String) = if (logsEnabled()) getWithLogging(dataName) else globalSymbolTable[dataName]
 
     open operator fun set(data: AbstractDataDefinition, value: Value) {
         require(data.canBeAssigned(value)) {
             "${data.name} of type ${data.type} defined at line ${data.position.line()} cannot be assigned the value $value"
         }
 
+        val programName = interpretationContext.currentProgramName
+
         renderLogInternal {
-            val logSource = { LogSourceData(this.interpretationContext.currentProgramName, data.startLine()) }
+            val logSource = { LogSourceData(programName, data.startLine()) }
             val previous = if (data.name in globalSymbolTable) {
                 globalSymbolTable[data.name]
             } else null
@@ -210,11 +210,11 @@ open class InternalInterpreter(
             }
             else -> {
                 renderLogInternal {
-                    val logSource = { LogSourceData(this.interpretationContext.currentProgramName, data.startLine()) }
+                    val logSource = { LogSourceData(programName, data.startLine()) }
                     LazyLogEntry.produceAssignment(logSource, data, value)
                 }
                 // deny reassignment if data is a constant
-                globalSymbolTable.set(data, coerce(value, data.type))?.let {
+                if (logsEnabled()) setWithLogging(data, value) else globalSymbolTable.set(data, coerce(value, data.type))?.let {
                     if (data.const) error("${data.name} is a const and cannot be assigned")
                 }
             }
@@ -228,7 +228,8 @@ open class InternalInterpreter(
     ) {
         val start = System.nanoTime()
 
-        val logSourceProducer = { LogSourceData(programName = interpretationContext.currentProgramName, line = compilationUnit.startLine()) }
+        val programName = interpretationContext.currentProgramName
+        val logSourceProducer = { LogSourceData(programName = programName, line = compilationUnit.startLine()) }
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLINI", "START") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLINI", "START") }
 
@@ -245,51 +246,54 @@ open class InternalInterpreter(
             beforeInitialization()
             compilationUnit.allDataDefinitions.forEach {
                 var value: Value? = null
-                if (it is DataDefinition) {
-                    value = when {
-                        it.name in initialValues -> {
-                            val initialValue = initialValues[it.name]
-                                ?: throw RuntimeException("Initial values for ${it.name} not found")
-                            if (InterpreterConfiguration.enableRuntimeChecksOnAssignement) {
-                                require(initialValue.assignableTo(it.type)) {
-                                    "Initial value for ${it.name} is not compatible. Passed $initialValue, type: ${it.type}"
+                when (it) {
+                    is DataDefinition -> {
+                        value = when {
+                            it.name in initialValues -> {
+                                val initialValue = initialValues[it.name]
+                                    ?: throw RuntimeException("Initial values for ${it.name} not found")
+                                if (InterpreterConfiguration.enableRuntimeChecksOnAssignement) {
+                                    require(initialValue.assignableTo(it.type)) {
+                                        "Initial value for ${it.name} is not compatible. Passed $initialValue, type: ${it.type}"
+                                    }
                                 }
+                                initialValue
                             }
-                            initialValue
-                        }
 
-                        it.initializationValue != null -> eval(it.initializationValue)
-                        it.isCompileTimeArray() -> toArrayValue(
-                            compilationUnit.compileTimeArray(index++),
-                            (it.type as ArrayType)
-                        )
+                            it.initializationValue != null -> eval(it.initializationValue)
+                            it.isCompileTimeArray() -> toArrayValue(
+                                compilationUnit.compileTimeArray(index++),
+                                (it.type as ArrayType)
+                            )
 
-                        else -> blankValue(it)
-                    }
-                    if (it.name !in initialValues) {
-                        blankValue(it)
-                        it.fields.forEach { field ->
-                            if (field.initializationValue != null) {
-                                val fieldValue = coerce(eval(field.initializationValue), field.type)
-                                (value as DataStructValue).set(field, fieldValue)
+                            else -> blankValue(it)
+                        }
+                        if (it.name !in initialValues) {
+                            blankValue(it)
+                            it.fields.forEach { field ->
+                                if (field.initializationValue != null) {
+                                    val fieldValue = coerce(eval(field.initializationValue), field.type)
+                                    (value as DataStructValue).set(field, fieldValue)
+                                }
                             }
                         }
                     }
-                } else if (it is InStatementDataDefinition) {
-                    value = if (it.parent is PlistParam) {
-                        when (it.name) {
-                            in initialValues -> initialValues[it.name]
-                                ?: throw RuntimeException("Initial values for ${it.name} not found")
-
-                            else -> if ((it.parent as PlistParam).dataDefinition().isNotEmpty()) {
-                                it.type.blank()
-                            } else {
-                                null
+                    is InStatementDataDefinition -> {
+                        value = if (it.parent is PlistParam) {
+                            when (it.name) {
+                                in initialValues -> initialValues[it.name]
+                                    ?: throw RuntimeException("Initial values for ${it.name} not found")
+
+                                else -> if ((it.parent as PlistParam).dataDefinition().isNotEmpty()) {
+                                    it.type.blank()
+                                } else {
+                                    null
+                                }
                             }
+                        } else {
+                            // TODO check this during the process of revision of DB access
+                            if (it.type is KListType) null else it.type.blank()
                         }
-                    } else {
-                        // TODO check this during the process of revision of DB access
-                        if (it.type is KListType) null else it.type.blank()
                     }
                 }
                 // Fix issue on CTDATA
@@ -326,7 +330,8 @@ open class InternalInterpreter(
 
         val initElapsed = (System.nanoTime() - start).nanoseconds
 
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableDuration(AnalyticsLoggingContext.SymbolTableAction.INIT, initElapsed)
+        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext()
+        analyticsContext?.recordSymbolTableAccess(programName, SymbolTableAction.INIT, initElapsed)
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLINI", "END") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLINI", "END") }
         renderLogInternal { LazyLogEntry.producePerformance(logSourceProducer, "SYMTBLINI", initElapsed) }
@@ -336,7 +341,7 @@ open class InternalInterpreter(
 
         val loadElapsed = measureNanoTime { afterInitialization(initialValues = initialValues) }.nanoseconds
 
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableDuration(AnalyticsLoggingContext.SymbolTableAction.LOAD, loadElapsed)
+        analyticsContext?.recordSymbolTableAccess(programName, SymbolTableAction.LOAD, loadElapsed)
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLLOAD", "END") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLLOAD", "END") }
         renderLogInternal { LazyLogEntry.producePerformance(logSourceProducer, "SYMTBLLOAD", loadElapsed) }
@@ -399,8 +404,6 @@ open class InternalInterpreter(
                     )
                 }
             }
-
-            onExecutionEnd()
         }.onFailure {
             if (it is ReturnException) {
                 status.returnValue = it.returnValue
@@ -444,13 +447,9 @@ open class InternalInterpreter(
     }
 
     private fun executeWithMute(statement: Statement) {
+        val programName = interpretationContext.currentProgramName
         renderLogInternal {
-            val logSource = {
-                LogSourceData(
-                    programName = this.interpretationContext.currentProgramName,
-                    line = statement.position.line()
-                )
-            }
+            val logSource = { LogSourceData(programName, statement.position.line()) }
             LazyLogEntry.produceLine(logSource)
         }
 
@@ -540,6 +539,7 @@ open class InternalInterpreter(
         compilationUnit: CompilationUnit,
         line: String
     ) {
+        val programName = interpretationContext.currentProgramName
         muteAnnotations.forEach {
             it.resolveAndValidate(compilationUnit)
             when (it) {
@@ -561,12 +561,7 @@ open class InternalInterpreter(
                     }
 
                     renderLogInternal {
-                        val logSource = {
-                            LogSourceData(
-                                this.interpretationContext.currentProgramName,
-                                it.startLine()
-                            )
-                        }
+                        val logSource = { LogSourceData(programName, it.startLine()) }
                         LazyLogEntry.produceMute(it, logSource, value)
                     }
 
@@ -602,13 +597,9 @@ open class InternalInterpreter(
 
                 is MuteFailAnnotation -> {
                     val message = it.message.evalWith(expressionEvaluation)
+                    val programName = this.interpretationContext.currentProgramName
                     renderLogInternal {
-                        val logSource = {
-                            LogSourceData(
-                                this.interpretationContext.currentProgramName,
-                                it.startLine()
-                            )
-                        }
+                        val logSource = { LogSourceData(programName, it.startLine()) }
                         LazyLogEntry.produceMute(it, logSource, message)
                     }
                     systemInterface.addExecutedAnnotation(
@@ -761,13 +752,9 @@ open class InternalInterpreter(
         val value = this[dataDefinition]
         if (value is NumberValue) {
             val newValue = value.increment(amount)
+            val programName = this.interpretationContext.currentProgramName
             renderLogInternal {
-                val logSource = {
-                    LogSourceData(
-                        this.interpretationContext.currentProgramName,
-                        dataDefinition.startLine()
-                    )
-                }
+                val logSource = { LogSourceData(programName, dataDefinition.startLine()) }
                 LazyLogEntry.produceData(logSource, dataDefinition, newValue, value)
             }
             globalSymbolTable[dataDefinition] = newValue
@@ -796,18 +783,13 @@ open class InternalInterpreter(
             else -> expression.evalWith(expressionEvaluation)
         }
 
-        val elapsed = System.nanoTime() - start
+        val elapsed = (System.nanoTime() - start).nanoseconds
 
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordExpressionDuration(elapsed.nanoseconds)
-        renderLogInternal {
-            val logSource = {
-                LogSourceData(
-                    this.interpretationContext.currentProgramName,
-                    expression.startLine()
-                )
-            }
-            LazyLogEntry.produceExpression(logSource, expression, value)
-        }
+        val programName = this.interpretationContext.currentProgramName
+        MainExecutionContext.getAnalyticsLoggingContext()?.recordExpressionExecution(programName, expression.loggableEntityName, elapsed)
+        val sourceProvider = { LogSourceData(programName, expression.startLine()) }
+        renderLogInternal { LazyLogEntry.produceExpression(sourceProvider, expression, value) }
+        renderLogInternal { LazyLogEntry.producePerformance(sourceProvider, expression.loggableEntityName, elapsed) }
 
         return value
     }
@@ -1162,12 +1144,8 @@ open class InternalInterpreter(
     }
 
     private inline fun executeWithLogging(statement: Statement) {
-        val sourceProducer = {
-            LogSourceData(
-                programName = this.interpretationContext.currentProgramName,
-                line = statement.position.line()
-            )
-        }
+        val programName = this.interpretationContext.currentProgramName
+        val sourceProducer = { LogSourceData(programName, statement.position.line()) }
 
         renderLogInternal { statement.getResolutionLogRenderer(sourceProducer) }
 
@@ -1185,7 +1163,7 @@ open class InternalInterpreter(
             statement.execute(this)
         }.nanoseconds
 
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordStatementDuration(statement.loggableEntityName, executionTime)
+        MainExecutionContext.getAnalyticsLoggingContext()?.recordStatementExecution(programName, statement.loggableEntityName, executionTime)
 
         if (statement is LoopStatement) {
             renderLogInternal {
@@ -1205,15 +1183,39 @@ open class InternalInterpreter(
         renderLogInternal { LazyLogEntry.producePerformance(sourceProducer, statement.loggableEntityName, executionTime) }
     }
 
-    private fun onExecutionEnd() {
-        val logSource = { LogSourceData(this.interpretationContext.currentProgramName, "") }
+    override fun onInterpretationEnd() {
+        val loggingContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return
+        loggingContext.generateCompleteReport().forEach { entry -> renderLogInternal { entry } }
+    }
 
-        val loggingContext = MainExecutionContext.getAnalyticsLoggingContext()
-        loggingContext ?: return
+    private fun getWithLogging(data: String): Value {
+        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return globalSymbolTable[data]
+        val start = System.nanoTime()
+        val value = globalSymbolTable[data]
+        val elapsed = System.nanoTime() - start
+        analyticsContext.recordSymbolTableAccess(interpretationContext.currentProgramName, SymbolTableAction.GET, elapsed.nanoseconds)
+        return value
+    }
 
-        loggingContext.generateCompleteReport(logSource).forEach {
-            entry -> renderLogInternal { entry }
+    private fun getWithLogging(data: AbstractDataDefinition): Value {
+        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return globalSymbolTable[data]
+        val start = System.nanoTime()
+        val value = globalSymbolTable[data]
+        val elapsed = System.nanoTime() - start
+        analyticsContext.recordSymbolTableAccess(interpretationContext.currentProgramName, SymbolTableAction.GET, elapsed.nanoseconds)
+        return value
+    }
+
+    private fun setWithLogging(data: AbstractDataDefinition, value: Value) {
+        fun setValue() {
+            globalSymbolTable.set(data, coerce(value, data.type))?.let {
+                if (data.const) error("${data.name} is a const and cannot be assigned")
+            }
         }
+
+        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return setValue()
+        val elapsed = measureNanoTime { setValue() }
+        analyticsContext.recordSymbolTableAccess(interpretationContext.currentProgramName, SymbolTableAction.SET, elapsed.nanoseconds)
     }
 }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
index 44aa36ef5..0ad5876c6 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
@@ -41,6 +41,7 @@ data class LogSourceData(
 ) {
     companion object {
         val UNKNOWN get() = LogSourceData("", "")
+        fun fromProgram(name: String) = LogSourceData(name, "")
     }
     val filename get() = programName.replace('\\', '/').substringAfterLast("/").substringBeforeLast(".")
     fun projectLine(newLine: String) = LogSourceData(programName, newLine)
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
index b43bf4708..bf023378b 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
@@ -99,7 +99,7 @@ class RpgProgram(val cu: CompilationUnit, val name: String = "<UNNAMED RPG PROGR
             }
         }
         this.systemInterface = systemInterface
-        val logSource = { LogSourceData(name, "") }
+        val logSource = { LogSourceData.fromProgram(name) }
         logHandlers.renderLog(LazyLogEntry.produceStatement(logSource, "INTERPRETATION", "START"))
         val changedInitialValues: List<Value>
         val elapsed = measureNanoTime {
@@ -153,6 +153,9 @@ class RpgProgram(val cu: CompilationUnit, val name: String = "<UNNAMED RPG PROGR
             // here clear symbol table if needed
             interpreter.doSomethingAfterExecution()
             MainExecutionContext.getProgramStack().pop()
+            if (MainExecutionContext.getProgramStack().isEmpty()) {
+                interpreter.onInterpretationEnd()
+            }
         }.nanoseconds
         logHandlers.renderLog(LazyLogEntry.produceStatement(logSource, "INTERPRETATION", "END"))
         logHandlers.renderLog(LazyLogEntry.producePerformance(logSource, "INTERPRETATION", elapsed))
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt
index 6a65185b0..6602aea8f 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt
@@ -1,7 +1,6 @@
 package com.smeup.rpgparser.interpreter
 
 import com.smeup.rpgparser.execution.MainExecutionContext
-import com.smeup.rpgparser.logging.AnalyticsLoggingContext
 import kotlin.system.measureNanoTime
 import kotlin.time.Duration.Companion.nanoseconds
 
@@ -167,7 +166,7 @@ class MemorySliceMgr(private val storage: IMemorySliceStorage) {
                     val elapsed = measureNanoTime {
                         storage.store(memorySliceId = slice.memorySliceId, values = values)
                     }.nanoseconds
-                    MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableDuration(AnalyticsLoggingContext.SymbolTableAction.STORE, elapsed)
+                    MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableAccess(slice.memorySliceId.programName, SymbolTableAction.STORE, elapsed)
                     MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "SYMTBLSTORE", "END"))
                     MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "SYMTBLSTORE", elapsed))
                 }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
index 6f26bd77e..693247c12 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
@@ -2,127 +2,93 @@ package com.smeup.rpgparser.logging
 
 import com.smeup.rpgparser.interpreter.LazyLogEntry
 import com.smeup.rpgparser.interpreter.LogEntry
-import com.smeup.rpgparser.interpreter.LogSourceProvider
-import java.util.*
-import kotlin.collections.HashMap
+import com.smeup.rpgparser.interpreter.LogSourceData
+import com.smeup.rpgparser.interpreter.SymbolTableAction
 import kotlin.time.Duration
 import kotlin.time.Duration.Companion.nanoseconds
 import kotlin.time.DurationUnit
 
+/**
+ * Object used to store metadata for ANALYTICS log channel.
+ * @see LogChannel.ANALYTICS
+ */
 class AnalyticsLoggingContext {
-    private val timeUsageByStatement: HashMap<String, UsageMeasurement> = hashMapOf()
-    private val symbolTableTimeUsage: EnumMap<SymbolTableAction, UsageMeasurement> = EnumMap(SymbolTableAction::class.java)
+    private val programUsageTable = ProgramUsageTable()
     private var renderingTimeMeasurement = UsageMeasurement.new()
-    private var expressionTimeMeasurement = UsageMeasurement.new()
 
     private val initTimestamp = System.nanoTime()
-
     private val totalTime
         get() = (System.nanoTime() - initTimestamp).nanoseconds
 
-    enum class SymbolTableAction {
-        INIT,
-        LOAD,
-        STORE
-    }
-
-    data class UsageMeasurement(val duration: Duration, val hit: Long) {
-        companion object {
-            fun new(): UsageMeasurement = UsageMeasurement(
-                duration = Duration.ZERO,
-                hit = 0
-            )
-        }
-    }
-
-    fun recordRenderingDuration(executionTime: Duration) {
-        renderingTimeMeasurement = UsageMeasurement(
-            duration = renderingTimeMeasurement.duration + executionTime,
-            hit = renderingTimeMeasurement.hit + 1
-        )
-    }
-
-    fun recordExpressionDuration(executionTime: Duration) {
-        expressionTimeMeasurement = UsageMeasurement(
-            duration = renderingTimeMeasurement.duration + executionTime,
-            hit = renderingTimeMeasurement.hit + 1
-        )
-    }
-
-    fun recordSymbolTableDuration(action: SymbolTableAction, executionTime: Duration) {
-        val entry = symbolTableTimeUsage.getOrPut(action) { UsageMeasurement.new() }
-        symbolTableTimeUsage[action] = UsageMeasurement(
-            duration = entry.duration + executionTime,
-            hit = entry.hit + 1
-        )
-    }
-
-    fun recordStatementDuration(name: String, executionTime: Duration) {
-        val entry = timeUsageByStatement.getOrPut(name) { UsageMeasurement.new() }
-        timeUsageByStatement[name] = UsageMeasurement(
-            duration = entry.duration + executionTime,
-            hit = entry.hit + 1
-        )
-    }
-
-    fun generateCompleteReport(source: LogSourceProvider): List<LazyLogEntry> {
-        val timeUsageEntries = generateTimeUsageByStatementReportEntries(source)
-        val symTableEntries = generateSymbolTableTimeUsageReportEntries(source)
-        val expressionEntry = generateExpressionReportEntry(source)
-        val logTimeEntry = generateLogTimeReportEntry(source)
-        val programExecutionEntry = generateProgramReportEntry(source)
+    private val durationUnit = DurationUnit.MICROSECONDS
 
-        return timeUsageEntries + symTableEntries + expressionEntry + logTimeEntry + programExecutionEntry
+    /**
+     * Records log rendering duration.
+     */
+    fun recordRenderingDuration(time: Duration) {
+        renderingTimeMeasurement = renderingTimeMeasurement.hit(time)
     }
 
-    private fun generateTimeUsageByStatementReportEntries(source: LogSourceProvider): List<LazyLogEntry> {
-        return timeUsageByStatement.toList().map {
-            val statementName = it.first
-            val duration = it.second.duration
-            val hit = it.second.hit
-
-            val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "STMT TIME")
-            LazyLogEntry(entry) { sep ->
-                "$statementName$sep${duration.toString(DurationUnit.MICROSECONDS)}${sep}$hit"
-            }
+    /**
+     * Records the execution of an expression.
+     * @see ILoggableExpression
+     */
+    fun recordExpressionExecution(program: String, entity: String, time: Duration) =
+        programUsageTable.recordExpression(program, entity, time)
+
+    /**
+     * Records an interaction with the symbol table.
+     * @see SymbolTableAction
+     */
+    fun recordSymbolTableAccess(program: String, action: SymbolTableAction, time: Duration) =
+        programUsageTable.recordSymbolTableAction(program, action, time)
+
+    /**
+     * Records the execution of a statement.
+     * @see ILoggableStatement
+     */
+    fun recordStatementExecution(program: String, entity: String, time: Duration) =
+        programUsageTable.recordStatement(program, entity, time)
+
+    /**
+     * Generate an ANALYTICS report based on currently collected metadata in the form
+     * of a list of LazyLogEntry.
+     * @see LazyLogEntry
+     */
+    fun generateCompleteReport(): List<LazyLogEntry> {
+        val statementEntries = mutableListOf<LazyLogEntry>()
+        val expressionEntries = mutableListOf<LazyLogEntry>()
+        val symbolTableEntries = mutableListOf<LazyLogEntry>()
+
+        programUsageTable.asSequence().forEach {
+            val program = it.key
+            val statement = programUsageTable.generateStatementLogEntries(program, durationUnit)
+            val expression = programUsageTable.generateExpressionLogEntries(program, durationUnit)
+            val symTable = programUsageTable.generateSymbolTableLogEntries(program, durationUnit)
+
+            statementEntries.addAll(statement)
+            expressionEntries.addAll(expression)
+            symbolTableEntries.addAll(symTable)
         }
-    }
 
-    private fun generateSymbolTableTimeUsageReportEntries(source: LogSourceProvider): List<LazyLogEntry> {
-        return symbolTableTimeUsage.toList().map {
-            val action = it.first
-            val duration = it.second.duration
-            val hit = it.second.hit
+        val logTimeEntry = generateLogTimeReportEntry()
+        val programExecutionEntry = generateProgramReportEntry()
 
-            val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "SYMTBL TIME")
-            LazyLogEntry(entry) { sep ->
-                "${action.name}$sep${duration.toString(DurationUnit.MICROSECONDS)}${sep}$hit"
-            }
-        }
-    }
-
-    private fun generateExpressionReportEntry(source: LogSourceProvider): LazyLogEntry {
-        val duration = expressionTimeMeasurement.duration
-        val hit = expressionTimeMeasurement.hit
-
-        val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "EXPR TIME")
-        return LazyLogEntry(entry) { sep ->
-            "${duration.toString(DurationUnit.MICROSECONDS)}$sep$hit"
-        }
+        return statementEntries + expressionEntries + symbolTableEntries + logTimeEntry + programExecutionEntry
     }
 
-    private fun generateLogTimeReportEntry(source: LogSourceProvider): LazyLogEntry {
+    private fun generateLogTimeReportEntry(): LazyLogEntry {
         val duration = renderingTimeMeasurement.duration
         val hit = renderingTimeMeasurement.hit
 
-        val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "LOG TIME")
+        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "LOG TIME")
         return LazyLogEntry(entry) { sep ->
-            "${duration.toString(DurationUnit.MICROSECONDS)}$sep$hit"
+            "${duration.toString(durationUnit)}$sep$hit"
         }
     }
 
-    private fun generateProgramReportEntry(source: LogSourceProvider): LazyLogEntry {
-        val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "PROGRAM TIME")
-        return LazyLogEntry(entry) { totalTime.toString(DurationUnit.MICROSECONDS) }
+    private fun generateProgramReportEntry(): LazyLogEntry {
+        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "PROGRAM TIME")
+        return LazyLogEntry(entry) { totalTime.toString(durationUnit) }
     }
 }
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
new file mode 100644
index 000000000..35d2ba42e
--- /dev/null
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
@@ -0,0 +1,110 @@
+package com.smeup.rpgparser.logging
+
+import com.smeup.rpgparser.interpreter.LazyLogEntry
+import com.smeup.rpgparser.interpreter.LogEntry
+import com.smeup.rpgparser.interpreter.LogSourceData
+import com.smeup.rpgparser.interpreter.SymbolTableAction
+import java.util.*
+import kotlin.collections.HashMap
+import kotlin.time.Duration
+import kotlin.time.DurationUnit
+
+/**
+ * Collects the usage information about the main parts of the program.
+ */
+class ProgramUsageStats {
+    val statements: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
+    val expressions: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
+    val symbolTableActions: EnumMap<SymbolTableAction, UsageMeasurement> by lazy {
+        EnumMap(SymbolTableAction::class.java)
+    }
+}
+
+typealias ProgramUsageTable = HashMap<String, ProgramUsageStats>
+
+/**
+ * Records the execution of a statement.
+ * @see ILoggableStatement
+ */
+fun ProgramUsageTable.recordStatement(program: String, entity: String, time: Duration) {
+    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+    val measurement = programStats.statements.getOrDefault(entity, UsageMeasurement.new())
+    programStats.statements[entity] = measurement.hit(time)
+}
+
+/**
+ * Records the execution of an expression.
+ * @see ILoggableExpression
+ */
+fun ProgramUsageTable.recordExpression(program: String, entity: String, time: Duration) {
+    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+    val measurement = programStats.expressions.getOrDefault(entity, UsageMeasurement.new())
+    programStats.expressions[entity] = measurement.hit(time)
+}
+
+/**
+ * Records an interaction with the symbol table.
+ * @see SymbolTableAction
+ */
+fun ProgramUsageTable.recordSymbolTableAction(program: String, action: SymbolTableAction, time: Duration) {
+    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+    val measurement = programStats.symbolTableActions.getOrDefault(action, UsageMeasurement.new())
+    programStats.symbolTableActions[action] = measurement.hit(time)
+}
+
+/**
+ * Generate an ANALYTICS statement usage report in the form of a sequence of LazyLogEntry.
+ * @see LazyLogEntry
+ */
+fun ProgramUsageTable.generateStatementLogEntries(program: String, unit: DurationUnit = DurationUnit.NANOSECONDS): Sequence<LazyLogEntry> {
+    val stats = this[program] ?: return emptySequence()
+
+    return stats.statements.asSequence().map {
+        val statementName = it.key
+        val duration = it.value.duration
+        val hit = it.value.hit
+
+        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "STMT TIME")
+        LazyLogEntry(entry) { sep ->
+            "$program$sep$statementName$sep${duration.toString(unit)}${sep}$hit"
+        }
+    }
+}
+
+/**
+ * Generate an ANALYTICS expression usage report in the form of a sequence of LazyLogEntry.
+ * @see LazyLogEntry
+ */
+fun ProgramUsageTable.generateExpressionLogEntries(program: String, unit: DurationUnit = DurationUnit.NANOSECONDS): Sequence<LazyLogEntry> {
+    val stats = this[program] ?: return emptySequence()
+
+    return stats.expressions.asSequence().map {
+        val exprName = it.key
+        val duration = it.value.duration
+        val hit = it.value.hit
+
+        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "EXPR TIME")
+        LazyLogEntry(entry) { sep ->
+            "$program$sep$exprName$sep${duration.toString(unit)}${sep}$hit"
+        }
+    }
+}
+
+/**
+ * Generate an ANALYTICS symbol table usage report in the form of a sequence of LazyLogEntry.
+ * @see LazyLogEntry
+ */
+fun ProgramUsageTable.generateSymbolTableLogEntries(program: String, unit: DurationUnit = DurationUnit.NANOSECONDS): Sequence<LazyLogEntry> {
+    val stats = this[program] ?: return emptySequence()
+
+    return stats.symbolTableActions.asSequence().map {
+        val action = it.key
+        val duration = it.value.duration
+        val hit = it.value.hit
+
+        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "SYMTBL TIME")
+        LazyLogEntry(entry) { sep ->
+            "$program$sep$action$sep${duration.toString(unit)}${sep}$hit"
+        }
+    }
+}
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/UsageMeasurement.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/UsageMeasurement.kt
new file mode 100644
index 000000000..fcd57db57
--- /dev/null
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/UsageMeasurement.kt
@@ -0,0 +1,27 @@
+package com.smeup.rpgparser.logging
+
+import kotlin.time.Duration
+
+/**
+ * Object used to keep track of the usage of statements, expression or other parts of the execution.
+ * @see ProgramUsageStats
+ */
+data class UsageMeasurement(val duration: Duration, val hit: Long) {
+    companion object {
+        /**
+         * Create a new empty UsageMeasurement.
+         */
+        fun new(): UsageMeasurement = UsageMeasurement(
+            duration = Duration.ZERO,
+            hit = 0
+        )
+    }
+
+    /**
+     * Record a hit
+     */
+    fun hit(time: Duration) = UsageMeasurement(
+        hit = hit + 1,
+        duration = duration + time
+    )
+}
\ No newline at end of file

From 5a8fd4484fcc555b8dafbab41be1cec0a2b0b8b9 Mon Sep 17 00:00:00 2001
From: lanarimarco <marco.lanari@smeup.com>
Date: Fri, 3 May 2024 09:29:27 +0200
Subject: [PATCH 04/22] Add in extension function String.outputOf a callback
 that allows to customize the system interface. Change executeT10_A60_P02 test
 unit to log in console perf and analytics

---
 .../test/kotlin/com/smeup/rpgparser/AbstractTest.kt    | 10 +++++++++-
 .../smeup/rpgparser/evaluation/SmeupInterpreterTest.kt |  8 +++++++-
 2 files changed, 16 insertions(+), 2 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
index 9f6fead7c..816ad8d6d 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
@@ -240,13 +240,21 @@ abstract class AbstractTest {
      *
      * @param trimEnd A boolean value indicating whether the output should be trimmed or not. Default value is true.
      * @param configuration The configuration for the execution of the program.
+     * @param afterSystemInterface A callback function to be executed after the system interface is created.
+     * Default is an empty function.
      * @return A list of strings representing the output of the program. If trimEnd is true, the strings are trimmed.
      */
-    protected fun String.outputOf(trimEnd: Boolean = true, configuration: Configuration = Configuration()): List<String> {
+    protected fun String.outputOf(
+        trimEnd: Boolean = true,
+        configuration: Configuration = Configuration(),
+        afterSystemInterface: (systemInterface: JavaSystemInterface) -> Unit = {}
+
+    ): List<String> {
         val messages = mutableListOf<String>()
         val systemInterface = JavaSystemInterface().apply {
             onDisplay = { message, _ -> messages.add(message) }
         }
+        afterSystemInterface.invoke(systemInterface)
         executePgm(programName = this, systemInterface = systemInterface, configuration = configuration)
         return if (trimEnd) messages.map { it.trimEnd() } else messages
     }
diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
index b41a0f1d4..013a0b629 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
@@ -5,6 +5,8 @@ import com.smeup.rpgparser.AbstractTest
 import com.smeup.rpgparser.execution.Configuration
 import com.smeup.rpgparser.execution.ReloadConfig
 import com.smeup.rpgparser.execution.SimpleReloadConfig
+import com.smeup.rpgparser.logging.LogChannel
+import com.smeup.rpgparser.logging.consoleLoggingConfiguration
 import org.junit.Test
 import java.time.LocalDateTime
 import java.time.format.DateTimeFormatter
@@ -278,7 +280,11 @@ open class SmeupInterpreterTest : AbstractTest() {
     @Test
     fun executeT10_A60_P02() {
         val expected = listOf<String>("C10_P1: MULANGT102")
-        assertEquals(expected, "smeup/T10_A60_P02".outputOf())
+        assertEquals(expected, "smeup/T10_A60_P02".outputOf(
+            afterSystemInterface = { si ->
+                si.loggingConfiguration = consoleLoggingConfiguration(LogChannel.PERFORMANCE, LogChannel.ANALYTICS)
+            }
+        ))
 
         assertFailsWith<Exception> {
             "smeup/T10_A60_P02F".outputOf()

From cb28ddeb12dee6561cded3b36d3b1ee87400566c Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Fri, 3 May 2024 16:22:59 +0200
Subject: [PATCH 05/22] Fix some formatting issues

---
 .../com/smeup/rpgparser/interpreter/logs.kt    |  5 +----
 .../logging/AnalyticsLoggingContext.kt         | 14 +++++++-------
 .../rpgparser/logging/ProgramUsageTable.kt     | 18 +++++++++---------
 .../rpgparser/smeup/PerfLoggingExample.kt      |  8 ++++++++
 4 files changed, 25 insertions(+), 20 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
index 0ad5876c6..cafda9c50 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
@@ -223,10 +223,7 @@ class LazyLogEntry(val entry: LogEntry, val renderContent: (sep: String) -> Stri
         fun producePerformance(source: LogSourceProvider, entity: String, elapsed: Duration): LazyLogEntry {
             val entry = LogEntry(source, LogChannel.PERFORMANCE.getPropertyName(), entity)
             return LazyLogEntry(entry) {
-                buildString {
-                    append("elapsed ")
-                    append(elapsed.toString(DurationUnit.MICROSECONDS))
-                }
+                elapsed.inWholeMicroseconds.toString()
             }
         }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
index 693247c12..5aa277e6f 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
@@ -20,8 +20,6 @@ class AnalyticsLoggingContext {
     private val totalTime
         get() = (System.nanoTime() - initTimestamp).nanoseconds
 
-    private val durationUnit = DurationUnit.MICROSECONDS
-
     /**
      * Records log rendering duration.
      */
@@ -62,9 +60,9 @@ class AnalyticsLoggingContext {
 
         programUsageTable.asSequence().forEach {
             val program = it.key
-            val statement = programUsageTable.generateStatementLogEntries(program, durationUnit)
-            val expression = programUsageTable.generateExpressionLogEntries(program, durationUnit)
-            val symTable = programUsageTable.generateSymbolTableLogEntries(program, durationUnit)
+            val statement = programUsageTable.generateStatementLogEntries(program)
+            val expression = programUsageTable.generateExpressionLogEntries(program)
+            val symTable = programUsageTable.generateSymbolTableLogEntries(program)
 
             statementEntries.addAll(statement)
             expressionEntries.addAll(expression)
@@ -83,12 +81,14 @@ class AnalyticsLoggingContext {
 
         val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "LOG TIME")
         return LazyLogEntry(entry) { sep ->
-            "${duration.toString(durationUnit)}$sep$hit"
+            "$sep${duration.inWholeMicroseconds}$sep$hit"
         }
     }
 
     private fun generateProgramReportEntry(): LazyLogEntry {
         val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "PROGRAM TIME")
-        return LazyLogEntry(entry) { totalTime.toString(durationUnit) }
+        return LazyLogEntry(entry) { sep ->
+            "$sep${totalTime.inWholeMicroseconds}$sep"
+        }
     }
 }
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
index 35d2ba42e..8ece06438 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
@@ -56,7 +56,7 @@ fun ProgramUsageTable.recordSymbolTableAction(program: String, action: SymbolTab
  * Generate an ANALYTICS statement usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry
  */
-fun ProgramUsageTable.generateStatementLogEntries(program: String, unit: DurationUnit = DurationUnit.NANOSECONDS): Sequence<LazyLogEntry> {
+fun ProgramUsageTable.generateStatementLogEntries(program: String): Sequence<LazyLogEntry> {
     val stats = this[program] ?: return emptySequence()
 
     return stats.statements.asSequence().map {
@@ -64,9 +64,9 @@ fun ProgramUsageTable.generateStatementLogEntries(program: String, unit: Duratio
         val duration = it.value.duration
         val hit = it.value.hit
 
-        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "STMT TIME")
+        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "STMT TIME")
         LazyLogEntry(entry) { sep ->
-            "$program$sep$statementName$sep${duration.toString(unit)}${sep}$hit"
+            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
         }
     }
 }
@@ -75,7 +75,7 @@ fun ProgramUsageTable.generateStatementLogEntries(program: String, unit: Duratio
  * Generate an ANALYTICS expression usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry
  */
-fun ProgramUsageTable.generateExpressionLogEntries(program: String, unit: DurationUnit = DurationUnit.NANOSECONDS): Sequence<LazyLogEntry> {
+fun ProgramUsageTable.generateExpressionLogEntries(program: String): Sequence<LazyLogEntry> {
     val stats = this[program] ?: return emptySequence()
 
     return stats.expressions.asSequence().map {
@@ -83,9 +83,9 @@ fun ProgramUsageTable.generateExpressionLogEntries(program: String, unit: Durati
         val duration = it.value.duration
         val hit = it.value.hit
 
-        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "EXPR TIME")
+        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "EXPR TIME")
         LazyLogEntry(entry) { sep ->
-            "$program$sep$exprName$sep${duration.toString(unit)}${sep}$hit"
+            "$exprName$sep${duration.inWholeMicroseconds}${sep}$hit"
         }
     }
 }
@@ -94,7 +94,7 @@ fun ProgramUsageTable.generateExpressionLogEntries(program: String, unit: Durati
  * Generate an ANALYTICS symbol table usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry
  */
-fun ProgramUsageTable.generateSymbolTableLogEntries(program: String, unit: DurationUnit = DurationUnit.NANOSECONDS): Sequence<LazyLogEntry> {
+fun ProgramUsageTable.generateSymbolTableLogEntries(program: String): Sequence<LazyLogEntry> {
     val stats = this[program] ?: return emptySequence()
 
     return stats.symbolTableActions.asSequence().map {
@@ -102,9 +102,9 @@ fun ProgramUsageTable.generateSymbolTableLogEntries(program: String, unit: Durat
         val duration = it.value.duration
         val hit = it.value.hit
 
-        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "SYMTBL TIME")
+        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "SYMTBL TIME")
         LazyLogEntry(entry) { sep ->
-            "$program$sep$action$sep${duration.toString(unit)}${sep}$hit"
+            "$action$sep${duration.inWholeMicroseconds}${sep}$hit"
         }
     }
 }
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt
index 6dbff9fe0..06fd24484 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt
@@ -16,4 +16,12 @@ class PerfLoggingExample : MULANGTTest() {
         }
         executePgm(programName = "performance/MUTE10_10", systemInterface = si)
     }
+
+    @Test @Category(PerformanceTest::class)
+    fun testT10_A60_P02() {
+        val si = JavaSystemInterface().apply {
+            loggingConfiguration = consoleLoggingConfiguration(LogChannel.PERFORMANCE, LogChannel.ANALYTICS)
+        }
+        executePgm(programName = "smeup/T10_A60_P02", systemInterface = si)
+    }
 }
\ No newline at end of file

From 4b60d91458f8fdb00503e7d2f0adea131c0db3e2 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Mon, 13 May 2024 11:48:54 +0200
Subject: [PATCH 06/22] Refactor program time collection

---
 .../smeup/rpgparser/interpreter/program.kt    |  5 ++--
 .../logging/AnalyticsLoggingContext.kt        | 27 +++++++++++--------
 2 files changed, 18 insertions(+), 14 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
index bf023378b..6905d6ae2 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
@@ -153,12 +153,11 @@ class RpgProgram(val cu: CompilationUnit, val name: String = "<UNNAMED RPG PROGR
             // here clear symbol table if needed
             interpreter.doSomethingAfterExecution()
             MainExecutionContext.getProgramStack().pop()
-            if (MainExecutionContext.getProgramStack().isEmpty()) {
-                interpreter.onInterpretationEnd()
-            }
         }.nanoseconds
         logHandlers.renderLog(LazyLogEntry.produceStatement(logSource, "INTERPRETATION", "END"))
         logHandlers.renderLog(LazyLogEntry.producePerformance(logSource, "INTERPRETATION", elapsed))
+        MainExecutionContext.getAnalyticsLoggingContext()?.recordInterpretationDuration(elapsed)
+        interpreter.onInterpretationEnd()
         return changedInitialValues
     }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
index 5aa277e6f..c91fc8fdf 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
@@ -5,8 +5,6 @@ import com.smeup.rpgparser.interpreter.LogEntry
 import com.smeup.rpgparser.interpreter.LogSourceData
 import com.smeup.rpgparser.interpreter.SymbolTableAction
 import kotlin.time.Duration
-import kotlin.time.Duration.Companion.nanoseconds
-import kotlin.time.DurationUnit
 
 /**
  * Object used to store metadata for ANALYTICS log channel.
@@ -15,10 +13,7 @@ import kotlin.time.DurationUnit
 class AnalyticsLoggingContext {
     private val programUsageTable = ProgramUsageTable()
     private var renderingTimeMeasurement = UsageMeasurement.new()
-
-    private val initTimestamp = System.nanoTime()
-    private val totalTime
-        get() = (System.nanoTime() - initTimestamp).nanoseconds
+    private var interpretationTimeMeasurement = UsageMeasurement.new()
 
     /**
      * Records log rendering duration.
@@ -27,6 +22,13 @@ class AnalyticsLoggingContext {
         renderingTimeMeasurement = renderingTimeMeasurement.hit(time)
     }
 
+    /**
+     * Records interpretation duration.
+     */
+    fun recordInterpretationDuration(time: Duration) {
+        interpretationTimeMeasurement = interpretationTimeMeasurement.hit(time)
+    }
+
     /**
      * Records the execution of an expression.
      * @see ILoggableExpression
@@ -70,9 +72,9 @@ class AnalyticsLoggingContext {
         }
 
         val logTimeEntry = generateLogTimeReportEntry()
-        val programExecutionEntry = generateProgramReportEntry()
+        val interpretationTimeEntry = generateInterpretationReportEntry()
 
-        return statementEntries + expressionEntries + symbolTableEntries + logTimeEntry + programExecutionEntry
+        return statementEntries + expressionEntries + symbolTableEntries + logTimeEntry + interpretationTimeEntry
     }
 
     private fun generateLogTimeReportEntry(): LazyLogEntry {
@@ -85,10 +87,13 @@ class AnalyticsLoggingContext {
         }
     }
 
-    private fun generateProgramReportEntry(): LazyLogEntry {
-        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "PROGRAM TIME")
+    private fun generateInterpretationReportEntry(): LazyLogEntry {
+        val duration = interpretationTimeMeasurement.duration
+        val hit = interpretationTimeMeasurement.hit
+
+        val entry = LogEntry({ LogSourceData.UNKNOWN }, LogChannel.ANALYTICS.getPropertyName(), "INTERPRETATION TIME")
         return LazyLogEntry(entry) { sep ->
-            "$sep${totalTime.inWholeMicroseconds}$sep"
+            "$sep${duration.inWholeMicroseconds}$sep$hit"
         }
     }
 }
\ No newline at end of file

From 571b39c4d530423d849f7dd078ca89236e25cdcc Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Mon, 13 May 2024 11:50:57 +0200
Subject: [PATCH 07/22] Fix ktlintCheck

---
 .../main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt | 1 -
 1 file changed, 1 deletion(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
index 8ece06438..9040af582 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
@@ -7,7 +7,6 @@ import com.smeup.rpgparser.interpreter.SymbolTableAction
 import java.util.*
 import kotlin.collections.HashMap
 import kotlin.time.Duration
-import kotlin.time.DurationUnit
 
 /**
  * Collects the usage information about the main parts of the program.

From cb48818a2b655de9d20f14b2e8860a72281fb608 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Mon, 13 May 2024 15:01:35 +0200
Subject: [PATCH 08/22] Fix outdated test

---
 .../kotlin/com/smeup/rpgparser/execution/RunnerTest.kt    | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/execution/RunnerTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/execution/RunnerTest.kt
index efd7874ac..9693f3f87 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/execution/RunnerTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/execution/RunnerTest.kt
@@ -91,10 +91,10 @@ class RunnerTest : AbstractTest() {
         SingletonRpgSystem.addProgramFinder(ResourceProgramFinder("/logging/"))
         runnerMain(arrayOf("--log-configuration", configurationFile.absolutePath, "TEST_06", "AA", "'ABCD'", "1**"))
         val logs = FileUtils.readLines(logFile, Charset.defaultCharset())
-        assertContain(logs, "PERF\tTEST_06\t39\tFOR\telapsed")
-        assertContain(logs, "PERF\tTEST_06\t31\tFOR\telapsed")
-        assertContain(logs, "PERF\tTEST_06\t67\tEXSR\telapsed")
-        assertContain(logs, "PERF\tTEST_06\t\tINTERPRETATION\telapsed")
+        assertContain(logs, "PERF\tTEST_06\t39\tFOR")
+        assertContain(logs, "PERF\tTEST_06\t31\tFOR")
+        assertContain(logs, "PERF\tTEST_06\t67\tEXSR")
+        assertContain(logs, "PERF\tTEST_06\t\tINTERPRETATION")
     }
 
     private fun assertContain(logs: List<String>, expected: String) {

From f9ef48f6e3b9b11894fcace238d5940ba253705f Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Mon, 13 May 2024 15:35:43 +0200
Subject: [PATCH 09/22] Avoid duplicate ANALYTICS output

---
 .../main/kotlin/com/smeup/rpgparser/interpreter/program.kt | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
index 6905d6ae2..45b93c271 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
@@ -154,10 +154,15 @@ class RpgProgram(val cu: CompilationUnit, val name: String = "<UNNAMED RPG PROGR
             interpreter.doSomethingAfterExecution()
             MainExecutionContext.getProgramStack().pop()
         }.nanoseconds
+
         logHandlers.renderLog(LazyLogEntry.produceStatement(logSource, "INTERPRETATION", "END"))
         logHandlers.renderLog(LazyLogEntry.producePerformance(logSource, "INTERPRETATION", elapsed))
         MainExecutionContext.getAnalyticsLoggingContext()?.recordInterpretationDuration(elapsed)
-        interpreter.onInterpretationEnd()
+        
+        if (MainExecutionContext.getProgramStack().isEmpty()) {
+            interpreter.onInterpretationEnd()
+        }
+
         return changedInitialValues
     }
 

From e89e4165ea45c2642c2f41c99131c734e5cf7621 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Tue, 14 May 2024 14:44:53 +0200
Subject: [PATCH 10/22] Fix missing position for certain expressions

---
 .../smeup/rpgparser/parsing/ast/statements.kt | 12 +++---
 .../parsing/parsetreetoast/expressions.kt     | 38 +++++++++----------
 .../rpgparser/parsing/parsetreetoast/misc.kt  |  2 +-
 .../parsing/parsetreetoast/statements.kt      | 12 +++---
 4 files changed, 32 insertions(+), 32 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/statements.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/statements.kt
index 580471545..4da0f01e7 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/statements.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/ast/statements.kt
@@ -705,7 +705,7 @@ data class CallStmt(
                     }
                 } else {
                     if (!interpreter.exists(it.param.name)) {
-                        interpreter.assign(it.dataDefinition, interpreter.eval(BlanksRefExpr()))
+                        interpreter.assign(it.dataDefinition, interpreter.eval(BlanksRefExpr(it.position)))
                     }
                 }
             } else {
@@ -1101,19 +1101,19 @@ data class ClearStmt(
                  */
                 if (this.value.variable.referred?.type is OccurableDataStructureType) {
                     val origValue = interpreter.eval(value) as OccurableDataStructValue
-                    newValue = interpreter.assign(value, BlanksRefExpr()) as OccurableDataStructValue
+                    newValue = interpreter.assign(value, BlanksRefExpr(this.position)) as OccurableDataStructValue
                     newValue.pos(origValue.occurrence)
                 } else {
-                    interpreter.assign(value, BlanksRefExpr())
+                    interpreter.assign(value, BlanksRefExpr(this.position))
                 }
             }
 
             is IndicatorExpr -> {
-                interpreter.assign(value, BlanksRefExpr())
+                interpreter.assign(value, BlanksRefExpr(this.position))
             }
 
             is ArrayAccessExpr -> {
-                interpreter.assign(value, BlanksRefExpr())
+                interpreter.assign(value, BlanksRefExpr(this.position))
             }
 
             else -> throw UnsupportedOperationException("I do not know how to clear ${this.value}")
@@ -1608,7 +1608,7 @@ data class DoStmt(
                     } catch (e: IterException) {
                         // nothing to do here
                     }
-                    interpreter.assign(index, PlusExpr(index, IntLiteral(1)))
+                    interpreter.assign(index, PlusExpr(index, IntLiteral(1), this.position))
                 }
             } catch (e: LeaveException) {
                 // nothing to do here
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/expressions.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/expressions.kt
index b7f641ff7..b60ec2b03 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/expressions.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/expressions.kt
@@ -30,24 +30,24 @@ fun RpgParser.ExpressionContext.toAst(conf: ToAstConfiguration = ToAstConfigurat
         this.identifier() != null -> this.identifier().toAst(conf)
         this.bif() != null -> this.bif().toAst(conf)
         this.literal() != null -> this.literal().toAst(conf)
-        this.EQUAL() != null -> EqualityExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-        this.OR() != null -> LogicalOrExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-        this.AND() != null -> LogicalAndExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
+        this.EQUAL() != null -> EqualityExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+        this.OR() != null -> LogicalOrExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+        this.AND() != null -> LogicalAndExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
         this.comparisonOperator() != null -> when {
-            this.comparisonOperator().GT() != null -> GreaterThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-            this.comparisonOperator().GE() != null -> GreaterEqualThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-            this.comparisonOperator().LT() != null -> LessThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-            this.comparisonOperator().LE() != null -> LessEqualThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-            this.comparisonOperator().NE() != null -> DifferentThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
+            this.comparisonOperator().GT() != null -> GreaterThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+            this.comparisonOperator().GE() != null -> GreaterEqualThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+            this.comparisonOperator().LT() != null -> LessThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+            this.comparisonOperator().LE() != null -> LessEqualThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+            this.comparisonOperator().NE() != null -> DifferentThanExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
             else -> todo(conf = conf)
         }
         this.function() != null -> this.function().toAst(conf)
         this.NOT() != null -> NotExpr(this.expression(0).toAst(conf), toPosition(conf.considerPosition))
-        this.PLUS() != null -> PlusExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-        this.MINUS() != null -> MinusExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-        this.MULT() != null || this.MULT_NOSPACE() != null -> MultExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-        this.DIV() != null -> DivExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
-        this.EXP() != null -> ExpExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf))
+        this.PLUS() != null -> PlusExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+        this.MINUS() != null -> MinusExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+        this.MULT() != null || this.MULT_NOSPACE() != null -> MultExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+        this.DIV() != null -> DivExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
+        this.EXP() != null -> ExpExpr(this.expression(0).toAst(conf), this.expression(1).toAst(conf), toPosition(conf.considerPosition))
         this.indicator() != null -> this.indicator().toAst(conf)
         this.unaryExpression() != null -> this.unaryExpression().toAst(conf)
         // FIXME it is rather ugly that we have to do this: we should get a different parse tree here
@@ -58,14 +58,14 @@ fun RpgParser.ExpressionContext.toAst(conf: ToAstConfiguration = ToAstConfigurat
 }
 
 internal fun RpgParser.UnaryExpressionContext.toAst(conf: ToAstConfiguration = ToAstConfiguration()): Expression {
-    if (this.children.size > 0) {
-        return when {
-            this.children[0].text.equals("-") && this.children[1] is ExpressionContext -> NegationExpr((this.children[1] as ExpressionContext).toAst(conf))
-            else -> todo(conf = conf)
-        }
+    if (this.children.isEmpty()) {
+        todo(conf = conf)
     }
 
-    return todo(conf = conf)
+    return when {
+        this.children[0].text.equals("-") && this.children[1] is ExpressionContext -> NegationExpr((this.children[1] as ExpressionContext).toAst(conf), toPosition(conf.considerPosition))
+        else -> todo(conf = conf)
+    }
 }
 
 internal fun RpgParser.IndicatorContext.toAst(conf: ToAstConfiguration = ToAstConfiguration()): IndicatorExpr {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/misc.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/misc.kt
index caab48d0d..6fcbfd86c 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/misc.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/misc.kt
@@ -1002,7 +1002,7 @@ private fun annidatedReferenceExpression(
             } else {
                 IntLiteral(indexValue, computeNewPosition(position, text))
             }
-        expr = ArrayAccessExpr(expr, indexExpression)
+        expr = ArrayAccessExpr(expr, indexExpression, position)
     }
     return expr as AssignableExpression
 }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/statements.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/statements.kt
index e8bb11dc6..867d50402 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/statements.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/parsetreetoast/statements.kt
@@ -285,12 +285,12 @@ internal fun ComparisonOperator.asExpression(factor1: RpgParser.FactorContext, f
     val left = factor1.toAstIfSymbolicConstant() ?: factor1.content?.toAst(conf) ?: factor1.error("Factor 1 cannot be null", conf = conf)
     val right = factor2.toAstIfSymbolicConstant() ?: factor2.content?.toAst(conf) ?: factor2.error("Factor 2 cannot be null", conf = conf)
     return when (this) {
-        ComparisonOperator.EQ -> EqualityExpr(left, right)
-        ComparisonOperator.NE -> DifferentThanExpr(left, right)
-        ComparisonOperator.GE -> GreaterEqualThanExpr(left, right)
-        ComparisonOperator.GT -> GreaterThanExpr(left, right)
-        ComparisonOperator.LE -> LessEqualThanExpr(left, right)
-        ComparisonOperator.LT -> LessThanExpr(left, right)
+        ComparisonOperator.EQ -> EqualityExpr(left, right, left.position)
+        ComparisonOperator.NE -> DifferentThanExpr(left, right, left.position)
+        ComparisonOperator.GE -> GreaterEqualThanExpr(left, right, left.position)
+        ComparisonOperator.GT -> GreaterThanExpr(left, right, left.position)
+        ComparisonOperator.LE -> LessEqualThanExpr(left, right, left.position)
+        ComparisonOperator.LT -> LessThanExpr(left, right, left.position)
     }
 }
 

From 61a45518dd97fbd1ded23ec7f3ea8d4006cf0581 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Tue, 14 May 2024 14:45:50 +0200
Subject: [PATCH 11/22] Add separator between timestamp and channel on log
 render

---
 .../com/smeup/rpgparser/logging/handlers_for_channels.kt | 9 +++++++++
 .../src/main/resources/log4j2.properties                 | 2 +-
 2 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/handlers_for_channels.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/handlers_for_channels.kt
index 94abe7fde..9d3febc4f 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/handlers_for_channels.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/handlers_for_channels.kt
@@ -29,6 +29,7 @@ class ExpressionLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("EXPR")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -47,6 +48,7 @@ class PerformanceLogHandler(level: LogLevel, sep: String) : LogHandler(level, se
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("PERF")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -65,6 +67,7 @@ class StatementLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep)
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("STMT")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -83,6 +86,7 @@ class DataLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep), Int
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("DATA")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -100,6 +104,7 @@ class LoopLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep), Int
     private val logger = LogManager.getLogger(LogChannel.LOOP.getPropertyName())
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("LOOP")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -118,6 +123,7 @@ class ResolutionLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("RESL")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -136,6 +142,7 @@ class ParsingLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep),
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("PARS")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -154,6 +161,7 @@ class ErrorLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep), In
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("ERR")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
@@ -172,6 +180,7 @@ class AnalyticsLogHandler(level: LogLevel, sep: String) : LogHandler(level, sep)
 
     override fun render(renderer: LazyLogEntry): String {
         return buildString {
+            append(sep)
             append("ANALYTICS")
             append(sep)
             append(renderer.render(sep, withHeader = true, withScope = false))
diff --git a/rpgJavaInterpreter-core/src/main/resources/log4j2.properties b/rpgJavaInterpreter-core/src/main/resources/log4j2.properties
index 8b85ee35d..c5de15758 100644
--- a/rpgJavaInterpreter-core/src/main/resources/log4j2.properties
+++ b/rpgJavaInterpreter-core/src/main/resources/log4j2.properties
@@ -6,7 +6,7 @@ appenders = console
 appender.console.type = Console
 appender.console.name = DUMMY
 appender.console.layout.type = PatternLayout
-appender.console.layout.pattern = %d{HH:mm:ss.SSS} %m%n
+appender.console.layout.pattern = %d{HH:mm:ss.SSS}%m%n
 
 
 rootLogger.level = off

From df1b0d057a98b4d0a3c1ca931d7c692fb1aac860 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Tue, 14 May 2024 14:52:38 +0200
Subject: [PATCH 12/22] Add support for nested statements logging

---
 .../interpreter/internal_interpreter.kt       | 30 +++++++++++-------
 .../logging/AnalyticsLoggingContext.kt        | 30 +++++++++++++++++-
 .../rpgparser/logging/ProgramUsageTable.kt    | 31 +++++++++++++++++++
 3 files changed, 79 insertions(+), 12 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
index add07cb6e..0c6e7caba 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
@@ -990,12 +990,12 @@ open class InternalInterpreter(
                 if (target is DataRefExpr && value is IntLiteral) {
                     increment(target.variable.referred!!, value.value)
                 } else {
-                    assign(target, eval(PlusExpr(target, value)))
+                    assign(target, eval(PlusExpr(target, value, target.position)))
                 }
-            MINUS_ASSIGNMENT -> assign(target, eval(MinusExpr(target, value)))
-            MULT_ASSIGNMENT -> assign(target, eval(MultExpr(target, value)))
-            DIVIDE_ASSIGNMENT -> assign(target, eval(DivExpr(target, value)))
-            EXP_ASSIGNMENT -> assign(target, eval(ExpExpr(target, value)))
+            MINUS_ASSIGNMENT -> assign(target, eval(MinusExpr(target, value, target.position)))
+            MULT_ASSIGNMENT -> assign(target, eval(MultExpr(target, value, target.position)))
+            DIVIDE_ASSIGNMENT -> assign(target, eval(DivExpr(target, value, target.position)))
+            EXP_ASSIGNMENT -> assign(target, eval(ExpExpr(target, value, target.position)))
         }
     }
 
@@ -1006,11 +1006,11 @@ open class InternalInterpreter(
     ): Value {
         return when (operator) {
             NORMAL_ASSIGNMENT -> assignEachElement(target, eval(value))
-            PLUS_ASSIGNMENT -> assignEachElement(target, eval(PlusExpr(target, value)))
-            MINUS_ASSIGNMENT -> assignEachElement(target, eval(MinusExpr(target, value)))
-            MULT_ASSIGNMENT -> assignEachElement(target, eval(MultExpr(target, value)))
-            DIVIDE_ASSIGNMENT -> assignEachElement(target, eval(DivExpr(target, value)))
-            EXP_ASSIGNMENT -> assignEachElement(target, eval(ExpExpr(target, value)))
+            PLUS_ASSIGNMENT -> assignEachElement(target, eval(PlusExpr(target, value, target.position)))
+            MINUS_ASSIGNMENT -> assignEachElement(target, eval(MinusExpr(target, value, target.position)))
+            MULT_ASSIGNMENT -> assignEachElement(target, eval(MultExpr(target, value, target.position)))
+            DIVIDE_ASSIGNMENT -> assignEachElement(target, eval(DivExpr(target, value, target.position)))
+            EXP_ASSIGNMENT -> assignEachElement(target, eval(ExpExpr(target, value, target.position)))
         }
     }
 
@@ -1146,10 +1146,13 @@ open class InternalInterpreter(
     private inline fun executeWithLogging(statement: Statement) {
         val programName = this.interpretationContext.currentProgramName
         val sourceProducer = { LogSourceData(programName, statement.position.line()) }
+        val loggingContext = MainExecutionContext.getAnalyticsLoggingContext()
 
         renderLogInternal { statement.getResolutionLogRenderer(sourceProducer) }
 
+        val isSelfNested = loggingContext?.isExecutingCompositeStatement ?: false
         if (statement is CompositeStatement) {
+            loggingContext?.enterCompositeStatement(statement.loggableEntityName)
             renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "START") }
         } else {
             renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "EXEC") }
@@ -1163,7 +1166,11 @@ open class InternalInterpreter(
             statement.execute(this)
         }.nanoseconds
 
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordStatementExecution(programName, statement.loggableEntityName, executionTime)
+        loggingContext?.let { ctx ->
+            if (ctx.isExecutingCompositeStatement && isSelfNested) {
+                ctx.recordNestedStatementExecution(programName, statement.loggableEntityName, executionTime)
+            } else ctx.recordStatementExecution(programName, statement.loggableEntityName, executionTime)
+        }
 
         if (statement is LoopStatement) {
             renderLogInternal {
@@ -1177,6 +1184,7 @@ open class InternalInterpreter(
         }
 
         if (statement is CompositeStatement) {
+            loggingContext?.exitCompositeStatement()
             renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "END") }
         }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
index c91fc8fdf..7da36bfaf 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
@@ -4,6 +4,7 @@ import com.smeup.rpgparser.interpreter.LazyLogEntry
 import com.smeup.rpgparser.interpreter.LogEntry
 import com.smeup.rpgparser.interpreter.LogSourceData
 import com.smeup.rpgparser.interpreter.SymbolTableAction
+import java.util.Stack
 import kotlin.time.Duration
 
 /**
@@ -15,6 +16,23 @@ class AnalyticsLoggingContext {
     private var renderingTimeMeasurement = UsageMeasurement.new()
     private var interpretationTimeMeasurement = UsageMeasurement.new()
 
+    private val statementScope = Stack<String>()
+
+    /**
+     * Checks whether we are in a CompositeStatement scope or not.
+     */
+    val isExecutingCompositeStatement get() = statementScope.isNotEmpty()
+
+    /**
+     * Records the beginning of the execution of a CompositeStatement.
+     */
+    fun enterCompositeStatement(entity: String) { statementScope.push(entity) }
+
+    /**
+     * Records the end of the execution of a CompositeStatement.
+     */
+    fun exitCompositeStatement() { statementScope.pop() }
+
     /**
      * Records log rendering duration.
      */
@@ -50,6 +68,13 @@ class AnalyticsLoggingContext {
     fun recordStatementExecution(program: String, entity: String, time: Duration) =
         programUsageTable.recordStatement(program, entity, time)
 
+    /**
+     * Records the execution of a nested statement.
+     * @see ILoggableStatement
+     */
+    fun recordNestedStatementExecution(program: String, entity: String, time: Duration) =
+        programUsageTable.recordNestedStatement(program, statementScope, entity, time)
+
     /**
      * Generate an ANALYTICS report based on currently collected metadata in the form
      * of a list of LazyLogEntry.
@@ -59,22 +84,25 @@ class AnalyticsLoggingContext {
         val statementEntries = mutableListOf<LazyLogEntry>()
         val expressionEntries = mutableListOf<LazyLogEntry>()
         val symbolTableEntries = mutableListOf<LazyLogEntry>()
+        val nestedStatementEntries = mutableListOf<LazyLogEntry>()
 
         programUsageTable.asSequence().forEach {
             val program = it.key
             val statement = programUsageTable.generateStatementLogEntries(program)
             val expression = programUsageTable.generateExpressionLogEntries(program)
             val symTable = programUsageTable.generateSymbolTableLogEntries(program)
+            val nestedStatement = programUsageTable.generateNestedStatementLogEntries(program)
 
             statementEntries.addAll(statement)
             expressionEntries.addAll(expression)
             symbolTableEntries.addAll(symTable)
+            nestedStatementEntries.addAll(nestedStatement)
         }
 
         val logTimeEntry = generateLogTimeReportEntry()
         val interpretationTimeEntry = generateInterpretationReportEntry()
 
-        return statementEntries + expressionEntries + symbolTableEntries + logTimeEntry + interpretationTimeEntry
+        return statementEntries + expressionEntries + symbolTableEntries + nestedStatementEntries + logTimeEntry + interpretationTimeEntry
     }
 
     private fun generateLogTimeReportEntry(): LazyLogEntry {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
index 9040af582..d46e23557 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
@@ -17,6 +17,7 @@ class ProgramUsageStats {
     val symbolTableActions: EnumMap<SymbolTableAction, UsageMeasurement> by lazy {
         EnumMap(SymbolTableAction::class.java)
     }
+    val nestedStatements: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
 }
 
 typealias ProgramUsageTable = HashMap<String, ProgramUsageStats>
@@ -31,6 +32,17 @@ fun ProgramUsageTable.recordStatement(program: String, entity: String, time: Dur
     programStats.statements[entity] = measurement.hit(time)
 }
 
+/**
+ * Records the execution of a nested statement.
+ * @see ILoggableStatement
+ */
+fun ProgramUsageTable.recordNestedStatement(program: String, scope: Stack<String>, entity: String, time: Duration) {
+    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+    val path = "${scope.joinToString(separator = "/")}/$entity"
+    val measurement = programStats.nestedStatements.getOrDefault(path, UsageMeasurement.new())
+    programStats.nestedStatements[path] = measurement.hit(time)
+}
+
 /**
  * Records the execution of an expression.
  * @see ILoggableExpression
@@ -70,6 +82,25 @@ fun ProgramUsageTable.generateStatementLogEntries(program: String): Sequence<Laz
     }
 }
 
+/**
+ * Generate an ANALYTICS nested statement usage report in the form of a sequence of LazyLogEntry.
+ * @see LazyLogEntry
+ */
+fun ProgramUsageTable.generateNestedStatementLogEntries(program: String): Sequence<LazyLogEntry> {
+    val stats = this[program] ?: return emptySequence()
+
+    return stats.nestedStatements.asSequence().map {
+        val statementName = it.key
+        val duration = it.value.duration
+        val hit = it.value.hit
+
+        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "NESTED STMT TIME")
+        LazyLogEntry(entry) { sep ->
+            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
+        }
+    }
+}
+
 /**
  * Generate an ANALYTICS expression usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry

From eadb0d6579b2f470f37005fad48a39c0c5e0ecd0 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Tue, 14 May 2024 15:08:11 +0200
Subject: [PATCH 13/22] Fix pattern in LoggingTest

---
 .../src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt  | 1 -
 .../src/test/kotlin/com/smeup/rpgparser/logging/LoggingTest.kt  | 2 +-
 2 files changed, 1 insertion(+), 2 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
index 45b93c271..c9ae5b9da 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
@@ -158,7 +158,6 @@ class RpgProgram(val cu: CompilationUnit, val name: String = "<UNNAMED RPG PROGR
         logHandlers.renderLog(LazyLogEntry.produceStatement(logSource, "INTERPRETATION", "END"))
         logHandlers.renderLog(LazyLogEntry.producePerformance(logSource, "INTERPRETATION", elapsed))
         MainExecutionContext.getAnalyticsLoggingContext()?.recordInterpretationDuration(elapsed)
-        
         if (MainExecutionContext.getProgramStack().isEmpty()) {
             interpreter.onInterpretationEnd()
         }
diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/logging/LoggingTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/logging/LoggingTest.kt
index cdb3b3f08..f5f8b9c93 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/logging/LoggingTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/logging/LoggingTest.kt
@@ -36,7 +36,7 @@ class LoggingTest : AbstractTest() {
     private val varValue = "MYVALUE"
     private val logFormatRegexWhenStandardLog = Regex(pattern = "\\d+:\\d+:\\d+\\.\\d+\\s+DATA\\t$programName\\t\\tASSIGN\\t$varName = $varValue\\twas: N/D\\s*")
     // there is no time stamp reference
-    private val logFormatRegexWhenLogAsCallback = Regex(pattern = "DATA\\t$programName\\t\\tASSIGN\\t$varName = $varValue\\twas: N/D\\s*")
+    private val logFormatRegexWhenLogAsCallback = Regex(pattern = "\\s*DATA\\t$programName\\t\\tASSIGN\\t$varName = $varValue\\twas: N/D\\s*")
 
     @After
     fun after() {

From bf67090435cc3c8d4bb305f741c8b420bb094d90 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Wed, 15 May 2024 12:27:04 +0200
Subject: [PATCH 14/22] Add support for nested expressions in analytics

---
 .../execution/MainExecutionContext.kt         |  3 +-
 .../logging/AnalyticsLoggingContext.kt        | 28 ++++++++++++++++-
 .../rpgparser/logging/ProgramUsageTable.kt    | 31 +++++++++++++++++++
 3 files changed, 59 insertions(+), 3 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt
index 6ff42be0d..6c7f4dba5 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt
@@ -35,7 +35,7 @@ object MainExecutionContext {
     // default values in case jariko is not called from the command line program
     private val context: ThreadLocal<Context> by lazy { ThreadLocal<Context>() }
     private val noContextIdProvider: AtomicInteger by lazy { AtomicInteger() }
-    private val noContextAttributes: MutableMap<String, Any> by lazy { mutableMapOf<String, Any>() }
+    private val noContextAttributes: MutableMap<String, Any> by lazy { mutableMapOf() }
     private val noConfiguration: Configuration by lazy { Configuration() }
     private val noProgramStack: Stack<RpgProgram> by lazy { Stack<RpgProgram>() }
     private val noParsingProgramStack: Stack<ParsingProgram> by lazy { Stack<ParsingProgram>() }
@@ -211,7 +211,6 @@ data class Context(
         DBFileFactory(it.nativeAccessConfig)
     }
 ) {
-
     private val logHandlers: MutableList<InterpreterLogHandler> by lazy {
         systemInterface.getAllLogHandlers()
     }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
index 7da36bfaf..97bedd92e 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
@@ -17,12 +17,18 @@ class AnalyticsLoggingContext {
     private var interpretationTimeMeasurement = UsageMeasurement.new()
 
     private val statementScope = Stack<String>()
+    private val expressionScope = Stack<String>()
 
     /**
      * Checks whether we are in a CompositeStatement scope or not.
      */
     val isExecutingCompositeStatement get() = statementScope.isNotEmpty()
 
+    /**
+     * Checks whether we are executing an expression or not.
+     */
+    val isExecutingExpression get() = expressionScope.isNotEmpty()
+
     /**
      * Records the beginning of the execution of a CompositeStatement.
      */
@@ -33,6 +39,16 @@ class AnalyticsLoggingContext {
      */
     fun exitCompositeStatement() { statementScope.pop() }
 
+    /**
+     * Records the beginning of the execution of an expression.
+     */
+    fun enterExpression(entity: String) { expressionScope.push(entity) }
+
+    /**
+     * Records the end of the execution of an expression.
+     */
+    fun exitExpression() { expressionScope.pop() }
+
     /**
      * Records log rendering duration.
      */
@@ -75,6 +91,13 @@ class AnalyticsLoggingContext {
     fun recordNestedStatementExecution(program: String, entity: String, time: Duration) =
         programUsageTable.recordNestedStatement(program, statementScope, entity, time)
 
+    /**
+     * Records the execution of a nested expression from the current expression scope state.
+     * @see ILoggableExpression
+     */
+    fun recordNestedExpressionExecutionFromScope(program: String, time: Duration) =
+        programUsageTable.recordNestedExpression(program, expressionScope, time)
+
     /**
      * Generate an ANALYTICS report based on currently collected metadata in the form
      * of a list of LazyLogEntry.
@@ -85,6 +108,7 @@ class AnalyticsLoggingContext {
         val expressionEntries = mutableListOf<LazyLogEntry>()
         val symbolTableEntries = mutableListOf<LazyLogEntry>()
         val nestedStatementEntries = mutableListOf<LazyLogEntry>()
+        val nestedExpressionEntries = mutableListOf<LazyLogEntry>()
 
         programUsageTable.asSequence().forEach {
             val program = it.key
@@ -92,17 +116,19 @@ class AnalyticsLoggingContext {
             val expression = programUsageTable.generateExpressionLogEntries(program)
             val symTable = programUsageTable.generateSymbolTableLogEntries(program)
             val nestedStatement = programUsageTable.generateNestedStatementLogEntries(program)
+            val nestedExpression = programUsageTable.generateNestedExpressionLogEntries(program)
 
             statementEntries.addAll(statement)
             expressionEntries.addAll(expression)
             symbolTableEntries.addAll(symTable)
             nestedStatementEntries.addAll(nestedStatement)
+            nestedExpressionEntries.addAll(nestedExpression)
         }
 
         val logTimeEntry = generateLogTimeReportEntry()
         val interpretationTimeEntry = generateInterpretationReportEntry()
 
-        return statementEntries + expressionEntries + symbolTableEntries + nestedStatementEntries + logTimeEntry + interpretationTimeEntry
+        return statementEntries + expressionEntries + symbolTableEntries + nestedStatementEntries + nestedExpressionEntries + logTimeEntry + interpretationTimeEntry
     }
 
     private fun generateLogTimeReportEntry(): LazyLogEntry {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
index d46e23557..5abf8c506 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
@@ -18,6 +18,7 @@ class ProgramUsageStats {
         EnumMap(SymbolTableAction::class.java)
     }
     val nestedStatements: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
+    val nestedExpressions: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
 }
 
 typealias ProgramUsageTable = HashMap<String, ProgramUsageStats>
@@ -43,6 +44,17 @@ fun ProgramUsageTable.recordNestedStatement(program: String, scope: Stack<String
     programStats.nestedStatements[path] = measurement.hit(time)
 }
 
+/**
+ * Records the execution of a nested expression.
+ * @see ILoggableExpression
+ */
+fun ProgramUsageTable.recordNestedExpression(program: String, scope: Stack<String>, time: Duration) {
+    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+    val path = scope.joinToString(separator = "->")
+    val measurement = programStats.nestedExpressions.getOrDefault(path, UsageMeasurement.new())
+    programStats.nestedExpressions[path] = measurement.hit(time)
+}
+
 /**
  * Records the execution of an expression.
  * @see ILoggableExpression
@@ -101,6 +113,25 @@ fun ProgramUsageTable.generateNestedStatementLogEntries(program: String): Sequen
     }
 }
 
+/**
+ * Generate an ANALYTICS nested expression usage report in the form of a sequence of LazyLogEntry.
+ * @see LazyLogEntry
+ */
+fun ProgramUsageTable.generateNestedExpressionLogEntries(program: String): Sequence<LazyLogEntry> {
+    val stats = this[program] ?: return emptySequence()
+
+    return stats.nestedExpressions.asSequence().map {
+        val statementName = it.key
+        val duration = it.value.duration
+        val hit = it.value.hit
+
+        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "NESTED EXPR TIME")
+        LazyLogEntry(entry) { sep ->
+            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
+        }
+    }
+}
+
 /**
  * Generate an ANALYTICS expression usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry

From 7712030a9ae59a25ba408e70ff2fa99e25e9b483 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Wed, 15 May 2024 12:27:20 +0200
Subject: [PATCH 15/22] Implement ANALYTICS nested expressions logging

---
 .../interpreter/ExpressionEvaluation.kt       | 383 ++++++++++--------
 .../interpreter/internal_interpreter.kt       |   6 -
 2 files changed, 217 insertions(+), 172 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
index b16a6fecc..e8e25512c 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
@@ -16,6 +16,7 @@
 
 package com.smeup.rpgparser.interpreter
 
+import com.smeup.rpgparser.execution.MainExecutionContext
 import com.smeup.rpgparser.parsing.ast.*
 import com.smeup.rpgparser.parsing.parsetreetoast.LogicalCondition
 import com.smeup.rpgparser.utils.asBigDecimal
@@ -30,8 +31,10 @@ import java.math.RoundingMode
 import java.time.ZoneId
 import java.time.temporal.ChronoUnit
 import kotlin.math.abs
+import kotlin.math.pow
 import kotlin.math.roundToLong
 import kotlin.math.sqrt
+import kotlin.time.Duration.Companion.nanoseconds
 
 class ExpressionEvaluation(
     val systemInterface: SystemInterface,
@@ -44,77 +47,113 @@ class ExpressionEvaluation(
     private fun evalAsLong(expression: Expression): Long = expression.evalWith(this).asInt().value
     private fun evalAsDecimal(expression: Expression): BigDecimal = expression.evalWith(this).asDecimal().value
 
-    override fun eval(expression: StringLiteral): Value = StringValue(expression.value)
-    override fun eval(expression: IntLiteral) = IntValue(expression.value)
-    override fun eval(expression: RealLiteral) = DecimalValue(expression.value)
-    override fun eval(expression: NumberOfElementsExpr): Value {
-        return when (val value = expression.value.evalWith(this)) {
+    private inline fun proxyLogging(expression: Expression, action: () -> Value): Value {
+        if (systemInterface.getAllLogHandlers().isEmpty()) return action()
+
+        val programName = MainExecutionContext.getExecutionProgramName()
+        val loggingContext = MainExecutionContext.getAnalyticsLoggingContext()
+        val isSelfNested = loggingContext?.isExecutingExpression ?: false
+        loggingContext?.enterExpression(expression.loggableEntityName)
+
+        val start = System.nanoTime()
+        val value = action()
+        val elapsed = (System.nanoTime() - start).nanoseconds
+
+        MainExecutionContext.log(
+            LazyLogEntry.producePerformance(
+                { LogSourceData(programName, expression.startLine()) },
+                expression.loggableEntityName,
+                elapsed
+            )
+        )
+
+        loggingContext?.let { ctx ->
+            if (isSelfNested)
+                ctx.recordNestedExpressionExecutionFromScope(programName, elapsed)
+            else ctx.recordExpressionExecution(programName, expression.loggableEntityName, elapsed)
+
+            ctx.exitExpression()
+        }
+
+        return value
+    }
+
+    override fun eval(expression: StringLiteral): Value = proxyLogging(expression) { StringValue(expression.value) }
+    override fun eval(expression: IntLiteral) = proxyLogging(expression) { IntValue(expression.value) }
+    override fun eval(expression: RealLiteral) = proxyLogging(expression) { DecimalValue(expression.value) }
+
+    override fun eval(expression: NumberOfElementsExpr): Value = proxyLogging(expression) {
+        return@proxyLogging when (val value = expression.value.evalWith(this)) {
             is ArrayValue -> value.arrayLength().asValue()
             is OccurableDataStructValue -> value.occurs.asValue()
             else -> throw IllegalStateException("Cannot ask number of elements of $value")
         }
     }
 
-    override fun eval(expression: DataRefExpr) = interpreterStatus.getVar(
-        expression.variable.referred
-            ?: throw IllegalStateException("Unsolved reference ${expression.variable.name} at ${expression.position}")
-    )
+    override fun eval(expression: DataRefExpr) = proxyLogging(expression) {
+        interpreterStatus.getVar(
+            expression.variable.referred
+                ?: throw IllegalStateException("Unsolved reference ${expression.variable.name} at ${expression.position}")
+        )
+    }
 
-    override fun eval(expression: EqualityExpr): Value {
+    override fun eval(expression: EqualityExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return areEquals(left, right).asValue()
+        areEquals(left, right).asValue()
     }
 
-    override fun eval(expression: DifferentThanExpr): Value {
+    override fun eval(expression: DifferentThanExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return (!areEquals(left, right)).asValue()
+        (!areEquals(left, right)).asValue()
     }
 
-    override fun eval(expression: GreaterThanExpr): Value {
+    override fun eval(expression: GreaterThanExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return isGreaterThan(left, right, localizationContext.charset).asValue()
+        isGreaterThan(left, right, localizationContext.charset).asValue()
     }
 
-    override fun eval(expression: GreaterEqualThanExpr): Value {
+    override fun eval(expression: GreaterEqualThanExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return (isGreaterThan(left, right, localizationContext.charset) || areEquals(left, right)).asValue()
+        (isGreaterThan(left, right, localizationContext.charset) || areEquals(left, right)).asValue()
     }
 
-    override fun eval(expression: LessEqualThanExpr): Value {
+    override fun eval(expression: LessEqualThanExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return (isEqualOrSmaller(left, right, localizationContext.charset)).asValue()
+        (isEqualOrSmaller(left, right, localizationContext.charset)).asValue()
     }
 
-    override fun eval(expression: LessThanExpr): Value {
+    override fun eval(expression: LessThanExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return isSmallerThan(left, right, localizationContext.charset).asValue()
+        isSmallerThan(left, right, localizationContext.charset).asValue()
     }
 
-    override fun eval(expression: BlanksRefExpr) = BlanksValue
-    override fun eval(expression: DecExpr): Value {
+    override fun eval(expression: BlanksRefExpr) = proxyLogging(expression) { BlanksValue } as BlanksValue
+
+    override fun eval(expression: DecExpr): Value = proxyLogging(expression) {
         val decDigits = expression.decDigits.evalWith(this).asInt().value
         val valueAsString = expression.value.evalWith(this).asString().value
         val valueAsBigDecimal = valueAsString.asBigDecimal()
         require(valueAsBigDecimal != null) {
             "Line ${expression.position?.line()} - %DEC can't understand '$valueAsString'"
         }
-        return if (decDigits == 0L) {
+
+        return@proxyLogging if (decDigits == 0L) {
             IntValue(valueAsBigDecimal.toLong())
         } else {
             DecimalValue(valueAsBigDecimal)
         }
     }
 
-    override fun eval(expression: PlusExpr): Value {
+    override fun eval(expression: PlusExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return when {
+        return@proxyLogging when {
             left is StringValue && right is AbstractStringValue -> {
                 if (left.varying) {
                     val s = left.value.trimEnd() + right.getWrappedString()
@@ -151,61 +190,20 @@ class ExpressionEvaluation(
         }
     }
 
-    private fun sum(left: ArrayValue, right: ArrayValue, position: Position?): ArrayValue {
-        val listValue = when {
-            left.elementType is StringType && right.elementType is StringType ->
-                left.elements().mapIndexed { i: Int, v: Value ->
-                    if (right.elements().size > i) {
-                        val rightElement = right.getElement(i + 1)
-
-                        val valueToAdd: String = if (v.asString().varying) {
-                            (v.asString().value + rightElement.asString().value)
-                        } else {
-                            (v.asString().value + " ".repeat(left.elementType.elementSize() - v.asString().value.length) + rightElement.asString().value)
-                        }
-                        StringValue(valueToAdd, left.elementType.hasVariableSize())
-                    } else {
-                        v
-                    }
-                }
-            left.elementType is NumberType && right.elementType is NumberType ->
-                left.elements().mapIndexed { i: Int, v: Value ->
-                    if (right.elements().size > i) {
-                        val rightElement = right.getElement(i + 1)
-                        when {
-                            v is IntValue && rightElement is IntValue -> {
-                                (v + rightElement)
-                            }
-
-                            v is NumberValue && rightElement is NumberValue -> {
-                                DecimalValue(v.bigDecimal.plus(rightElement.bigDecimal))
-                            }
-
-                            else -> throw UnsupportedOperationException("Unable to sum ${left.elementType} and ${right.elementType} as Array elements at $position")
-                        }
-                    } else {
-                        v
-                    }
-                }
-            else -> throw UnsupportedOperationException("Unable to sum ${left.elementType} and ${right.elementType} as Array elements at $position")
-        } as MutableList<Value>
-        return ConcreteArrayValue(listValue, left.elementType)
-    }
-
-    override fun eval(expression: MinusExpr): Value {
+    override fun eval(expression: MinusExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return when {
+        return@proxyLogging when {
             left is IntValue && right is IntValue -> (left - right)
             left is NumberValue && right is NumberValue -> DecimalValue(left.bigDecimal.minus(right.bigDecimal))
             else -> throw UnsupportedOperationException("I do not know how to sum $left and $right at ${expression.position}")
         }
     }
 
-    override fun eval(expression: MultExpr): Value {
+    override fun eval(expression: MultExpr): Value = proxyLogging(expression) {
         val left = expression.left.evalWith(this)
         val right = expression.right.evalWith(this)
-        return when {
+        return@proxyLogging when {
             left is IntValue && right is IntValue -> (left * right)
             left is NumberValue && right is NumberValue -> {
                 DecimalValue(left.bigDecimal.multiply(right.bigDecimal))
@@ -214,25 +212,25 @@ class ExpressionEvaluation(
         }
     }
 
-    override fun eval(expression: CharExpr): Value {
+    override fun eval(expression: CharExpr): Value = proxyLogging(expression) {
         val value = expression.value.evalWith(this)
         val representation = value.stringRepresentation(expression.format)
 
         if (expression.value !is DivExpr) {
-            return StringValue(representation)
+            return@proxyLogging StringValue(representation)
         }
 
         // Decimals are always returned with 10 decimal digits
         // fill with 0 if necessary
         val numDecimals = value.asDecimal().value.scale()
-        return when {
+        return@proxyLogging when {
             numDecimals == 0 -> StringValue("$representation.0000000000")
             numDecimals < 10 -> StringValue(representation + "0".repeat(10 - numDecimals))
             else -> StringValue(representation.trim())
         }
     }
 
-    override fun eval(expression: LookupExpr): Value {
+    override fun eval(expression: LookupExpr): Value = proxyLogging(expression) {
         val searchValued = expression.searchedValued.evalWith(this)
         val array = expression.array.evalWith(this) as ArrayValue
         var index = array.elements().indexOfFirst {
@@ -251,22 +249,24 @@ class ExpressionEvaluation(
         val upperLimit = start.plus(length).value - 1
         if (lowerLimit > index || upperLimit < index) index = -1
 
-        return if (index == -1) 0.asValue() else (index + 1).asValue()
+        return@proxyLogging if (index == -1) 0.asValue() else (index + 1).asValue()
     }
 
-    override fun eval(expression: ArrayAccessExpr): Value {
+    override fun eval(expression: ArrayAccessExpr): Value = proxyLogging(expression) {
         val arrayValueRaw = expression.array.evalWith(this)
         val arrayValue = arrayValueRaw as? ArrayValue
             ?: throw IllegalStateException("Array access to something that does not look like an array: ${expression.render()} (${expression.position})")
         val indexValue = expression.index.evalWith(this)
-        return arrayValue.getElement(indexValue.asInt().value.toInt())
+        arrayValue.getElement(indexValue.asInt().value.toInt())
     }
 
-    override fun eval(expression: HiValExpr) = HiValValue
-    override fun eval(expression: LowValExpr) = LowValValue
-    override fun eval(expression: ZeroExpr) = ZeroValue
-    override fun eval(expression: AllExpr) = AllValue(eval(expression.charsToRepeat).asString().value)
-    override fun eval(expression: TranslateExpr): Value {
+    override fun eval(expression: HiValExpr) = proxyLogging(expression) { HiValValue } as HiValValue
+    override fun eval(expression: LowValExpr) = proxyLogging(expression) { LowValValue } as LowValValue
+    override fun eval(expression: ZeroExpr) = proxyLogging(expression) { ZeroValue } as ZeroValue
+    override fun eval(expression: AllExpr) = proxyLogging(expression) {
+        AllValue(eval(expression.charsToRepeat).asString().value)
+    } as AllValue
+    override fun eval(expression: TranslateExpr): Value = proxyLogging(expression) {
         val originalChars = expression.from.evalWith(this).asString().value
         val newChars = expression.to.evalWith(this).asString().value
         val start = expression.startPos.evalWith(this).asInt().value.toInt()
@@ -282,42 +282,44 @@ class ExpressionEvaluation(
         substitutionMap.forEach {
             right = right.replace(it.key, it.value)
         }
-        return StringValue(pair.first + right)
+        StringValue(pair.first + right)
     }
 
-    override fun eval(expression: LogicalAndExpr): Value {
+    override fun eval(expression: LogicalAndExpr): Value = proxyLogging(expression) {
         val left = evalAsBoolean(expression.left)
-        return if (left) {
+        return@proxyLogging if (left) {
             expression.right.evalWith(this)
         } else {
             BooleanValue.FALSE
         }
     }
 
-    override fun eval(expression: LogicalOrExpr): Value {
+    override fun eval(expression: LogicalOrExpr): Value = proxyLogging(expression) {
         val left = evalAsBoolean(expression.left)
-        return if (left) {
+        return@proxyLogging if (left) {
             BooleanValue.TRUE
         } else {
             expression.right.evalWith(this)
         }
     }
 
-    override fun eval(expression: LogicalCondition): Value {
+    override fun eval(expression: LogicalCondition): Value = proxyLogging(expression) {
         if (expression.ands.any { !evalAsBoolean(it) } && !expression.ors.any { evalAsBoolean(it) }) {
-            return BooleanValue.FALSE
+            return@proxyLogging BooleanValue.FALSE
         }
 
         if (evalAsBoolean(expression.expression)) {
-            return BooleanValue.TRUE
+            return@proxyLogging BooleanValue.TRUE
         }
 
-        return BooleanValue(expression.ors.any { evalAsBoolean(it) })
+        BooleanValue(expression.ors.any { evalAsBoolean(it) })
     }
 
-    override fun eval(expression: OnRefExpr) = BooleanValue.TRUE
-    override fun eval(expression: NotExpr) = BooleanValue(!evalAsBoolean(expression.base))
-    override fun eval(expression: ScanExpr): Value {
+    override fun eval(expression: OnRefExpr) = proxyLogging(expression) { BooleanValue.TRUE } as BooleanValue
+    override fun eval(expression: NotExpr) = proxyLogging(expression) {
+        BooleanValue(!evalAsBoolean(expression.base))
+    } as BooleanValue
+    override fun eval(expression: ScanExpr): Value = proxyLogging(expression) {
         var startIndex = 0
         if (expression.start != null) {
             startIndex = expression.start.evalWith(this).asInt().value.toInt()
@@ -331,21 +333,22 @@ class ExpressionEvaluation(
             expression.source.evalWith(this).asString().value.substring(0, startIndex + length)
         } ?: expression.source.evalWith(this).asString().value
         val result = source.indexOf(value, startIndex)
-        return IntValue(if (result == -1) 0 else result.toLong() + 1)
+        IntValue(if (result == -1) 0 else result.toLong() + 1)
     }
-    override fun eval(expression: CheckExpr): Value {
-        var startpos = 0
+
+    override fun eval(expression: CheckExpr): Value = proxyLogging(expression) {
+        var startPos = 0
         if (expression.start != null) {
-            startpos = expression.start.evalWith(this).asInt().value.toInt()
-            if (startpos > 0) {
-                startpos -= 1
+            startPos = expression.start.evalWith(this).asInt().value.toInt()
+            if (startPos > 0) {
+                startPos -= 1
             }
         }
         val comparator = expression.value.evalWith(this).asString().value
         val base = expression.source.evalWith(this).asString().value.toCharArray()
 
         var result = 0
-        for (i in startpos until base.size) {
+        for (i in startPos until base.size) {
             val currChar = base[i]
             if (!comparator.contains(currChar)) {
                 result = i + 1
@@ -353,21 +356,21 @@ class ExpressionEvaluation(
             }
         }
 
-        return IntValue(result.toLong())
+        IntValue(result.toLong())
     }
 
-    override fun eval(expression: SubstExpr): Value {
+    override fun eval(expression: SubstExpr): Value = proxyLogging(expression) {
         val length = if (expression.length != null) expression.length.evalWith(this).asInt().value.toInt() else 0
         val start = expression.start.evalWith(this).asInt().value.toInt() - 1
         val originalString = expression.string.evalWith(this).asString().value
-        return if (length == 0) {
+        return@proxyLogging if (length == 0) {
             StringValue(originalString.padEnd(start + 1).substring(start))
         } else {
             StringValue(originalString.padEnd(start + length + 1).substring(start, start + length))
         }
     }
 
-    override fun eval(expression: SubarrExpr): Value {
+    override fun eval(expression: SubarrExpr): Value = proxyLogging(expression) {
         val start = expression.start.evalWith(this).asInt().value.toInt() - 1
         val numberOfElement: Int? = if (expression.numberOfElements != null) expression.numberOfElements.evalWith(this).asInt().value.toInt() else null
         val originalArray: ArrayValue = expression.array.evalWith(this).asArray()
@@ -376,11 +379,11 @@ class ExpressionEvaluation(
         } else {
             (start) + numberOfElement
         }
-        return originalArray.take(start, to)
+        originalArray.take(start, to)
     }
 
-    override fun eval(expression: LenExpr): Value {
-        return when (val value = expression.value.evalWith(this)) {
+    override fun eval(expression: LenExpr): Value = proxyLogging(expression) {
+        return@proxyLogging when (val value = expression.value.evalWith(this)) {
             is StringValue -> {
                 when (expression.value) {
                     is DataRefExpr -> {
@@ -447,23 +450,24 @@ class ExpressionEvaluation(
         }
     }
 
-    override fun eval(expression: OffRefExpr) = BooleanValue.FALSE
+    override fun eval(expression: OffRefExpr) = proxyLogging(expression) { BooleanValue.FALSE } as BooleanValue
 
-    override fun eval(expression: NegationExpr): DecimalValue {
+    override fun eval(expression: NegationExpr): DecimalValue = proxyLogging(expression) {
         val value = expression.value1.evalWith(this).asDecimal().value
-        return DecimalValue(-value)
-    }
+        DecimalValue(-value)
+    } as DecimalValue
 
-    override fun eval(expression: IndicatorExpr): BooleanValue {
+    override fun eval(expression: IndicatorExpr): BooleanValue = proxyLogging(expression) {
         // if index is passed through expression, it means that it is a dynamic indicator
         val runtimeIndex = expression.indexExpression?.evalWith(this)?.asInt()?.value?.toInt() ?: expression.index
-        return interpreterStatus.indicator(runtimeIndex)
-    }
-    override fun eval(expression: FunctionCall): Value {
+        interpreterStatus.indicator(runtimeIndex)
+    } as BooleanValue
+
+    override fun eval(expression: FunctionCall): Value = proxyLogging(expression) {
         val functionToCall = expression.function.name
         val function = systemInterface.findFunction(interpreterStatus.symbolTable, functionToCall)
             ?: throw RuntimeException("Function $functionToCall cannot be found (${expression.position.line()})")
-        return FunctionWrapper(function = function, functionName = functionToCall, expression).let { functionWrapper ->
+        FunctionWrapper(function = function, functionName = functionToCall, expression).let { functionWrapper ->
             val paramsValues = expression.args.map {
                 if (it is DataRefExpr) {
                     FunctionValue(variableName = it.variable.name, value = it.evalWith(this))
@@ -475,29 +479,29 @@ class ExpressionEvaluation(
         }
     }
 
-    override fun eval(expression: TimeStampExpr): Value {
+    override fun eval(expression: TimeStampExpr): Value = proxyLogging(expression) {
         if (expression.value == null) {
-            return TimeStampValue.now()
+            return@proxyLogging TimeStampValue.now()
         } else {
             val evaluated = expression.value.evalWith(this)
             if (evaluated is StringValue) {
-                return TimeStampValue.of(evaluated.value)
+                return@proxyLogging TimeStampValue.of(evaluated.value)
             }
             TODO("TimeStamp parsing: " + evaluated)
         }
     }
 
-    override fun eval(expression: EditcExpr): Value {
+    override fun eval(expression: EditcExpr): Value = proxyLogging(expression) {
         val n = expression.value.evalWith(this)
         val format = expression.format.evalWith(this)
         if (format !is StringValue) throw UnsupportedOperationException("Required string value, but got $format at ${expression.position}")
-        return n.asDecimal().formatAs(format.value, expression.value.type(), localizationContext.decedit)
+        n.asDecimal().formatAs(format.value, expression.value.type(), localizationContext.decedit)
     }
 
-    override fun eval(expression: DiffExpr): Value {
+    override fun eval(expression: DiffExpr): Value = proxyLogging(expression) {
         val v1 = expression.value1.evalWith(this)
         val v2 = expression.value2.evalWith(this)
-        return when (expression.durationCode) {
+        return@proxyLogging when (expression.durationCode) {
             is DurationInMSecs -> IntValue(
                 ChronoUnit.MICROS.between(
                     v2.asTimeStamp().value.atZone(ZoneId.systemDefault()).toInstant(), v1.asTimeStamp().value.atZone(ZoneId.systemDefault()).toInstant()
@@ -536,7 +540,7 @@ class ExpressionEvaluation(
         }
     }
 
-    override fun eval(expression: DivExpr): Value {
+    override fun eval(expression: DivExpr): Value = proxyLogging(expression) {
         val v1 = expression.left.evalWith(this)
         val v2 = expression.right.evalWith(this)
         require(v1 is NumberValue && v2 is NumberValue)
@@ -569,17 +573,17 @@ class ExpressionEvaluation(
             v1.bigDecimal.divide(v2.bigDecimal, MathContext.DECIMAL128)
         }
         // TODO rounding and scale???
-        return DecimalValue(res)
+        DecimalValue(res)
     }
 
-    override fun eval(expression: ExpExpr): Value {
+    override fun eval(expression: ExpExpr): Value = proxyLogging(expression) {
         val v1 = expression.left.evalWith(this)
         val v2 = expression.right.evalWith(this)
-        return DecimalValue(BigDecimal(Math.pow(v1.asInt().value.toDouble(), v2.asInt().value.toDouble())))
+        DecimalValue(BigDecimal(v1.asInt().value.toDouble().pow(v2.asInt().value.toDouble())))
     }
 
-    override fun eval(expression: TrimrExpr): Value {
-        return if (expression.charactersToTrim == null) {
+    override fun eval(expression: TrimrExpr): Value = proxyLogging(expression) {
+        return@proxyLogging if (expression.charactersToTrim == null) {
             StringValue(evalAsString(expression.value).trimEnd())
         } else {
             val suffix = evalAsString(expression.charactersToTrim)
@@ -591,83 +595,92 @@ class ExpressionEvaluation(
         }
     }
 
-    override fun eval(expression: TrimlExpr): Value {
-        if (expression.charactersToTrim == null) {
-            return StringValue(evalAsString(expression.value).trimStart())
+    override fun eval(expression: TrimlExpr): Value = proxyLogging(expression) {
+        return@proxyLogging if (expression.charactersToTrim == null) {
+            StringValue(evalAsString(expression.value).trimStart())
         } else {
             val prefix = evalAsString(expression.charactersToTrim)
             var result = evalAsString(expression.value)
             while (result.startsWith(prefix)) {
                 result = result.substringAfter(prefix)
             }
-            return StringValue(result)
+            StringValue(result)
         }
     }
 
-    override fun eval(expression: TrimExpr) = StringValue(evalAsString(expression.value).trim())
-    override fun eval(expression: FoundExpr): Value {
+    override fun eval(expression: TrimExpr) = proxyLogging(expression) {
+        StringValue(evalAsString(expression.value).trim())
+    } as StringValue
+    override fun eval(expression: FoundExpr): Value = proxyLogging(expression) {
         // TODO fix this bad implementation
         if (expression.name == null) {
-            return BooleanValue(interpreterStatus.lastFound)
+            return@proxyLogging BooleanValue(interpreterStatus.lastFound)
         }
         TODO("Line ${expression.position?.line()} - %FOUND expression with file names is not implemented yet")
     }
 
-    override fun eval(expression: EofExpr): Value {
-
+    override fun eval(expression: EofExpr): Value = proxyLogging(expression) {
         if (expression.name == null) {
-            return BooleanValue(interpreterStatus.lastDBFile?.eof() ?: false)
+            return@proxyLogging BooleanValue(interpreterStatus.lastDBFile?.eof() ?: false)
         }
         TODO("Line ${expression.position?.line()} - %EOF expression with file names is not implemented yet")
     }
 
-    override fun eval(expression: EqualExpr): Value {
+    override fun eval(expression: EqualExpr): Value = proxyLogging(expression) {
         if (expression.name == null) {
-            return BooleanValue(interpreterStatus.lastDBFile?.equal() ?: false)
+            return@proxyLogging BooleanValue(interpreterStatus.lastDBFile?.equal() ?: false)
         }
         TODO("Line ${expression.position?.line()} - %EQUAL expression with file names is not implemented yet")
     }
 
-    override fun eval(expression: AbsExpr): Value {
+    override fun eval(expression: AbsExpr): Value = proxyLogging(expression) {
         val value = evalAsDecimal(expression.value)
-        return DecimalValue(BigDecimal.valueOf(abs(value.toDouble())))
+        DecimalValue(BigDecimal.valueOf(abs(value.toDouble())))
     }
 
-    override fun eval(expression: EditwExpr): Value {
+    override fun eval(expression: EditwExpr): Value = proxyLogging(expression) {
         val n = expression.value.evalWith(this)
         val format = evalAsString(expression.format)
-        return n.asDecimal().formatAsWord(format, expression.value.type())
+        n.asDecimal().formatAsWord(format, expression.value.type())
     }
 
-    override fun eval(expression: IntExpr): Value =
-        when (val value = expression.value.evalWith(this)) {
+    override fun eval(expression: IntExpr): Value = proxyLogging(expression) {
+        return@proxyLogging when (val value = expression.value.evalWith(this)) {
             is StringValue ->
                 IntValue(cleanNumericString(value.value).asLong())
+
             is DecimalValue ->
                 value.asInt()
+
             is UnlimitedStringValue ->
                 IntValue(cleanNumericString(value.value).asLong())
+
             else -> throw UnsupportedOperationException("I do not know how to handle $value with %INT")
         }
+    }
 
-    override fun eval(expression: InthExpr): Value =
+    override fun eval(expression: InthExpr): Value = proxyLogging(expression) {
         when (val value = expression.value.evalWith(this)) {
             is StringValue ->
                 IntValue(value.value.toDouble().roundToLong())
+
             is DecimalValue ->
                 IntValue(value.value.toDouble().roundToLong())
+
             is UnlimitedStringValue ->
                 IntValue(value.value.toDouble().roundToLong())
+
             else -> throw UnsupportedOperationException("I do not know how to handle $value with %INTH")
         }
+    }
 
-    override fun eval(expression: RemExpr): Value {
+    override fun eval(expression: RemExpr): Value = proxyLogging(expression) {
         val n = evalAsLong(expression.dividend)
         val m = evalAsLong(expression.divisor)
-        return IntValue(n % m)
+        IntValue(n % m)
     }
 
-    override fun eval(expression: QualifiedAccessExpr): Value {
+    override fun eval(expression: QualifiedAccessExpr): Value = proxyLogging(expression) {
         val dataStringValue = when (val value = expression.container.evalWith(this)) {
             is DataStructValue -> {
                 value
@@ -676,16 +689,15 @@ class ExpressionEvaluation(
             is OccurableDataStructValue -> {
                 value.value()
             }
-
             else -> {
                 throw ClassCastException(value::class.java.name)
             }
         }
-        return dataStringValue[expression.field.referred
+        return@proxyLogging dataStringValue[expression.field.referred
             ?: throw IllegalStateException("Referenced to field not resolved: ${expression.field.name}")]
     }
 
-    override fun eval(expression: ReplaceExpr): Value {
+    override fun eval(expression: ReplaceExpr): Value = proxyLogging(expression) {
         val replacement = evalAsString(expression.replacement)
         val sourceString = evalAsString(expression.source)
         val replacementLength: Int = replacement.length
@@ -712,41 +724,39 @@ class ExpressionEvaluation(
             }
         }
         // truncated if length is greater than type.elementSize
-        return if (result.length > expression.source.type().elementSize()) {
+        return@proxyLogging if (result.length > expression.source.type().elementSize()) {
             StringValue(result.substring(0, expression.source.type().elementSize()), expression.source.type().hasVariableSize())
         } else {
             StringValue(result, expression.source.type().hasVariableSize())
         }
     }
 
-    override fun eval(expression: SqrtExpr): Value {
+    override fun eval(expression: SqrtExpr): Value = proxyLogging(expression) {
         val value = evalAsDecimal(expression.value)
-        return DecimalValue(BigDecimal.valueOf(sqrt(value.toDouble())))
+        DecimalValue(BigDecimal.valueOf(sqrt(value.toDouble())))
     }
 
     override fun eval(expression: AssignmentExpr) =
         throw RuntimeException("AssignmentExpr should be handled by the interpreter: $expression")
 
-    override fun eval(expression: GlobalIndicatorExpr): Value {
+    override fun eval(expression: GlobalIndicatorExpr): Value = proxyLogging(expression) {
         val value = StringBuilder()
         for (i in IndicatorType.Predefined.range) {
             value.append(if (interpreterStatus.indicators[i] == null) "0" else if (interpreterStatus.indicators[i]!!.value) "1" else "0")
         }
-        return StringValue(value.toString())
+        StringValue(value.toString())
     }
 
-    override fun eval(expression: ParmsExpr): Value {
-        return IntValue(interpreterStatus.params.toLong())
-    }
+    override fun eval(expression: ParmsExpr): Value = proxyLogging(expression) { IntValue(interpreterStatus.params.toLong()) }
 
-    override fun eval(expression: OpenExpr): Value {
+    override fun eval(expression: OpenExpr): Value = proxyLogging(expression) {
         val name = expression.name
         require(name != null) {
             "Line ${expression.position?.line()} - %OPEN require a table name"
         }
         val enrichedDBFile = interpreterStatus.dbFileMap.get(name)
             ?: throw RuntimeException("Table $name cannot be found (${expression.position.line()})")
-        return BooleanValue(enrichedDBFile.open)
+        BooleanValue(enrichedDBFile.open)
     }
 
     private fun cleanNumericString(s: String): String {
@@ -757,4 +767,45 @@ class ExpressionEvaluation(
             else -> result
         }
     }
+
+    private fun sum(left: ArrayValue, right: ArrayValue, position: Position?): ArrayValue {
+        val listValue = when {
+            left.elementType is StringType && right.elementType is StringType ->
+                left.elements().mapIndexed { i: Int, v: Value ->
+                    if (right.elements().size > i) {
+                        val rightElement = right.getElement(i + 1)
+
+                        val valueToAdd: String = if (v.asString().varying) {
+                            (v.asString().value + rightElement.asString().value)
+                        } else {
+                            (v.asString().value + " ".repeat(left.elementType.elementSize() - v.asString().value.length) + rightElement.asString().value)
+                        }
+                        StringValue(valueToAdd, left.elementType.hasVariableSize())
+                    } else {
+                        v
+                    }
+                }
+            left.elementType is NumberType && right.elementType is NumberType ->
+                left.elements().mapIndexed { i: Int, v: Value ->
+                    if (right.elements().size > i) {
+                        val rightElement = right.getElement(i + 1)
+                        when {
+                            v is IntValue && rightElement is IntValue -> {
+                                (v + rightElement)
+                            }
+
+                            v is NumberValue && rightElement is NumberValue -> {
+                                DecimalValue(v.bigDecimal.plus(rightElement.bigDecimal))
+                            }
+
+                            else -> throw UnsupportedOperationException("Unable to sum ${left.elementType} and ${right.elementType} as Array elements at $position")
+                        }
+                    } else {
+                        v
+                    }
+                }
+            else -> throw UnsupportedOperationException("Unable to sum ${left.elementType} and ${right.elementType} as Array elements at $position")
+        } as MutableList<Value>
+        return ConcreteArrayValue(listValue, left.elementType)
+    }
 }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
index 0c6e7caba..a31a0b6c8 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
@@ -774,8 +774,6 @@ open class InternalInterpreter(
     }
 
     override fun eval(expression: Expression): Value {
-        val start = System.nanoTime()
-
         val value = when (expression) {
             is AssignmentExpr -> {
                 assign(expression.target, expression.value)
@@ -783,13 +781,9 @@ open class InternalInterpreter(
             else -> expression.evalWith(expressionEvaluation)
         }
 
-        val elapsed = (System.nanoTime() - start).nanoseconds
-
         val programName = this.interpretationContext.currentProgramName
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordExpressionExecution(programName, expression.loggableEntityName, elapsed)
         val sourceProvider = { LogSourceData(programName, expression.startLine()) }
         renderLogInternal { LazyLogEntry.produceExpression(sourceProvider, expression, value) }
-        renderLogInternal { LazyLogEntry.producePerformance(sourceProvider, expression.loggableEntityName, elapsed) }
 
         return value
     }

From 5dd3ff08b478202507805fadfbfeb7622b8d99ac Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Wed, 22 May 2024 10:56:42 +0200
Subject: [PATCH 16/22] Move analytics records to performance logs creation

---
 .../interpreter/ExpressionEvaluation.kt       |  14 +-
 .../interpreter/internal_interpreter.kt       |  56 +++++---
 .../com/smeup/rpgparser/interpreter/logs.kt   |  20 ++-
 .../smeup/rpgparser/interpreter/program.kt    |   4 +-
 .../interpreter/symbol_table_storaging.kt     |   4 +-
 .../logging/AnalyticsLoggingContext.kt        |  52 +++++---
 .../rpgparser/logging/ProgramUsageTable.kt    | 125 ++++++++++++------
 .../parsing/facade/RpgParserFacade.kt         |  17 +--
 .../rpgparser/parsing/facade/preprocess.kt    |   3 +-
 9 files changed, 187 insertions(+), 108 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
index e8e25512c..5db32776a 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
@@ -17,6 +17,7 @@
 package com.smeup.rpgparser.interpreter
 
 import com.smeup.rpgparser.execution.MainExecutionContext
+import com.smeup.rpgparser.logging.ProgramUsageType
 import com.smeup.rpgparser.parsing.ast.*
 import com.smeup.rpgparser.parsing.parsetreetoast.LogicalCondition
 import com.smeup.rpgparser.utils.asBigDecimal
@@ -52,29 +53,20 @@ class ExpressionEvaluation(
 
         val programName = MainExecutionContext.getExecutionProgramName()
         val loggingContext = MainExecutionContext.getAnalyticsLoggingContext()
-        val isSelfNested = loggingContext?.isExecutingExpression ?: false
-        loggingContext?.enterExpression(expression.loggableEntityName)
 
         val start = System.nanoTime()
         val value = action()
         val elapsed = (System.nanoTime() - start).nanoseconds
 
         MainExecutionContext.log(
-            LazyLogEntry.producePerformance(
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
                 { LogSourceData(programName, expression.startLine()) },
+                ProgramUsageType.Expression,
                 expression.loggableEntityName,
                 elapsed
             )
         )
 
-        loggingContext?.let { ctx ->
-            if (isSelfNested)
-                ctx.recordNestedExpressionExecutionFromScope(programName, elapsed)
-            else ctx.recordExpressionExecution(programName, expression.loggableEntityName, elapsed)
-
-            ctx.exitExpression()
-        }
-
         return value
     }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
index a31a0b6c8..352eb99f9 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
@@ -21,6 +21,7 @@ import com.smeup.dbnative.file.Record
 import com.smeup.rpgparser.execution.ErrorEvent
 import com.smeup.rpgparser.execution.ErrorEventSource
 import com.smeup.rpgparser.execution.MainExecutionContext
+import com.smeup.rpgparser.logging.ProgramUsageType
 import com.smeup.rpgparser.parsing.ast.*
 import com.smeup.rpgparser.parsing.ast.AssignmentOperator.*
 import com.smeup.rpgparser.parsing.facade.SourceReference
@@ -331,20 +332,18 @@ open class InternalInterpreter(
         val initElapsed = (System.nanoTime() - start).nanoseconds
 
         val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext()
-        analyticsContext?.recordSymbolTableAccess(programName, SymbolTableAction.INIT, initElapsed)
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLINI", "END") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLINI", "END") }
-        renderLogInternal { LazyLogEntry.producePerformance(logSourceProducer, "SYMTBLINI", initElapsed) }
+        renderLogInternal { LazyLogEntry.producePerformanceAndUpdateAnalytics(logSourceProducer, ProgramUsageType.SymbolTable, SymbolTableAction.INIT.name, initElapsed) }
 
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLLOAD", "START") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLLOAD", "START") }
 
         val loadElapsed = measureNanoTime { afterInitialization(initialValues = initialValues) }.nanoseconds
 
-        analyticsContext?.recordSymbolTableAccess(programName, SymbolTableAction.LOAD, loadElapsed)
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLLOAD", "END") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLLOAD", "END") }
-        renderLogInternal { LazyLogEntry.producePerformance(logSourceProducer, "SYMTBLLOAD", loadElapsed) }
+        renderLogInternal { LazyLogEntry.producePerformanceAndUpdateAnalytics(logSourceProducer, ProgramUsageType.SymbolTable, SymbolTableAction.LOAD.name, loadElapsed) }
     }
 
     private fun toArrayValue(compileTimeArray: CompileTimeArray, arrayType: ArrayType): Value {
@@ -597,7 +596,6 @@ open class InternalInterpreter(
 
                 is MuteFailAnnotation -> {
                     val message = it.message.evalWith(expressionEvaluation)
-                    val programName = this.interpretationContext.currentProgramName
                     renderLogInternal {
                         val logSource = { LogSourceData(programName, it.startLine()) }
                         LazyLogEntry.produceMute(it, logSource, message)
@@ -1144,9 +1142,7 @@ open class InternalInterpreter(
 
         renderLogInternal { statement.getResolutionLogRenderer(sourceProducer) }
 
-        val isSelfNested = loggingContext?.isExecutingCompositeStatement ?: false
         if (statement is CompositeStatement) {
-            loggingContext?.enterCompositeStatement(statement.loggableEntityName)
             renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "START") }
         } else {
             renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "EXEC") }
@@ -1160,11 +1156,7 @@ open class InternalInterpreter(
             statement.execute(this)
         }.nanoseconds
 
-        loggingContext?.let { ctx ->
-            if (ctx.isExecutingCompositeStatement && isSelfNested) {
-                ctx.recordNestedStatementExecution(programName, statement.loggableEntityName, executionTime)
-            } else ctx.recordStatementExecution(programName, statement.loggableEntityName, executionTime)
-        }
+        loggingContext?.recordStatementExecution(programName, statement.loggableEntityName, executionTime)
 
         if (statement is LoopStatement) {
             renderLogInternal {
@@ -1178,11 +1170,10 @@ open class InternalInterpreter(
         }
 
         if (statement is CompositeStatement) {
-            loggingContext?.exitCompositeStatement()
             renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "END") }
         }
 
-        renderLogInternal { LazyLogEntry.producePerformance(sourceProducer, statement.loggableEntityName, executionTime) }
+        renderLogInternal { LazyLogEntry.producePerformanceAndUpdateAnalytics(sourceProducer, ProgramUsageType.Statement, statement.loggableEntityName, executionTime) }
     }
 
     override fun onInterpretationEnd() {
@@ -1191,20 +1182,38 @@ open class InternalInterpreter(
     }
 
     private fun getWithLogging(data: String): Value {
-        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return globalSymbolTable[data]
         val start = System.nanoTime()
         val value = globalSymbolTable[data]
         val elapsed = System.nanoTime() - start
-        analyticsContext.recordSymbolTableAccess(interpretationContext.currentProgramName, SymbolTableAction.GET, elapsed.nanoseconds)
+        val programName = interpretationContext.currentProgramName
+
+        renderLogInternal {
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
+                { LogSourceData.fromProgram(programName) },
+                ProgramUsageType.SymbolTable,
+                SymbolTableAction.GET.name,
+                elapsed.nanoseconds
+            )
+        }
+
         return value
     }
 
     private fun getWithLogging(data: AbstractDataDefinition): Value {
-        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return globalSymbolTable[data]
         val start = System.nanoTime()
         val value = globalSymbolTable[data]
         val elapsed = System.nanoTime() - start
-        analyticsContext.recordSymbolTableAccess(interpretationContext.currentProgramName, SymbolTableAction.GET, elapsed.nanoseconds)
+        val programName = interpretationContext.currentProgramName
+
+        renderLogInternal {
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
+                { LogSourceData(programName, data.startLine()) },
+                ProgramUsageType.SymbolTable,
+                SymbolTableAction.GET.name,
+                elapsed.nanoseconds
+            )
+        }
+
         return value
     }
 
@@ -1215,9 +1224,16 @@ open class InternalInterpreter(
             }
         }
 
-        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return setValue()
         val elapsed = measureNanoTime { setValue() }
-        analyticsContext.recordSymbolTableAccess(interpretationContext.currentProgramName, SymbolTableAction.SET, elapsed.nanoseconds)
+        val programName = interpretationContext.currentProgramName
+        renderLogInternal {
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
+                { LogSourceData(programName, data.startLine()) },
+                ProgramUsageType.SymbolTable,
+                SymbolTableAction.SET.name,
+                elapsed.nanoseconds
+            )
+        }
     }
 }
 
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
index cafda9c50..79ccb6aef 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
@@ -19,6 +19,7 @@ package com.smeup.rpgparser.interpreter
 import com.smeup.rpgparser.execution.ErrorEvent
 import com.smeup.rpgparser.execution.MainExecutionContext
 import com.smeup.rpgparser.logging.LogChannel
+import com.smeup.rpgparser.logging.ProgramUsageType
 import com.smeup.rpgparser.parsing.ast.*
 import com.smeup.rpgparser.parsing.facade.SourceReference
 import com.smeup.rpgparser.utils.asNonNullString
@@ -227,6 +228,22 @@ class LazyLogEntry(val entry: LogEntry, val renderContent: (sep: String) -> Stri
             }
         }
 
+        /**
+         * Create a new LazyLogEntry for the PERF channel and updates AnalyticsContext with its data
+         * @see LogChannel
+         */
+        fun producePerformanceAndUpdateAnalytics(source: LogSourceProvider, type: ProgramUsageType, entity: String, elapsed: Duration): LazyLogEntry {
+            val entry = LogEntry(source, LogChannel.PERFORMANCE.getPropertyName(), entity)
+
+            val loggingContext = MainExecutionContext.getAnalyticsLoggingContext()
+            val programName = MainExecutionContext.getExecutionProgramName()
+            loggingContext?.recordUsage(programName, type, entity, elapsed)
+
+            return LazyLogEntry(entry) {
+                elapsed.inWholeMicroseconds.toString()
+            }
+        }
+
         /**
          * Create a new LazyLogEntry for the ANALYTICS channel
          * @see LogChannel
@@ -481,7 +498,8 @@ fun List<InterpreterLogHandler>.renderLog(renderer: LazyLogEntry) {
         }
     }.nanoseconds
 
-    MainExecutionContext.getAnalyticsLoggingContext()?.recordRenderingDuration(time)
+    val programName = MainExecutionContext.getExecutionProgramName()
+    MainExecutionContext.getAnalyticsLoggingContext()?.recordUsage(programName, ProgramUsageType.LogRendering, "", time)
 }
 
 fun Position?.line() = this?.relative()?.second?.renderStartLine().asNonNullString()
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
index c9ae5b9da..680aaa670 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/program.kt
@@ -17,6 +17,7 @@
 package com.smeup.rpgparser.interpreter
 
 import com.smeup.rpgparser.execution.MainExecutionContext
+import com.smeup.rpgparser.logging.ProgramUsageType
 import com.smeup.rpgparser.parsing.ast.*
 import com.smeup.rpgparser.parsing.facade.RpgParserFacade
 import com.smeup.rpgparser.parsing.parsetreetoast.resolveAndValidate
@@ -156,8 +157,7 @@ class RpgProgram(val cu: CompilationUnit, val name: String = "<UNNAMED RPG PROGR
         }.nanoseconds
 
         logHandlers.renderLog(LazyLogEntry.produceStatement(logSource, "INTERPRETATION", "END"))
-        logHandlers.renderLog(LazyLogEntry.producePerformance(logSource, "INTERPRETATION", elapsed))
-        MainExecutionContext.getAnalyticsLoggingContext()?.recordInterpretationDuration(elapsed)
+        logHandlers.renderLog(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Interpretation, "INTERPRETATION", elapsed))
         if (MainExecutionContext.getProgramStack().isEmpty()) {
             interpreter.onInterpretationEnd()
         }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt
index 6602aea8f..837dab6b6 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/symbol_table_storaging.kt
@@ -1,6 +1,7 @@
 package com.smeup.rpgparser.interpreter
 
 import com.smeup.rpgparser.execution.MainExecutionContext
+import com.smeup.rpgparser.logging.ProgramUsageType
 import kotlin.system.measureNanoTime
 import kotlin.time.Duration.Companion.nanoseconds
 
@@ -166,9 +167,8 @@ class MemorySliceMgr(private val storage: IMemorySliceStorage) {
                     val elapsed = measureNanoTime {
                         storage.store(memorySliceId = slice.memorySliceId, values = values)
                     }.nanoseconds
-                    MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableAccess(slice.memorySliceId.programName, SymbolTableAction.STORE, elapsed)
                     MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "SYMTBLSTORE", "END"))
-                    MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "SYMTBLSTORE", elapsed))
+                    MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.SymbolTable, SymbolTableAction.STORE.name, elapsed))
                 }
             }
             if (result.isFailure) {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
index 97bedd92e..e06fe684d 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/AnalyticsLoggingContext.kt
@@ -4,7 +4,6 @@ import com.smeup.rpgparser.interpreter.LazyLogEntry
 import com.smeup.rpgparser.interpreter.LogEntry
 import com.smeup.rpgparser.interpreter.LogSourceData
 import com.smeup.rpgparser.interpreter.SymbolTableAction
-import java.util.Stack
 import kotlin.time.Duration
 
 /**
@@ -16,38 +15,38 @@ class AnalyticsLoggingContext {
     private var renderingTimeMeasurement = UsageMeasurement.new()
     private var interpretationTimeMeasurement = UsageMeasurement.new()
 
-    private val statementScope = Stack<String>()
-    private val expressionScope = Stack<String>()
+//    private val statementScope = Stack<String>()
+//    private val expressionScope = Stack<String>()
 
     /**
      * Checks whether we are in a CompositeStatement scope or not.
      */
-    val isExecutingCompositeStatement get() = statementScope.isNotEmpty()
+//    val isExecutingCompositeStatement get() = statementScope.isNotEmpty()
 
     /**
      * Checks whether we are executing an expression or not.
      */
-    val isExecutingExpression get() = expressionScope.isNotEmpty()
+//    val isExecutingExpression get() = expressionScope.isNotEmpty()
 
     /**
      * Records the beginning of the execution of a CompositeStatement.
      */
-    fun enterCompositeStatement(entity: String) { statementScope.push(entity) }
+//    fun enterCompositeStatement(entity: String) { statementScope.push(entity) }
 
     /**
      * Records the end of the execution of a CompositeStatement.
      */
-    fun exitCompositeStatement() { statementScope.pop() }
+//    fun exitCompositeStatement() { statementScope.pop() }
 
     /**
      * Records the beginning of the execution of an expression.
      */
-    fun enterExpression(entity: String) { expressionScope.push(entity) }
+//    fun enterExpression(entity: String) { expressionScope.push(entity) }
 
     /**
      * Records the end of the execution of an expression.
      */
-    fun exitExpression() { expressionScope.pop() }
+//    fun exitExpression() { expressionScope.pop() }
 
     /**
      * Records log rendering duration.
@@ -77,6 +76,22 @@ class AnalyticsLoggingContext {
     fun recordSymbolTableAccess(program: String, action: SymbolTableAction, time: Duration) =
         programUsageTable.recordSymbolTableAction(program, action, time)
 
+    /**
+     * Records a parsing step.
+     */
+    fun recordParsing(program: String, step: String, time: Duration) =
+        programUsageTable.recordParsing(program, step, time)
+
+    fun recordUsage(program: String, type: ProgramUsageType, entity: String, time: Duration) =
+        when (type) {
+            ProgramUsageType.Parsing -> recordParsing(program, entity, time)
+            ProgramUsageType.Statement -> recordStatementExecution(program, entity, time)
+            ProgramUsageType.Expression -> recordExpressionExecution(program, entity, time)
+            ProgramUsageType.SymbolTable -> recordSymbolTableAccess(program, SymbolTableAction.valueOf(entity), time)
+            ProgramUsageType.LogRendering -> recordRenderingDuration(time)
+            ProgramUsageType.Interpretation -> recordInterpretationDuration(time)
+        }
+
     /**
      * Records the execution of a statement.
      * @see ILoggableStatement
@@ -88,15 +103,15 @@ class AnalyticsLoggingContext {
      * Records the execution of a nested statement.
      * @see ILoggableStatement
      */
-    fun recordNestedStatementExecution(program: String, entity: String, time: Duration) =
-        programUsageTable.recordNestedStatement(program, statementScope, entity, time)
+//    fun recordNestedStatementExecution(program: String, entity: String, time: Duration) =
+//        programUsageTable.recordNestedStatement(program, statementScope, entity, time)
 
     /**
      * Records the execution of a nested expression from the current expression scope state.
      * @see ILoggableExpression
      */
-    fun recordNestedExpressionExecutionFromScope(program: String, time: Duration) =
-        programUsageTable.recordNestedExpression(program, expressionScope, time)
+//    fun recordNestedExpressionExecutionFromScope(program: String, time: Duration) =
+//        programUsageTable.recordNestedExpression(program, expressionScope, time)
 
     /**
      * Generate an ANALYTICS report based on currently collected metadata in the form
@@ -107,28 +122,25 @@ class AnalyticsLoggingContext {
         val statementEntries = mutableListOf<LazyLogEntry>()
         val expressionEntries = mutableListOf<LazyLogEntry>()
         val symbolTableEntries = mutableListOf<LazyLogEntry>()
-        val nestedStatementEntries = mutableListOf<LazyLogEntry>()
-        val nestedExpressionEntries = mutableListOf<LazyLogEntry>()
+        val parsingEntries = mutableListOf<LazyLogEntry>()
 
         programUsageTable.asSequence().forEach {
             val program = it.key
             val statement = programUsageTable.generateStatementLogEntries(program)
             val expression = programUsageTable.generateExpressionLogEntries(program)
             val symTable = programUsageTable.generateSymbolTableLogEntries(program)
-            val nestedStatement = programUsageTable.generateNestedStatementLogEntries(program)
-            val nestedExpression = programUsageTable.generateNestedExpressionLogEntries(program)
+            val parsing = programUsageTable.generateParsingLogEntries(program)
 
             statementEntries.addAll(statement)
             expressionEntries.addAll(expression)
             symbolTableEntries.addAll(symTable)
-            nestedStatementEntries.addAll(nestedStatement)
-            nestedExpressionEntries.addAll(nestedExpression)
+            parsingEntries.addAll(parsing)
         }
 
         val logTimeEntry = generateLogTimeReportEntry()
         val interpretationTimeEntry = generateInterpretationReportEntry()
 
-        return statementEntries + expressionEntries + symbolTableEntries + nestedStatementEntries + nestedExpressionEntries + logTimeEntry + interpretationTimeEntry
+        return statementEntries + expressionEntries + symbolTableEntries + parsingEntries + logTimeEntry + interpretationTimeEntry
     }
 
     private fun generateLogTimeReportEntry(): LazyLogEntry {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
index 5abf8c506..c3a495adc 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt
@@ -8,6 +8,15 @@ import java.util.*
 import kotlin.collections.HashMap
 import kotlin.time.Duration
 
+enum class ProgramUsageType {
+    Statement,
+    Expression,
+    SymbolTable,
+    Parsing,
+    LogRendering,
+    Interpretation
+}
+
 /**
  * Collects the usage information about the main parts of the program.
  */
@@ -17,8 +26,9 @@ class ProgramUsageStats {
     val symbolTableActions: EnumMap<SymbolTableAction, UsageMeasurement> by lazy {
         EnumMap(SymbolTableAction::class.java)
     }
-    val nestedStatements: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
-    val nestedExpressions: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
+    val parsingSteps: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
+//    val nestedStatements: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
+//    val nestedExpressions: HashMap<String, UsageMeasurement> by lazy { hashMapOf() }
 }
 
 typealias ProgramUsageTable = HashMap<String, ProgramUsageStats>
@@ -37,23 +47,23 @@ fun ProgramUsageTable.recordStatement(program: String, entity: String, time: Dur
  * Records the execution of a nested statement.
  * @see ILoggableStatement
  */
-fun ProgramUsageTable.recordNestedStatement(program: String, scope: Stack<String>, entity: String, time: Duration) {
-    val programStats = this.getOrPut(program) { ProgramUsageStats() }
-    val path = "${scope.joinToString(separator = "/")}/$entity"
-    val measurement = programStats.nestedStatements.getOrDefault(path, UsageMeasurement.new())
-    programStats.nestedStatements[path] = measurement.hit(time)
-}
+// fun ProgramUsageTable.recordNestedStatement(program: String, scope: Stack<String>, entity: String, time: Duration) {
+//    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+//    val path = "${scope.joinToString(separator = "/")}/$entity"
+//    val measurement = programStats.nestedStatements.getOrDefault(path, UsageMeasurement.new())
+//    programStats.nestedStatements[path] = measurement.hit(time)
+// }
 
 /**
  * Records the execution of a nested expression.
  * @see ILoggableExpression
  */
-fun ProgramUsageTable.recordNestedExpression(program: String, scope: Stack<String>, time: Duration) {
-    val programStats = this.getOrPut(program) { ProgramUsageStats() }
-    val path = scope.joinToString(separator = "->")
-    val measurement = programStats.nestedExpressions.getOrDefault(path, UsageMeasurement.new())
-    programStats.nestedExpressions[path] = measurement.hit(time)
-}
+// fun ProgramUsageTable.recordNestedExpression(program: String, scope: Stack<String>, time: Duration) {
+//    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+//    val path = scope.joinToString(separator = "->")
+//    val measurement = programStats.nestedExpressions.getOrDefault(path, UsageMeasurement.new())
+//    programStats.nestedExpressions[path] = measurement.hit(time)
+// }
 
 /**
  * Records the execution of an expression.
@@ -75,6 +85,16 @@ fun ProgramUsageTable.recordSymbolTableAction(program: String, action: SymbolTab
     programStats.symbolTableActions[action] = measurement.hit(time)
 }
 
+/**
+ * Records a parsing step.
+ * @see SymbolTableAction
+ */
+fun ProgramUsageTable.recordParsing(program: String, step: String, time: Duration) {
+    val programStats = this.getOrPut(program) { ProgramUsageStats() }
+    val measurement = programStats.parsingSteps.getOrDefault(step, UsageMeasurement.new())
+    programStats.parsingSteps[step] = measurement.hit(time)
+}
+
 /**
  * Generate an ANALYTICS statement usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry
@@ -97,40 +117,40 @@ fun ProgramUsageTable.generateStatementLogEntries(program: String): Sequence<Laz
 /**
  * Generate an ANALYTICS nested statement usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry
- */
-fun ProgramUsageTable.generateNestedStatementLogEntries(program: String): Sequence<LazyLogEntry> {
-    val stats = this[program] ?: return emptySequence()
-
-    return stats.nestedStatements.asSequence().map {
-        val statementName = it.key
-        val duration = it.value.duration
-        val hit = it.value.hit
-
-        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "NESTED STMT TIME")
-        LazyLogEntry(entry) { sep ->
-            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
-        }
-    }
-}
+// */
+// fun ProgramUsageTable.generateNestedStatementLogEntries(program: String): Sequence<LazyLogEntry> {
+//    val stats = this[program] ?: return emptySequence()
+//
+//    return stats.nestedStatements.asSequence().map {
+//        val statementName = it.key
+//        val duration = it.value.duration
+//        val hit = it.value.hit
+//
+//        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "NESTED STMT TIME")
+//        LazyLogEntry(entry) { sep ->
+//            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
+//        }
+//    }
+// }
 
 /**
  * Generate an ANALYTICS nested expression usage report in the form of a sequence of LazyLogEntry.
  * @see LazyLogEntry
  */
-fun ProgramUsageTable.generateNestedExpressionLogEntries(program: String): Sequence<LazyLogEntry> {
-    val stats = this[program] ?: return emptySequence()
-
-    return stats.nestedExpressions.asSequence().map {
-        val statementName = it.key
-        val duration = it.value.duration
-        val hit = it.value.hit
-
-        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "NESTED EXPR TIME")
-        LazyLogEntry(entry) { sep ->
-            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
-        }
-    }
-}
+// fun ProgramUsageTable.generateNestedExpressionLogEntries(program: String): Sequence<LazyLogEntry> {
+//    val stats = this[program] ?: return emptySequence()
+//
+//    return stats.nestedExpressions.asSequence().map {
+//        val statementName = it.key
+//        val duration = it.value.duration
+//        val hit = it.value.hit
+//
+//        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "NESTED EXPR TIME")
+//        LazyLogEntry(entry) { sep ->
+//            "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit"
+//        }
+//    }
+// }
 
 /**
  * Generate an ANALYTICS expression usage report in the form of a sequence of LazyLogEntry.
@@ -168,4 +188,23 @@ fun ProgramUsageTable.generateSymbolTableLogEntries(program: String): Sequence<L
             "$action$sep${duration.inWholeMicroseconds}${sep}$hit"
         }
     }
+}
+
+/**
+ * Generate an ANALYTICS parsing usage report in the form of a sequence of LazyLogEntry.
+ * @see LazyLogEntry
+ */
+fun ProgramUsageTable.generateParsingLogEntries(program: String): Sequence<LazyLogEntry> {
+    val stats = this[program] ?: return emptySequence()
+
+    return stats.parsingSteps.asSequence().map {
+        val step = it.key
+        val duration = it.value.duration
+        val hit = it.value.hit
+
+        val entry = LogEntry({ LogSourceData.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "PARS TIME")
+        LazyLogEntry(entry) { sep ->
+            "$step$sep${duration.inWholeMicroseconds}${sep}$hit"
+        }
+    }
 }
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/RpgParserFacade.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/RpgParserFacade.kt
index 99eae83ad..ed924fad2 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/RpgParserFacade.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/RpgParserFacade.kt
@@ -26,6 +26,7 @@ import com.smeup.rpgparser.execution.ErrorEventSource
 import com.smeup.rpgparser.execution.MainExecutionContext
 import com.smeup.rpgparser.execution.ParsingProgram
 import com.smeup.rpgparser.interpreter.*
+import com.smeup.rpgparser.logging.ProgramUsageType
 import com.smeup.rpgparser.parsing.ast.CompilationUnit
 import com.smeup.rpgparser.parsing.ast.SourceProgram
 import com.smeup.rpgparser.parsing.ast.createCompilationUnit
@@ -197,7 +198,7 @@ class RpgParserFacade {
 
         MainExecutionContext.log(LazyLogEntry.produceStatement(endLogSource, "RPGLOAD", "END"))
         MainExecutionContext.log(LazyLogEntry.produceParsingEnd(endLogSource, "RPGLOAD", elapsedLoad))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(endLogSource, "RPGLOAD", elapsedLoad))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(endLogSource, ProgramUsageType.Parsing, "RPGLOAD", elapsedLoad))
 
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "LEXER", "START"))
         MainExecutionContext.log(LazyLogEntry.produceParsingStart(logSource, "LEXER"))
@@ -216,7 +217,7 @@ class RpgParserFacade {
 
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "LEXER", "END"))
         MainExecutionContext.log(LazyLogEntry.produceParsingEnd(logSource, "LEXER", elapsedLexer))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "LEXER", elapsedLexer))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "LEXER", elapsedLexer))
 
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "PARSER", "START"))
         MainExecutionContext.log(LazyLogEntry.produceParsingStart(logSource, "PARSER"))
@@ -234,7 +235,7 @@ class RpgParserFacade {
         }.nanoseconds
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "PARSER", "END"))
         MainExecutionContext.log(LazyLogEntry.produceParsingEnd(logSource, "PARSER", elapsedParser))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "PARSER", elapsedParser))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "PARSER", elapsedParser))
         return parser
     }
 
@@ -259,7 +260,7 @@ class RpgParserFacade {
         }.nanoseconds
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "CHKPTREE", "END"))
         MainExecutionContext.log(LazyLogEntry.produceParsingEnd(logSource, "CHKPTREE", elapsed))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "CHKPTREE", elapsed))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "CHKPTREE", elapsed))
     }
 
     private fun parseMute(code: String, errors: MutableList<Error>): MuteParser.MuteLineContext {
@@ -320,7 +321,7 @@ class RpgParserFacade {
             }
         }.nanoseconds
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "FINDMUTES", "END"))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "FINDMUTES", elapsed))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "FINDMUTES", elapsed))
         return mutes
     }
 
@@ -358,7 +359,7 @@ class RpgParserFacade {
         }.nanoseconds
         MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "RCONTEXT", "END"))
         MainExecutionContext.log(LazyLogEntry.produceParsingEnd(logSource, "RCONTEXT", elapsedRoot))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "RCONTEXT", elapsedRoot))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "RCONTEXT", elapsedRoot))
         var mutes: MutesImmutableMap? = null
         if (muteSupport) {
             mutes = findMutes(code, errors)
@@ -380,7 +381,7 @@ class RpgParserFacade {
                     val elapsed = (System.nanoTime() - start).nanoseconds
                     MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "AST", "END"))
                     MainExecutionContext.log(LazyLogEntry.produceParsingEnd(logSource, "AST", elapsed))
-                    MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "AST", elapsed))
+                    MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "AST", elapsed))
                 }
             } else {
                 null
@@ -437,7 +438,7 @@ class RpgParserFacade {
             }.nanoseconds
             MainExecutionContext.log(LazyLogEntry.produceStatement(logSource, "AST", "END"))
             MainExecutionContext.log(LazyLogEntry.produceParsingEnd(logSource, "AST", elapsed))
-            MainExecutionContext.log(LazyLogEntry.producePerformance(logSource, "AST", elapsed))
+            MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(logSource, ProgramUsageType.Parsing, "AST", elapsed))
             compilationUnit
         }.onFailure {
             throw AstCreatingException(result.src, it)
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/preprocess.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/preprocess.kt
index 91f8b3f49..8ea4ce201 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/preprocess.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/preprocess.kt
@@ -3,6 +3,7 @@ package com.smeup.rpgparser.parsing.facade
 import com.smeup.rpgparser.execution.MainExecutionContext
 import com.smeup.rpgparser.interpreter.LazyLogEntry
 import com.smeup.rpgparser.interpreter.LogSourceData
+import com.smeup.rpgparser.logging.ProgramUsageType
 import java.io.BufferedReader
 import java.io.InputStream
 import kotlin.system.measureNanoTime
@@ -27,7 +28,7 @@ fun InputStream.preprocess(
     }.apply {
         val endLogSource = { LogSourceData(programName, preprocessed.lines().size.toString()) }
         MainExecutionContext.log(LazyLogEntry.produceStatement(endLogSource, "PREPROP", "END"))
-        MainExecutionContext.log(LazyLogEntry.producePerformance(endLogSource, "PREPROP", this.nanoseconds))
+        MainExecutionContext.log(LazyLogEntry.producePerformanceAndUpdateAnalytics(endLogSource, ProgramUsageType.Parsing, "PREPROP", this.nanoseconds))
     }
     return preprocessed
 }
\ No newline at end of file

From aca6fc120b1f237a78b5b58835e4baf2a49bf535 Mon Sep 17 00:00:00 2001
From: lanarimarco <marco.lanari@smeup.com>
Date: Thu, 23 May 2024 18:10:53 +0200
Subject: [PATCH 17/22] Add some perf logging test examples

---
 .../rpgparser/smeup/PerfLoggingExample.kt     | 24 +++++++++++++++++
 .../test/resources/smeup/T10_A60_P03.rpgle    | 26 +++++++++++++++++++
 .../test/resources/smeup/T10_A80_P02.rpgle    | 24 +++++++++++++++++
 .../test/resources/smeup/T40_A20_P17.rpgle    | 20 ++++++++++++++
 4 files changed, 94 insertions(+)
 create mode 100644 rpgJavaInterpreter-core/src/test/resources/smeup/T10_A60_P03.rpgle
 create mode 100644 rpgJavaInterpreter-core/src/test/resources/smeup/T10_A80_P02.rpgle
 create mode 100644 rpgJavaInterpreter-core/src/test/resources/smeup/T40_A20_P17.rpgle

diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt
index 06fd24484..258d09d0c 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/smeup/PerfLoggingExample.kt
@@ -24,4 +24,28 @@ class PerfLoggingExample : MULANGTTest() {
         }
         executePgm(programName = "smeup/T10_A60_P02", systemInterface = si)
     }
+
+    @Test @Category(PerformanceTest::class)
+    fun testT10_A60_P03() {
+        val si = JavaSystemInterface().apply {
+            loggingConfiguration = consoleLoggingConfiguration(LogChannel.ANALYTICS)
+        }
+        executePgm(programName = "smeup/T10_A60_P03", systemInterface = si)
+    }
+
+    @Test @Category(PerformanceTest::class)
+    fun testT40_A20_P17() {
+        val si = JavaSystemInterface().apply {
+            loggingConfiguration = consoleLoggingConfiguration(LogChannel.ANALYTICS)
+        }
+        executePgm(programName = "smeup/T40_A20_P17", systemInterface = si)
+    }
+
+    @Test @Category(PerformanceTest::class)
+    fun testT10_A80_P02() {
+        val si = JavaSystemInterface().apply {
+            loggingConfiguration = consoleLoggingConfiguration(LogChannel.ANALYTICS)
+        }
+        executePgm(programName = "smeup/T10_A80_P02", systemInterface = si)
+    }
 }
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/test/resources/smeup/T10_A60_P03.rpgle b/rpgJavaInterpreter-core/src/test/resources/smeup/T10_A60_P03.rpgle
new file mode 100644
index 000000000..7ba33c30f
--- /dev/null
+++ b/rpgJavaInterpreter-core/src/test/resources/smeup/T10_A60_P03.rpgle
@@ -0,0 +1,26 @@
+     D NNN             S              6  0 INZ(100000)
+     D £DBG_Str        S           2560                                         Stringa
+     D £DBG_Pas        S             10
+      * Variabili sezione A60
+     D A60_A10         S             10
+     D A60_P1          S             10    INZ('MULANGT10')
+     D A60_P2          S              2  0
+     D A60_P3          S             50
+
+     C                   EVAL      £DBG_Pas='P03'
+      *
+     C                   CLEAR                   A60_P3
+     C                   DO        NNN
+     C                   EXSR      SUB_A60_A
+     C                   ENDDO
+     C                   EVAL      £DBG_Str='CALL('+A60_P1+', '
+     C                                     +%CHAR(A60_P2)
+     C                                     +', '+A60_P3+') '
+      *
+
+     C     SUB_A60_A     BEGSR
+     C                   CALL      'MULANGTB10'
+     C                   PARM                    A60_P1
+     C                   PARM      1             A60_P2
+     C                   PARM                    A60_P3
+     C                   ENDSR
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/test/resources/smeup/T10_A80_P02.rpgle b/rpgJavaInterpreter-core/src/test/resources/smeup/T10_A80_P02.rpgle
new file mode 100644
index 000000000..4b4df69e4
--- /dev/null
+++ b/rpgJavaInterpreter-core/src/test/resources/smeup/T10_A80_P02.rpgle
@@ -0,0 +1,24 @@
+     D NNN             S              6  0 INZ(100000)
+     D £DBG_Str        S           2560
+     D £DBG_Pas        S             10
+     D A80_N1          S              2  0
+     DA80_CALL1        PR
+     DC1_PAR1                         2  0
+
+    OA* A£.CDOP(CALLP )
+     D* CALLP procedura vuota (100.000 volte)
+     C                   EVAL      £DBG_Pas='P02'
+     C                   EVAL      A80_N1 = 0
+     C                   DO        NNN
+     C                   CALLP     A80_CALL1(A80_N1)
+     C                   ENDDO
+     C                   EVAL      £DBG_Str='A80_CALL1'
+
+    RD* Procedura vuota
+      *---------------------------------------------------------------------
+     PA80_CALL1        B
+     DA80_CALL1        PI
+     DC1_PAR1                         2  0
+      *
+     PA80_CALL1        E
+      *---------------------------------------------------------------------
\ No newline at end of file
diff --git a/rpgJavaInterpreter-core/src/test/resources/smeup/T40_A20_P17.rpgle b/rpgJavaInterpreter-core/src/test/resources/smeup/T40_A20_P17.rpgle
new file mode 100644
index 000000000..d8b6020d2
--- /dev/null
+++ b/rpgJavaInterpreter-core/src/test/resources/smeup/T40_A20_P17.rpgle
@@ -0,0 +1,20 @@
+     D NNN             S              6  0 INZ(100000)
+     D £DBG_Str        S           2560
+     D £DBG_Pas        S             10
+     D A20_DIM_P01     S              4    DIM(200)
+     D A20_DIM_P04     S              4    DIM(200)
+
+
+    OA* A£.CDOP(MOVEA  )
+     D* MOVEA(P) 100.000 volte
+     C                   EVAL      £DBG_Pas='P17'
+     C                   DO        NNN
+     C                   EXSR      SUB_A20_D
+     C                   ENDDO
+     C                   EVAL      £DBG_Str=%TRIMR(A20_DIM_P01(1))
+      *
+
+
+     C     SUB_A20_D     BEGSR
+     C                   MOVEA(P)  A20_DIM_P01   A20_DIM_P04
+     C                   ENDSR
\ No newline at end of file

From e93ef3ee32671481dea8b328b1c4189a3a8cb791 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Fri, 24 May 2024 10:03:51 +0200
Subject: [PATCH 18/22] Cleanup

---
 .../rpgparser/interpreter/ExpressionEvaluation.kt    |  1 -
 .../rpgparser/interpreter/internal_interpreter.kt    |  1 -
 .../kotlin/com/smeup/rpgparser/interpreter/logs.kt   | 12 ++++++------
 3 files changed, 6 insertions(+), 8 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
index 5db32776a..907ccb899 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt
@@ -52,7 +52,6 @@ class ExpressionEvaluation(
         if (systemInterface.getAllLogHandlers().isEmpty()) return action()
 
         val programName = MainExecutionContext.getExecutionProgramName()
-        val loggingContext = MainExecutionContext.getAnalyticsLoggingContext()
 
         val start = System.nanoTime()
         val value = action()
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
index 352eb99f9..193b8b380 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
@@ -331,7 +331,6 @@ open class InternalInterpreter(
 
         val initElapsed = (System.nanoTime() - start).nanoseconds
 
-        val analyticsContext = MainExecutionContext.getAnalyticsLoggingContext()
         renderLogInternal { LazyLogEntry.produceInformational(logSourceProducer, "SYMTBLINI", "END") }
         renderLogInternal { LazyLogEntry.produceStatement(logSourceProducer, "SYMTBLINI", "END") }
         renderLogInternal { LazyLogEntry.producePerformanceAndUpdateAnalytics(logSourceProducer, ProgramUsageType.SymbolTable, SymbolTableAction.INIT.name, initElapsed) }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
index 79ccb6aef..4c9fe7b75 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/logs.kt
@@ -221,12 +221,12 @@ class LazyLogEntry(val entry: LogEntry, val renderContent: (sep: String) -> Stri
          * Create a new LazyLogEntry for the PERF channel
          * @see LogChannel
          */
-        fun producePerformance(source: LogSourceProvider, entity: String, elapsed: Duration): LazyLogEntry {
-            val entry = LogEntry(source, LogChannel.PERFORMANCE.getPropertyName(), entity)
-            return LazyLogEntry(entry) {
-                elapsed.inWholeMicroseconds.toString()
-            }
-        }
+//        fun producePerformance(source: LogSourceProvider, entity: String, elapsed: Duration): LazyLogEntry {
+//            val entry = LogEntry(source, LogChannel.PERFORMANCE.getPropertyName(), entity)
+//            return LazyLogEntry(entry) {
+//                elapsed.inWholeMicroseconds.toString()
+//            }
+//        }
 
         /**
          * Create a new LazyLogEntry for the PERF channel and updates AnalyticsContext with its data

From 8ad5a645538b582ac7d07965c0aa19deb19de598 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Fri, 24 May 2024 13:55:46 +0200
Subject: [PATCH 19/22] Move SymbolTable logging logic

---
 .../execution/MainExecutionContext.kt         |   7 +
 .../rpgparser/interpreter/SymbolTable.kt      | 190 ++++++++++++------
 .../interpreter/internal_interpreter.kt       |  61 +-----
 3 files changed, 140 insertions(+), 118 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt
index 6c7f4dba5..ea297b7e5 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/execution/MainExecutionContext.kt
@@ -175,6 +175,11 @@ object MainExecutionContext {
         context.get()?.renderLog(renderer)
     }
 
+    /**
+     * Checks if logging is enabled
+     */
+    val isLoggingEnabled get() = context.get()?.isLoggingEnabled ?: false
+
     /***
      * Get DB File Factory
      */
@@ -218,6 +223,8 @@ data class Context(
     fun renderLog(renderer: LazyLogEntry) {
         logHandlers.renderLog(renderer)
     }
+
+    val isLoggingEnabled get() = logHandlers.isNotEmpty()
 }
 
 data class ParsingProgram(val name: String) {
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTable.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTable.kt
index 966367a19..36cb91a56 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTable.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/SymbolTable.kt
@@ -16,6 +16,10 @@
 
 package com.smeup.rpgparser.interpreter
 
+import com.smeup.rpgparser.execution.MainExecutionContext
+import com.smeup.rpgparser.logging.ProgramUsageType
+import kotlin.time.Duration.Companion.nanoseconds
+
 class SymbolTable : ISymbolTable {
     private val values = LinkedHashMap<AbstractDataDefinition, Value>()
     private val names = mutableMapOf<String, AbstractDataDefinition>()
@@ -25,69 +29,38 @@ class SymbolTable : ISymbolTable {
 
     override var parentSymbolTable: ISymbolTable? = null
 
-    override operator fun get(data: AbstractDataDefinition): Value {
-        return when (data.scope.visibility) {
-            Visibility.Program -> (programSymbolTable as SymbolTable).getLocal(data)
-            Visibility.Local -> getLocal(data)
-            Visibility.Static -> (getStaticSymbolTable(data.scope.reference!!) as SymbolTable).getLocal(data)
-        }
-    }
-
-    private fun getLocal(data: AbstractDataDefinition): Value {
-        if (data is FieldDefinition) {
-            val containerValue = get(data.container)
-            return if (data.container.isArray()) {
-                TODO("We do not yet handle an array container")
-            } else if (data.declaredArrayInLine != null) {
-                ProjectedArrayValue.forData(containerValue as DataStructValue, data)
-            } else {
-                // Should be always a DataStructValue
-                if (containerValue is DataStructValue) {
-                    return coerce(containerValue[data], data.type)
-                } else if (containerValue is OccurableDataStructValue) {
-                    return coerce(containerValue.value()[data], data.type)
-                } else {
-                    throw IllegalStateException("The container value is expected to be a DataStructValue, instead it is $containerValue")
-                }
-            }
-        }
-        return values[data] ?: throw IllegalArgumentException("Cannot find searched value for $data")
-    }
+    override operator fun get(data: AbstractDataDefinition) =
+        if (MainExecutionContext.isLoggingEnabled) getWithLogging(data) else getInternal(data)
 
-    override operator fun get(dataName: String): Value {
-        val data = dataDefinitionByName(dataName)
-        if (data != null) {
-            return get(data)
-        }
-        // We did not find a top-level declaration with that name,
-        // looking among fields
-        for (topLevelValue in values) {
-            if (topLevelValue.key is DataDefinition) {
-                val field = (topLevelValue.key as DataDefinition).fields.firstOrNull {
-                    it.name.equals(dataName, ignoreCase = true) && it.canBeUsedUnqualified()
-                }
-                if (field != null) {
-                    return if (topLevelValue.key.type is ArrayType) {
-                        TODO("We do not yet handle top level values of array type")
-                    } else {
-                        (topLevelValue.value as DataStructValue)[field]
-                    }
-                }
-            }
-        }
-        throw IllegalArgumentException("Cannot find searchedValued for $dataName")
-    }
+    override operator fun get(dataName: String): Value =
+        if (MainExecutionContext.isLoggingEnabled) getWithLogging(dataName) else getInternal(dataName)
 
     override fun dataDefinitionByName(dataName: String): AbstractDataDefinition? {
         return names[dataName.uppercase()] ?: parentSymbolTable?.let { (parentSymbolTable as SymbolTable).names[dataName.uppercase()] }
     }
 
     override operator fun set(data: AbstractDataDefinition, value: Value): Value? {
-        return when (data.scope.visibility) {
+        val start = System.nanoTime()
+
+        val output = when (data.scope.visibility) {
             Visibility.Program -> (programSymbolTable as SymbolTable).setLocal(data, value)
             Visibility.Local -> setLocal(data, value)
             Visibility.Static -> (getStaticSymbolTable(data.scope.reference!!) as SymbolTable).setLocal(data, value)
         }
+
+        val elapsed = System.nanoTime() - start
+
+        val programName = MainExecutionContext.getExecutionProgramName()
+        MainExecutionContext.log(
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
+                { LogSourceData.fromProgram(programName) },
+                ProgramUsageType.SymbolTable,
+                SymbolTableAction.SET.name,
+                elapsed.nanoseconds
+            )
+        )
+
+        return output
     }
 
     private fun setLocal(data: AbstractDataDefinition, value: Value): Value? {
@@ -110,14 +83,18 @@ class SymbolTable : ISymbolTable {
                 return ProjectedArrayValue.forData(containerValue as DataStructValue, data)
             } else {
                 // Should be always a DataStructValue
-                if (containerValue is DataStructValue) {
-                    containerValue.set(data, value.forType(data.type))
-                    return coerce(containerValue[data], data.type)
-                } else if (containerValue is OccurableDataStructValue) {
-                    containerValue.value().set(data, value.forType(data.type))
-                    return coerce(containerValue.value()[data], data.type)
-                } else {
-                    throw IllegalStateException("The container value is expected to be a DataStructValue, instead it is $containerValue")
+                when (containerValue) {
+                    is DataStructValue -> {
+                        containerValue.set(data, value.forType(data.type))
+                        return coerce(containerValue[data], data.type)
+                    }
+                    is OccurableDataStructValue -> {
+                        containerValue.value().set(data, value.forType(data.type))
+                        return coerce(containerValue.value()[data], data.type)
+                    }
+                    else -> {
+                        throw IllegalStateException("The container value is expected to be a DataStructValue, instead it is $containerValue")
+                    }
                 }
             }
         } else {
@@ -142,4 +119,97 @@ class SymbolTable : ISymbolTable {
      * @return if is empty
      * */
     override fun isEmpty() = values.isEmpty()
+
+    private fun getInternal(data: AbstractDataDefinition): Value = when (data.scope.visibility) {
+        Visibility.Program -> (programSymbolTable as SymbolTable).getLocal(data)
+        Visibility.Local -> getLocal(data)
+        Visibility.Static -> (getStaticSymbolTable(data.scope.reference!!) as SymbolTable).getLocal(data)
+    }
+
+    private fun getInternal(dataName: String): Value {
+        val data = dataDefinitionByName(dataName)
+        if (data != null) {
+            return get(data)
+        }
+        // We did not find a top-level declaration with that name,
+        // looking among fields
+        return findInFields(dataName)
+    }
+
+    private fun getWithLogging(data: AbstractDataDefinition): Value {
+        val start = System.nanoTime()
+        val value = getInternal(data)
+        val elapsed = System.nanoTime() - start
+
+        val programName = MainExecutionContext.getExecutionProgramName()
+        MainExecutionContext.log(
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
+                { LogSourceData.fromProgram(programName) },
+                ProgramUsageType.SymbolTable,
+                SymbolTableAction.GET.name,
+                elapsed.nanoseconds
+            )
+        )
+
+        return value
+    }
+
+    private fun getWithLogging(dataName: String): Value {
+        val start = System.nanoTime()
+        val value = getInternal(dataName)
+        val elapsed = System.nanoTime() - start
+
+        val programName = MainExecutionContext.getExecutionProgramName()
+        MainExecutionContext.log(
+            LazyLogEntry.producePerformanceAndUpdateAnalytics(
+                { LogSourceData.fromProgram(programName) },
+                ProgramUsageType.SymbolTable,
+                SymbolTableAction.GET.name,
+                elapsed.nanoseconds
+            )
+        )
+
+        return value
+    }
+
+    private fun getLocal(data: AbstractDataDefinition): Value {
+        if (data is FieldDefinition) {
+            val containerValue = get(data.container)
+            return if (data.container.isArray()) {
+                TODO("We do not yet handle an array container")
+            } else if (data.declaredArrayInLine != null) {
+                ProjectedArrayValue.forData(containerValue as DataStructValue, data)
+            } else {
+                // Should be always a DataStructValue
+                when (containerValue) {
+                    is DataStructValue -> return coerce(containerValue[data], data.type)
+                    is OccurableDataStructValue -> return coerce(containerValue.value()[data], data.type)
+                    else -> {
+                        throw IllegalStateException("The container value is expected to be a DataStructValue, instead it is $containerValue")
+                    }
+                }
+            }
+        }
+
+        return values[data] ?: throw IllegalArgumentException("Cannot find searched value for $data")
+    }
+
+    private fun findInFields(dataName: String): Value {
+        values
+            .filterKeys { it is DataDefinition }
+            .forEach {
+                val field = (it.key as DataDefinition).fields.firstOrNull {
+                        field -> field.name.equals(dataName, ignoreCase = true) && field.canBeUsedUnqualified()
+                }
+                if (field != null) {
+                    return if (it.key.type is ArrayType) {
+                        TODO("We do not yet handle top level values of array type")
+                    } else {
+                        (it.value as DataStructValue)[field]
+                    }
+                }
+            }
+
+        throw IllegalArgumentException("Cannot find searchedValued for $dataName")
+    }
 }
diff --git a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
index 193b8b380..0b1e2bef6 100644
--- a/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
+++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/internal_interpreter.kt
@@ -148,8 +148,8 @@ open class InternalInterpreter(
 
     override fun dataDefinitionByName(name: String) = globalSymbolTable.dataDefinitionByName(name)
 
-    override operator fun get(data: AbstractDataDefinition) = if (logsEnabled()) getWithLogging(data) else globalSymbolTable[data]
-    override operator fun get(dataName: String) = if (logsEnabled()) getWithLogging(dataName) else globalSymbolTable[dataName]
+    override operator fun get(data: AbstractDataDefinition) = globalSymbolTable[data]
+    override operator fun get(dataName: String) = globalSymbolTable[dataName]
 
     open operator fun set(data: AbstractDataDefinition, value: Value) {
         require(data.canBeAssigned(value)) {
@@ -215,7 +215,7 @@ open class InternalInterpreter(
                     LazyLogEntry.produceAssignment(logSource, data, value)
                 }
                 // deny reassignment if data is a constant
-                if (logsEnabled()) setWithLogging(data, value) else globalSymbolTable.set(data, coerce(value, data.type))?.let {
+                globalSymbolTable.set(data, coerce(value, data.type))?.let {
                     if (data.const) error("${data.name} is a const and cannot be assigned")
                 }
             }
@@ -1179,61 +1179,6 @@ open class InternalInterpreter(
         val loggingContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return
         loggingContext.generateCompleteReport().forEach { entry -> renderLogInternal { entry } }
     }
-
-    private fun getWithLogging(data: String): Value {
-        val start = System.nanoTime()
-        val value = globalSymbolTable[data]
-        val elapsed = System.nanoTime() - start
-        val programName = interpretationContext.currentProgramName
-
-        renderLogInternal {
-            LazyLogEntry.producePerformanceAndUpdateAnalytics(
-                { LogSourceData.fromProgram(programName) },
-                ProgramUsageType.SymbolTable,
-                SymbolTableAction.GET.name,
-                elapsed.nanoseconds
-            )
-        }
-
-        return value
-    }
-
-    private fun getWithLogging(data: AbstractDataDefinition): Value {
-        val start = System.nanoTime()
-        val value = globalSymbolTable[data]
-        val elapsed = System.nanoTime() - start
-        val programName = interpretationContext.currentProgramName
-
-        renderLogInternal {
-            LazyLogEntry.producePerformanceAndUpdateAnalytics(
-                { LogSourceData(programName, data.startLine()) },
-                ProgramUsageType.SymbolTable,
-                SymbolTableAction.GET.name,
-                elapsed.nanoseconds
-            )
-        }
-
-        return value
-    }
-
-    private fun setWithLogging(data: AbstractDataDefinition, value: Value) {
-        fun setValue() {
-            globalSymbolTable.set(data, coerce(value, data.type))?.let {
-                if (data.const) error("${data.name} is a const and cannot be assigned")
-            }
-        }
-
-        val elapsed = measureNanoTime { setValue() }
-        val programName = interpretationContext.currentProgramName
-        renderLogInternal {
-            LazyLogEntry.producePerformanceAndUpdateAnalytics(
-                { LogSourceData(programName, data.startLine()) },
-                ProgramUsageType.SymbolTable,
-                SymbolTableAction.SET.name,
-                elapsed.nanoseconds
-            )
-        }
-    }
 }
 
 fun MutableMap<IndicatorKey, BooleanValue>.clearStatelessIndicators() {

From 9d604c0a66b9e1dbae96bbc3db36c7d20a75c906 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Fri, 24 May 2024 14:06:16 +0200
Subject: [PATCH 20/22] Update logging documentation

---
 docs/logging.md | 53 +++++++++++++++++++++++++++++--------------------
 1 file changed, 31 insertions(+), 22 deletions(-)

diff --git a/docs/logging.md b/docs/logging.md
index ba6625eab..b20672e76 100644
--- a/docs/logging.md
+++ b/docs/logging.md
@@ -201,10 +201,10 @@ The log records are generated at the end of statements block, measuring the
 time in microseconds.
 
 ```
-15:51:55.838 PERF   MULANGTC10      7       PLIST   elapsed 8.875us
-15:51:55.840 PERF   MULANGTC10      13      EVAL    elapsed 566us
-15:51:55.840 PERF   MULANGTC10      14      EVAL    elapsed 35.084us
-+---------------- header -----------------+--------+----- perf ----+
+13:21:41.347    PERF    MULANGTC10    11      DataRefExpr     60
+13:21:41.347    PERF    MULANGTC10    11      %CHAR           504
+13:21:41.347    PERF    MULANGTC10    11      PlusExpr        1048
++---------------- header -----------------+----- entity -----+-- time --+
 ```
 
 ## Parsing Channel PARS
@@ -243,33 +243,42 @@ of strategies used to locate a RPG/Java program.
 ## Analytics Channel ANALYTICS
 The analytics channel provides processed collected during the whole execution cycle. Information yield by this channel are derived by a LoggingContext where logging metadata are stored.
 
-Statement time analytics provide information about which statements were called during the program execution, how much time was spent totally to execute that statement and how many times each one was hit.
+Statement time analytics provide information about which statements and expressions were called during the program execution, how much time was spent totally to execute them and how many times each one was hit.
 
 ```
-12:25:35.612 ANALYTICS    MUTE10_10        STMT TIME    DISPLAY 204us   1
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    EXSR    450369us        1
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    SET     146us   1
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    TIME    3026us  2
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    DO      441230us        1
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    EVAL    3857us  2
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    ZADD    204600us        200000
-12:25:35.613 ANALYTICS    MUTE10_10        STMT TIME    SUBDUR  601us   1
-+------------- header ------------+--------+-------------------+----- analytics ------+
+12:42:44.064    ANALYTICS    T40_A20_P17        STMT TIME    MOVEA           7325609 200000
+12:42:44.065    ANALYTICS    T40_A20_P17        STMT TIME    EXSR            7458565 200000
+12:42:44.065    ANALYTICS    T40_A20_P17        STMT TIME    DO              9345378 2
+12:42:44.065    ANALYTICS    T40_A20_P17        STMT TIME    EVAL            4306    4
+12:42:44.065    ANALYTICS    T40_A20_P17        EXPR TIME    DataRefExpr     47253   200002
+12:42:44.066    ANALYTICS    T40_A20_P17        EXPR TIME    %TRIMR          92      1
+12:42:44.066    ANALYTICS    T40_A20_P17        EXPR TIME    StringLiteral   2       1
+12:42:44.066    ANALYTICS    T40_A20_P17        EXPR TIME    ArrayAccessExpr 42      1
+12:42:44.066    ANALYTICS    T40_A20_P17        EXPR TIME    IntLiteral      7       3
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    RPGLOAD         3027    1
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    PARSER          93840   1
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    CHKPTREE        514     1
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    AST             174884  1
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    LEXER           54853   1
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    PREPROP         5115    1
+12:42:44.066    ANALYTICS    T40_A20_P17        PARS TIME    RCONTEXT        161939  1
++---------- header ---------+------ prog ------+---------- entity ---------+- time -+- hit -+
 ```
 
-Symbol table analytics provide the same information of the statement analytics but referred to symbol table actions rather than statement execution.
+Symbol table analytics provide the same information of other analytics but referred to symbol table actions rather than statement execution.
 ```
-12:25:35.613 ANALYTICS    MUTE10_10        SYMTBL TIME    INIT    21429us    1
-12:25:35.613 ANALYTICS    MUTE10_10        SYMTBL TIME    LOAD    131us      1
-+------------- header ------------+--------+------------------+-- analytics --+
+12:42:44.066    ANALYTICS    T40_A20_P17        SYMTBL TIME  INIT            14457   1
+12:42:44.066    ANALYTICS    T40_A20_P17        SYMTBL TIME  LOAD            1051    1
+12:42:44.066    ANALYTICS    T40_A20_P17        SYMTBL TIME  GET             44663   400011
+12:42:44.066    ANALYTICS    T40_A20_P17        SYMTBL TIME  SET             164870  100007
++---------- header ---------+------ prog ------+---------- entity ---------+- time -+- hit -+
 ```
 
 There are also other analytics which provide their own informational data. Here are some examples:
 ```
-12:25:35.615 ANALYTICS    MUTE10_10        EXPR TIME       56195us    1300104
-12:25:35.615 ANALYTICS    MUTE10_10        LOG TIME        56177us    1300109
-12:25:35.615 ANALYTICS    MUTE10_10        PROGRAM TIME    1220526us
-+------------- header ------------+--------+---------------+--- analytics --+
+12:42:44.070    ANALYTICS                       LOG TIME                     61886   1900103
+12:42:44.070    ANALYTICS                       INTERPRETATION TIME          4706819 1
++---------- header ---------+------ prog ------+---------- entity ---------+- time -+- hit -+
 ```
 
 ## Error Channel ERR

From 6c84525a0508f52ff5243a80dab1a72ec5ccf419 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Fri, 24 May 2024 14:50:25 +0200
Subject: [PATCH 21/22] Disable afterSystemInterface

---
 .../test/kotlin/com/smeup/rpgparser/AbstractTest.kt   |  7 +++----
 .../rpgparser/evaluation/SmeupInterpreterTest.kt      | 11 ++---------
 2 files changed, 5 insertions(+), 13 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
index 816ad8d6d..1ef13acc7 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
@@ -246,15 +246,14 @@ abstract class AbstractTest {
      */
     protected fun String.outputOf(
         trimEnd: Boolean = true,
-        configuration: Configuration = Configuration(),
-        afterSystemInterface: (systemInterface: JavaSystemInterface) -> Unit = {}
-
+        configuration: Configuration = Configuration()
+//        afterSystemInterface: (systemInterface: JavaSystemInterface) -> Unit = {},
     ): List<String> {
         val messages = mutableListOf<String>()
         val systemInterface = JavaSystemInterface().apply {
             onDisplay = { message, _ -> messages.add(message) }
         }
-        afterSystemInterface.invoke(systemInterface)
+//        afterSystemInterface(systemInterface)
         executePgm(programName = this, systemInterface = systemInterface, configuration = configuration)
         return if (trimEnd) messages.map { it.trimEnd() } else messages
     }
diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
index bcb0cb3db..fe09da7f9 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
@@ -5,8 +5,6 @@ import com.smeup.rpgparser.AbstractTest
 import com.smeup.rpgparser.execution.Configuration
 import com.smeup.rpgparser.execution.ReloadConfig
 import com.smeup.rpgparser.execution.SimpleReloadConfig
-import com.smeup.rpgparser.logging.LogChannel
-import com.smeup.rpgparser.logging.consoleLoggingConfiguration
 import org.junit.Test
 import java.time.LocalDateTime
 import java.time.format.DateTimeFormatter
@@ -280,13 +278,8 @@ open class SmeupInterpreterTest : AbstractTest() {
 
     @Test
     fun executeT10_A60_P02() {
-        val expected = listOf<String>("C10_P1: MULANGT102")
-        assertEquals(expected, "smeup/T10_A60_P02".outputOf(
-            afterSystemInterface = { si ->
-                si.loggingConfiguration = consoleLoggingConfiguration(LogChannel.PERFORMANCE, LogChannel.ANALYTICS)
-            }
-        ))
-
+        val expected = listOf("C10_P1: MULANGT102")
+        assertEquals(expected, "smeup/T10_A60_P02".outputOf())
         assertFailsWith<Exception> {
             "smeup/T10_A60_P02F".outputOf()
         }

From 52c5ce16e729afbd922a54fb0c2012addeb54a36 Mon Sep 17 00:00:00 2001
From: Domenico <domenico.mancini@apuliasoft.com>
Date: Tue, 28 May 2024 11:58:10 +0200
Subject: [PATCH 22/22] Fix issue with afterSystemInterface

---
 .../test/kotlin/com/smeup/rpgparser/AbstractTest.kt    | 10 +++++++---
 .../smeup/rpgparser/evaluation/SmeupInterpreterTest.kt |  8 +++++++-
 2 files changed, 14 insertions(+), 4 deletions(-)

diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
index 1ef13acc7..16d022320 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/AbstractTest.kt
@@ -26,6 +26,7 @@ import com.smeup.rpgparser.parsing.ast.CompilationUnit
 import com.smeup.rpgparser.rpginterop.DirRpgProgramFinder
 import com.smeup.rpgparser.rpginterop.RpgProgramFinder
 import com.smeup.rpgparser.rpginterop.SourceProgramFinder
+import org.apache.logging.log4j.LogManager
 import java.io.File
 import java.io.PrintStream
 import kotlin.test.AfterTest
@@ -60,6 +61,9 @@ abstract class AbstractTest {
     fun afterTest() {
         System.setOut(defaultOut)
         System.setErr(defaultErr)
+
+        // Cleanup logging configurations injected at runtime
+        LogManager.shutdown()
     }
 
     /**
@@ -246,14 +250,14 @@ abstract class AbstractTest {
      */
     protected fun String.outputOf(
         trimEnd: Boolean = true,
-        configuration: Configuration = Configuration()
-//        afterSystemInterface: (systemInterface: JavaSystemInterface) -> Unit = {},
+        configuration: Configuration = Configuration(),
+        afterSystemInterface: (systemInterface: JavaSystemInterface) -> Unit = {}
     ): List<String> {
         val messages = mutableListOf<String>()
         val systemInterface = JavaSystemInterface().apply {
             onDisplay = { message, _ -> messages.add(message) }
         }
-//        afterSystemInterface(systemInterface)
+        afterSystemInterface(systemInterface)
         executePgm(programName = this, systemInterface = systemInterface, configuration = configuration)
         return if (trimEnd) messages.map { it.trimEnd() } else messages
     }
diff --git a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
index fe09da7f9..184735c89 100644
--- a/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
+++ b/rpgJavaInterpreter-core/src/test/kotlin/com/smeup/rpgparser/evaluation/SmeupInterpreterTest.kt
@@ -5,6 +5,8 @@ import com.smeup.rpgparser.AbstractTest
 import com.smeup.rpgparser.execution.Configuration
 import com.smeup.rpgparser.execution.ReloadConfig
 import com.smeup.rpgparser.execution.SimpleReloadConfig
+import com.smeup.rpgparser.logging.LogChannel
+import com.smeup.rpgparser.logging.consoleLoggingConfiguration
 import org.junit.Test
 import java.time.LocalDateTime
 import java.time.format.DateTimeFormatter
@@ -279,7 +281,11 @@ open class SmeupInterpreterTest : AbstractTest() {
     @Test
     fun executeT10_A60_P02() {
         val expected = listOf("C10_P1: MULANGT102")
-        assertEquals(expected, "smeup/T10_A60_P02".outputOf())
+        assertEquals(expected, "smeup/T10_A60_P02".outputOf(
+            afterSystemInterface = { si ->
+                si.loggingConfiguration = consoleLoggingConfiguration(LogChannel.PERFORMANCE, LogChannel.ANALYTICS)
+            }
+        ))
         assertFailsWith<Exception> {
             "smeup/T10_A60_P02F".outputOf()
         }