On Tue, 3 Dec 2024 10:14:28 +0100
Christian Schoenebeck <qemu_...@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 new helper function returns
> immediately if tracing of event 'v9fs_walk' is currently not enabled.
>
> Signed-off-by: Christian Schoenebeck <qemu_...@crudebyte.com>
> ---
Reviewed-by: Greg Kurz <gr...@kaod.org>
> CCing tracing maintainers in case they have better ideas how to do this.
>
> 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))
> + {
> + 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);
> + } 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"
--
Greg
