The interpreter provides a logging facility to trace the RPG program execution. To enable the log functionality it is required to specify the configuration file using the -lc or --log-configuration on the runner command line, the muterunner command line or for any other tool.
The logging permits to monitor the interpreter behaviour at the runtime. The logging messages are is subdivided in channels, each one designed to capture a specific aspect of the interpreter.
The output consists of a set of data records, with a fixed header segment with common data and a variable data segment specific for each channel.
The values of the record are separated by a character specified in the configuration file. This permits to easily process the resulting logs as CSV files or using comman line tools such as cut.
The available channels are:
- Data: monitors the accesses to the variables.
- Expression: traces the expressions encountered during the program execution.
- Statement: provides information about the statements executed.
- Loop: captures the loop execution including the number of iterations.
- Performance: measures the execution time.
- Parsing: measures parsing phase time.
- Resolution: provides information about the process to identify the routines or programs to invoke.
- Error: provides information about error event occurred during the whole cycle of program interpretation.
- Analytics provides information about higher level data collected during the whole cycle of program interpretation.
The log system is modeled on the concept of channels as previously mentioned. Each channel is defined in the LogChannel enum as a variant. In order to handle logs for a specific channel a specialization of the abstract class LogHandler must be implemented and provided by the LogHandlerFactory.
LogHandlers are not strictly bound to channels. This means that more handlers can be defined to serve more specific needs if needed (for example logging debug information). Handlers defined with this mechanism can then be attached to the SystemInterface manually.
Each log line is fired by rendering a LazyLogEntry.
These are data classes that contain:
- A
LogEntrywhich provides information about the source of the log and it's nature (scopeandaction) - A
renderContentfunction
java -jar /home/<user>/git-projects/jariko/rpgJavaInterpreter-core/build/libs/rpgJavaInterpreter-core-all.jar -lc /home/<user>/jariko_rpg/logging.config /home/<user>/jariko_rpg/X1_X21_03C.rpgle- the rpgJavaIntepreter-core-all.jar required can be generated by ./gradlew fatJar command, see the development guide
- it could be necessary to run above 'java -jar...' command directly from .rpgle container directory, or tell the interpreter the Program Search Directories via the the -psd start opition
You can enable logging also in case of you want switch on the "mutes" interpretation.
java -jar /home/<user>/git-projects/jariko/rpgJavaInterpreter-core/build/libs/rpgJavaInterpreter-core-mute-all.jar -lc /home/<user>/jariko_rpg/logging.config /home/<user>/jariko_rpg/X1_X21_03C.rpgle- the rpgJavaInterpreter-core-mute-all.jar required can be generated by ./gradlew fatMuteJar command, see the development guide
The logging configuration file is a plain text file containing the parameters to enable/disable the channels and set the output device.
#
# Logging configuration file
#
logger.data.separator = \t
logger.date.pattern = HH:mm:ss.SSS
logger.file.path = /var/log/smeup-rpg
logger.file.name = log.log
data.level = all
data.output = console
loop.level = all
loop.output = console
expression.level = all
expression.output = console
statement.level = all
statement.output = file
performance.level = all
performance.output = console
resolution.level = off
resolution.output = console
parsing.level = off
parsing.output = console
error.level = off
error.output = console
The value specified in logger.data.separator is the character used to separate the values within a record.
Each record has contains a timestamp in the logger.date.pattern allows to specify the format of the data.
The logging allows to redirect the output to the console or to file. In case of file the parameters logger.file.path and logger.file.name allow to set the path and the filename of the log file.
The channel configuration consist of two values: level and output.
-
The level allows to enable or disable the channel, the possible values are all and off.
-
The output parameter specifies where the log will be redirected, in case is set to console, the logging information are written on the screen otherwise if set ot file the data will be appended to the file specified by logger.file.path and logger.file.name.
If you don't want to pass the configuration to the logging system using a file, you could use the consoleLoggingConfiguration or the fileLoggingConfiguration fun combined with the LogChannel enum.
For example:
val si = JavaSystemInterface(consoleLoggingConfiguration(LogChannel.EXPRESSION, LogChannel.PERFORMANCE))
or
val si = JavaSystemInterface(fileLoggingConfiguration(File("/home/pippo", "example.log"), LogChannel.EXPRESSION, LogChannel.PERFORMANCE))
Each log record consists of a fixed header containing the common data and a variable data segment which depends on the channel.
<TIMESTAMP><S><CHANNEL><S><PROGRAM><S><LINE><S><ACTION><S><CHANNEL SPECIFIC>
+------------------ header ------------------------------+----- data ------+
The header contains the following data:
- TIMESTAMP timestamp of the record
- PROGRAM name of the program, if available
- LINE the line of code, if available, or lines number of source code
- CHANNEL a mnemonic name of the channel
The S represent the separator character specified in the configuration.
The data channel monitors the accesses to the variables during the program execution.
14:53:47.263 DATA MUTE10_10 16 ASSIGN $V = 1 was: 0
+------------ header ---------------+-------+--- data ----+
The log record collects the initial value zero in this case and the new value assigned by a statement. In the example above the value of variable V has an initial value of 0 (zero) and assume the value of 1.
The statement channel captures information about the statement executed.
15:04:57.031 STMT MUTE10_10 47 EXEC EVAL $TIMMS = $TIMMS / 1000
+-------------- header ---------------+------+-------- statement ---------+
In the example above the record contains the statement executed EVAL $TIMMS = $TIMMS / 1000.
Some statements might also emit proper and more specific information in the data section of the log entry.
The statement channel also tracks the start and the end of a program or subroutine.
15:16:28.859 STMT MUTE10_10 START INTERPRETATION
15:04:57.041 STMT MUTE10_10 END INTERPRETATION
+-------------- header ---------------+--------+---- stmt ----+
The expression channel collect all the expressions encountered during the program execution.
15:59:20.546 EXPR MULANGTC10 12 EVAL C10_P2 = 1 true
+-------------------- header ----------------+---- expr ----+----+
The loop channel captures the execution of loops. Two log records are created, the first when the loop starts and second when the loop exits. The end loop record include the number of cycles actually executed.
10:01:16.243 LOOP MUTE10_10 39 START DO
10:01:16.631 LOOP MUTE10_10 39 END DO 100000
+--------------- header -------------+--- loop ---+------+
Please note that statements like LEAVE may affect the number of cycles actually executed.
The performance channel measures the execution time of statements. The log records are generated at the end of statements block, measuring the time in microseconds.
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 --+
The parsing channel measures the parsing time needed to build AST. The log records related to the end of a parsing phase provide also the elapsed time information.
12:03:32.724 PARS MUTE10_10 START RPGLOAD
12:03:32.730 PARS MUTE10_10 56 END RPGLOAD elapsed 2936us
12:03:32.730 PARS MUTE10_10 START LEXER
12:03:32.778 PARS MUTE10_10 END LEXER elapsed 47015us
12:03:32.778 PARS MUTE10_10 START PARSER
12:03:32.883 PARS MUTE10_10 END PARSER elapsed 104924us
12:03:32.883 PARS MUTE10_10 START RCONTEXT
12:03:33.118 PARS MUTE10_10 END RCONTEXT elapsed 234507us
12:03:33.118 PARS MUTE10_10 START CHKPTREE
12:03:33.120 PARS MUTE10_10 END CHKPTREE elapsed 1681us
12:03:33.121 PARS MUTE10_10 START AST
12:03:33.306 PARS MUTE10_10 END AST elapsed 185138us
+--------------- header ----------------+---------+---- parse ----+----- time -----+
The resolution channel provides information about the action taken in order to resolve a program. When the interpreter starts, the RESL channel logs the list of strategies used to locate a RPG/Java program.
12:57:47.387 RESL directory: ./resources/test/performance
12:57:47.389 RESL directory: ./resources
15:47:40.824 RESL T10_A60_P02 8 CALL "MULANGTC10"
+------------ header -------------+-------------- resolution --------------+
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 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: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 other analytics but referred to symbol table actions rather than statement execution.
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:42:44.070 ANALYTICS LOG TIME 61886 1900103
12:42:44.070 ANALYTICS INTERPRETATION TIME 4706819 1
+---------- header ---------+------ prog ------+---------- entity ---------+- time -+- hit -+
The error channel catches the error events (instances of com.smeup.rpgparser.execution.ErrorEvent).
These events are particularly meaningful during the program syntax checking, below we can see an example.
As you can see, the ErrorEvent is shown through its string representation.
10:05:03.612 ERR T10_A60_P02 4 ErrorEvent(error=java.lang.IllegalStateException: token recognition error at: 'Error', errorEventSource=Parser, absoluteLine=4, sourceReference=SourceReference(sourceReferenceType=Program, sourceId=T10_A60_P02, relativeLine=4, position=Position(start=Line 4, Column 5, end=Line 4, Column 5)), fragment= Error)
For further information about the ErrorEvent see the kotlin-doc in Configuration.kt