Plan is to replace the existing debug infrastructure with Qemu tracing infrastructure so that user can dynamically enable/disable trace events and therefore a meaningful trace log can be generated which can be further filtered using analysis script.
Note: Because of current simpletrace limitations, the trace events are logging at max 6 args, however, once the more args are supported, we can change trace events to log more info as well. Also, This initial patch only provides a replacement for existing debug infra. More trace events to be added later for newly added handlers and sub-routines. Signed-off-by: Harsh Prateek Bora <ha...@linux.vnet.ibm.com> --- hw/9pfs/virtio-9p.c | 62 +++++++++++++++++++++++++++++++++++++++++++++++++++ trace-events | 47 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 109 insertions(+), 0 deletions(-) diff --git a/hw/9pfs/virtio-9p.c b/hw/9pfs/virtio-9p.c index 1d1933f..6ee498f 100644 --- a/hw/9pfs/virtio-9p.c +++ b/hw/9pfs/virtio-9p.c @@ -20,6 +20,7 @@ #include "virtio-9p-debug.h" #include "virtio-9p-xattr.h" #include "virtio-9p-coth.h" +#include "trace.h" int debug_9p_pdu; int open_fd_hw; @@ -977,6 +978,7 @@ static void complete_pdu(V9fsState *s, V9fsPDU *pdu, ssize_t len) if (s->proto_version == V9FS_PROTO_2000L) { id = P9_RLERROR; } + trace_complete_pdu(pdu->tag, pdu->id, id); /* Trace ERROR */ } /* fill out the header */ @@ -1286,6 +1288,7 @@ static void v9fs_version(void *opaque) size_t offset = 7; pdu_unmarshal(pdu, offset, "ds", &s->msize, &version); + trace_v9fs_version1(pdu->tag, pdu->id, s->msize, version.data); if (!strcmp(version.data, "9P2000.u")) { s->proto_version = V9FS_PROTO_2000U; @@ -1296,6 +1299,8 @@ static void v9fs_version(void *opaque) } offset += pdu_marshal(pdu, offset, "ds", s->msize, &version); + trace_v9fs_version2(pdu->tag, pdu->id, s->msize, version.data); + complete_pdu(s, pdu, offset); v9fs_string_free(&version); @@ -1314,6 +1319,7 @@ static void v9fs_attach(void *opaque) ssize_t err; pdu_unmarshal(pdu, offset, "ddssd", &fid, &afid, &uname, &aname, &n_uname); + trace_v9fs_attach1(pdu->tag, pdu->id, fid, afid, uname.data, aname.data); fidp = alloc_fid(s, fid); if (fidp == NULL) { @@ -1338,6 +1344,7 @@ static void v9fs_attach(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_attach2(pdu->tag, pdu->id, qid.type, qid.version, qid.path); complete_pdu(s, pdu, err); v9fs_string_free(&uname); v9fs_string_free(&aname); @@ -1355,6 +1362,7 @@ static void v9fs_stat(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "d", &fid); + trace_v9fs_stat1(pdu->tag, pdu->id, fid); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -1375,6 +1383,8 @@ static void v9fs_stat(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_stat2(pdu->tag, pdu->id, v9stat.mode, v9stat.atime, v9stat.mtime, v9stat.length); + complete_pdu(s, pdu, err); } @@ -1391,6 +1401,7 @@ static void v9fs_getattr(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "dq", &fid, &request_mask); + trace_v9fs_getattr1(pdu->tag, pdu->id, fid, request_mask); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -1420,6 +1431,10 @@ static void v9fs_getattr(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_getattr2(pdu->tag, pdu->id, v9stat_dotl.st_result_mask, + v9stat_dotl.st_mode, v9stat_dotl.st_uid, + v9stat_dotl.st_gid); + complete_pdu(s, pdu, retval); } @@ -1547,6 +1562,8 @@ static void v9fs_walk(void *opaque) offset += pdu_unmarshal(pdu, offset, "ddw", &fid, &newfid, &nwnames); + trace_v9fs_walk1(pdu->tag, pdu->id, fid, newfid, nwnames); + if (nwnames && nwnames <= P9_MAXWELEM) { wnames = g_malloc0(sizeof(wnames[0]) * nwnames); qids = g_malloc0(sizeof(qids[0]) * nwnames); @@ -1603,6 +1620,7 @@ out: v9fs_path_free(&dpath); v9fs_path_free(&path); out_nofid: + trace_v9fs_walk2(pdu->tag, pdu->id, nwnames, qids); complete_pdu(s, pdu, err); if (nwnames && nwnames <= P9_MAXWELEM) { for (name_idx = 0; name_idx < nwnames; name_idx++) { @@ -1653,6 +1671,8 @@ static void v9fs_open(void *opaque) } else { pdu_unmarshal(pdu, offset, "db", &fid, &mode); } + trace_v9fs_open1(pdu->tag, pdu->id, fid, mode); + fidp = get_fid(pdu, fid); if (fidp == NULL) { err = -ENOENT; @@ -1699,6 +1719,7 @@ static void v9fs_open(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_open2(pdu->tag, pdu->id, qid.type, qid.version, qid.path, iounit); complete_pdu(s, pdu, err); } @@ -1717,6 +1738,7 @@ static void v9fs_lcreate(void *opaque) pdu_unmarshal(pdu, offset, "dsddd", &dfid, &name, &flags, &mode, &gid); + trace_v9fs_lcreate1(pdu->tag, pdu->id, dfid, flags, mode, gid); fidp = get_fid(pdu, dfid); if (fidp == NULL) { @@ -1746,6 +1768,7 @@ static void v9fs_lcreate(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_lcreate2(pdu->tag, pdu->id, qid.type, qid.version, qid.path, iounit); complete_pdu(pdu->s, pdu, err); v9fs_string_free(&name); } @@ -1761,6 +1784,8 @@ static void v9fs_fsync(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "dd", &fid, &datasync); + trace_v9fs_fsync(pdu->tag, pdu->id, fid, datasync); + fidp = get_fid(pdu, fid); if (fidp == NULL) { err = -ENOENT; @@ -1785,6 +1810,7 @@ static void v9fs_clunk(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "d", &fid); + trace_v9fs_clunk(pdu->tag, pdu->id, fid); fidp = clunk_fid(s, fid); if (fidp == NULL) { @@ -1901,6 +1927,7 @@ static void v9fs_read(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "dqd", &fid, &off, &max_count); + trace_v9fs_read1(pdu->tag, pdu->id, fid, off, max_count); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -1959,6 +1986,7 @@ static void v9fs_read(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_read2(pdu->tag, pdu->id, count, err); complete_pdu(s, pdu, err); } @@ -2043,6 +2071,8 @@ static void v9fs_readdir(void *opaque) pdu_unmarshal(pdu, offset, "dqd", &fid, &initial_offset, &max_count); + trace_v9fs_readdir1(pdu->tag, pdu->id, fid, initial_offset, max_count); + fidp = get_fid(pdu, fid); if (fidp == NULL) { retval = -EINVAL; @@ -2068,6 +2098,7 @@ static void v9fs_readdir(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_readdir2(pdu->tag, pdu->id, count, retval); complete_pdu(s, pdu, retval); } @@ -2132,6 +2163,7 @@ static void v9fs_write(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "dqdv", &fid, &off, &count, sg, &cnt); + trace_v9fs_write1(pdu->tag, pdu->id, fid, off, count, cnt); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -2178,6 +2210,7 @@ static void v9fs_write(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_write2(pdu->tag, pdu->id, total, err); complete_pdu(s, pdu, err); } @@ -2202,6 +2235,8 @@ static void v9fs_create(void *opaque) pdu_unmarshal(pdu, offset, "dsdbs", &fid, &name, &perm, &mode, &extension); + trace_v9fs_create1(pdu->tag, pdu->id, fid, name.data, perm, mode); + fidp = get_fid(pdu, fid); if (fidp == NULL) { err = -EINVAL; @@ -2335,6 +2370,7 @@ static void v9fs_create(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_create2(pdu->tag, pdu->id, qid.type, qid.version, qid.path, iounit); complete_pdu(pdu->s, pdu, err); v9fs_string_free(&name); v9fs_string_free(&extension); @@ -2355,6 +2391,7 @@ static void v9fs_symlink(void *opaque) size_t offset = 7; pdu_unmarshal(pdu, offset, "dssd", &dfid, &name, &symname, &gid); + trace_v9fs_symlink1(pdu->tag, pdu->id, dfid, name.data, symname.data, gid); dfidp = get_fid(pdu, dfid); if (dfidp == NULL) { @@ -2371,6 +2408,7 @@ static void v9fs_symlink(void *opaque) out: put_fid(pdu, dfidp); out_nofid: + trace_v9fs_symlink2(pdu->tag, pdu->id, qid.type, qid.version, qid.path); complete_pdu(pdu->s, pdu, err); v9fs_string_free(&name); v9fs_string_free(&symname); @@ -2385,6 +2423,7 @@ static void v9fs_flush(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "w", &tag); + trace_v9fs_flush(pdu->tag, pdu->id, tag); QLIST_FOREACH(cancel_pdu, &s->active_list, next) { if (cancel_pdu->tag == tag) { @@ -2415,6 +2454,7 @@ static void v9fs_link(void *opaque) int err = 0; pdu_unmarshal(pdu, offset, "dds", &dfid, &oldfid, &name); + trace_v9fs_link(pdu->tag, pdu->id, dfid, oldfid, name.data); dfidp = get_fid(pdu, dfid); if (dfidp == NULL) { @@ -2448,6 +2488,7 @@ static void v9fs_remove(void *opaque) V9fsPDU *pdu = opaque; pdu_unmarshal(pdu, offset, "d", &fid); + trace_v9fs_remove(pdu->tag, pdu->id, fid); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -2727,6 +2768,7 @@ static void v9fs_wstat(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "dwS", &fid, &unused, &v9stat); + trace_v9fs_wstat(pdu->tag, pdu->id, fid, v9stat.mode, v9stat.atime, v9stat.mtime); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -2895,6 +2937,7 @@ static void v9fs_mknod(void *opaque) pdu_unmarshal(pdu, offset, "dsdddd", &fid, &name, &mode, &major, &minor, &gid); + trace_v9fs_mknod1(pdu->tag, pdu->id, fid, mode, major, minor); fidp = get_fid(pdu, fid); if (fidp == NULL) { @@ -2912,6 +2955,7 @@ static void v9fs_mknod(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_mknod2(pdu->tag, pdu->id, qid.type, qid.version, qid.path); complete_pdu(s, pdu, err); v9fs_string_free(&name); } @@ -2939,6 +2983,9 @@ static void v9fs_lock(void *opaque) pdu_unmarshal(pdu, offset, "dbdqqds", &fid, &flock->type, &flock->flags, &flock->start, &flock->length, &flock->proc_id, &flock->client_id); + + trace_v9fs_lock1(pdu->tag, pdu->id, fid, flock->type, flock->start, flock->length); + status = P9_LOCK_ERROR; /* We support only block flag now (that too ignored currently) */ @@ -2961,6 +3008,7 @@ out: out_nofid: err = offset; err += pdu_marshal(pdu, offset, "b", status); + trace_v9fs_lock2(pdu->tag, pdu->id, status); complete_pdu(s, pdu, err); v9fs_string_free(&flock->client_id); g_free(flock); @@ -2985,6 +3033,8 @@ static void v9fs_getlock(void *opaque) &glock->start, &glock->length, &glock->proc_id, &glock->client_id); + trace_v9fs_getlock1(pdu->tag, pdu->id, fid, glock->type, glock->start, glock->length); + fidp = get_fid(pdu, fid); if (fidp == NULL) { err = -ENOENT; @@ -3002,6 +3052,9 @@ static void v9fs_getlock(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_getlock2(pdu->tag, pdu->id, glock->type, glock->start, + glock->length, glock->proc_id); + complete_pdu(s, pdu, err); v9fs_string_free(&glock->client_id); g_free(glock); @@ -3022,6 +3075,8 @@ static void v9fs_mkdir(void *opaque) pdu_unmarshal(pdu, offset, "dsdd", &fid, &name, &mode, &gid); + trace_v9fs_mkdir1(pdu->tag, pdu->id, fid, name.data, mode, gid); + fidp = get_fid(pdu, fid); if (fidp == NULL) { err = -ENOENT; @@ -3037,6 +3092,7 @@ static void v9fs_mkdir(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_mkdir2(pdu->tag, pdu->id, qid.type, qid.version, qid.path, err); complete_pdu(pdu->s, pdu, err); v9fs_string_free(&name); } @@ -3054,6 +3110,8 @@ static void v9fs_xattrwalk(void *opaque) V9fsState *s = pdu->s; pdu_unmarshal(pdu, offset, "dds", &fid, &newfid, &name); + trace_v9fs_xattrwalk1(pdu->tag, pdu->id, fid, newfid, name.data); + file_fidp = get_fid(pdu, fid); if (file_fidp == NULL) { err = -ENOENT; @@ -3130,6 +3188,7 @@ out: put_fid(pdu, xattr_fidp); } out_nofid: + trace_v9fs_xattrwalk2(pdu->tag, pdu->id, size); complete_pdu(s, pdu, err); v9fs_string_free(&name); } @@ -3149,6 +3208,7 @@ static void v9fs_xattrcreate(void *opaque) pdu_unmarshal(pdu, offset, "dsqd", &fid, &name, &size, &flags); + trace_v9fs_xattrcreate(pdu->tag, pdu->id, fid, name.data, size, flags); file_fidp = get_fid(pdu, fid); if (file_fidp == NULL) { @@ -3185,6 +3245,7 @@ static void v9fs_readlink(void *opaque) V9fsFidState *fidp; pdu_unmarshal(pdu, offset, "d", &fid); + trace_v9fs_readlink1(pdu->tag, pdu->id, fid); fidp = get_fid(pdu, fid); if (fidp == NULL) { err = -ENOENT; @@ -3202,6 +3263,7 @@ static void v9fs_readlink(void *opaque) out: put_fid(pdu, fidp); out_nofid: + trace_v9fs_readlink2(pdu->tag, pdu->id, target.data); complete_pdu(pdu->s, pdu, err); } diff --git a/trace-events b/trace-events index a31d9aa..143c9f0 100644 --- a/trace-events +++ b/trace-events @@ -502,3 +502,50 @@ escc_sunkbd_event_in(int ch) "Untranslated keycode %2.2x" escc_sunkbd_event_out(int ch) "Translated keycode %2.2x" escc_kbd_command(int val) "Command %d" escc_sunmouse_event(int dx, int dy, int buttons_state) "dx=%d dy=%d buttons=%01x" + + +# hw/9pfs/virtio-9p.c +complete_pdu(uint16_t tag, uint8_t id, int8_t resp_id) "tag %d id %d response_id %d" +v9fs_version1(uint16_t tag, uint8_t id, int32_t msize, char* version) "tag %d id %d msize %d version %s" +v9fs_version2(uint16_t tag, uint8_t id, int32_t msize, char* version) "tag %d id %d msize %d version %s" +v9fs_attach1(uint16_t tag, uint8_t id, int32_t fid, int32_t afid, char* uname, char* aname) "tag %d id %d fid %d afid %d aname %s" +v9fs_attach2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path) "tag %d id %d type %d version %d path %"PRId64"" +v9fs_stat1(uint16_t tag, uint8_t id, int32_t fid) "tag %d id %d fid %d" +v9fs_stat2(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_getattr1(uint16_t tag, uint8_t id, int32_t fid, uint64_t request_mask) "tag %d id %d fid %d request_mask %"PRIu64"" +v9fs_getattr2(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_walk1(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_walk2(uint16_t tag, uint8_t id, uint16_t nwnames, void* qids) "tag %d id %d nwnames %d qids %p" +v9fs_open1(uint16_t tag, uint8_t id, int32_t fid, int32_t mode) "tag %d id %d fid %d mode %d" +v9fs_open2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path, int iounit) "tag %d id %d qid={type %d version %d path %"PRId64"} iounit %d" +v9fs_lcreate1(uint16_t tag, uint8_t id, int32_t dfid, int32_t flags, int32_t mode, uint32_t gid) "tag %d id %d dfid %d flags %d mode %d gid %u" +v9fs_lcreate2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path, int32_t iounit) "tag %d id %d qid={type %d version %d path %"PRId64"}" +v9fs_fsync(uint16_t tag, uint8_t id, int32_t fid, int datasync) "tag %d id %d fid %d datasync %d" +v9fs_clunk(uint16_t tag, uint8_t id, int32_t fid) "tag %d id %d fid %d" +v9fs_read1(uint16_t tag, uint8_t id, int32_t fid, int64_t off, int32_t max_count) "tag %d id %d fid %d off %"PRId64" max_count %d" +v9fs_read2(uint16_t tag, uint8_t id, int32_t count, ssize_t err) "tag %d id %d count %d err %zd" +v9fs_readdir1(uint16_t tag, uint8_t id, int32_t fid, int64_t offset, int32_t max_count) "tag %d id %d fid %d offset %"PRId64" max_count %d" +v9fs_readdir2(uint16_t tag, uint8_t id, int32_t count, ssize_t retval) "tag %d id %d count %d retval %zd" +v9fs_write1(uint16_t tag, uint8_t id, int32_t fid, int64_t off, int32_t count, int cnt) "tag %d id %d fid %d off %"PRId64" count %d cnt %d" +v9fs_write2(uint16_t tag, uint8_t id, int32_t total, ssize_t err) "tag %d id %d total %d err %zd" +v9fs_create1(uint16_t tag, uint8_t id, int32_t fid, char* name, int32_t perm, int8_t mode) "tag %d id %d fid %d name %s perm %d mode %d" +v9fs_create2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path, int iounit) "tag %d id %d qid={type %d version %d path %"PRId64"} iounit %d" +v9fs_symlink1(uint16_t tag, uint8_t id, int32_t fid, char* name, char* symname, uint32_t gid) "tag %d id %d fid %d name %s symname %s gid %u" +v9fs_symlink2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path) "tag %d id %d qid={type %d version %d path %"PRId64"}" +v9fs_flush(uint16_t tag, uint8_t id, int16_t flush_tag) "tag %d id %d flush_tag %d" +v9fs_link(uint16_t tag, uint8_t id, int32_t dfid, int32_t oldfid, char* name) "tag %d id %d dfid %d oldfid %d name %s" +v9fs_remove(uint16_t tag, uint8_t id, int32_t fid) "tag %d id %d fid %d" +v9fs_wstat(uint16_t tag, uint8_t id, int32_t fid, int32_t mode, int32_t atime, int32_t mtime) "tag %d id %d fid %d stat={mode %d atime %d mtime}" +v9fs_mknod1(uint16_t tag, uint8_t id, int32_t fid, int mode, int major, int minor) "tag %d id %d fid %d mode %d major %d minor %d" +v9fs_mknod2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path) "tag %d id %d qid={type %d version %d path %"PRId64"}" +v9fs_lock1(uint16_t tag, uint8_t id, int32_t fid, uint8_t type, uint64_t start, uint64_t length) "tag %d id %d fid %d type %d start %"PRIu64" length %"PRIu64"" +v9fs_lock2(uint16_t tag, uint8_t id, int8_t status) "tag %d id %d status %d" +v9fs_getlock1(uint16_t tag, uint8_t id, int32_t fid, uint8_t type, uint64_t start, uint64_t length)"tag %d id %d fid %d type %d start %"PRIu64" length %"PRIu64"" +v9fs_getlock2(uint16_t tag, uint8_t id, uint8_t type, uint64_t start, uint64_t length, uint32_t proc_id) "tag %d id %d type %d start %"PRIu64" length %"PRIu64" proc_id %u" +v9fs_mkdir1(uint16_t tag, uint8_t id, int32_t fid, char* name, int mode, uint32_t gid) "tag %d id %d fid %d name %s mode %d" +v9fs_mkdir2(uint16_t tag, uint8_t id, int8_t type, int32_t version, int64_t path, int err) "tag %d id %d qid={type %d version %d path %"PRId64"}" +v9fs_xattrwalk1(uint16_t tag, uint8_t id, int32_t fid, int32_t newfid, char* name) "tag %d id %d fid %d newfid %d name %s" +v9fs_xattrwalk2(uint16_t tag, uint8_t id, int64_t size) "tag %d id %d size %"PRId64"" +v9fs_xattrcreate(uint16_t tag, uint8_t id, int32_t fid, char* name, int64_t size, int flags) "tag %d id %d fid %d name %s size %"PRId64" flags %d" +v9fs_readlink1(uint16_t tag, uint8_t id, int32_t fid) "tag %d id %d fid %d" +v9fs_readlink2(uint16_t tag, uint8_t id, char* target) "tag %d id %d name %s" -- 1.7.1.1