mmc: Provide tracepoints for request processing
diff mbox

Message ID 05d6338bddae751c1755e7825d4179658e78cc71.1458819912.git.baolin.wang@linaro.org
State New
Headers show

Commit Message

(Exiting) Baolin Wang March 24, 2016, 11:54 a.m. UTC
This patch provides some tracepoints for the lifecycle of a request from
fetching to completion to help with performance analysis of MMC subsystem.

Signed-off-by: Baolin Wang <baolin.wang@linaro.org>
---
 drivers/mmc/card/block.c   |    6 ++
 drivers/mmc/card/queue.c   |    4 +
 drivers/mmc/core/core.c    |    5 ++
 include/trace/events/mmc.h |  188 ++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 203 insertions(+)
 create mode 100644 include/trace/events/mmc.h

Comments

kbuild test robot March 24, 2016, 2:02 p.m. UTC | #1
Hi Baolin,

[auto build test ERROR on ulf.hansson-mmc/next]
[also build test ERROR on v4.5 next-20160324]
[if your patch is applied to the wrong git tree, please drop us a note to help improving the system]

url:    https://github.com/0day-ci/linux/commits/Baolin-Wang/mmc-Provide-tracepoints-for-request-processing/20160324-195755
base:   https://git.linaro.org/people/ulf.hansson/mmc next
config: x86_64-rhel (attached as .config)
reproduce:
        # save the attached .config to linux build tree
        make ARCH=x86_64 

All errors (new ones prefixed by >>):

>> ERROR: "__tracepoint_mmc_request_start" [drivers/mmc/core/mmc_core.ko] undefined!
>> ERROR: "__tracepoint_mmc_request_done" [drivers/mmc/core/mmc_core.ko] undefined!

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation
Jens Axboe March 24, 2016, 2:08 p.m. UTC | #2
On 03/24/2016 05:54 AM, Baolin Wang wrote:
> This patch provides some tracepoints for the lifecycle of a request from
> fetching to completion to help with performance analysis of MMC subsystem.

Most of these already exist as block layer trace points, why do we need 
mmc specific ones?
kbuild test robot March 24, 2016, 2:53 p.m. UTC | #3
Hi Baolin,

[auto build test ERROR on ulf.hansson-mmc/next]
[also build test ERROR on v4.5 next-20160324]
[if your patch is applied to the wrong git tree, please drop us a note to help improving the system]

url:    https://github.com/0day-ci/linux/commits/Baolin-Wang/mmc-Provide-tracepoints-for-request-processing/20160324-195755
base:   https://git.linaro.org/people/ulf.hansson/mmc next
config: x86_64-randconfig-n0-03242034 (attached as .config)
reproduce:
        # save the attached .config to linux build tree
        make ARCH=x86_64 

All errors (new ones prefixed by >>):

   drivers/built-in.o: In function `mmc_request_done':
>> (.text+0x62f58f): undefined reference to `__tracepoint_mmc_request_done'
   drivers/built-in.o: In function `mmc_request_done':
   (.text+0x62f65e): undefined reference to `__tracepoint_mmc_request_done'
   drivers/built-in.o: In function `mmc_request_done':
   (.text+0x62f6ee): undefined reference to `__tracepoint_mmc_request_done'
   drivers/built-in.o: In function `mmc_start_request':
>> core.c:(.text+0x62f8f1): undefined reference to `__tracepoint_mmc_request_start'
   core.c:(.text+0x62f9ad): undefined reference to `__tracepoint_mmc_request_start'
   core.c:(.text+0x62fbf1): undefined reference to `__tracepoint_mmc_request_start'

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation
Steven Rostedt March 24, 2016, 3:13 p.m. UTC | #4
On Thu, 24 Mar 2016 19:54:08 +0800
Baolin Wang <baolin.wang@linaro.org> wrote:


