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

[Christian Schoenebeck <qemu_oss@crudebyte.com>]

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_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.

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"
>