Intel Simics hardware models generally output log messages for various kinds of events. The simulator's log system offers a very powerful system for configuring which log messages to see - from which objects, at which level. The result is often large volumes of output. That output can be configured and sent to files for later inspection, as well as used in scripts to stop the simulation, or take other actions when a log message appears.
Here we will show some logging examples when running the qsp-x86/firststeps target machine.
Launch the simulator with the qsp-x86/firststeps target.
$ ./simics qsp-x86/firststeps
The starting point is the large set of options available to the log-setup command. To check the current settings, just issue log-setup alone:
simics> log-setup
Time stamp : disabled
Picoseconds : disabled
Real time : disabled
Disassembly : disabled
Log to console : enabled
Include group : disabled
Include level : disabled
Log file : disabled
All objects in the Intel Simics simulator, and all log messages, have a log level. The default log level is 1, which is supposed to show important information. Log level 2 to 4 add progressively more information. To configure and inspect the log level of an object, use the log-level object command. This will show or configure the log level for the object.
simics> log-level board.mb.nb.bridge 2
[board.mb.nb.bridge] Changing log level: 1 -> 2
simics> log-level board.mb.nb.bridge
Current log levels:
Lvl Object | Lvl Object
-----------------------------------------+------------------------------------
2 board.mb.nb.bridge | 2 board.mb.nb.bridge.port
2 board.mb.nb.bridge.bank | 2 board.mb.nb.bridge.port.HRESET
2 board.mb.nb.bridge.bank.io_regs | 2 board.mb.nb.bridge.port.msg
2 board.mb.nb.bridge.bank.pcie_config | 2 board.mb.nb.bridge.port.phy
The log messages that are displayed are those which have a level less than or equal to the ones configured on the object.
Each log message also has a log type, and similarly like log levels, we can configure which log types to display on each object:
simics> log-type board.mb.nb.bridge info
board.mb.nb.bridge:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.bank:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.bank.io_regs:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.bank.pcie_config:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.port:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.port.HRESET:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.port.msg:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
board.mb.nb.bridge.port.phy:
enabled log types: "info"
disabled log types: "error" "spec-viol" "unimpl" "critical" "warning"
When we run the simulation, log messages will appear based on our filtering.
simics> run 1000
[board.mb.nb.bridge.bank.io_regs info] PCIe write 0xe0000001 to ff:0.1 offset 0x50, 4 bytes
It is also possible to set breakpoints on log messages. These can similarly be filtered on object, log type etc.
To see when in virtual time a log message is printed, use log-setup -time-stamp. This will print the processor that provided the virtual time for the message, its current instruction pointer or program counter (address of the instruction active when the log was printed), and its current cycle count. To turn it off, use -no-time-stamp. The -pico-seconds and -real-time are similar, but prints picosecond resolution timestamps and real time, respectively.
simics> log-setup -time-stamp
simics> bp.log.break object = board.mb.nb.bridge.bank.io_regs type = info
Breakpoint 3: Break on 'info' log messages from board.mb.nb.bridge.bank.io_regs hierarchy
simics> run
[board.mb.nb.bridge.bank.io_regs info] {board.mb.cpu0.core[0][0] 0xfffecbf7 136713}
PCI read 0x0 from bus 0, device 31, function 0, register 68 (0x44, 1 bytes), PCIE address = 0xf8044
[board.mb.nb.bridge.bank.io_regs] Breakpoint 1: board.mb.nb.bridge.bank.io_regs log message of type info
To send all log outputs to a file, use log-setup logfile=<filename>. To overwrite an existing file, the -overwrite flag must be given. To stop output, use the command log-setup -no-log-file.
Tracing is a way to observe what is going on during the simulation. The Intel Simics simulator has a Breakpoint Manager that includes functionality for tracing various types of events. This means that messages (in fact, log messages) are printed when an event of the specified occurs. Such a sequence of messages is what is here is known as a trace.
Here we will show some tracing examples.
Launch the simulator with the qsp-x86/firststeps target.
$ ./simics qsp-x86/firststeps
First, we can try tracing control register updates. By default, it traces updates on the primary processor (in this case there is only one).
simics> bp.control_register.trace -all
3
Since traces are handled as breakpoints, the trace properties can be observed with the bp.list command.
From bp.list we can see on the last line that we got id 3, which will be used later when deleting the trace.
simics> bp.list
┌──┬───────────────────────────────────┬───────┬───────┬────────────┬─────────┐
│ID│ Description │Enabled│Oneshot│Ignore count│Hit count│
├──┼───────────────────────────────────┼───────┼───────┼────────────┼─────────┤
│ 1│Clock board.mb.cpu0.core[0][0] │ true │ false │ 0│ 0│
│ │break at time 5.0 │ │ │ │ │
├──┼───────────────────────────────────┼───────┼───────┼────────────┼─────────┤
│ 2│Console 'board.serconsole.con' │ true │ false │ 0│ 0│
│ │break on "root.*@grml.*#.* " │ │ │ │ │
│ │(regexp) │ │ │ │ │
├──┼───────────────────────────────────┼───────┼───────┼────────────┼─────────┤
│ 3│board.mb.cpu0.core[0][0] break on │ true │ false │ 0│ 0│
│ │R/W of any register │ │ │ │ │
└──┴───────────────────────────────────┴───────┴───────┴────────────┴─────────┘
We run the simulation and observe the trace output where we can see that registers are read and written.
simics> run 1000
[bp.control_register trace] [trace:3] board.mb.cpu0.core[0][0] cr0 <- 0x23
[bp.control_register trace] [trace:3] board.mb.cpu0.core[0][0] cr4 <- 0x640
[bp.control_register trace] [trace:3] board.mb.cpu0.core[0][0] read of cr4
[bp.control_register trace] [trace:3] board.mb.cpu0.core[0][0] cr4 <- 0x640
The trace output are log messages and can be controlled with the log-setup command. For example, each message can be prepended with a time-stamp, indicating the processor, program counter and the cycle count at the point where the event occurred.
simics> log-setup -time-stamp
simics> c 17450
[bp.control_register trace] {board.mb.cpu0.core[0][0] 0xffff95f3 398353} [trace:3] board.mb.cpu0.core[0][0] read of IA32_APIC_BASE
Here is another example where we trace memory accesses. First, we remove the previous trace.
simics> bp.delete id = 3
Now we turn on tracing of all memory read accesses to a specific region. Again, by default this will trace accesses on the primary processor and hence these are virtual addresses.
simics> bp.memory.trace address = 0 length = 100000 -r
We run the simulation again and notice a memory access.
simics> run 386_985_232 cycles
[bp.memory trace] {board.mb.cpu0.core[0][0] 0x60837d57 387383681} [trace:5] board.cell_context 'r' access to v:0x10 len=4
Several other types of events can also be traced, such as target console string output and hits at specific source code lines.