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

[Stefan Hajnoczi <stefanha@gmail.com>]

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

On Fri, Dec 6, 2024, 11:44 Christian Schoenebeck <qemu_oss@crudebyte.com>
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 conversion function is only
> called if tracing of event 'v9fs_walk' is currently enabled.
>
> Signed-off-by: Christian Schoenebeck <qemu_oss@crudebyte.com>
> Reviewed-by: Greg Kurz <groug@kaod.org>
> ---
>  V2:
>  - Use trace_event_get_state_backends(TRACE_V9FS_WALK) instead of
>    trace_event_get_state(TRACE_V9FS_WALK) && qemu_loglevel_mask(LOG_TRACE).
>  - Move that check from helper function trace_v9fs_walk_wnames() to caller
>    function v9fs_walk().
>
>  hw/9pfs/9p.c         | 36 +++++++++++++++++++++++++++++++-----
>  hw/9pfs/trace-events |  2 +-
>  2 files changed, 32 insertions(+), 6 deletions(-)
>

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>


> diff --git a/hw/9pfs/9p.c b/hw/9pfs/9p.c
> index 578517739a..6f24c1abb3 100644
> --- a/hw/9pfs/9p.c
> +++ b/hw/9pfs/9p.c
> @@ -1774,6 +1774,21 @@ 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".
> + *
> + * 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 = g_malloc0_n(nwnames + 1, sizeof(char *));
> +    for (size_t i = 0; i < nwnames; ++i) {
> +        arr[i] = wnames[i].data;
> +    }
> +    return g_strjoinv(", ", arr);
> +}
> +
>  static void coroutine_fn v9fs_walk(void *opaque)
>  {
>      int name_idx, nwalked;
> @@ -1787,6 +1802,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 +1816,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 +1828,23 @@ 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;
>          }
> +        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);
> +        }
> +    } else {
> +        trace_v9fs_walk(pdu->tag, pdu->id, fid, newfid, nwnames, "");
>      }
> +
>      fidp = get_fid(pdu, fid);
>      if (fidp == NULL) {
>          err = -ENOENT;
> @@ -1957,7 +1979,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
>
>
>

[-- Attachment #2: Type: text/html, Size: 7646 bytes --]