> +++ b/include/trace/events/mmc.h
> @@ -0,0 +1,188 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM mmc
> +
> +#if !defined(_TRACE_MMC_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_MMC_H
> +
> +#include <linux/blkdev.h>
> +#include <linux/mmc/core.h>
> +#include <linux/mmc/host.h>
> +#include <linux/tracepoint.h>
> +
> +DECLARE_EVENT_CLASS(mmc_request,
> +
> +	TP_PROTO(struct request *rq),
> +
> +	TP_ARGS(rq),
> +
> +	TP_STRUCT__entry(
> +		__field(sector_t,		sector)
> +		__field(unsigned int,		data_len)
> +		__field(int,			cmd_dir)
> +		__field(struct request *,	rq)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->sector = blk_rq_pos(rq);
> +		__entry->data_len = blk_rq_bytes(rq);
> +		__entry->cmd_dir = rq_data_dir(rq);
> +		__entry->rq = rq;
> +	),
> +
> +	TP_printk("struct request[%p]:sector=%lu rw=%d len=%u",
> +		  (struct request *)__entry->rq,
> +		  (unsigned long)__entry->sector,
> +		  (int)__entry->cmd_dir,
> +		  (unsigned int)__entry->data_len)

Why the typecasts? __entry->rq is already of the type "struct request *"
as you declared it in the TP_STRUCT__entry(). Same for the other fields.


> +);
> +
> +DEFINE_EVENT(mmc_request, mmc_queue_fetch,
> +
> +	TP_PROTO(struct request *rq),
> +
> +	TP_ARGS(rq)
> +
> +);
> +
> +DEFINE_EVENT(mmc_request, mmc_block_packed_req,
> +
> +	TP_PROTO(struct request *rq),
> +
> +	TP_ARGS(rq)
> +
> +);
> +
> +DEFINE_EVENT(mmc_request, mmc_block_req_done,
> +
> +	TP_PROTO(struct request *rq),
> +
> +	TP_ARGS(rq)
> +
> +);
> +
> +TRACE_EVENT(mmc_request_start,
> +
> +	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
> +
> +	TP_ARGS(host, mrq),
> +
> +	TP_STRUCT__entry(
> +		__field(u32,			cmd_opcode)
> +		__field(u32,			cmd_arg)
> +		__field(unsigned int,		cmd_flags)
> +		__field(u32,			stop_opcode)
> +		__field(u32,			stop_arg)
> +		__field(unsigned int,		stop_flags)
> +		__field(u32,			sbc_opcode)
> +		__field(u32,			sbc_arg)
> +		__field(unsigned int,		sbc_flags)
> +		__field(unsigned int,		blocks)
> +		__field(unsigned int,		blksz)
> +		__field(unsigned int,		data_flags)
> +		__field(struct mmc_request *,	mrq)
> +		__field(struct mmc_host *,	host)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->cmd_opcode = mrq->cmd->opcode;
> +		__entry->cmd_arg = mrq->cmd->arg;
> +		__entry->cmd_flags = mrq->cmd->flags;
> +		__entry->stop_opcode = mrq->stop ? mrq->stop->opcode : 0;
> +		__entry->stop_arg = mrq->stop ? mrq->stop->arg : 0;
> +		__entry->stop_flags = mrq->stop ? mrq->stop->flags : 0;
> +		__entry->sbc_opcode = mrq->sbc ? mrq->sbc->opcode : 0;
> +		__entry->sbc_arg = mrq->sbc ? mrq->sbc->arg : 0;
> +		__entry->sbc_flags = mrq->sbc ? mrq->sbc->flags : 0;
> +		__entry->blksz = mrq->data ? mrq->data->blksz : 0;
> +		__entry->blocks = mrq->data ? mrq->data->blocks : 0;
> +		__entry->data_flags = mrq->data ? mrq->data->flags : 0;
> +		__entry->mrq = mrq;
> +		__entry->host = host;
> +	),
> +
> +	TP_printk("%s: start struct mmc_request[%p]: "
> +		  "cmd_opcode=%u cmd_arg=0x%x cmd_flags=0x%x "
> +		  "stop_opcode=%u stop_arg=0x%x stop_flags=0x%x "
> +		  "sbc_opcode=%u sbc_arg=0x%x sbc_flags=0x%x "
> +		  "blocks=%u blksz=%u data_flags=0x%x",
> +		  mmc_hostname((struct mmc_host *)__entry->host),

Is this safe? I see mmc_hostname() defined as:

 dev_name(&(x)->class_dev)

Which would be here:

 dev_name(&(__entry->host)->class_dev)

How what happens if ater you trace a host, you free it? Then the old
pointer will still be in the buffer. If the user reads the trace data
and this is called, then __entry->host will be pointing to freed data,
and the dereference could cause a system crash.


> +		  (struct mmc_request *)__entry->mrq,
> +		  (u32)__entry->cmd_opcode, (u32)__entry->cmd_arg,
> +		  (unsigned int)__entry->cmd_flags,
> +		  (u32)__entry->stop_opcode, (u32)__entry->stop_arg,
> +		  (unsigned int)__entry->stop_flags,
> +		  (u32)__entry->sbc_opcode, (u32)__entry->sbc_arg,
> +		  (unsigned int)__entry->sbc_flags,
> +		  (unsigned int)__entry->blocks,
> +		  (unsigned int)__entry->blksz,
> +		  (unsigned int)__entry->data_flags)
> +);
> +
> +TRACE_EVENT(mmc_request_done,
> +
> +	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
> +
> +	TP_ARGS(host, mrq),
> +
> +	TP_STRUCT__entry(
> +		__field(u32,		cmd_opcode)
> +		__field(int,		cmd_err)
> +		__array(u32,		cmd_resp,	4)
> +		__field(u32,		stop_opcode)
> +		__field(int,		stop_err)
> +		__array(u32,		stop_resp,	4)
> +		__field(u32,		sbc_opcode)
> +		__field(int,		sbc_err)
> +		__array(u32,		sbc_resp,	4)
> +		__field(unsigned int,		bytes_xfered)
> +		__field(int,			data_err)
> +		__field(struct mmc_request *,	mrq)
> +		__field(struct mmc_host *,	host)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->cmd_opcode = mrq->cmd->opcode;
> +		__entry->cmd_err = mrq->cmd->error;
> +		memcpy(__entry->cmd_resp, mrq->cmd->resp, 4);
> +		__entry->stop_opcode = mrq->stop ? mrq->stop->opcode : 0;
> +		__entry->stop_err = mrq->stop ? mrq->stop->error : 0;
> +		__entry->stop_resp[0] = mrq->stop ? mrq->stop->resp[0] : 0;
> +		__entry->stop_resp[1] = mrq->stop ? mrq->stop->resp[1] : 0;
> +		__entry->stop_resp[2] = mrq->stop ? mrq->stop->resp[2] : 0;
> +		__entry->stop_resp[3] = mrq->stop ? mrq->stop->resp[3] : 0;
> +		__entry->sbc_opcode = mrq->sbc ? mrq->sbc->opcode : 0;
> +		__entry->sbc_err = mrq->sbc ? mrq->sbc->error : 0;
> +		__entry->sbc_resp[0] = mrq->sbc ? mrq->sbc->resp[0] : 0;
> +		__entry->sbc_resp[1] = mrq->sbc ? mrq->sbc->resp[1] : 0;
> +		__entry->sbc_resp[2] = mrq->sbc ? mrq->sbc->resp[2] : 0;
> +		__entry->sbc_resp[3] = mrq->sbc ? mrq->sbc->resp[3] : 0;
> +		__entry->bytes_xfered = mrq->data ? mrq->data->bytes_xfered : 0;
> +		__entry->data_err = mrq->data ? mrq->data->error : 0;
> +		__entry->host = host;
> +		__entry->mrq = mrq;
> +	),
> +
> +	TP_printk("%s: end struct mmc_request[%p]: "
> +		  "cmd_opcode=%u cmd_err=%d cmd_resp=0x%x 0x%x 0x%x 0x%x "
> +		  "stop_opcode=%u stop_err=%d stop_resp=0x%x 0x%x 0x%x 0x%x "
> +		  "sbc_opcode=%u sbc_err=%d sbc_resp=0x%x 0x%x 0x%x 0x%x "
> +		  "bytes_xfered=%u data_err=%d",
> +		  mmc_hostname((struct mmc_host *)__entry->host),

Same here, and please get rid of all the redundant typecasts.

-- Steve

> +		  (struct mmc_request *)__entry->mrq,
> +		  (u32)__entry->cmd_opcode, (int)__entry->cmd_err,
> +		  (u32)__entry->cmd_resp[0], (u32)__entry->cmd_resp[1],
> +		  (u32)__entry->cmd_resp[2], (u32)__entry->cmd_resp[3],
> +		  (u32)__entry->stop_opcode, (int)__entry->stop_err,
> +		  (u32)__entry->stop_resp[0], (u32)__entry->stop_resp[1],
> +		  (u32)__entry->stop_resp[2], (u32)__entry->stop_resp[3],
> +		  (u32)__entry->sbc_opcode, (int)__entry->sbc_err,
> +		  (u32)__entry->sbc_resp[0], (u32)__entry->sbc_resp[1],
> +		  (u32)__entry->sbc_resp[2], (u32)__entry->sbc_resp[3],
> +		  (unsigned int)__entry->bytes_xfered,
> +		  (int)__entry->data_err)
> +);
> +
> +#endif /* _TRACE_MMC_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>

