[PATCH 0/2] Ceph tracepoints

[PATCH 0/2] Ceph tracepoints

[Jim Schutt]

Hi Alex,

I ran across tracker #2374 today - I've been carrying these two
tracepoint patches for a while.  Perhaps you'll find them useful.

Jim Schutt (2):
  ceph: add tracepoints for message submission on read/write requests
  ceph: add tracepoints for message send queueing and completion, reply
    handling

 fs/ceph/addr.c              |    8 +++
 fs/ceph/file.c              |    6 ++
 include/trace/events/ceph.h |  144 +++++++++++++++++++++++++++++++++++++++++++
 net/ceph/messenger.c        |    9 +++-
 net/ceph/osd_client.c       |    8 +++
 5 files changed, 174 insertions(+), 1 deletions(-)
 create mode 100644 include/trace/events/ceph.h

-- 
1.7.8.2

[PATCH 1/2] ceph: add tracepoints for message submission on read/write requests

[Jim Schutt]

Trace callers of ceph_osdc_start_request, so that call locations
are identified implicitly.

Put the tracepoints after calls to ceph_osdc_start_request,
since it fills in the request transaction ID and request OSD.

Signed-off-by: Jim Schutt <jaschut@sandia.gov>
---
 fs/ceph/addr.c              |    8 ++++
 fs/ceph/file.c              |    6 +++
 include/trace/events/ceph.h |   77 +++++++++++++++++++++++++++++++++++++++++++
 net/ceph/osd_client.c       |    7 ++++
 4 files changed, 98 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/ceph.h

diff --git a/fs/ceph/addr.c b/fs/ceph/addr.c
index 173b1d2..f552579 100644
--- a/fs/ceph/addr.c
+++ b/fs/ceph/addr.c
@@ -13,6 +13,12 @@
 #include "mds_client.h"
 #include <linux/ceph/osd_client.h>
 
