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 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..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 @@ -35,7 +35,7 @@ object MainExecutionContext { // default values in case jariko is not called from the command line program private val context: ThreadLocal by lazy { ThreadLocal() } private val noContextIdProvider: AtomicInteger by lazy { AtomicInteger() } - private val noContextAttributes: MutableMap by lazy { mutableMapOf() } + private val noContextAttributes: MutableMap by lazy { mutableMapOf() } private val noConfiguration: Configuration by lazy { Configuration() } private val noProgramStack: Stack by lazy { Stack() } private val noParsingProgramStack: Stack by lazy { Stack() } @@ -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 */ @@ -211,7 +216,6 @@ data class Context( DBFileFactory(it.nativeAccessConfig) } ) { - private val logHandlers: MutableList by lazy { systemInterface.getAllLogHandlers() } @@ -219,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/ExpressionEvaluation.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/interpreter/ExpressionEvaluation.kt index 78fbfb553..abe980392 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,8 @@ 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 @@ -30,8 +32,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 +48,103 @@ 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 start = System.nanoTime() + val value = action() + val elapsed = (System.nanoTime() - start).nanoseconds + + MainExecutionContext.log( + LazyLogEntry.producePerformanceAndUpdateAnalytics( + { LogSourceData(programName, expression.startLine()) }, + ProgramUsageType.Expression, + expression.loggableEntityName, + elapsed + ) + ) + + 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 +181,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 - 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 +203,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 +240,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 +273,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 +324,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 +347,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 +370,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 +441,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 +470,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 +531,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 +564,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 +586,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 +680,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 +715,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) } override fun eval(expression: SizeExpr): Value { @@ -770,4 +771,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 + return ConcreteArrayValue(listValue, left.elementType) + } } 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/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() private val names = mutableMapOf() @@ -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/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..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 @@ -21,7 +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.AnalyticsLoggingContext +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 @@ -149,7 +149,6 @@ 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] open operator fun set(data: AbstractDataDefinition, value: Value) { @@ -157,8 +156,10 @@ open class InternalInterpreter( "${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,7 +211,7 @@ 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 @@ -228,7 +229,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 +247,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,20 +331,18 @@ open class InternalInterpreter( val initElapsed = (System.nanoTime() - start).nanoseconds - MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableDuration(AnalyticsLoggingContext.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 - MainExecutionContext.getAnalyticsLoggingContext()?.recordSymbolTableDuration(AnalyticsLoggingContext.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 { @@ -399,8 +402,6 @@ open class InternalInterpreter( ) } } - - onExecutionEnd() }.onFailure { if (it is ReturnException) { status.returnValue = it.returnValue @@ -444,13 +445,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 +537,7 @@ open class InternalInterpreter( compilationUnit: CompilationUnit, line: String ) { + val programName = interpretationContext.currentProgramName muteAnnotations.forEach { it.resolveAndValidate(compilationUnit) when (it) { @@ -561,12 +559,7 @@ open class InternalInterpreter( } renderLogInternal { - val logSource = { - LogSourceData( - this.interpretationContext.currentProgramName, - it.startLine() - ) - } + val logSource = { LogSourceData(programName, it.startLine()) } LazyLogEntry.produceMute(it, logSource, value) } @@ -603,12 +596,7 @@ open class InternalInterpreter( is MuteFailAnnotation -> { val message = it.message.evalWith(expressionEvaluation) renderLogInternal { - val logSource = { - LogSourceData( - this.interpretationContext.currentProgramName, - it.startLine() - ) - } + val logSource = { LogSourceData(programName, it.startLine()) } LazyLogEntry.produceMute(it, logSource, message) } systemInterface.addExecutedAnnotation( @@ -761,13 +749,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 @@ -787,8 +771,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) @@ -796,18 +778,9 @@ open class InternalInterpreter( else -> expression.evalWith(expressionEvaluation) } - val elapsed = System.nanoTime() - start - - MainExecutionContext.getAnalyticsLoggingContext()?.recordExpressionDuration(elapsed.nanoseconds) - renderLogInternal { - val logSource = { - LogSourceData( - this.interpretationContext.currentProgramName, - expression.startLine() - ) - } - LazyLogEntry.produceExpression(logSource, expression, value) - } + val programName = this.interpretationContext.currentProgramName + val sourceProvider = { LogSourceData(programName, expression.startLine()) } + renderLogInternal { LazyLogEntry.produceExpression(sourceProvider, expression, value) } return value } @@ -1008,12 +981,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))) } } @@ -1024,11 +997,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))) } } @@ -1162,12 +1135,9 @@ 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()) } + val loggingContext = MainExecutionContext.getAnalyticsLoggingContext() renderLogInternal { statement.getResolutionLogRenderer(sourceProducer) } @@ -1185,7 +1155,7 @@ open class InternalInterpreter( statement.execute(this) }.nanoseconds - MainExecutionContext.getAnalyticsLoggingContext()?.recordStatementDuration(statement.loggableEntityName, executionTime) + loggingContext?.recordStatementExecution(programName, statement.loggableEntityName, executionTime) if (statement is LoopStatement) { renderLogInternal { @@ -1202,18 +1172,12 @@ open class InternalInterpreter( renderLogInternal { statement.getStatementLogRenderer(sourceProducer, "END") } } - renderLogInternal { LazyLogEntry.producePerformance(sourceProducer, statement.loggableEntityName, executionTime) } + renderLogInternal { LazyLogEntry.producePerformanceAndUpdateAnalytics(sourceProducer, ProgramUsageType.Statement, statement.loggableEntityName, executionTime) } } - private fun onExecutionEnd() { - val logSource = { LogSourceData(this.interpretationContext.currentProgramName, "") } - - val loggingContext = MainExecutionContext.getAnalyticsLoggingContext() - loggingContext ?: return - - loggingContext.generateCompleteReport(logSource).forEach { - entry -> renderLogInternal { entry } - } + override fun onInterpretationEnd() { + val loggingContext = MainExecutionContext.getAnalyticsLoggingContext() ?: return + loggingContext.generateCompleteReport().forEach { entry -> renderLogInternal { entry } } } } 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..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 @@ -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 @@ -41,6 +42,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) @@ -219,13 +221,26 @@ 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 { +// 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 + * @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) { - buildString { - append("elapsed ") - append(elapsed.toString(DurationUnit.MICROSECONDS)) - } + elapsed.inWholeMicroseconds.toString() } } @@ -483,7 +498,8 @@ fun List.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 b43bf4708..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 @@ -99,7 +100,7 @@ class RpgProgram(val cu: CompilationUnit, val name: String = " val elapsed = measureNanoTime { @@ -154,8 +155,13 @@ class RpgProgram(val cu: CompilationUnit, val name: String = " = hashMapOf() - private val symbolTableTimeUsage: EnumMap = 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 - ) + private var interpretationTimeMeasurement = UsageMeasurement.new() + +// private val statementScope = Stack() +// private val expressionScope = Stack() + + /** + * 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. + */ +// fun enterCompositeStatement(entity: String) { statementScope.push(entity) } + + /** + * Records the end of the execution of a CompositeStatement. + */ +// 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. + */ + fun recordRenderingDuration(time: Duration) { + renderingTimeMeasurement = renderingTimeMeasurement.hit(time) } - fun recordStatementDuration(name: String, executionTime: Duration) { - val entry = timeUsageByStatement.getOrPut(name) { UsageMeasurement.new() } - timeUsageByStatement[name] = UsageMeasurement( - duration = entry.duration + executionTime, - hit = entry.hit + 1 - ) + /** + * Records interpretation duration. + */ + fun recordInterpretationDuration(time: Duration) { + interpretationTimeMeasurement = interpretationTimeMeasurement.hit(time) } - fun generateCompleteReport(source: LogSourceProvider): List { - val timeUsageEntries = generateTimeUsageByStatementReportEntries(source) - val symTableEntries = generateSymbolTableTimeUsageReportEntries(source) - val expressionEntry = generateExpressionReportEntry(source) - val logTimeEntry = generateLogTimeReportEntry(source) - val programExecutionEntry = generateProgramReportEntry(source) - - return timeUsageEntries + symTableEntries + expressionEntry + logTimeEntry + programExecutionEntry - } - - private fun generateTimeUsageByStatementReportEntries(source: LogSourceProvider): List { - 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 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) } - } - - private fun generateSymbolTableTimeUsageReportEntries(source: LogSourceProvider): List { - return symbolTableTimeUsage.toList().map { - val action = it.first - val duration = it.second.duration - val hit = it.second.hit - val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "SYMTBL TIME") - LazyLogEntry(entry) { sep -> - "${action.name}$sep${duration.toString(DurationUnit.MICROSECONDS)}${sep}$hit" - } + /** + * Records the execution of a statement. + * @see ILoggableStatement + */ + 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) + + /** + * 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. + * @see LazyLogEntry + */ + fun generateCompleteReport(): List { + val statementEntries = mutableListOf() + val expressionEntries = mutableListOf() + val symbolTableEntries = mutableListOf() + val parsingEntries = mutableListOf() + + programUsageTable.asSequence().forEach { + val program = it.key + val statement = programUsageTable.generateStatementLogEntries(program) + val expression = programUsageTable.generateExpressionLogEntries(program) + val symTable = programUsageTable.generateSymbolTableLogEntries(program) + val parsing = programUsageTable.generateParsingLogEntries(program) + + statementEntries.addAll(statement) + expressionEntries.addAll(expression) + symbolTableEntries.addAll(symTable) + parsingEntries.addAll(parsing) } - } - private fun generateExpressionReportEntry(source: LogSourceProvider): LazyLogEntry { - val duration = expressionTimeMeasurement.duration - val hit = expressionTimeMeasurement.hit + val logTimeEntry = generateLogTimeReportEntry() + val interpretationTimeEntry = generateInterpretationReportEntry() - val entry = LogEntry(source, LogChannel.ANALYTICS.getPropertyName(), "EXPR TIME") - return LazyLogEntry(entry) { sep -> - "${duration.toString(DurationUnit.MICROSECONDS)}$sep$hit" - } + return statementEntries + expressionEntries + symbolTableEntries + parsingEntries + logTimeEntry + interpretationTimeEntry } - 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" + "$sep${duration.inWholeMicroseconds}$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 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${duration.inWholeMicroseconds}$sep$hit" + } } } \ 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..c3a495adc --- /dev/null +++ b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/logging/ProgramUsageTable.kt @@ -0,0 +1,210 @@ +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 + +enum class ProgramUsageType { + Statement, + Expression, + SymbolTable, + Parsing, + LogRendering, + Interpretation +} + +/** + * Collects the usage information about the main parts of the program. + */ +class ProgramUsageStats { + val statements: HashMap by lazy { hashMapOf() } + val expressions: HashMap by lazy { hashMapOf() } + val symbolTableActions: EnumMap by lazy { + EnumMap(SymbolTableAction::class.java) + } + val parsingSteps: HashMap by lazy { hashMapOf() } +// val nestedStatements: HashMap by lazy { hashMapOf() } +// val nestedExpressions: HashMap by lazy { hashMapOf() } +} + +typealias ProgramUsageTable = HashMap + +/** + * 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 a nested statement. + * @see ILoggableStatement + */ +// fun ProgramUsageTable.recordNestedStatement(program: String, scope: Stack, 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, 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 + */ +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) +} + +/** + * 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 + */ +fun ProgramUsageTable.generateStatementLogEntries(program: String): Sequence { + 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.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "STMT TIME") + LazyLogEntry(entry) { sep -> + "$statementName$sep${duration.inWholeMicroseconds}${sep}$hit" + } + } +} + +/** + * Generate an ANALYTICS nested statement usage report in the form of a sequence of LazyLogEntry. + * @see LazyLogEntry +// */ +// fun ProgramUsageTable.generateNestedStatementLogEntries(program: String): Sequence { +// 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 { +// 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 + */ +fun ProgramUsageTable.generateExpressionLogEntries(program: String): Sequence { + 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.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "EXPR TIME") + LazyLogEntry(entry) { sep -> + "$exprName$sep${duration.inWholeMicroseconds}${sep}$hit" + } + } +} + +/** + * Generate an ANALYTICS symbol table usage report in the form of a sequence of LazyLogEntry. + * @see LazyLogEntry + */ +fun ProgramUsageTable.generateSymbolTableLogEntries(program: String): Sequence { + 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.fromProgram(program) }, LogChannel.ANALYTICS.getPropertyName(), "SYMTBL TIME") + LazyLogEntry(entry) { sep -> + "$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 { + 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/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 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/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 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 d0113f46c..08a44cda5 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 } 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 24bf0da2d..81472c7ad 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/facade/RpgParserFacade.kt b/rpgJavaInterpreter-core/src/main/kotlin/com/smeup/rpgparser/parsing/facade/RpgParserFacade.kt index 7ea84e484..75f80902b 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 @@ -29,6 +29,8 @@ import com.smeup.rpgparser.interpreter.LazyLogEntry import com.smeup.rpgparser.interpreter.LogSourceData import com.smeup.rpgparser.interpreter.StatementReference import com.smeup.rpgparser.interpreter.line +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 @@ -202,7 +204,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")) @@ -221,7 +223,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")) @@ -239,7 +241,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 } @@ -264,7 +266,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): MuteParser.MuteLineContext { @@ -325,7 +327,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 } @@ -363,7 +365,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) @@ -385,7 +387,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 @@ -443,7 +445,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 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 ca2b2ca7c..e54633c05 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 e8731aabb..0306261c3 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 @@ -1033,7 +1033,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 14531caf7..25b3dfa26 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 @@ -320,12 +320,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) } } 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 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..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() } /** @@ -240,13 +244,20 @@ 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 { + protected fun String.outputOf( + trimEnd: Boolean = true, + configuration: Configuration = Configuration(), + afterSystemInterface: (systemInterface: JavaSystemInterface) -> Unit = {} + ): List { val messages = mutableListOf() val systemInterface = JavaSystemInterface().apply { onDisplay = { message, _ -> messages.add(message) } } + 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 b383396bf..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 @@ -278,9 +280,12 @@ open class SmeupInterpreterTest : AbstractTest() { @Test fun executeT10_A60_P02() { - val expected = listOf("C10_P1: MULANGT102") - assertEquals(expected, "smeup/T10_A60_P02".outputOf()) - + val expected = listOf("C10_P1: MULANGT102") + assertEquals(expected, "smeup/T10_A60_P02".outputOf( + afterSystemInterface = { si -> + si.loggingConfiguration = consoleLoggingConfiguration(LogChannel.PERFORMANCE, LogChannel.ANALYTICS) + } + )) assertFailsWith { "smeup/T10_A60_P02F".outputOf() } 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, expected: String) { 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() { 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..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 @@ -16,4 +16,36 @@ 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) + } + + @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