Re: [PATCH] Rust: Add tracing and logging support for Rust code

[Stefan Hajnoczi <stefanha@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 4949 bytes --]

On Mon, Mar 31, 2025 at 07:26:33PM -0500, saman wrote:
> This change introduces initial support for tracing and logging in Rust-based
> QEMU code. As an example, tracing and logging have been implemented in the
> pl011 device, which is written in Rust.
> 
> - Updated `rust/wrapper.h` to include the `qemu/log.h` and `hw/char/trace.h` header.
> - Added log.rs to wrap `qemu_log_mask` and `qemu_log_mask_and_addr`
> - Modified `tracetool` scripts to move C function implementation from
>   header to .c
> - Added log and trace in rust version of PL011 device
> 
> Future enhancements could include generating idiomatic Rust APIs for tracing
> using the tracetool scripts
> 
> Signed-off-by: saman <saman@enumclass.cc>
> ---
>  include/qemu/log-for-trace.h        |  5 +--
>  rust/hw/char/pl011/src/device.rs    | 34 +++++++++++++++---
>  rust/hw/char/pl011/src/registers.rs | 20 +++++++++++
>  rust/qemu-api/meson.build           |  1 +
>  rust/qemu-api/src/lib.rs            |  1 +
>  rust/qemu-api/src/log.rs            | 54 +++++++++++++++++++++++++++++
>  rust/wrapper.h                      |  2 ++
>  scripts/tracetool/format/c.py       | 16 +++++++++
>  scripts/tracetool/format/h.py       | 11 ++----
>  util/log.c                          |  5 +++
>  10 files changed, 131 insertions(+), 18 deletions(-)
>  create mode 100644 rust/qemu-api/src/log.rs
> 
> diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> index d47c9cd446..ad5cd0dd24 100644
> --- a/include/qemu/log-for-trace.h
> +++ b/include/qemu/log-for-trace.h
> @@ -24,10 +24,7 @@ extern int qemu_loglevel;
>  #define LOG_TRACE          (1 << 15)
>  
>  /* Returns true if a bit is set in the current loglevel mask */
> -static inline bool qemu_loglevel_mask(int mask)
> -{
> -    return (qemu_loglevel & mask) != 0;
> -}
> +bool qemu_loglevel_mask(int mask);
>  
>  /* main logging function */
>  void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
> diff --git a/rust/hw/char/pl011/src/device.rs b/rust/hw/char/pl011/src/device.rs
> index bf88e0b00a..42385a7bf6 100644
> --- a/rust/hw/char/pl011/src/device.rs
> +++ b/rust/hw/char/pl011/src/device.rs
> @@ -2,15 +2,21 @@
>  // Author(s): Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
>  // SPDX-License-Identifier: GPL-2.0-or-later
>  
> -use std::{ffi::CStr, mem::size_of, ptr::addr_of_mut};
> +use std::{
> +    ffi::{CStr, CString},
> +    mem::size_of,
> +    ptr::addr_of_mut,
> +};
>  
>  use qemu_api::{
>      chardev::{CharBackend, Chardev, Event},
>      impl_vmstate_forward,
>      irq::{IRQState, InterruptSource},
> +    log::Mask,
>      memory::{hwaddr, MemoryRegion, MemoryRegionOps, MemoryRegionOpsBuilder},
>      prelude::*,
>      qdev::{Clock, ClockEvent, DeviceImpl, DeviceState, Property, ResetType, ResettablePhasesImpl},
> +    qemu_log_mask,
>      qom::{ObjectImpl, Owned, ParentField},
>      static_assert,
>      sysbus::{SysBusDevice, SysBusDeviceImpl},
> @@ -298,7 +304,7 @@ pub(self) fn write(
>              DMACR => {
>                  self.dmacr = value;
>                  if value & 3 > 0 {
> -                    // qemu_log_mask(LOG_UNIMP, "pl011: DMA not implemented\n");
> +                    qemu_log_mask!(Mask::log_unimp, "pl011: DMA not implemented\n");
>                      eprintln!("pl011: DMA not implemented");
>                  }
>              }
> @@ -535,11 +541,21 @@ fn read(&self, offset: hwaddr, _size: u32) -> u64 {
>                  u64::from(device_id[(offset - 0xfe0) >> 2])
>              }
>              Err(_) => {
> -                // qemu_log_mask(LOG_GUEST_ERROR, "pl011_read: Bad offset 0x%x\n", (int)offset);
> +                qemu_log_mask!(
> +                    Mask::log_guest_error,
> +                    "pl011_read: Bad offset 0x%x\n",
> +                    offset as i32
> +                );
>                  0
>              }
>              Ok(field) => {
> +                let regname = field.as_str();
>                  let (update_irq, result) = self.regs.borrow_mut().read(field);
> +                let c_string = CString::new(regname).expect("CString::new failed");
> +                let name_ptr = c_string.as_ptr();
> +                unsafe {
> +                    qemu_api::bindings::trace_pl011_read(offset as u32, result, name_ptr);
> +                }

I didn't look closely to see whether CString::new(field.as_str()) boils
down to allocating a new string or just pointing to a NUL-terminated
string constant in the .rodata section of the binary, but this looks
suspicious.

It has the pattern:

  ...do work to produce trace event arguments...
  trace_foo(arg1, arg2, arg3);

Tracing is intended to be as low-overhead as possible when trace events
are disabled but compiled in. The work to produce event arguments must
be done only when the trace event is enabled.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]