| Message ID | 20181218045138.4282-2-yupeng0921@gmail.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v4,1/2] export trace.c helper functions to other modules | expand |
> @@ -899,6 +900,10 @@ static inline void nvme_handle_cqe(struct nvme_queue *nvmeq, u16 idx) > } > > req = blk_mq_tag_to_rq(*nvmeq->tags, cqe->command_id); > + trace_nvme_sq(req->rq_disk, > + nvmeq->qid, > + le16_to_cpu(cqe->sq_head), > + nvmeq->sq_tail); Why the newline escapes? why not escape at the 80 char border? Other than that, looks fine, Reviewed-by: Sagi Grimberg <sagi@grimberg.me>
On Mon, Dec 17, 2018 at 11:26 PM Sagi Grimberg <sagi@grimberg.me> wrote: > > > > @@ -899,6 +900,10 @@ static inline void nvme_handle_cqe(struct nvme_queue *nvmeq, u16 idx) > > } > > > > req = blk_mq_tag_to_rq(*nvmeq->tags, cqe->command_id); > > + trace_nvme_sq(req->rq_disk, > > + nvmeq->qid, > > + le16_to_cpu(cqe->sq_head), > > + nvmeq->sq_tail); > > Why the newline escapes? why not escape at the 80 char border? > Sorry, I don't quite understand your meaning. Do you mean I'd better change this: trace_nvme_sq(req->rq_disk, nvmeq->qid, le16_to_cpu(cqe->sq_head), nvmeq->sq_tail); to something like below: trace_nvme_sq(req->rq_disk, nvmeq->qid, le16_to_cpu(cqe->sq_head), nvmeq->sq_tail); Please let me know whether my understanding is correct.
On Mon, Dec 17, 2018 at 11:44:51PM -0800, peng yu wrote: > Sorry, I don't quite understand your meaning. Do you mean I'd better > change this: > trace_nvme_sq(req->rq_disk, > nvmeq->qid, > le16_to_cpu(cqe->sq_head), > nvmeq->sq_tail); > to something like below: > trace_nvme_sq(req->rq_disk, nvmeq->qid, le16_to_cpu(cqe->sq_head), > nvmeq->sq_tail); > Please let me know whether my understanding is correct. Yes. Let me know if this version that I've applied is fine with you: http://git.infradead.org/nvme.git/commitdiff/ed537628e59166a080d618825a7d175565a9cad4
On Mon, Dec 17, 2018 at 08:51:38PM -0800, yupeng wrote: > +TRACE_EVENT(nvme_sq, > + TP_PROTO(void *rq_disk, int qid, int sq_head, int sq_tail), > + TP_ARGS(rq_disk, qid, sq_head, sq_tail), > + TP_STRUCT__entry( > + __array(char, disk, DISK_NAME_LEN) > + __field(int, qid) > + __field(int, sq_head) > + __field(int, sq_tail) > + ), > + TP_fast_assign( > + __assign_disk_name(__entry->disk, rq_disk); > + __entry->qid = qid; > + __entry->sq_head = sq_head; > + __entry->sq_tail = sq_tail; > + ), > + TP_printk("nvme: %s qid=%d head=%d tail=%d", > + __print_disk_name(__entry->disk), No need for a space after the %s. __print_disk_name already appends a space if there's a disk name, and we don't want the extra space if there isn't one. Also, every other nvme trace has a ',' after each entry. Not a big deal, just minor format consistency.
On Tue, Dec 18, 2018 at 10:26:46AM -0700, Keith Busch wrote: > No need for a space after the %s. __print_disk_name already appends a > space if there's a disk name, and we don't want the extra space if there > isn't one. Also, every other nvme trace has a ',' after each entry. Not > a big deal, just minor format consistency. Yeah. What about something like this incremental patch to make the trace formatting and argument passing match what we otherwise do: diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c index 2477bd906904..5a0bf6a24d50 100644 --- a/drivers/nvme/host/pci.c +++ b/drivers/nvme/host/pci.c @@ -1004,8 +1004,7 @@ static inline void nvme_handle_cqe(struct nvme_queue *nvmeq, u16 idx) } req = blk_mq_tag_to_rq(*nvmeq->tags, cqe->command_id); - trace_nvme_sq(req->rq_disk, nvmeq->qid, le16_to_cpu(cqe->sq_head), - nvmeq->sq_tail); + trace_nvme_sq(req, cqe->sq_head, nvmeq->sq_tail); nvme_end_request(req, cqe->status, cqe->result); } diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h index cf666709bc50..3564120aa7b3 100644 --- a/drivers/nvme/host/trace.h +++ b/drivers/nvme/host/trace.h @@ -185,22 +185,24 @@ TRACE_EVENT(nvme_async_event, #undef aer_name TRACE_EVENT(nvme_sq, - TP_PROTO(void *rq_disk, int qid, int sq_head, int sq_tail), - TP_ARGS(rq_disk, qid, sq_head, sq_tail), + TP_PROTO(struct request *req, __le16 sq_head, int sq_tail), + TP_ARGS(req, sq_head, sq_tail), TP_STRUCT__entry( + __field(int, ctrl_id) __array(char, disk, DISK_NAME_LEN) __field(int, qid) - __field(int, sq_head) - __field(int, sq_tail) + __field(u16, sq_head) + __field(u16, sq_tail) ), TP_fast_assign( - __assign_disk_name(__entry->disk, rq_disk); - __entry->qid = qid; - __entry->sq_head = sq_head; + __entry->ctrl_id = nvme_req(req)->ctrl->instance; + __assign_disk_name(__entry->disk, req->rq_disk); + __entry->qid = nvme_req_qid(req); + __entry->sq_head = le16_to_cpu(sq_head); __entry->sq_tail = sq_tail; ), - TP_printk("nvme: %s qid=%d head=%d tail=%d", - __print_disk_name(__entry->disk), + TP_printk("nvme%d: %sqid=%d, head=%u, tail=%u", + __entry->ctrl_id, __print_disk_name(__entry->disk), __entry->qid, __entry->sq_head, __entry->sq_tail ) );
On Tue, Dec 18, 2018 at 06:47:50PM +0100, hch@lst.de wrote: > On Tue, Dec 18, 2018 at 10:26:46AM -0700, Keith Busch wrote: > > No need for a space after the %s. __print_disk_name already appends a > > space if there's a disk name, and we don't want the extra space if there > > isn't one. Also, every other nvme trace has a ',' after each entry. Not > > a big deal, just minor format consistency. > > Yeah. What about something like this incremental patch to make the > trace formatting and argument passing match what we otherwise do: Nice, that looks good. It's also necessary for admin commands since there was no other way to see which controller a completion came from without this. Reviewed-by: Keith Busch <keith.busch@intel.com> > diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c > index 2477bd906904..5a0bf6a24d50 100644 > --- a/drivers/nvme/host/pci.c > +++ b/drivers/nvme/host/pci.c > @@ -1004,8 +1004,7 @@ static inline void nvme_handle_cqe(struct nvme_queue *nvmeq, u16 idx) > } > > req = blk_mq_tag_to_rq(*nvmeq->tags, cqe->command_id); > - trace_nvme_sq(req->rq_disk, nvmeq->qid, le16_to_cpu(cqe->sq_head), > - nvmeq->sq_tail); > + trace_nvme_sq(req, cqe->sq_head, nvmeq->sq_tail); > nvme_end_request(req, cqe->status, cqe->result); > } > > diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h > index cf666709bc50..3564120aa7b3 100644 > --- a/drivers/nvme/host/trace.h > +++ b/drivers/nvme/host/trace.h > @@ -185,22 +185,24 @@ TRACE_EVENT(nvme_async_event, > #undef aer_name > > TRACE_EVENT(nvme_sq, > - TP_PROTO(void *rq_disk, int qid, int sq_head, int sq_tail), > - TP_ARGS(rq_disk, qid, sq_head, sq_tail), > + TP_PROTO(struct request *req, __le16 sq_head, int sq_tail), > + TP_ARGS(req, sq_head, sq_tail), > TP_STRUCT__entry( > + __field(int, ctrl_id) > __array(char, disk, DISK_NAME_LEN) > __field(int, qid) > - __field(int, sq_head) > - __field(int, sq_tail) > + __field(u16, sq_head) > + __field(u16, sq_tail) > ), > TP_fast_assign( > - __assign_disk_name(__entry->disk, rq_disk); > - __entry->qid = qid; > - __entry->sq_head = sq_head; > + __entry->ctrl_id = nvme_req(req)->ctrl->instance; > + __assign_disk_name(__entry->disk, req->rq_disk); > + __entry->qid = nvme_req_qid(req); > + __entry->sq_head = le16_to_cpu(sq_head); > __entry->sq_tail = sq_tail; > ), > - TP_printk("nvme: %s qid=%d head=%d tail=%d", > - __print_disk_name(__entry->disk), > + TP_printk("nvme%d: %sqid=%d, head=%u, tail=%u", > + __entry->ctrl_id, __print_disk_name(__entry->disk), > __entry->qid, __entry->sq_head, __entry->sq_tail > ) > );
On Tue, Dec 18, 2018 at 9:47 AM hch@lst.de <hch@lst.de> wrote: > diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c > index 2477bd906904..5a0bf6a24d50 100644 > --- a/drivers/nvme/host/pci.c > +++ b/drivers/nvme/host/pci.c > @@ -1004,8 +1004,7 @@ static inline void nvme_handle_cqe(struct nvme_queue *nvmeq, u16 idx) > } > > req = blk_mq_tag_to_rq(*nvmeq->tags, cqe->command_id); > - trace_nvme_sq(req->rq_disk, nvmeq->qid, le16_to_cpu(cqe->sq_head), > - nvmeq->sq_tail); > + trace_nvme_sq(req, cqe->sq_head, nvmeq->sq_tail); > nvme_end_request(req, cqe->status, cqe->result); > } > > diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h > index cf666709bc50..3564120aa7b3 100644 > --- a/drivers/nvme/host/trace.h > +++ b/drivers/nvme/host/trace.h > @@ -185,22 +185,24 @@ TRACE_EVENT(nvme_async_event, > #undef aer_name > > TRACE_EVENT(nvme_sq, > - TP_PROTO(void *rq_disk, int qid, int sq_head, int sq_tail), > - TP_ARGS(rq_disk, qid, sq_head, sq_tail), > + TP_PROTO(struct request *req, __le16 sq_head, int sq_tail), > + TP_ARGS(req, sq_head, sq_tail), > TP_STRUCT__entry( > + __field(int, ctrl_id) > __array(char, disk, DISK_NAME_LEN) > __field(int, qid) > - __field(int, sq_head) > - __field(int, sq_tail) > + __field(u16, sq_head) > + __field(u16, sq_tail) > ), > TP_fast_assign( > - __assign_disk_name(__entry->disk, rq_disk); > - __entry->qid = qid; > - __entry->sq_head = sq_head; > + __entry->ctrl_id = nvme_req(req)->ctrl->instance; > + __assign_disk_name(__entry->disk, req->rq_disk); > + __entry->qid = nvme_req_qid(req); > + __entry->sq_head = le16_to_cpu(sq_head); > __entry->sq_tail = sq_tail; > ), > - TP_printk("nvme: %s qid=%d head=%d tail=%d", > - __print_disk_name(__entry->disk), > + TP_printk("nvme%d: %sqid=%d, head=%u, tail=%u", > + __entry->ctrl_id, __print_disk_name(__entry->disk), > __entry->qid, __entry->sq_head, __entry->sq_tail > ) > ); I think this change is nice. Will you submit this change or are you suggesting me to do it?
On Tue, Dec 18, 2018 at 05:19:00PM -0800, peng yu wrote: > I think this change is nice. Will you submit this change or are you > suggesting me to do it? I've folded the changes in.
diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c index c33bb201b884..52df2f7fef37 100644 --- a/drivers/nvme/host/pci.c +++ b/drivers/nvme/host/pci.c @@ -32,6 +32,7 @@ #include <linux/sed-opal.h> #include <linux/pci-p2pdma.h> +#include "trace.h" #include "nvme.h" #define SQ_SIZE(depth) (depth * sizeof(struct nvme_command)) @@ -899,6 +900,10 @@ static inline void nvme_handle_cqe(struct nvme_queue *nvmeq, u16 idx) } req = blk_mq_tag_to_rq(*nvmeq->tags, cqe->command_id); + trace_nvme_sq(req->rq_disk, + nvmeq->qid, + le16_to_cpu(cqe->sq_head), + nvmeq->sq_tail); nvme_end_request(req, cqe->status, cqe->result); } diff --git a/drivers/nvme/host/trace.c b/drivers/nvme/host/trace.c index 8ca7079ed2bc..7bfaace23e1e 100644 --- a/drivers/nvme/host/trace.c +++ b/drivers/nvme/host/trace.c @@ -142,3 +142,5 @@ const char *nvme_trace_disk_name(struct trace_seq *p, char *name) return ret; } EXPORT_SYMBOL_GPL(nvme_trace_disk_name); + +EXPORT_TRACEPOINT_SYMBOL(nvme_sq); diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h index 196d5bd56718..3606cd7000f4 100644 --- a/drivers/nvme/host/trace.h +++ b/drivers/nvme/host/trace.h @@ -184,6 +184,27 @@ TRACE_EVENT(nvme_async_event, #undef aer_name +TRACE_EVENT(nvme_sq, + TP_PROTO(void *rq_disk, int qid, int sq_head, int sq_tail), + TP_ARGS(rq_disk, qid, sq_head, sq_tail), + TP_STRUCT__entry( + __array(char, disk, DISK_NAME_LEN) + __field(int, qid) + __field(int, sq_head) + __field(int, sq_tail) + ), + TP_fast_assign( + __assign_disk_name(__entry->disk, rq_disk); + __entry->qid = qid; + __entry->sq_head = sq_head; + __entry->sq_tail = sq_tail; + ), + TP_printk("nvme: %s qid=%d head=%d tail=%d", + __print_disk_name(__entry->disk), + __entry->qid, __entry->sq_head, __entry->sq_tail + ) +); + #endif /* _TRACE_NVME_H */ #undef TRACE_INCLUDE_PATH
export nvme disk name, queue id, sq_head, sq_tail to trace event usage example: go to the event directory: cd /sys/kernel/debug/tracing/events/nvme/nvme_sq filter by disk name: echo 'disk=="nvme1n1"' > filter enable the event: echo 1 > enable check results from trace_pipe: cat /sys/kernel/debug/tracing/trace_pipe In practice, this patch help me debug hardware related performant issue. Signed-off-by: yupeng <yupeng0921@gmail.com> --- drivers/nvme/host/pci.c | 5 +++++ drivers/nvme/host/trace.c | 2 ++ drivers/nvme/host/trace.h | 21 +++++++++++++++++++++ 3 files changed, 28 insertions(+)