On Mon, May 19, 2025 at 10:14 AM Manos Pitsidianakis
<manos.pitsidiana...@linaro.org> wrote:
> There's also the `tracing` framework
> https://docs.rs/tracing/latest/tracing/ that is quite nice for
> defining tracing events **and** spans for logs. I find it confusing
> that it still ties tracing events with log level filters though
> (info/warn/error/debug/trace).
I like the overall look of the tracing crate API a lot. One thing that
I don't like is that it's very string-heavy. In general it seems to
have more overhead than tracetool if you use `Interest::Sometimes`; it
uses Strings for event names and targets but not ids (the default
event name is even "event FILE:LINE" which is not really usable except
for development), making matches (especially "enabled()" checks) slow.
Secondarily, built-in support for fmt::Debug/fmt::Display lets you get
away with not thinking of *which* fields you want to record. But it's
powerful, easy to use and it also has very few dependencies, which is
nice.
> Perhaps this is also a good opportunity to restructure QEMU's logging
> in general. [...]
> If we align QEMU's general logging to use log levels, we can convert
> guest error logs to "Error" level logs of type: "guest", and unimp
> logs to "Error" logs of type "unimplemented". Or, "Warn" instead of
> "Error". Then, all trace_* items become straightforwardly Trace level
> log items.
Focusing for a second on guest and unimp items, do you think that
there would be macros like `guest_error!` and `unimp!` (similar to how
`tracing` has shortcuts `error!` or `warn!`)? If so, we could add them
even now, so that any future changes to the implementation would be
transparent.
> Then, all we have to do in the Rust side is implement a `tracing`
> subscriber that consumes these traces and pushes them into QEMU's C
> implementation.
As I said above, I am a bit worried about performance implications of
having Strings for event names and targets but yes, using the tracing
crate is definitely something to think about! As you say, it provides
an opportunity to add structure to QEMU's logging and maybe we can get
the best of both worlds from both `tracing` and tracetool. Do you
think util/log.c could become a wrapper around event!() and
tracing_subscriber::FmtSubscriber (with log levels based on LOG_*
constants, as you mentioned)? Then the `log` backend for tracetool
could generate Rust code that calls trace!() instead of C code that
calls qemu_log().
Or you could do the same thing to the error_vprintf/error_printf
implementations, and then Rust code could use error! and warn! where C
code uses error_report() and warn_report(). It's a common complaint
that error_report() and warn_report() get lost in logs for example,
and `tracing` could add some structure there.
It could also be a very good starting point for thinking about C->Rust
FFI (i.e. implementing in Rust functionality that is used by C code).
In the meanwhile, another thing that could be done is take inspiration
from the `tracing` API, for example adding an #[instrument] macro to
qemu_api_macros:
impl PL011Registers {
#[instrument(target = "hw_char", name = "pl011_write",
fields(offset = offset as u32, value))
pub(self) fn write(...) { }
}
This way, even if tracetool and trace-events file remain part of the
architecture, the API is more familiar to Rust developers. It'd be a
nice addition to Tanish's work (he's my student that's working on Rust
tracepoints.
Paolo