--
To unsubscribe from this list: send the line "unsubscribe linux-mmc" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
(Exiting) Baolin Wang March 25, 2016, 7:32 a.m. UTC | #5
On 24 March 2016 at 22:08, Jens Axboe <axboe@fb.com> wrote:
> On 03/24/2016 05:54 AM, Baolin Wang wrote:
>>
>> This patch provides some tracepoints for the lifecycle of a request from
>> fetching to completion to help with performance analysis of MMC subsystem.
>
>
> Most of these already exist as block layer trace points, why do we need mmc
> specific ones?

Currently the MMC core does not have any tracepoints for use with
ftrace. These are very useful as they provide a very low overhead
runtime controllable way of getting diagnostics from the system which
is capable of recording a great deal of information without impacting
system performance. We have tracepoints in the block layer so we can
do some trace of MMC but none in MMC itself so adding some where
appropriate would help people follow the activity of subsystem.

>
>
> --
> Jens Axboe
>
(Exiting) Baolin Wang March 25, 2016, 7:58 a.m. UTC | #6
On 24 March 2016 at 23:13, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Thu, 24 Mar 2016 19:54:08 +0800
> Baolin Wang <baolin.wang@linaro.org> wrote:
>
>
>> +++ b/include/trace/events/mmc.h
>> @@ -0,0 +1,188 @@
>> +#undef TRACE_SYSTEM
>> +#define TRACE_SYSTEM mmc
>> +
>> +#if !defined(_TRACE_MMC_H) || defined(TRACE_HEADER_MULTI_READ)
>> +#define _TRACE_MMC_H
>> +
>> +#include <linux/blkdev.h>
>> +#include <linux/mmc/core.h>
>> +#include <linux/mmc/host.h>
>> +#include <linux/tracepoint.h>
>> +
>> +DECLARE_EVENT_CLASS(mmc_request,
>> +
>> +     TP_PROTO(struct request *rq),
>> +
>> +     TP_ARGS(rq),
>> +
>> +     TP_STRUCT__entry(
>> +             __field(sector_t,               sector)
>> +             __field(unsigned int,           data_len)
>> +             __field(int,                    cmd_dir)
>> +             __field(struct request *,       rq)
>> +     ),
>> +
>> +     TP_fast_assign(
>> +             __entry->sector = blk_rq_pos(rq);
>> +             __entry->data_len = blk_rq_bytes(rq);
>> +             __entry->cmd_dir = rq_data_dir(rq);
>> +             __entry->rq = rq;
>> +     ),
>> +
>> +     TP_printk("struct request[%p]:sector=%lu rw=%d len=%u",
>> +               (struct request *)__entry->rq,
>> +               (unsigned long)__entry->sector,
>> +               (int)__entry->cmd_dir,
>> +               (unsigned int)__entry->data_len)
>
> Why the typecasts? __entry->rq is already of the type "struct request *"
> as you declared it in the TP_STRUCT__entry(). Same for the other fields.

Oh, I'll remove all the typecasts. Thanks.

>
>
>> +);
>> +
>> +DEFINE_EVENT(mmc_request, mmc_queue_fetch,
>> +
>> +     TP_PROTO(struct request *rq),
>> +
>> +     TP_ARGS(rq)
>> +
>> +);
>> +
>> +DEFINE_EVENT(mmc_request, mmc_block_packed_req,
>> +
>> +     TP_PROTO(struct request *rq),
>> +
>> +     TP_ARGS(rq)
>> +
>> +);
>> +
>> +DEFINE_EVENT(mmc_request, mmc_block_req_done,
>> +
>> +     TP_PROTO(struct request *rq),
>> +
>> +     TP_ARGS(rq)
>> +
>> +);
>> +
>> +TRACE_EVENT(mmc_request_start,
>> +
>> +     TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
>> +
>> +     TP_ARGS(host, mrq),
>> +
>> +     TP_STRUCT__entry(
>> +             __field(u32,                    cmd_opcode)
>> +             __field(u32,                    cmd_arg)
>> +             __field(unsigned int,           cmd_flags)
>> +             __field(u32,                    stop_opcode)
>> +             __field(u32,                    stop_arg)
>> +             __field(unsigned int,           stop_flags)
>> +             __field(u32,                    sbc_opcode)
>> +             __field(u32,                    sbc_arg)
>> +             __field(unsigned int,           sbc_flags)
>> +             __field(unsigned int,           blocks)
>> +             __field(unsigned int,           blksz)
>> +             __field(unsigned int,           data_flags)
>> +             __field(struct mmc_request *,   mrq)
>> +             __field(struct mmc_host *,      host)
>> +     ),
>> +
>> +     TP_fast_assign(
>> +             __entry->cmd_opcode = mrq->cmd->opcode;
>> +             __entry->cmd_arg = mrq->cmd->arg;
>> +             __entry->cmd_flags = mrq->cmd->flags;
>> +             __entry->stop_opcode = mrq->stop ? mrq->stop->opcode : 0;
>> +             __entry->stop_arg = mrq->stop ? mrq->stop->arg : 0;
>> +             __entry->stop_flags = mrq->stop ? mrq->stop->flags : 0;
>> +             __entry->sbc_opcode = mrq->sbc ? mrq->sbc->opcode : 0;
>> +             __entry->sbc_arg = mrq->sbc ? mrq->sbc->arg : 0;
>> +             __entry->sbc_flags = mrq->sbc ? mrq->sbc->flags : 0;
>> +             __entry->blksz = mrq->data ? mrq->data->blksz : 0;
>> +             __entry->blocks = mrq->data ? mrq->data->blocks : 0;
>> +             __entry->data_flags = mrq->data ? mrq->data->flags : 0;
>> +             __entry->mrq = mrq;
>> +             __entry->host = host;
>> +     ),
>> +
>> +     TP_printk("%s: start struct mmc_request[%p]: "
>> +               "cmd_opcode=%u cmd_arg=0x%x cmd_flags=0x%x "
>> +               "stop_opcode=%u stop_arg=0x%x stop_flags=0x%x "
>> +               "sbc_opcode=%u sbc_arg=0x%x sbc_flags=0x%x "
>> +               "blocks=%u blksz=%u data_flags=0x%x",
>> +               mmc_hostname((struct mmc_host *)__entry->host),
>
> Is this safe? I see mmc_hostname() defined as:
>
>  dev_name(&(x)->class_dev)
>
> Which would be here:
>
>  dev_name(&(__entry->host)->class_dev)
>
> How what happens if ater you trace a host, you free it? Then the old
> pointer will still be in the buffer. If the user reads the trace data
> and this is called, then __entry->host will be pointing to freed data,
> and the dereference could cause a system crash.

Sorry, I missed that, you are right. I'll fix that in next version.
Thanks for your good comments.

>
>
>> +               (struct mmc_request *)__entry->mrq,
>> +               (u32)__entry->cmd_opcode, (u32)__entry->cmd_arg,
>> +               (unsigned int)__entry->cmd_flags,
>> +               (u32)__entry->stop_opcode, (u32)__entry->stop_arg,
>> +               (unsigned int)__entry->stop_flags,
>> +               (u32)__entry->sbc_opcode, (u32)__entry->sbc_arg,
>> +               (unsigned int)__entry->sbc_flags,
>> +               (unsigned int)__entry->blocks,
>> +               (unsigned int)__entry->blksz,
>> +               (unsigned int)__entry->data_flags)
>> +);
>> +
>> +TRACE_EVENT(mmc_request_done,
>> +
>> +     TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
>> +
>> +     TP_ARGS(host, mrq),
>> +
>> +     TP_STRUCT__entry(
>> +             __field(u32,            cmd_opcode)
>> +             __field(int,            cmd_err)
>> +             __array(u32,            cmd_resp,       4)
>> +             __field(u32,            stop_opcode)
>> +             __field(int,            stop_err)
>> +             __array(u32,            stop_resp,      4)
>> +             __field(u32,            sbc_opcode)
>> +             __field(int,            sbc_err)
>> +             __array(u32,            sbc_resp,       4)
>> +             __field(unsigned int,           bytes_xfered)
>> +             __field(int,                    data_err)
>> +             __field(struct mmc_request *,   mrq)
>> +             __field(struct mmc_host *,      host)
>> +     ),
>> +
>> +     TP_fast_assign(
>> +             __entry->cmd_opcode = mrq->cmd->opcode;
>> +             __entry->cmd_err = mrq->cmd->error;
>> +             memcpy(__entry->cmd_resp, mrq->cmd->resp, 4);
>> +             __entry->stop_opcode = mrq->stop ? mrq->stop->opcode : 0;
>> +             __entry->stop_err = mrq->stop ? mrq->stop->error : 0;
>> +             __entry->stop_resp[0] = mrq->stop ? mrq->stop->resp[0] : 0;
>> +             __entry->stop_resp[1] = mrq->stop ? mrq->stop->resp[1] : 0;
>> +             __entry->stop_resp[2] = mrq->stop ? mrq->stop->resp[2] : 0;
>> +             __entry->stop_resp[3] = mrq->stop ? mrq->stop->resp[3] : 0;
>> +             __entry->sbc_opcode = mrq->sbc ? mrq->sbc->opcode : 0;
>> +             __entry->sbc_err = mrq->sbc ? mrq->sbc->error : 0;
>> +             __entry->sbc_resp[0] = mrq->sbc ? mrq->sbc->resp[0] : 0;
>> +             __entry->sbc_resp[1] = mrq->sbc ? mrq->sbc->resp[1] : 0;
>> +             __entry->sbc_resp[2] = mrq->sbc ? mrq->sbc->resp[2] : 0;
>> +             __entry->sbc_resp[3] = mrq->sbc ? mrq->sbc->resp[3] : 0;
>> +             __entry->bytes_xfered = mrq->data ? mrq->data->bytes_xfered : 0;
>> +             __entry->data_err = mrq->data ? mrq->data->error : 0;
>> +             __entry->host = host;
>> +             __entry->mrq = mrq;
>> +     ),
>> +
>> +     TP_printk("%s: end struct mmc_request[%p]: "
>> +               "cmd_opcode=%u cmd_err=%d cmd_resp=0x%x 0x%x 0x%x 0x%x "
>> +               "stop_opcode=%u stop_err=%d stop_resp=0x%x 0x%x 0x%x 0x%x "
>> +               "sbc_opcode=%u sbc_err=%d sbc_resp=0x%x 0x%x 0x%x 0x%x "
>> +               "bytes_xfered=%u data_err=%d",
>> +               mmc_hostname((struct mmc_host *)__entry->host),
>
> Same here, and please get rid of all the redundant typecasts.

OK.

>
> -- Steve
>
>> +               (struct mmc_request *)__entry->mrq,
>> +               (u32)__entry->cmd_opcode, (int)__entry->cmd_err,
>> +               (u32)__entry->cmd_resp[0], (u32)__entry->cmd_resp[1],
>> +               (u32)__entry->cmd_resp[2], (u32)__entry->cmd_resp[3],
>> +               (u32)__entry->stop_opcode, (int)__entry->stop_err,
>> +               (u32)__entry->stop_resp[0], (u32)__entry->stop_resp[1],
>> +               (u32)__entry->stop_resp[2], (u32)__entry->stop_resp[3],
>> +               (u32)__entry->sbc_opcode, (int)__entry->sbc_err,
>> +               (u32)__entry->sbc_resp[0], (u32)__entry->sbc_resp[1],
>> +               (u32)__entry->sbc_resp[2], (u32)__entry->sbc_resp[3],
>> +               (unsigned int)__entry->bytes_xfered,
>> +               (int)__entry->data_err)
>> +);
>> +
>> +#endif /* _TRACE_MMC_H */
>> +
>> +/* This part must be outside protection */
>> +#include <trace/define_trace.h>
>
Jens Axboe March 25, 2016, 2:07 p.m. UTC | #7
On 03/25/2016 01:32 AM, Baolin Wang wrote:
> On 24 March 2016 at 22:08, Jens Axboe <axboe@fb.com> wrote:
>> On 03/24/2016 05:54 AM, Baolin Wang wrote:
>>>
>>> This patch provides some tracepoints for the lifecycle of a request from
>>> fetching to completion to help with performance analysis of MMC subsystem.
>>
>>
>> Most of these already exist as block layer trace points, why do we need mmc
>> specific ones?
>
> Currently the MMC core does not have any tracepoints for use with
> ftrace. These are very useful as they provide a very low overhead
> runtime controllable way of getting diagnostics from the system which
> is capable of recording a great deal of information without impacting
> system performance. We have tracepoints in the block layer so we can
> do some trace of MMC but none in MMC itself so adding some where
> appropriate would help people follow the activity of subsystem.

