On Wednesday, December 4, 2024 9:59:59 PM CET Stefan Hajnoczi wrote:
> 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_...@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.
Hi Stefan,
> > 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.
Makes sense, I'll change that.
> > + {
> > + 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.
Mmm, it doesn't make much of a difference from execution PoV. Having the check
in very small trace_v9fs_walk_wnames() function would save 2 lines in rather
large v9fs_walk() function.
In the end, both are fine with me.
Thanks for your feedback!
/Christian
> > + } 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"
>
