Re: [PATCH] 9pfs: improve v9fs_walk() tracing

[Stefan Hajnoczi]

On Tue, Dec 03, 2024 at 10:14:28AM +0100, Christian Schoenebeck wrote:
> 'Twalk' is the most important request type in the 9p protocol to look out
> for when debugging 9p communication. That's because it is the only part
> of the 9p protocol which actually deals with human-readable path names,
> whereas all other 9p request types work on numeric file IDs (FIDs) only.
> 
> Improve tracing of 'Twalk' requests, e.g. let's say client wanted to walk
> to "/home/bob/src", then improve trace output from:
> 
>   v9fs_walk tag 0 id 110 fid 0 newfid 1 nwnames=3
> 
> to:
> 
>   v9fs_walk tag=0 id=110 fid=0 newfid=1 nwnames=3 wnames={home, bob, src}
> 
> To achieve this, add a new helper function trace_v9fs_walk_wnames() which
> converts the received V9fsString array of individual path elements into a
> comma-separated string presentation for being passed to the tracing system.
> As this conversion is somewhat expensive, this new helper function returns
> immediately if tracing of event 'v9fs_walk' is currently not enabled.
> 
> Signed-off-by: Christian Schoenebeck <qemu_oss@crudebyte.com>
> ---
>  CCing tracing maintainers in case they have better ideas how to do this.

Thanks, Christian. Comments below but this looks fine if you prefer to
keep it this way.

