|
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [UNIKRAFT PATCH 2/7] lib/uk9p: Use uk_trace instead of uk_pr_debug
This patch enables nanosecond-resolution tracing of 9pfs performance
without the added noise of having to output the message; the same
mechanism can also be used to inspect the behavior of the protocol.
Excerpt from the output traces for a read() with in-depth tracing:
607016885 uk_9p_trace_read fid 2 offset 61440 count 4096
607020599 uk_9p_trace_request_allocated
607020627 uk_9p_trace_ready tag 0
607023469 uk_9p_trace_sent tag 0
607062214 uk_9p_trace_received tag 0
607062258 uk_9p_trace_read_end count 4096
Signed-off-by: Cristian Banu <cristb@xxxxxxxxx>
---
lib/uk9p/9p.c | 205 +++++++++++++++++++++++++++++++++++---------------
1 file changed, 145 insertions(+), 60 deletions(-)
diff --git a/lib/uk9p/9p.c b/lib/uk9p/9p.c
index 638555b..d6ba3cf 100644
--- a/lib/uk9p/9p.c
+++ b/lib/uk9p/9p.c
@@ -40,16 +40,40 @@
#include <uk/9preq.h>
#include <uk/9pfid.h>
+/*
+ * Define UK_DEBUG_TRACE to enable traces in this file.
+ * Also define UK_9P_INDEPTH_TRACES to enable more in-depth traces.
+ *
+ * These lines must be added before including uk/trace.h.
+ */
+#include <uk/trace.h>
+
+UK_TRACEPOINT(uk_9p_trace_ready, "tag %u", uint16_t);
+UK_TRACEPOINT(uk_9p_trace_sent, "tag %u", uint16_t);
+UK_TRACEPOINT(uk_9p_trace_received, "tag %u", uint16_t);
+UK_TRACEPOINT(uk_9p_trace_request_allocated, "");
+
static inline int send_and_wait_zc(struct uk_9pdev *dev, struct uk_9preq *req,
enum uk_9preq_zcdir zc_dir, void *zc_buf, uint32_t zc_size,
uint32_t zc_offset)
{
int rc;
- if ((rc = uk_9preq_ready(req, zc_dir, zc_buf, zc_size, zc_offset)) ||
- (rc = uk_9pdev_request(dev, req)) ||
- (rc = uk_9preq_waitreply(req)))
+ if ((rc = uk_9preq_ready(req, zc_dir, zc_buf, zc_size, zc_offset)))
+ return rc;
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_ready(req->tag);
+#endif
+ if ((rc = uk_9pdev_request(dev, req)))
return rc;
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_sent(req->tag);
+#endif
+ if ((rc = uk_9preq_waitreply(req)))
+ return rc;
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_received(req->tag);
+#endif
return 0;
}
@@ -60,6 +84,10 @@ static inline int send_and_wait_no_zc(struct uk_9pdev *dev,
return send_and_wait_zc(dev, req, UK_9PREQ_ZCDIR_NONE, NULL, 0, 0);
}
+UK_TRACEPOINT(uk_9p_trace_version, "msize %u version %s",
+ uint32_t, const char *);
+UK_TRACEPOINT(uk_9p_trace_version_end, "msize %u", uint32_t);
+
struct uk_9preq *uk_9p_version(struct uk_9pdev *dev,
const char *requested, struct uk_9p_str *received)
{
@@ -68,14 +96,16 @@ struct uk_9preq *uk_9p_version(struct uk_9pdev *dev,
int rc = 0;
uint32_t new_msize;
+ uk_9p_trace_version(dev->msize, requested);
uk_9p_str_init(&requested_str, requested);
req = uk_9pdev_req_create(dev, UK_9P_TVERSION, __PAGE_SIZE);
if (PTRISERR(req))
return req;
- uk_pr_debug("TVERSION msize %u version %s\n",
- dev->msize, requested);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
if ((rc = uk_9preq_write32(req, dev->msize)) ||
(rc = uk_9preq_writestr(req, &requested_str)) ||
@@ -83,9 +113,7 @@ struct uk_9preq *uk_9p_version(struct uk_9pdev *dev,
(rc = uk_9preq_read32(req, &new_msize)) ||
(rc = uk_9preq_readstr(req, received)))
goto free;
-
- uk_pr_debug("RVERSION msize %u version %.*s\n", new_msize,
- received->size, received->data);
+ uk_9p_trace_version_end(new_msize);
/*
* Note: the 9P specification mentions that new_msize <= dev->msize.
@@ -103,6 +131,11 @@ free:
return ERR2PTR(rc);
}
+UK_TRACEPOINT(uk_9p_trace_attach, "fid %u afid %u uname %s aname %s n_uname
%u",
+ uint32_t, uint32_t, const char *, const char *, uint32_t);
+UK_TRACEPOINT(uk_9p_trace_attach_end, "qid type %u version %u path %lu",
+ uint32_t, uint32_t, uint64_t);
+
struct uk_9pfid *uk_9p_attach(struct uk_9pdev *dev, uint32_t afid,
const char *uname, const char *aname, uint32_t n_uname)
{
@@ -119,16 +152,18 @@ struct uk_9pfid *uk_9p_attach(struct uk_9pdev *dev,
uint32_t afid,
if (PTRISERR(fid))
return fid;
+ uk_9p_trace_attach(fid->fid, afid, uname, aname, n_uname);
+
req = uk_9pdev_req_create(dev, UK_9P_TATTACH, __PAGE_SIZE);
if (PTRISERR(req)) {
uk_9pdev_fid_release(fid);
return (void *)req;
}
- uk_pr_debug("TATTACH fid %u afid %u uname %s aname %s n_uname %u\n",
- fid->fid, afid, uname, aname, n_uname);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
- rc = 0;
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = uk_9preq_write32(req, afid)) ||
(rc = uk_9preq_writestr(req, &uname_str)) ||
@@ -137,11 +172,8 @@ struct uk_9pfid *uk_9p_attach(struct uk_9pdev *dev,
uint32_t afid,
(rc = send_and_wait_no_zc(dev, req)) ||
(rc = uk_9preq_readqid(req, &fid->qid)))
goto free;
-
uk_9pdev_req_remove(dev, req);
-
- uk_pr_debug("RATTACH qid type %u version %u path %lu\n",
- fid->qid.type, fid->qid.version, fid->qid.path);
+ uk_9p_trace_attach_end(fid->qid.type, fid->qid.version, fid->qid.path);
return fid;
@@ -151,26 +183,38 @@ free:
return ERR2PTR(rc);
}
+UK_TRACEPOINT(uk_9p_trace_flush, "oldtag %u", uint32_t);
+UK_TRACEPOINT(uk_9p_trace_flush_end, "");
+
int uk_9p_flush(struct uk_9pdev *dev, uint16_t oldtag)
{
struct uk_9preq *req;
int rc = 0;
+ uk_9p_trace_flush(oldtag);
+
req = uk_9pdev_req_create(dev, UK_9P_TFLUSH, __PAGE_SIZE);
if (PTRISERR(req))
return PTR2ERR(req);
- uk_pr_debug("TFLUSH oldtag %u\n", oldtag);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
+
if ((rc = uk_9preq_write16(req, oldtag)) ||
(rc = send_and_wait_no_zc(dev, req)))
goto out;
- uk_pr_debug("RFLUSH\n");
+ uk_9p_trace_flush_end();
out:
uk_9pdev_req_remove(dev, req);
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_walk, "fid %u newfid %u name %s",
+ uint32_t, uint32_t, const char *);
+UK_TRACEPOINT(uk_9p_trace_walk_end, "nwqid %u", uint32_t);
+
struct uk_9pfid *uk_9p_walk(struct uk_9pdev *dev, struct uk_9pfid *fid,
const char *name)
{
@@ -187,6 +231,7 @@ struct uk_9pfid *uk_9p_walk(struct uk_9pdev *dev, struct
uk_9pfid *fid,
if (PTRISERR(newfid))
return newfid;
+ uk_9p_trace_walk(fid->fid, newfid->fid, name ? name : "<NULL>");
nwname = name ? 1 : 0;
req = uk_9pdev_req_create(dev, UK_9P_TWALK, __PAGE_SIZE);
@@ -195,22 +240,16 @@ struct uk_9pfid *uk_9p_walk(struct uk_9pdev *dev, struct
uk_9pfid *fid,
goto out;
}
- if (name) {
- uk_pr_debug("TWALK fid %u newfid %u nwname %d name %s\n",
- fid->fid, newfid->fid, nwname, name);
- if ((rc = uk_9preq_write32(req, fid->fid)) ||
- (rc = uk_9preq_write32(req, newfid->fid)) ||
- (rc = uk_9preq_write16(req, nwname)) ||
- (rc = uk_9preq_writestr(req, &name_str)))
- goto out;
- } else {
- uk_pr_debug("TWALK fid %u newfid %u nwname %d\n",
- fid->fid, newfid->fid, nwname);
- if ((rc = uk_9preq_write32(req, fid->fid)) ||
- (rc = uk_9preq_write32(req, newfid->fid)) ||
- (rc = uk_9preq_write16(req, nwname)))
- goto out;
- }
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
+
+ if ((rc = uk_9preq_write32(req, fid->fid)) ||
+ (rc = uk_9preq_write32(req, newfid->fid)) ||
+ (rc = uk_9preq_write16(req, nwname)))
+ goto out;
+ if (name && (rc = uk_9preq_writestr(req, &name_str)))
+ goto out;
if ((rc = send_and_wait_no_zc(dev, req))) {
/*
@@ -224,7 +263,7 @@ struct uk_9pfid *uk_9p_walk(struct uk_9pdev *dev, struct
uk_9pfid *fid,
if ((rc = uk_9preq_read16(req, &nwqid)))
goto out;
- uk_pr_debug("RWALK nwqid %u\n", nwqid);
+ uk_9p_trace_walk_end(nwqid);
if (nwqid != nwname) {
rc = -ENOENT;
@@ -247,16 +286,24 @@ out:
return newfid;
}
+UK_TRACEPOINT(uk_9p_trace_open, "fid %u mode %u", uint32_t, uint32_t);
+UK_TRACEPOINT(uk_9p_trace_open_end,
+ "qid type %u version %u path %lu, iounit %u",
+ uint32_t, uint32_t, uint64_t, uint32_t);
+
int uk_9p_open(struct uk_9pdev *dev, struct uk_9pfid *fid, uint8_t mode)
{
struct uk_9preq *req;
int rc = 0;
+ uk_9p_trace_open(fid->fid, mode);
req = uk_9pdev_req_create(dev, UK_9P_TOPEN, __PAGE_SIZE);
if (PTRISERR(req))
return PTR2ERR(req);
- uk_pr_debug("TOPEN fid %u mode %u\n", fid->fid, mode);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = uk_9preq_write8(req, mode)) ||
@@ -265,8 +312,7 @@ int uk_9p_open(struct uk_9pdev *dev, struct uk_9pfid *fid,
uint8_t mode)
(rc = uk_9preq_read32(req, &fid->iounit)))
goto out;
- uk_pr_debug("ROPEN qid type %u version %u path %lu iounit %u\n",
- fid->qid.type, fid->qid.version, fid->qid.path,
+ uk_9p_trace_open_end(fid->qid.type, fid->qid.version, fid->qid.path,
fid->iounit);
out:
@@ -274,6 +320,11 @@ out:
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_create, "fid %u mode %u", uint32_t, uint32_t);
+UK_TRACEPOINT(uk_9p_trace_create_end,
+ "qid type %u version %u path %lu, iounit %u",
+ uint32_t, uint32_t, uint64_t, uint32_t);
+
int uk_9p_create(struct uk_9pdev *dev, struct uk_9pfid *fid,
const char *name, uint32_t perm, uint8_t mode,
const char *extension)
@@ -283,6 +334,7 @@ int uk_9p_create(struct uk_9pdev *dev, struct uk_9pfid *fid,
struct uk_9p_str extension_str;
int rc = 0;
+ uk_9p_trace_create(fid->fid, mode);
uk_9p_str_init(&name_str, name);
uk_9p_str_init(&extension_str, extension);
@@ -290,7 +342,9 @@ int uk_9p_create(struct uk_9pdev *dev, struct uk_9pfid *fid,
if (PTRISERR(req))
return PTR2ERR(req);
- uk_pr_debug("TOPEN fid %u mode %u\n", fid->fid, mode);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = uk_9preq_writestr(req, &name_str)) ||
@@ -301,9 +355,7 @@ int uk_9p_create(struct uk_9pdev *dev, struct uk_9pfid *fid,
(rc = uk_9preq_readqid(req, &fid->qid)) ||
(rc = uk_9preq_read32(req, &fid->iounit)))
goto out;
-
- uk_pr_debug("RCREATE qid type %u version %u path %lu iounit %u\n",
- fid->qid.type, fid->qid.version, fid->qid.path,
+ uk_9p_trace_create_end(fid->qid.type, fid->qid.version, fid->qid.path,
fid->iounit);
out:
@@ -311,11 +363,16 @@ out:
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_remove, "fid %u", uint32_t);
+UK_TRACEPOINT(uk_9p_trace_remove_end, "");
+
int uk_9p_remove(struct uk_9pdev *dev, struct uk_9pfid *fid)
{
struct uk_9preq *req;
int rc = 0;
+ uk_9p_trace_remove(fid->fid);
+
/* The fid is considered invalid even if the remove fails. */
fid->was_removed = 1;
@@ -323,17 +380,23 @@ int uk_9p_remove(struct uk_9pdev *dev, struct uk_9pfid
*fid)
if (PTRISERR(req))
return PTR2ERR(req);
- uk_pr_debug("TREMOVE fid %u\n", fid->fid);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
+
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = send_and_wait_no_zc(dev, req)))
goto out;
- uk_pr_debug("RREMOVE\n");
+ uk_9p_trace_remove_end();
out:
uk_9pdev_req_remove(dev, req);
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_clunk, "fid %u", uint32_t);
+UK_TRACEPOINT(uk_9p_trace_clunk_end, "");
+
int uk_9p_clunk(struct uk_9pdev *dev, struct uk_9pfid *fid)
{
struct uk_9preq *req;
@@ -346,34 +409,41 @@ int uk_9p_clunk(struct uk_9pdev *dev, struct uk_9pfid
*fid)
if (PTRISERR(req))
return PTR2ERR(req);
- uk_pr_debug("TCLUNK fid %u\n", fid->fid);
+ uk_9p_trace_clunk(fid->fid);
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = send_and_wait_no_zc(dev, req)))
goto out;
- uk_pr_debug("RCLUNK\n");
+ uk_9p_trace_clunk_end();
out:
uk_9pdev_req_remove(dev, req);
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_read, "fid %u offset %lu count %u",
+ uint32_t, uint64_t, uint32_t);
+UK_TRACEPOINT(uk_9p_trace_read_end, "count %u", uint32_t);
+
int64_t uk_9p_read(struct uk_9pdev *dev, struct uk_9pfid *fid,
uint64_t offset, uint32_t count, char *buf)
{
struct uk_9preq *req;
int64_t rc;
+ uk_9p_trace_read(fid->fid, offset, count);
+
if (fid->iounit != 0)
count = MIN(count, fid->iounit);
count = MIN(count, dev->msize - 11);
- uk_pr_debug("TREAD fid %u offset %lu count %u\n", fid->fid,
- offset, count);
-
req = uk_9pdev_req_create(dev, UK_9P_TREAD, __PAGE_SIZE);
if (PTRISERR(req))
return PTR2ERR(req);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
+
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = uk_9preq_write64(req, offset)) ||
(rc = uk_9preq_write32(req, count)) ||
@@ -381,8 +451,7 @@ int64_t uk_9p_read(struct uk_9pdev *dev, struct uk_9pfid
*fid,
count, 11)) ||
(rc = uk_9preq_read32(req, &count)))
goto out;
-
- uk_pr_debug("RREAD count %u\n", count);
+ uk_9p_trace_read_end(count);
rc = count;
@@ -391,21 +460,28 @@ out:
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_write, "fid %u offset %lu count %u",
+ uint32_t, uint64_t, uint32_t);
+UK_TRACEPOINT(uk_9p_trace_write_end, "count %u", uint32_t);
+
int64_t uk_9p_write(struct uk_9pdev *dev, struct uk_9pfid *fid,
uint64_t offset, uint32_t count, const char *buf)
{
struct uk_9preq *req;
int64_t rc;
+ uk_9p_trace_write(fid->fid, offset, count);
count = MIN(count, fid->iounit);
count = MIN(count, dev->msize - 23);
- uk_pr_debug("TWRITE fid %u offset %lu count %u\n", fid->fid,
- offset, count);
req = uk_9pdev_req_create(dev, UK_9P_TWRITE, __PAGE_SIZE);
if (PTRISERR(req))
return PTR2ERR(req);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
+
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = uk_9preq_write64(req, offset)) ||
(rc = uk_9preq_write32(req, count)) ||
@@ -413,8 +489,7 @@ int64_t uk_9p_write(struct uk_9pdev *dev, struct uk_9pfid
*fid,
(void *)buf, count, 23)) ||
(rc = uk_9preq_read32(req, &count)))
goto out;
-
- uk_pr_debug("RWRITE count %u\n", count);
+ uk_9p_trace_write_end(count);
rc = count;
@@ -423,6 +498,9 @@ out:
return rc;
}
+UK_TRACEPOINT(uk_9p_trace_stat, "fid %u", uint32_t);
+UK_TRACEPOINT(uk_9p_trace_stat_end, "");
+
struct uk_9preq *uk_9p_stat(struct uk_9pdev *dev, struct uk_9pfid *fid,
struct uk_9p_stat *stat)
{
@@ -430,19 +508,21 @@ struct uk_9preq *uk_9p_stat(struct uk_9pdev *dev, struct
uk_9pfid *fid,
int rc = 0;
uint16_t dummy;
+ uk_9p_trace_stat(fid->fid);
req = uk_9pdev_req_create(dev, UK_9P_TSTAT, __PAGE_SIZE);
if (PTRISERR(req))
return req;
- uk_pr_debug("TSTAT fid %u\n", fid->fid);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
if ((rc = uk_9preq_write32(req, fid->fid)) ||
(rc = send_and_wait_no_zc(dev, req)) ||
(rc = uk_9preq_read16(req, &dummy)) ||
(rc = uk_9preq_readstat(req, stat)))
goto out;
-
- uk_pr_debug("RSTAT\n");
+ uk_9p_trace_stat_end();
return req;
@@ -451,6 +531,9 @@ out:
return ERR2PTR(rc);
}
+UK_TRACEPOINT(uk_9p_trace_wstat, "fid %u", uint32_t);
+UK_TRACEPOINT(uk_9p_trace_wstat_end, "");
+
int uk_9p_wstat(struct uk_9pdev *dev, struct uk_9pfid *fid,
struct uk_9p_stat *stat)
{
@@ -458,11 +541,14 @@ int uk_9p_wstat(struct uk_9pdev *dev, struct uk_9pfid
*fid,
int rc = 0;
uint16_t *dummy;
+ uk_9p_trace_wstat(fid->fid);
req = uk_9pdev_req_create(dev, UK_9P_TWSTAT, __PAGE_SIZE);
if (PTRISERR(req))
return PTR2ERR(req);
- uk_pr_debug("TWSTAT fid %u\n", fid->fid);
+#ifdef UK_9P_INDEPTH_TRACES
+ uk_9p_trace_request_allocated();
+#endif
if ((rc = uk_9preq_write32(req, fid->fid)))
goto out;
@@ -475,8 +561,7 @@ int uk_9p_wstat(struct uk_9pdev *dev, struct uk_9pfid *fid,
if ((rc = send_and_wait_no_zc(dev, req)))
goto out;
-
- uk_pr_debug("RWSTAT\n");
+ uk_9p_trace_wstat_end();
out:
uk_9pdev_req_remove(dev, req);
--
2.26.2
|
 |
Lists.xenproject.org is hosted with RackSpace, monitoring our |