Overview
Oberon RTS provides mechanisms to monitor the running system, including the control programs and processes:
For development and actual usage:
- Run-time error detection, handling, and reporting: traps and aborts
For development:
- Keeping track of certain process state data, such as the procedure call stack, to be used for finding and fixing causes of run-time errors.
- Measuring the performance, such as process run-time values, to be used to assess the efficiency and feasibility of the running system.
Run-time Errors
See Run-time Errors.
Run-time errors are logged, to allow the inspection of error causes and the corresponding system’s responses by its error handling on a timeline.
Example log output: ASSERT violation (trap 7):
2021-12-20 04:00:16 TRAP 7 in proc t1 at pos 601 in TestErrors at 000198F8
2021-12-20 04:00:16 SYS RESET: reset all procs.
2021-12-20 04:00:16 PROC RST: adt 2
2021-12-20 04:00:16 PROC RST: gc 1
2021-12-20 04:00:16 PROC RST: t1 4
2021-12-20 04:00:16 PROC RST: cmd 3
2021-12-20 04:00:21 SYS OK SCR: 00001000Stack Overflow Monitor
Apart from its role in the context of run-time error detection, the stack overflow monitor also keeps track of the actual stack memory used by each process. Determining the needed stack space for each process is a critical design decision for a control program. The actually used stack space can be displayed using System.ShowProcesses (see below).
Monitoring stack overflow in software, while possible, would come at a substantial processing overhead (and a compiler change if we want to do this systematically). Therefore, Oberon RTS uses a hardware device in the FPGA. Hence, apart from setting the correct monitoring limits, and keeping track of the actually used stack space, upon coroutine transfer, there is no software overhead.
Calltrace
Module Calltrace, together with a hardware device in the FPGA, provides the functionality to print out a procedure call trace, that is, the stack of procedure calls as they occurred until the point where Calltrace.Trace is called.
Of course, such a stack needs to be maintained for each process separately. During development it’s helpful to print this call trace when encountering a run-time error.
The call trace stack is maintained by the hardware device in the FPGA. Apart from switching between the separate stacks upon coroutine transfer, there is no overhead in the software for this functionality.
Example: simple call procedure chain from a command, with an ASSERT violation in the last called procedure. Each called procedure calls Calltrace.Trace:
call trace stack: 3 id: 50
TestCall1 00018B1C 0000000C 3
Cmds 00012BD0 000004EC 315
Cmds 00012CF8 00000614 389
Cmds 00012C70 0000058C 355
max depth: 13
call trace stack: 3 id: 51
TestCall2 0001897C 0000000C 3
TestCall1 00018B20 00000010 4
Cmds 00012BD0 000004EC 315
Cmds 00012CF8 00000614 389
Cmds 00012C70 0000058C 355
max depth: 13
2021-12-20 05:05:05 TRAP 7 in proc cmd at pos 90 in TestCall3 at 000187D8
call trace stack: 3 id: 99
TestCall3 000187D8 00000008 2
TestCall2 00018980 00000010 4
TestCall1 00018B20 00000010 4
Cmds 00012BD0 000004EC 315
Cmds 00012CF8 00000614 389
Cmds 00012C70 0000058C 355
max depth: 15
2021-12-20 05:05:05 SYS RESET: reset all procs.
2021-12-20 05:05:05 PROC RST: adt 2
2021-12-20 05:05:05 PROC RST: gc 1
2021-12-20 05:05:05 PROC RST: cmd 3
2021-12-20 05:05:10 SYS OK SCR: 00001000Note that the Calltrace.Trace output is not part of the log. Direct log printing was enabled to see the log entries amid the trace output.
The numbers printed for each trace entry correspond to the BL instruction for the call done, first the absolute address, second the module-local address, third the module-local line of assembly code.
Process Monitor
Module ProcMonitor, together with a hardware device in the FGPA, provides the functionality to measure
- the time spent in each phase of the scheduler, Evaluation and Execution, and
- the time each process uses for its execution.
Measuring the run-times of the two phases is done over a sampling period of one second, recording the maximum value with each pass through Evaluation and Execution, respectively. These values can be inspected using System.Watch.
Measuring the processes’ run-time records the value of the latest run, plus the maximum ever used. These values can be inspected using System.ShowProcesses.
System.ShowProcesses
For the idle system, running only the system processes:
id ty pr tm n st rt rtm ovfl stk adr size hot used unused
adt 0 0 7 2 6 10 196 0 0000F0EC 256 0 120 136
gc 0 0 7 1 6 10 11 0 00014BFC 512 0 40 472
cmd 0 3 4 3 3 497 631 0 0006C000 15872 512 1636 14236
scheduler 0006FE00 512 0 92 420
timers: t0: 5 t1: 10 t2: 20 t3: 50 t4: 100 t5: 200 t6: 500 t7: 1000- id: process id,
adt= audit,gc= garbage collector,cmd= command handler - ty: type, such as system, or essential
- tm: timer used (if timed process)
- n: number in scheduler list
- st: status, such as timed, ready, or delayed
- rt: latest run-time, in microseconds
- rtm: max run-time, in microseconds
- ovfl: number of overflows detected
- stk adr: stack address
- size: stack size, in bytes
- hot: stack hot zone size, in bytes
- used: stack memory used, in bytes
- unused: stack memory unused, in bytes
- timers: timer periods, in milliseconds
Note the special entry for the scheduler, which just a coroutine, not a full-blown process.
System.Watch
For the idle system, running only the system processes:
Clock freq 42857142
Total RAM 524288
Modules space 442368 100224 22%
Heap space 65536 4928 7%
Disk sectors 65536 229 0%
Procs 3
MemLim 00080000
stackOrg 00070000
stackSize 00004000 16384
GC limit 49152
Eval 9 12
Exec 10 97820
Eval/Exec 933-
Eval: the latest sampling of the run-time, and the maximum ever sampling, of the Evaluation phase, in microseconds
-
Exec: the latest sampling of the run-time, and the maximum ever sampling, of the Execution phase, in microseconds
-
Eval/exec: the latest percentage of the Evaluation of the Execution phase, in percent * 10
Note the equality of the maximum run-time of process cmd, above, and of the Execution phase (plus/minus two microseconds due to the control logic).
With Some Load
With an idle system, the value Eval/Exec of 933, corresponding to 93.3%, is high, because the three system processes don’t put sufficient load onto the Execution phase. When loading the system with 15 processes (the system processes plus 12 test processes), the Evaluation phase’s run-time goes down to a more reasonable 8.7%.
System.ShowProcesses
id ty pr per n st rt rtm ovfl stk adr size hot used unused
p3 1 0 75000 7 6 102 325 0 00018D90 256 32 100 156
p2 1 0 5000 6 6 96 452 0 00018C90 256 32 100 156
p1 1 0 30000 5 6 249 446 0 00018B90 256 32 100 156
p0 1 0 40000 4 6 134 363 0 00018A90 256 32 100 156
adt 0 0 1000000 2 6 7 223 0 0000F410 256 0 164 92
gc 0 0 1000000 1 6 7 8 0 0001403C 512 0 40 472
p7 1 1 15000 11 6 77 490 1 00019190 256 32 100 156
p6 1 1 75000 10 6 32 344 1 00019090 256 32 100 156
p5 1 1 55000 9 6 172 357 1 00018F90 256 32 100 156
p4 1 1 20000 8 6 242 407 1 00018E90 256 32 100 156
p11 1 2 95000 15 6 128 414 0 00019590 256 32 100 156
p10 1 2 20000 14 6 140 395 2 00019490 256 32 100 156
p9 1 2 70000 13 6 255 382 2 00019390 256 32 100 156
p8 1 2 70000 12 6 45 363 2 00019290 256 32 100 156
cmd 0 3 100000 3 3 9 97802 0 0006C000 15872 512 1900 13972
scheduler 0006FE00 512 0 284 228
System.Watch
Clock freq 42857142
Total RAM 524288
Modules space 442368 106944 24%
Heap space 65536 11808 18%
Disk sectors 65536 229 0%
Procs 15
MemLim 00080000
stackOrg 00070000
stackSize 00004000 16384
GC limit 49152
Eval 35 40
Exec 409 97803
Eval/Exec 87 0With some more substantial processing by the test processes, the Eval/Exec value will even decrease to about 2% (scheduler overhead).