+
+#include <linux/tracepoint.h>
+#define CREATE_TRACE_POINTS
+#define CEPH_TRACE_FS_ADDR
+#include <trace/events/ceph.h>
+
 /*
  * Ceph address space ops.
  *
@@ -338,6 +344,7 @@ static int start_read(struct inode *inode, struct list_head *page_list, int max)
 
 	dout("start_read %p starting %p %lld~%lld\n", inode, req, off, len);
 	ret = ceph_osdc_start_request(osdc, req, false);
+	trace_ceph_async_readpages_req(req);
 	if (ret < 0)
 		goto out_pages;
 	ceph_osdc_put_request(req);
@@ -902,6 +909,7 @@ get_more_pages:
 		req->r_request->hdr.data_len = cpu_to_le32(len);
 
 		rc = ceph_osdc_start_request(&fsc->client->osdc, req, true);
+		trace_ceph_async_writepages_req(req);
 		BUG_ON(rc);
 		req = NULL;
 
diff --git a/fs/ceph/file.c b/fs/ceph/file.c
index ed72428..fc31def 100644
--- a/fs/ceph/file.c
+++ b/fs/ceph/file.c
@@ -10,6 +10,11 @@
 #include "super.h"
 #include "mds_client.h"
 
+#include <linux/tracepoint.h>
+#define CREATE_TRACE_POINTS
+#define CEPH_TRACE_FS_FILE
+#include <trace/events/ceph.h>
+
 /*
  * Ceph file operations
  *
@@ -568,6 +573,7 @@ more:
 	req->r_inode = inode;
 
 	ret = ceph_osdc_start_request(&fsc->client->osdc, req, false);
+	trace_ceph_sync_writepages_req(req);
 	if (!ret) {
 		if (req->r_safe_callback) {
 			/*
diff --git a/include/trace/events/ceph.h b/include/trace/events/ceph.h
new file mode 100644
index 0000000..182af2c
--- /dev/null
+++ b/include/trace/events/ceph.h
@@ -0,0 +1,77 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM ceph
+
+#if !defined(_TRACE_CEPH_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_CEPH_H
+
+
+#if !defined(TRACE_HEADER_MULTI_READ)
+
+static __always_inline int
+__ceph_req_num_ops(struct ceph_osd_request *req)
+{
+	struct ceph_osd_request_head *reqhead = req->r_request->front.iov_base;
+	return le16_to_cpu(reqhead->num_ops);
+}
+
+static __always_inline int
+__ceph_req_op_opcode(struct ceph_osd_request *req, int op)
+{
+	struct ceph_osd_request_head *reqhead = req->r_request->front.iov_base;
+	if (op < le16_to_cpu(reqhead->num_ops))
+		return le16_to_cpu(reqhead->ops[op].op);
+	else
+		return 0;
+}
+
+#endif
+
+DECLARE_EVENT_CLASS(ceph_start_req_class,
+	TP_PROTO(struct ceph_osd_request *req),
+	TP_ARGS(req),
+	TP_STRUCT__entry(
+		__field(unsigned long long, tid)
+		__field(int, osd)
+		__field(int, num_ops)
+		__array(unsigned, ops, 3)
+		__field(unsigned, pages)
+	),
+	TP_fast_assign(
+		__entry->tid = req->r_tid;
+		__entry->osd = req->r_osd->o_osd;
+		__entry->num_ops = __ceph_req_num_ops(req);
+		__entry->ops[0] = __ceph_req_op_opcode(req, 0);
+		__entry->ops[1] = __ceph_req_op_opcode(req, 1);
+		__entry->ops[2] = __ceph_req_op_opcode(req, 2);
+		__entry->pages = req->r_num_pages;
+	),
+	TP_printk("tid %llu osd%d ops %d 0x%04x/0x%04x/0x%04x pages %u",
+		  __entry->tid, __entry->osd, __entry->num_ops,
+		  __entry->ops[0], __entry->ops[1], __entry->ops[2],
+		  __entry->pages
+	)
+);
+
+#define DEFINE_CEPH_START_REQ_EVENT(name) \
+DEFINE_EVENT(ceph_start_req_class, name, \
+	TP_PROTO(struct ceph_osd_request *req), TP_ARGS(req))
+
+#ifdef CEPH_TRACE_FS_FILE
+DEFINE_CEPH_START_REQ_EVENT(ceph_sync_writepages_req);
+#endif
+
+#ifdef CEPH_TRACE_FS_ADDR
+DEFINE_CEPH_START_REQ_EVENT(ceph_async_writepages_req);
+DEFINE_CEPH_START_REQ_EVENT(ceph_async_readpages_req);
+#endif
+
+#ifdef CEPH_TRACE_NET_OSDC
+DEFINE_CEPH_START_REQ_EVENT(ceph_osdc_writepages_req);
+DEFINE_CEPH_START_REQ_EVENT(ceph_osdc_readpages_req);
+#endif
+
+
+#endif /* _TRACE_CEPH_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/net/ceph/osd_client.c b/net/ceph/osd_client.c
index 5e25405..f44e400 100644
--- a/net/ceph/osd_client.c
+++ b/net/ceph/osd_client.c
@@ -18,6 +18,11 @@
 #include <linux/ceph/auth.h>
 #include <linux/ceph/pagelist.h>
 
+#include <linux/tracepoint.h>
+#define CREATE_TRACE_POINTS
+#define CEPH_TRACE_NET_OSDC
+#include <trace/events/ceph.h>
+
 #define OSD_OP_FRONT_LEN	4096
 #define OSD_OPREPLY_FRONT_LEN	512
 
@@ -1906,6 +1911,7 @@ int ceph_osdc_readpages(struct ceph_osd_client *osdc,
 	     off, *plen, req->r_num_pages, page_align);
 
 	rc = ceph_osdc_start_request(osdc, req, false);
+	trace_ceph_osdc_readpages_req(req);
 	if (!rc)
 		rc = ceph_osdc_wait_request(osdc, req);
 
@@ -1948,6 +1954,7 @@ int ceph_osdc_writepages(struct ceph_osd_client *osdc, struct ceph_vino vino,
 	     req->r_num_pages);
 
 	rc = ceph_osdc_start_request(osdc, req, nofail);
+	trace_ceph_osdc_writepages_req(req);
 	if (!rc)
 		rc = ceph_osdc_wait_request(osdc, req);
 
-- 
1.7.8.2

[PATCH 2/2] ceph: add tracepoints for message send queueing and completion, reply handling

[Jim Schutt]

Signed-off-by: Jim Schutt <jaschut@sandia.gov>
---
 include/trace/events/ceph.h |   67 +++++++++++++++++++++++++++++++++++++++++++
 net/ceph/messenger.c        |    9 +++++-
 net/ceph/osd_client.c       |    1 +
 3 files changed, 76 insertions(+), 1 deletions(-)

diff --git a/include/trace/events/ceph.h b/include/trace/events/ceph.h
index 182af2c..b390f78 100644
--- a/include/trace/events/ceph.h
+++ b/include/trace/events/ceph.h
@@ -4,6 +4,9 @@
 #if !defined(_TRACE_CEPH_H) || defined(TRACE_HEADER_MULTI_READ)
 #define _TRACE_CEPH_H
 
+#if defined(CEPH_TRACE_FS_FILE) \
+ || defined(CEPH_TRACE_FS_ADDR) \
+ || defined(CEPH_TRACE_NET_OSDC)
 
 #if !defined(TRACE_HEADER_MULTI_READ)
 
@@ -68,8 +71,72 @@ DEFINE_CEPH_START_REQ_EVENT(ceph_async_readpages_req);
 #ifdef CEPH_TRACE_NET_OSDC
 DEFINE_CEPH_START_REQ_EVENT(ceph_osdc_writepages_req);
 DEFINE_CEPH_START_REQ_EVENT(ceph_osdc_readpages_req);
+
+TRACE_EVENT(ceph_handle_reply_msg,
+	TP_PROTO(struct ceph_connection *con,
+		 struct ceph_msg *msg,
+		 struct ceph_osd_reply_head *reply,
+		 void *req),
+	TP_ARGS(con, msg, reply, req),
+	TP_STRUCT__entry(
+		__field(unsigned long long, tid)
+		__field(long long, peer_num)
+		__field(void*, req)
+		__field(unsigned, peer_type)
+		__field(int, result)
+		__field(int, flags)
+	),
+	TP_fast_assign(
+		__entry->tid = le64_to_cpu(msg->hdr.tid);
+		__entry->peer_num = le64_to_cpu(con->peer_name.num);
+		__entry->peer_type = con->peer_name.type;
+		__entry->req = req;
+		__entry->result = le32_to_cpu(reply->result);
+		__entry->flags = le32_to_cpu(reply->flags);
+	),
+	TP_printk("peer %s%lld tid %llu result %d flags 0x%08x (req %p)",
+		  ceph_entity_type_name(__entry->peer_type), __entry->peer_num,
+		  __entry->tid, __entry->result, __entry->flags,  __entry->req
+	)
+);
 #endif
 
+#endif /* CEPH_TRACE_FS_FILE || CEPH_TRACE_FS_ADDR || CEPH_TRACE_NET_OSDC */
+
+#if defined(CEPH_TRACE_NET_MESSENGER)
+
+DECLARE_EVENT_CLASS(ceph_write_msg_class,
+	TP_PROTO(struct ceph_connection *con, struct ceph_msg *msg),
+	TP_ARGS(con, msg),
+	TP_STRUCT__entry(
+		__field(unsigned long long, tid)
+		__field(unsigned long long, seq)
+		__field(long long, peer_num)
+		__field(unsigned, peer_type)
+		__field(int, sent)
+	),
+	TP_fast_assign(
+		__entry->tid = le64_to_cpu(msg->hdr.tid);
+		__entry->seq = le64_to_cpu(msg->hdr.seq);
+		__entry->peer_num = le64_to_cpu(con->peer_name.num);
+		__entry->peer_type = con->peer_name.type;
+		__entry->sent = con->out_msg_pos.data_pos;
+	),
+	TP_printk("peer %s%lld tid %llu seq %llu sent %d",
+		  ceph_entity_type_name(__entry->peer_type), __entry->peer_num,
+		  __entry->tid, __entry->seq, __entry->sent)
+);
+
+#define CEPH_WRITE_MSG_EVENT(name) \
+DEFINE_EVENT(ceph_write_msg_class, name, \
+	TP_PROTO(struct ceph_connection *con, struct ceph_msg *msg), \
+	TP_ARGS(con, msg))
+
+CEPH_WRITE_MSG_EVENT(ceph_prepare_write_msg);
+CEPH_WRITE_MSG_EVENT(ceph_try_write_msg);
+CEPH_WRITE_MSG_EVENT(ceph_try_write_msg_done);
+
+#endif /* CEPH_TRACE_NET_MESSENGER */
 
 #endif /* _TRACE_CEPH_H */
 