But more than half of the trace points you added, those are DIRECTLY 
related to the block event. So what you are saying makes little sense. I 
see you resend it with the same trace points, I'll comment on that mail.
(Exiting) Baolin Wang March 28, 2016, 4:55 a.m. UTC | #8
On 25 March 2016 at 22:07, Jens Axboe <axboe@fb.com> wrote:
> On 03/25/2016 01:32 AM, Baolin Wang wrote:
>>
>> On 24 March 2016 at 22:08, Jens Axboe <axboe@fb.com> wrote:
>>>
>>> On 03/24/2016 05:54 AM, Baolin Wang wrote:
>>>>
>>>>
>>>> This patch provides some tracepoints for the lifecycle of a request from
>>>> fetching to completion to help with performance analysis of MMC
>>>> subsystem.
>>>
>>>
>>>
>>> Most of these already exist as block layer trace points, why do we need
>>> mmc
>>> specific ones?
>>
>>
>> Currently the MMC core does not have any tracepoints for use with
>> ftrace. These are very useful as they provide a very low overhead
>> runtime controllable way of getting diagnostics from the system which
>> is capable of recording a great deal of information without impacting
>> system performance. We have tracepoints in the block layer so we can
>> do some trace of MMC but none in MMC itself so adding some where
>> appropriate would help people follow the activity of subsystem.
>
>
> But more than half of the trace points you added, those are DIRECTLY related
> to the block event. So what you are saying makes little sense. I see you
> resend it with the same trace points, I'll comment on that mail.

