Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

update tracing and logging documentation #82

Merged
merged 6 commits into from
Jan 29, 2024
Merged

update tracing and logging documentation #82

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
bd7c41e
update tracing and logging documentation
RubBra Jan 23, 2024
55afdcd
implement pr feedback
RubBra Jan 25, 2024
4957ffb
add libmwr links
RubBra Jan 26, 2024
c70c88b
fix incorrect output description
RubBra Jan 26, 2024
b55ff12
fix line breaking and punctuation
RubBra Jan 26, 2024
874025c
add precise name for backend
RubBra Jan 28, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
184 changes: 65 additions & 119 deletions doc/logging.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,193 +1,139 @@
# VCML Logging
VCML uses a centralized logging system that allows its individual components
and models to report on everything that happens during the simulation. Log
messages are split into five categories, listed below in priority order:
VCML uses a centralized logging system provided by [libmwr](https://github.com/machineware-gmbh/mwr)
that allows its individual components and models to report on everything that happens during the simulation.
Log messages are split into four categories, listed below in priority order:

* `vcml::LOG_ERROR`: highest priority, used for reporting on errors, e.g., when
* `mwr::LOG_ERROR`: highest priority, used for reporting on errors, e.g., when
an exception is caught.
* `vcml::LOG_WARNING`: used for reporting abnormal events, such as missing files
* `mwr::LOG_WARNING`: used for reporting abnormal events, such as missing files
or erroneous configurations.
* `vcml::LOG_INFO`: used for generic info messages, e.g., for printing out the
* `mwr::LOG_INFO`: used for generic info messages, e.g., for printing out the
simulation duration or bus memory maps at the beginning of the simulation.
* `vcml::LOG_DEBUG`: for printing debug messages
* `vcml::LOG_TRACE`: lowest priority, used for tracing transactions entering or
exiting buses or peripheral components.
* `mwr::LOG_DEBUG`: for printing debug messages

Log message output adheres the following format:

`[<LEVEL> <TIME>] <SOURCE>: <MESSAGE>`

In this format, `<LEVEL>` refers to the log level and is shortened to its first
letter, i.e., `E`, `W`, `I`, `D` or `T`. After the log level, the current
SystemC time is printed with nanosecond resolution. One can optionally also
print out the current delta cycle after the time stamp by setting
`vcml::logger::print_delta_cycle = true`. The `<SOURCE>` of the log message is
automatically determined, depending on the log function you called (see below).
In this format, `<LEVEL>` refers to the log level and is shortened to its first letter,
i.e., `E`, `W`, `I`, or `D`. After the log level,
the current SystemC time is printed with nanosecond resolution.
The `<SOURCE>` of the log message is automatically determined,
depending on the log function you called (see below).
A full log message could therefore look like this:

`[D 1.000000200] system.uart0: component disabled`

This tells us that there was a debug message at *1s + 200ns*, informing us that
the component `system.uart0` has been disabled.
This tells us that there was a debug message at *1s + 200ns*,
informing us that the component `system.uart0` has been disabled.

Log messages can be generated using the global top level logging functions from
the `vcml` namespace. These functions use the current SystemC process name as
the log message source. They use a `printf` style for string formatting:
Log messages can be generated using the global top level logging function-like macros from the `mwr` namespace.
They use a `printf` style for string formatting:

```
namespace vcml {
void log_error(const char* format, ...);
void log_warn(const char* format, ...);
void log_info(const char* format, ...);
void log_debug(const char* format, ...);
namespace mwr {
log_error(...);
log_warn(...);
log_info(...);
log_debug(...);
}
```

Furthermore, the base class used for modeling hardware in VCML `vcml::component`
also provides logging functionality, that will add the name of the component
as the source of the log message:

```
namespace vcml {
class component {
public:
// ...
void log_error(const char* format, ...);
void log_warn(const char* format, ...);
void log_info(const char* format, ...);
void log_debug(const char* format, ...);
// ....
};
}
```

----
## Logging Output
In order to actually see log messages, you need a logger that will receive the
messages and display them in some form. VCML currently provides three loggers:
In order to actually see log messages, you need a publisher backend that will receive the messages and display them in some form.
[Libmwr](https://github.com/machineware-gmbh/mwr) currently provides three backends:

* `vcml::log_term`: write the log message to `stderr` using color if available.
* `vcml::log_file`: write log messages to a file specified during construction.
* `vcml::log_stream`: sends the log messages to any `std::ostream` instance.
* `mwr::publishers::terminal`: write the log message to `stderr` using color if available.
* `mwr::publishers::file`: write log messages to a file specified during construction.
* `mwr::publishers::stream`: sends the log messages to any `std::ostream` instance.

Each logger can furthermore also specify the log levels it is interested in.
Each publisher can furthermore also specify the log levels it is interested in.
This is done by calling the appropriate `set_level` methods as shown below:

```
vcml::log_file my_logger("log.txt");
my_logger.set_level(vcml::LOG_ERROR); // only receives error messages
my_logger.set_level(vcml::LOG_ERROR, vcml::LOG_INFO); // receives error, warning and info messages
mwr::publishers::file my_logger("log.txt");
my_logger.set_level(mwr::LOG_ERROR); // only receives error messages
my_logger.set_level(mwr::LOG_ERROR, mwr::LOG_INFO); // receives error, warning and info messages
```

Having multiple loggers for different purposes is possible and encouraged. You
could have for example a logger that exclusively receives messages from the
`vcml::LOG_DEBUG` level and writes them to a files. Then you could have a second
logger to print all other messages to console:
Having multiple publishers for different purposes is possible and encouraged.
You could have for example a logger that exclusively receives messages from the `mwr::LOG_DEBUG` level and writes them to a files.
Then you could have a second logger to print all other messages to console:

```
#include <vcml.h>

int sc_main(int argc, char** argv) {
vcml::log_file debug("debug.txt");
mwr::publishers::file debug("debug.txt");
debug.set_level(vcml::LOG_DEBUG);

vcml::log_term terminal;
mwr::publishers::term terminal;
terminal.set_level(vcml::LOG_ERROR, vcml::LOG_INFO);

...
}
```

Log printing is customizable to a certain extent, by setting the following
static print control variables of `vcml::logger::print_xxx` before or during
simulation:
Log printing is customizable to a certain extent,
by setting the following static print control variables of `mwr::publisher::print_xxx` before or during simulation:

| Print control | Description | Default |
|---------------------|---------------------------------------------|---------|
| `print_time_stamp` | Print the SystemC time of the log message | `true` |
| `print_delta_cycle` | Print the delta-cycle of the log message | `false` |
| `print_sender` | Print sending process or module | `true` |
| `print_source` | Print the source location of the log call | `false` |
| `print_backtrace` | Print backtraces for logged reports | `true` |
| Print control | Description | Default |
|---------------------|-------------------------------------------|---------|
| `print_timestamp` | Print the timestamp of the log message | `true` |
| `print_sender` | Print sending process or module | `true` |
| `print_source` | Print the source location of the log call | `false` |
| `print_backtrace` | Print backtraces for logged reports | `true` |

It is also possible to create your own logger if you need to process VCML log
messages in a customizable way. To define a custom logger, derive from
`vcml::logger` and override `vcml::logger::write_log`:
It is also possible to create your own publisher if you need to process [libmwr](https://github.com/machineware-gmbh/mwr) log messages in a customizable way.
To define a custom logger, derive from`mwr::publisher` and override `mwr::publisher::publish`:

```
class my_logger: public vcml::logger {
class my_publisher: public mwr::publisher {
public:
my_logger() ...
virtual ~my_logger() ...
virtual void log_line(const logmsg& msg);
my_publisher() ...
virtual ~my_publisher() ...
virtual void publish(const logmsg& msg) override;
};
```

When you are not using a custom `main` function, VCML will provide a default
one for you that accepts the following logging related program arguments:
When you are not using a custom `main` function, a default one is provided for you that accepts the following logging related program arguments:

* `-l <file>` or `--log <file`: creates a `vcml::log_file(<file>)`
* `-l <file>` or `--log-file <file>`: creates a `mwr::publishers::file(<file>)`
* `-l` or `--log`: without an extra filename, creates a `vcml::log_term`
* `--log-stdout`: Send log output to stdout
* `--log-file`: Send log output to file
* `--log-debug`: elevates the log level of all loggers to `LOG_DEBUG`
* `--log-delta`: toggles `vcml::logger::print_delta_cycle`

----
## Exceptions
The logging system is typically also used for exception reporting. VCML
generally uses the class `vcml::report` for exceptions, so a basic approach to
exception handling would be:
The logging system is typically also used for exception reporting.
[Libmwr](https://github.com/machineware-gmbh/mwr) generally uses the class `mwr::report` for exceptions,
so a basic approach to exception handling would be:

```
int sc_main(int argc, char** argv) {
vcml::log_term logger;
mwr::logger logger;
try {
// construct system
sc_core::sc_start();
return 0;
} catch (vcml::report& r) {
vcml::logger::log(r);
} catch (mwr::report& r) {
logger.error(r);
return EXIT_FAILURE;
} catch (std::exception& e) {
vcml::log_error(e.what());
mwr::log_error(e.what());
return EXIT_FAILURE;
}
}
```

This is also the default implementation used when not defining a custom `main`
function in your program.

*Note*: when you are using `vcml::logger::log(const vcml::report&)` to log an
exception, VCML will additionally print the call stack from when the exception
was thrown for debug purposes. This behaviour can be disabled by setting
`vcml::logger::print_backtrace = false`.
This is also the default implementation used when not defining a custom `main` function in your program.

----
## Tracing
The logging subsystem also features basic TLM transaction tracing functionality.
To take advantage of it, you need to create a logger that accepts messages from
the `vcml::LOG_TRACE` log level. If you are not defining a custom `main`
function in your program, you can create a default trace file logger using
`--trace <filename>`, or a stderr logger using `--trace` (without a file).

You can also use `vcml::trace` and `vcml::trace_errors` to log transactions or
just transactions that have an error state set. This feature is generally used
with buses and peripheral components to report on incoming and outgoing
transactions. The transaction type must be `tlm::tlm_generic_payload`. The
transaction will be converted to string using the following format:

`<DIR> <OP> <ADDRESS> [<VALUE>] (<RESPONSE>)`

Here, `<DIR>` refers to the direction of the transaction. Outgoing requests are
denoted with a `>>`, incoming responses use `<<`. `<OP>` refers to the access
operation and can be `RD` (read) or `WR` (write). `<ADDRESS>` shows the
destination address in hex and `<VALUE>` contains the individual byte values of
the internal transaction buffer. `<RESPONSE>` holds the current state of the
transaction, see the TLM reference manual for details. Following is an example
of an actual TLM transaction trace:

* reading four bytes from address 0x100: `<< RD 0x0000100 [00 FF 00 FF] (TLM_OK_RESPONSE)`
* writing single byte to invalid address: `<< WR 0xFFFFFFFF [EE] (TLM_ADDRESS_ERROR_RESPONSE)`
*Note*: when you are using `mwr::logger::error(const vcml::report&)` to log an exception,
the logger will additionally print the call stack from when the exception was thrown for debug purposes.
This behaviour can be disabled by setting `mwr::publisher::print_backtrace = false`.

----
Documentation April 2020
Documentation January 2024
3 changes: 2 additions & 1 deletion doc/main.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ can be used as *off-the-shelf* components to swiftly assemble an entire VP.

* Documentation files for VCML modeling primitives:
* [Logging](logging.md)
* [Tracing](tracing.md)
* [Components](components.md)
* [Properties](properties.md)
* [Backends](backends.md)
Expand Down Expand Up @@ -44,4 +45,4 @@ can be used as *off-the-shelf* components to swiftly assemble an entire VP.
* [Simulation Throttle](models/meta_throttle.md)

----
Documentation January 2021
Documentation January 2024
35 changes: 35 additions & 0 deletions doc/tracing.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,35 @@
# VCML Tracing

VCML offers transaction tracing functionality for TLM and various other protocols,
such as GPIO, CLK, PCI, I2C, SPI, SD, Serial, Ethernet, CAN and Virtio.
Tracing can be enabled globally via `system.trace=1` or for individual components via e.g. `system.sdhci.sd_out.trace=1`.

Tracing is available for all known payload types: `tlm_generic_payload`, `gpio_payload`,
`clk_payload`, `pci_payload`, `i2c_payload`, `spi_payload`, `sd_command`, `sd_data`,
`vq_message`, `serial_payload`, `eth_frame`, `can_frame`.

## Tracing Output
VCML currently has two tracing output options:

* `--trace-stdout`: Send tracing output to stdout.
* `-t <file>` or `--trace <file>`: send tracing output to file.

### Tracing Message Format

`[<PROTOCOL> <TIME>] <SOCKET> <DIR> <OP> <ADDRESS> [<VALUE>] (<RESPONSE>)`

Here, `<PROTOCOL>` refers to the specific protocol that was used, `<TIME>` is a transaction timestamp,
`<SOCKET>` the name of the specific socket involved in the transaction, `<DIR>` refers to the direction of the transaction.
Outgoing requests are denoted with a `>>`, incoming responses use `<<`.
`<OP>` refers to the access operation and can be `RD` (read) or `WR` (write).
`<ADDRESS>` shows the destination address in hex and `<VALUE>` contains the individual byte values of the internal transaction buffer.
`<RESPONSE>` holds the current state of the transaction,
see the TLM reference manual for details.
Following is an example of an actual TLM transaction trace:

* reading four bytes from address 0x100: `[TLM 10.910098127] system.uart0.thr << RD 0x0000100 [00 ff 00 ff] (TLM_OK_RESPONSE)`
* writing single byte to invalid address: `[TLM 10.910098127] system.cpu.hart0.data << WR 0xffffffff [ee] (TLM_ADDRESS_ERROR_RESPONSE)`


----
Documentation January 2024
Loading