diff --git a/net/ceph/messenger.c b/net/ceph/messenger.c
index ad5b708..033c4ab 100644
--- a/net/ceph/messenger.c
+++ b/net/ceph/messenger.c
@@ -20,6 +20,11 @@
 #include <linux/ceph/pagelist.h>
 #include <linux/export.h>
 
+#include <linux/tracepoint.h>
+#define CREATE_TRACE_POINTS
+#define CEPH_TRACE_NET_MESSENGER
+#include <trace/events/ceph.h>
+
 /*
  * Ceph uses the messenger to exchange ceph_msg messages with other
  * hosts in the system.  The messenger provides ordered and reliable
@@ -555,7 +560,7 @@ static void prepare_write_message(struct ceph_connection *con)
 		/* no, queue up footer too and be done */
 		prepare_write_message_footer(con, v);
 	}
-
+	trace_ceph_prepare_write_msg(con, m);
 	set_bit(WRITE_PENDING, &con->state);
 }
 
@@ -1853,8 +1858,10 @@ more_kvec:
 
 	/* msg pages? */
 	if (con->out_msg) {
+		trace_ceph_try_write_msg(con, con->out_msg);
 		if (con->out_msg_done) {
 			ceph_msg_put(con->out_msg);
+			trace_ceph_try_write_msg_done(con, con->out_msg);
 			con->out_msg = NULL;   /* we're done with this one */
 			goto do_next;
 		}
diff --git a/net/ceph/osd_client.c b/net/ceph/osd_client.c
index f44e400..767e253 100644
--- a/net/ceph/osd_client.c
+++ b/net/ceph/osd_client.c
@@ -1200,6 +1200,7 @@ static void handle_reply(struct ceph_osd_client *osdc, struct ceph_msg *msg,
 	/* lookup */
 	mutex_lock(&osdc->request_mutex);
 	req = __lookup_request(osdc, tid);
+	trace_ceph_handle_reply_msg(con, msg, rhead, req);
 	if (req == NULL) {
 		dout("handle_reply tid %llu dne\n", tid);
 		mutex_unlock(&osdc->request_mutex);
-- 
1.7.8.2

Re: [PATCH 0/2] Ceph tracepoints

[Alex Elder]

On 05/10/2012 09:35 AM, Jim Schutt wrote:
> Hi Alex,
>
> I ran across tracker #2374 today - I've been carrying these two
> tracepoint patches for a while.  Perhaps you'll find them useful.

GREAT!

I haven't looked at them but I will as soon as I get the chance.
I don't expect there's any reason not to use this as the foundation
I was looking for.

Thanks a lot.

					-Alex

> Jim Schutt (2):
>    ceph: add tracepoints for message submission on read/write requests
>    ceph: add tracepoints for message send queueing and completion, reply
>      handling
>
>   fs/ceph/addr.c              |    8 +++
>   fs/ceph/file.c              |    6 ++
>   include/trace/events/ceph.h |  144 +++++++++++++++++++++++++++++++++++++++++++
>   net/ceph/messenger.c        |    9 +++-
>   net/ceph/osd_client.c       |    8 +++
>   5 files changed, 174 insertions(+), 1 deletions(-)
>   create mode 100644 include/trace/events/ceph.h
>