OK. I'll address your comments on that new mail. Thanks.

>
> --
> Jens Axboe
>

Patch
diff mbox

diff --git a/drivers/mmc/card/block.c b/drivers/mmc/card/block.c
index fe207e5..d372a2d 100644
--- a/drivers/mmc/card/block.c
+++ b/drivers/mmc/card/block.c
@@ -46,6 +46,9 @@ 
 
 #include "queue.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/mmc.h>
+
 MODULE_ALIAS("mmc:block");
 #ifdef MODULE_PARAM_PREFIX
 #undef MODULE_PARAM_PREFIX
@@ -1709,6 +1712,7 @@  static u8 mmc_blk_prep_packed_list(struct mmc_queue *mq, struct request *req)
 		if (phys_segments > max_phys_segs)
 			break;
 
+		trace_mmc_block_packed_req(next);
 		list_add_tail(&next->queuelist, &mqrq->packed->list);
 		cur = next;
 		reqs++;
@@ -1870,6 +1874,7 @@  static int mmc_blk_end_packed_req(struct mmc_queue_req *mq_rq)
 		}
 		list_del_init(&prq->queuelist);
 		blk_end_request(prq, 0, blk_rq_bytes(prq));
+		trace_mmc_block_req_done(prq);
 		i++;
 	}
 