>  hw/9pfs/9p.c         | 42 +++++++++++++++++++++++++++++++++++++-----
>  hw/9pfs/trace-events |  2 +-
>  2 files changed, 38 insertions(+), 6 deletions(-)
> 
> diff --git a/hw/9pfs/9p.c b/hw/9pfs/9p.c
> index 578517739a..c08e7e492b 100644
> --- a/hw/9pfs/9p.c
> +++ b/hw/9pfs/9p.c
> @@ -1774,6 +1774,30 @@ static bool same_stat_id(const struct stat *a, const 
> struct stat *b)
>      return a->st_dev == b->st_dev && a->st_ino == b->st_ino;
>  }
>  
> +/*
> + * Returns a (newly allocated) comma-separated string presentation of the
> + * passed array for logging (tracing) purpose for trace event "v9fs_walk" 
> only.
> + * If tracing for that event is disabled, it immediately returns NULL 
> instead.
> + *
> + * It is caller's responsibility to free the returned string.
> + */
> +static char *trace_v9fs_walk_wnames(V9fsString *wnames, size_t nwnames)
> +{
> +    g_autofree char **arr = NULL;
> +
> +    if (trace_event_get_state(TRACE_V9FS_WALK) &&
> +        qemu_loglevel_mask(LOG_TRACE))

There is no need to call qemu_loglevel_mask() explicitly if you use
trace_event_get_state_backends() instead of trace_event_get_state(). The
QEMU log backend will check qemu_loglevel_mask(LOG_TRACE) for you.

> +    {
> +        arr = g_malloc0_n(nwnames + 1, sizeof(char *));
> +        for (size_t i = 0; i < nwnames; ++i) {
> +            arr[i] = wnames[i].data;
> +        }
> +        return g_strjoinv(", ", arr);
> +    }
> +
> +    return NULL;
> +}
> +
>  static void coroutine_fn v9fs_walk(void *opaque)
>  {
>      int name_idx, nwalked;
> @@ -1787,6 +1811,7 @@ static void coroutine_fn v9fs_walk(void *opaque)
>      size_t offset = 7;
>      int32_t fid, newfid;
>      P9ARRAY_REF(V9fsString) wnames = NULL;
> +    g_autofree char *trace_wnames = NULL;
>      V9fsFidState *fidp;
>      V9fsFidState *newfidp = NULL;
>      V9fsPDU *pdu = opaque;
> @@ -1800,11 +1825,9 @@ static void coroutine_fn v9fs_walk(void *opaque)
>      }
>      offset += err;
>  
> -    trace_v9fs_walk(pdu->tag, pdu->id, fid, newfid, nwnames);
> -
>      if (nwnames > P9_MAXWELEM) {
>          err = -EINVAL;
> -        goto out_nofid;
> +        goto out_nofid_nownames;
>      }
>      if (nwnames) {
>          P9ARRAY_NEW(V9fsString, wnames, nwnames);
> @@ -1814,15 +1837,20 @@ static void coroutine_fn v9fs_walk(void *opaque)
>          for (i = 0; i < nwnames; i++) {
>              err = pdu_unmarshal(pdu, offset, "s", &wnames[i]);
>              if (err < 0) {
> -                goto out_nofid;
> +                goto out_nofid_nownames;
>              }
>              if (name_is_illegal(wnames[i].data)) {
>                  err = -ENOENT;
> -                goto out_nofid;
> +                goto out_nofid_nownames;
>              }
>              offset += err;
>          }
> +        trace_wnames = trace_v9fs_walk_wnames(wnames, nwnames);
> +        trace_v9fs_walk(pdu->tag, pdu->id, fid, newfid, nwnames, 
> trace_wnames);

This could be adjusted slightly to avoid calling trace_v9fs_walk() when
the trace event is disabled. It's up to you but this pattern is more
common:

  if (trace_event_get_state_backends(TRACE_V9FS_WALK)) {
      trace_wnames = trace_v9fs_walk_wnames(wnames, nwnames);
      trace_v9fs_walk(pdu->tag, pdu->id, fid, newfid, nwnames, trace_wnames);
  }

Now trace_v9fs_walk_wnames() doesn't need to check the trace event state
internally.

> +    } else {
> +        trace_v9fs_walk(pdu->tag, pdu->id, fid, newfid, nwnames, "");
>      }
> +
>      fidp = get_fid(pdu, fid);
>      if (fidp == NULL) {
>          err = -ENOENT;
> @@ -1957,7 +1985,11 @@ out:
>      }
>      v9fs_path_free(&dpath);
>      v9fs_path_free(&path);
> +    goto out_pdu_complete;
> +out_nofid_nownames:
> +    trace_v9fs_walk(pdu->tag, pdu->id, fid, newfid, nwnames, "<?>");
>  out_nofid:
> +out_pdu_complete:
>      pdu_complete(pdu, err);
>  }
>  
> diff --git a/hw/9pfs/trace-events b/hw/9pfs/trace-events
> index a12e55c165..ed9f4e7209 100644
> --- a/hw/9pfs/trace-events
> +++ b/hw/9pfs/trace-events
> @@ -11,7 +11,7 @@ v9fs_stat(uint16_t tag, uint8_t id, int32_t fid) "tag %d id 
> %d fid %d"
>  v9fs_stat_return(uint16_t tag, uint8_t id, int32_t mode, int32_t atime, 
> int32_t mtime, int64_t length) "tag %d id %d stat={mode %d atime %d mtime %d 
> length %"PRId64"}"
>  v9fs_getattr(uint16_t tag, uint8_t id, int32_t fid, uint64_t request_mask) 
> "tag %d id %d fid %d request_mask %"PRIu64
>  v9fs_getattr_return(uint16_t tag, uint8_t id, uint64_t result_mask, uint32_t 
> mode, uint32_t uid, uint32_t gid) "tag %d id %d getattr={result_mask 
> %"PRId64" mode %u uid %u gid %u}"
> -v9fs_walk(uint16_t tag, uint8_t id, int32_t fid, int32_t newfid, uint16_t 
> nwnames) "tag %d id %d fid %d newfid %d nwnames %d"
> +v9fs_walk(uint16_t tag, uint8_t id, int32_t fid, int32_t newfid, uint16_t 
> nwnames, const char* wnames) "tag=%d id=%d fid=%d newfid=%d nwnames=%d 
> wnames={%s}"
>  v9fs_walk_return(uint16_t tag, uint8_t id, uint16_t nwnames, void* qids) 
> "tag %d id %d nwnames %d qids %p"
>  v9fs_open(uint16_t tag, uint8_t id, int32_t fid, int32_t mode) "tag %d id %d 
> fid %d mode %d"
>  v9fs_open_return(uint16_t tag, uint8_t id, uint8_t type, uint32_t version, 
> uint64_t path, int iounit) "tag %u id %u qid={type %u version %u path 
> %"PRIu64"} iounit %d"
> -- 
> 2.39.5
>

signature.asc
Description: PGP signature