| Message ID | E1tIPPo-006ldP-Uk@kylie.crudebyte.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | 9pfs: improve v9fs_walk() tracing | expand |
On Tue, 3 Dec 2024 10:14:28 +0100 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 new helper function returns > immediately if tracing of event 'v9fs_walk' is currently not enabled. > > Signed-off-by: Christian Schoenebeck <qemu_oss@crudebyte.com> > --- Reviewed-by: Greg Kurz <groug@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"
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 >
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" >
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"
'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. hw/9pfs/9p.c | 42 +++++++++++++++++++++++++++++++++++++----- hw/9pfs/trace-events | 2 +- 2 files changed, 38 insertions(+), 6 deletions(-)