@@ -1985,6 +1990,7 @@  static int mmc_blk_issue_rw_rq(struct mmc_queue *mq, struct request *rqc)
 			} else {
 				ret = blk_end_request(req, 0,
 						brq->data.bytes_xfered);
+				trace_mmc_block_req_done(req);
 			}
 
 			/*
diff --git a/drivers/mmc/card/queue.c b/drivers/mmc/card/queue.c
index 6f4323c..d0388cf 100644
--- a/drivers/mmc/card/queue.c
+++ b/drivers/mmc/card/queue.c
@@ -16,6 +16,7 @@ 
 #include <linux/kthread.h>
 #include <linux/scatterlist.h>
 #include <linux/dma-mapping.h>
+#include <trace/events/mmc.h>
 
 #include <linux/mmc/card.h>
 #include <linux/mmc/host.h>
@@ -64,6 +65,9 @@  static int mmc_queue_thread(void *d)
 		mq->mqrq_cur->req = req;
 		spin_unlock_irq(q->queue_lock);
 
+		if (req)
+			trace_mmc_queue_fetch(req);
+
 		if (req || mq->mqrq_prev->req) {
 			set_current_state(TASK_RUNNING);
 			cmd_flags = req ? req->cmd_flags : 0;
diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index f95d41f..cb575ca 100644
--- a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -29,6 +29,7 @@ 
 #include <linux/random.h>
 #include <linux/slab.h>
 #include <linux/of.h>
+#include <trace/events/mmc.h>
 
 #include <linux/mmc/card.h>
 #include <linux/mmc/host.h>
@@ -152,6 +153,8 @@  void mmc_request_done(struct mmc_host *host, struct mmc_request *mrq)
 
 		led_trigger_event(host->led, LED_OFF);
 
+		trace_mmc_request_done(host, mrq);
+
 		if (mrq->sbc) {
 			pr_debug("%s: req done <CMD%u>: %d: %08x %08x %08x %08x\n",
 				mmc_hostname(host), mrq->sbc->opcode,
@@ -229,6 +232,8 @@  static int mmc_start_request(struct mmc_host *host, struct mmc_request *mrq)
 	if (mmc_card_removed(host->card))
 		return -ENOMEDIUM;
 
+	trace_mmc_request_start(host, mrq);
+
 	if (mrq->sbc) {
 		pr_debug("<%s: starting CMD%u arg %08x flags %08x>\n",
 			 mmc_hostname(host), mrq->sbc->opcode,
diff --git a/include/trace/events/mmc.h b/include/trace/events/mmc.h
new file mode 100644
index 0000000..1af63cd
--- /dev/null
+++ b/include/trace/events/mmc.h
@@ -0,0 +1,188 @@ 
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM mmc
+
+#if !defined(_TRACE_MMC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_MMC_H
+
+#include <linux/blkdev.h>
+#include <linux/mmc/core.h>
+#include <linux/mmc/host.h>
+#include <linux/tracepoint.h>
+
+DECLARE_EVENT_CLASS(mmc_request,
+
+	TP_PROTO(struct request *rq),
+
+	TP_ARGS(rq),
+
+	TP_STRUCT__entry(
+		__field(sector_t,		sector)
+		__field(unsigned int,		data_len)
+		__field(int,			cmd_dir)
+		__field(struct request *,	rq)
+	),
+
+	TP_fast_assign(
+		__entry->sector = blk_rq_pos(rq);
+		__entry->data_len = blk_rq_bytes(rq);
+		__entry->cmd_dir = rq_data_dir(rq);
+		__entry->rq = rq;
+	),
+
+	TP_printk("struct request[%p]:sector=%lu rw=%d len=%u",
+		  (struct request *)__entry->rq,
+		  (unsigned long)__entry->sector,
+		  (int)__entry->cmd_dir,
+		  (unsigned int)__entry->data_len)
+);
+
+DEFINE_EVENT(mmc_request, mmc_queue_fetch,
+
+	TP_PROTO(struct request *rq),
+
+	TP_ARGS(rq)
+
+);
+
+DEFINE_EVENT(mmc_request, mmc_block_packed_req,
+
+	TP_PROTO(struct request *rq),
+
+	TP_ARGS(rq)
+
+);
+
+DEFINE_EVENT(mmc_request, mmc_block_req_done,
+
+	TP_PROTO(struct request *rq),
+
+	TP_ARGS(rq)
+
+);
+
+TRACE_EVENT(mmc_request_start,
+
+	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
+
+	TP_ARGS(host, mrq),
+
+	TP_STRUCT__entry(
+		__field(u32,			cmd_opcode)
+		__field(u32,			cmd_arg)
+		__field(unsigned int,		cmd_flags)
+		__field(u32,			stop_opcode)
+		__field(u32,			stop_arg)
+		__field(unsigned int,		stop_flags)
+		__field(u32,			sbc_opcode)
+		__field(u32,			sbc_arg)
+		__field(unsigned int,		sbc_flags)
+		__field(unsigned int,		blocks)
+		__field(unsigned int,		blksz)
+		__field(unsigned int,		data_flags)
+		__field(struct mmc_request *,	mrq)
+		__field(struct mmc_host *,	host)
+	),
+
+	TP_fast_assign(
+		__entry->cmd_opcode = mrq->cmd->opcode;
+		__entry->cmd_arg = mrq->cmd->arg;
+		__entry->cmd_flags = mrq->cmd->flags;
+		__entry->stop_opcode = mrq->stop ? mrq->stop->opcode : 0;
+		__entry->stop_arg = mrq->stop ? mrq->stop->arg : 0;
+		__entry->stop_flags = mrq->stop ? mrq->stop->flags : 0;
+		__entry->sbc_opcode = mrq->sbc ? mrq->sbc->opcode : 0;
+		__entry->sbc_arg = mrq->sbc ? mrq->sbc->arg : 0;
+		__entry->sbc_flags = mrq->sbc ? mrq->sbc->flags : 0;
+		__entry->blksz = mrq->data ? mrq->data->blksz : 0;
+		__entry->blocks = mrq->data ? mrq->data->blocks : 0;
+		__entry->data_flags = mrq->data ? mrq->data->flags : 0;
+		__entry->mrq = mrq;
+		__entry->host = host;
+	),
+
+	TP_printk("%s: start struct mmc_request[%p]: "
+		  "cmd_opcode=%u cmd_arg=0x%x cmd_flags=0x%x "
+		  "stop_opcode=%u stop_arg=0x%x stop_flags=0x%x "
+		  "sbc_opcode=%u sbc_arg=0x%x sbc_flags=0x%x "
+		  "blocks=%u blksz=%u data_flags=0x%x",
+		  mmc_hostname((struct mmc_host *)__entry->host),
+		  (struct mmc_request *)__entry->mrq,
+		  (u32)__entry->cmd_opcode, (u32)__entry->cmd_arg,
+		  (unsigned int)__entry->cmd_flags,
+		  (u32)__entry->stop_opcode, (u32)__entry->stop_arg,
+		  (unsigned int)__entry->stop_flags,
+		  (u32)__entry->sbc_opcode, (u32)__entry->sbc_arg,
+		  (unsigned int)__entry->sbc_flags,
+		  (unsigned int)__entry->blocks,
+		  (unsigned int)__entry->blksz,
+		  (unsigned int)__entry->data_flags)
+);
+
+TRACE_EVENT(mmc_request_done,
+
+	TP_PROTO(struct mmc_host *host, struct mmc_request *mrq),
+
+	TP_ARGS(host, mrq),
+
+	TP_STRUCT__entry(
+		__field(u32,		cmd_opcode)
+		__field(int,		cmd_err)
+		__array(u32,		cmd_resp,	4)
+		__field(u32,		stop_opcode)
+		__field(int,		stop_err)
+		__array(u32,		stop_resp,	4)
+		__field(u32,		sbc_opcode)
+		__field(int,		sbc_err)
+		__array(u32,		sbc_resp,	4)
+		__field(unsigned int,		bytes_xfered)
+		__field(int,			data_err)
+		__field(struct mmc_request *,	mrq)
+		__field(struct mmc_host *,	host)
+	),
+
+	TP_fast_assign(
+		__entry->cmd_opcode = mrq->cmd->opcode;
+		__entry->cmd_err = mrq->cmd->error;
+		memcpy(__entry->cmd_resp, mrq->cmd->resp, 4);
+		__entry->stop_opcode = mrq->stop ? mrq->stop->opcode : 0;
+		__entry->stop_err = mrq->stop ? mrq->stop->error : 0;
+		__entry->stop_resp[0] = mrq->stop ? mrq->stop->resp[0] : 0;
+		__entry->stop_resp[1] = mrq->stop ? mrq->stop->resp[1] : 0;
+		__entry->stop_resp[2] = mrq->stop ? mrq->stop->resp[2] : 0;
+		__entry->stop_resp[3] = mrq->stop ? mrq->stop->resp[3] : 0;
+		__entry->sbc_opcode = mrq->sbc ? mrq->sbc->opcode : 0;
+		__entry->sbc_err = mrq->sbc ? mrq->sbc->error : 0;
+		__entry->sbc_resp[0] = mrq->sbc ? mrq->sbc->resp[0] : 0;
+		__entry->sbc_resp[1] = mrq->sbc ? mrq->sbc->resp[1] : 0;
+		__entry->sbc_resp[2] = mrq->sbc ? mrq->sbc->resp[2] : 0;
+		__entry->sbc_resp[3] = mrq->sbc ? mrq->sbc->resp[3] : 0;
+		__entry->bytes_xfered = mrq->data ? mrq->data->bytes_xfered : 0;
+		__entry->data_err = mrq->data ? mrq->data->error : 0;
+		__entry->host = host;
+		__entry->mrq = mrq;
+	),
+
+	TP_printk("%s: end struct mmc_request[%p]: "
+		  "cmd_opcode=%u cmd_err=%d cmd_resp=0x%x 0x%x 0x%x 0x%x "
+		  "stop_opcode=%u stop_err=%d stop_resp=0x%x 0x%x 0x%x 0x%x "
+		  "sbc_opcode=%u sbc_err=%d sbc_resp=0x%x 0x%x 0x%x 0x%x "
+		  "bytes_xfered=%u data_err=%d",
+		  mmc_hostname((struct mmc_host *)__entry->host),
+		  (struct mmc_request *)__entry->mrq,
+		  (u32)__entry->cmd_opcode, (int)__entry->cmd_err,
+		  (u32)__entry->cmd_resp[0], (u32)__entry->cmd_resp[1],
+		  (u32)__entry->cmd_resp[2], (u32)__entry->cmd_resp[3],
+		  (u32)__entry->stop_opcode, (int)__entry->stop_err,
+		  (u32)__entry->stop_resp[0], (u32)__entry->stop_resp[1],
+		  (u32)__entry->stop_resp[2], (u32)__entry->stop_resp[3],
+		  (u32)__entry->sbc_opcode, (int)__entry->sbc_err,
+		  (u32)__entry->sbc_resp[0], (u32)__entry->sbc_resp[1],
+		  (u32)__entry->sbc_resp[2], (u32)__entry->sbc_resp[3],
+		  (unsigned int)__entry->bytes_xfered,
+		  (int)__entry->data_err)
+);
+
+#endif /* _TRACE_MMC_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>