From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753791AbcLMUWM (ORCPT ); Tue, 13 Dec 2016 15:22:12 -0500 Received: from smtprelay0192.hostedemail.com ([216.40.44.192]:52615 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1752925AbcLMUWL (ORCPT ); Tue, 13 Dec 2016 15:22:11 -0500 X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::::::::::::::::,RULES_HIT:2:41:355:379:541:599:800:960:968:973:988:989:1260:1277:1311:1313:1314:1345:1359:1437:1515:1516:1518:1535:1593:1594:1605:1730:1747:1777:1792:2393:2553:2559:2562:2693:2897:2904:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3873:3874:4049:4118:4605:5007:6117:6119:6261:6609:7576:7875:7903:8603:10004:10848:10967:11026:11232:11473:11657:11658:11914:12043:12291:12296:12438:12555:12683:12740:12760:13439:13972:14096:14097:14659:21063:21080:21451:30012:30029:30034:30036:30046:30054:30071:30083:30090:30091,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:7,LUA_SUMMARY:none X-HE-Tag: north50_4cc7244c54639 X-Filterd-Recvd-Size: 7536 Date: Tue, 13 Dec 2016 15:22:06 -0500 From: Steven Rostedt To: Subhash Jadavani Cc: vinholikatti@gmail.com, jejb@linux.vnet.ibm.com, martin.petersen@oracle.com, linux-scsi@vger.kernel.org, Lee Susman , Ingo Molnar , Sahitya Tummala , Venkat Gopalakrishnan , linux-kernel@vger.kernel.org (open list) Subject: Re: [PATCH v2 11/12] scsi: ufs: add trace event for ufs commands Message-ID: <20161213152206.79e78435@gandalf.local.home> In-Reply-To: <1481658740-32292-1-git-send-email-subhashj@codeaurora.org> References: <1481658740-32292-1-git-send-email-subhashj@codeaurora.org> X-Mailer: Claws Mail 3.14.0 (GTK+ 2.24.31; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, 13 Dec 2016 11:52:16 -0800 Subhash Jadavani wrote: > From: Lee Susman > > Use the ftrace infrastructure to conditionally trace ufs command events. > New trace event is created, which samples the following ufs command data: > - device name > - optional identification string > - task tag > - doorbell register > - number of transfer bytes > - interrupt status register > - request start LBA > - command opcode > > Currently we only fully trace read(10) and write(10) commands. > All other commands which pass through ufshcd_send_command() will be > printed with "-1" in the lba and transfer_len fields. > > Usage: > echo 1 > /sys/kernel/debug/tracing/events/ufs/enable > cat /sys/kernel/debug/tracing/trace_pipe > > Signed-off-by: Lee Susman > Signed-off-by: Subhash Jadavani > --- > drivers/scsi/ufs/ufshcd.c | 52 +++++++++++++++++++++++++++++++++++++++++++++- > include/trace/events/ufs.h | 38 +++++++++++++++++++++++++++++++++ > 2 files changed, 89 insertions(+), 1 deletion(-) > > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c > index 33f3947..926d1ef 100644 > --- a/drivers/scsi/ufs/ufshcd.c > +++ b/drivers/scsi/ufs/ufshcd.c > @@ -301,6 +301,51 @@ static inline void ufshcd_remove_non_printable(char *val) > *val = ' '; > } > > +#ifdef CONFIG_TRACEPOINTS > +static void ufshcd_add_command_trace(struct ufs_hba *hba, > + unsigned int tag, const char *str) Is this function only to use if you enable the tracepoint? Is there anything here doing something that wouldn't be enabled if tracing wasn't configured in? Also, if this is in a code execution path, it appears that you do this work regardless if the tracer is running or not. > +{ > + sector_t lba = -1; > + u8 opcode = 0; > + u32 intr, doorbell; > + struct ufshcd_lrb *lrbp; > + int transfer_len = -1; > + > + lrbp = &hba->lrb[tag]; > + > + if (lrbp->cmd) { /* data phase exists */ > + opcode = (u8)(*lrbp->cmd->cmnd); > + if ((opcode == READ_10) || (opcode == WRITE_10)) { > + /* > + * Currently we only fully trace read(10) and write(10) > + * commands > + */ > + if (lrbp->cmd->request && lrbp->cmd->request->bio) > + lba = > + lrbp->cmd->request->bio->bi_iter.bi_sector; > + transfer_len = be32_to_cpu( > + lrbp->ucd_req_ptr->sc.exp_data_transfer_len); > + } > + } > + > + intr = ufshcd_readl(hba, REG_INTERRUPT_STATUS); > + doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL); > + trace_ufshcd_command(dev_name(hba->dev), str, tag, > + doorbell, transfer_len, intr, lba, opcode); > +} > + > +static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba, > + unsigned int tag, const char *str) > +{ > + ufshcd_add_command_trace(hba, tag, str); > +} > +#else > +static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba, > + unsigned int tag, const char *str) > +{ > +} > +#endif If my above assumptions are correct, I recommend removing the above #if, and have it always configured. Then... > + > static void ufshcd_print_host_regs(struct ufs_hba *hba) > { > /* > @@ -1193,6 +1238,7 @@ void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag) > ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL); > /* Make sure that doorbell is committed immediately */ > wmb(); Add: if (trace_ufshcd_command_enabled()) ufshcd_cond_add_cmd_trace(hba, task_tag, "send"); For one thing, the function only gets called if the tracepoint ufshcd_command is enabled. Now if CONFIG_TRACEPOINTS is not configured in, then the trace_ufshcd_command_enabled() turns into a "return false;" which one would hope that gcc will take that as a if (0) and optimized the entire function out of existence. This would make the code a bit cleaner and accomplish the same. -- Steve > } > > /** > @@ -3982,6 +4028,7 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba, > lrbp = &hba->lrb[index]; > cmd = lrbp->cmd; > if (cmd) { > + ufshcd_cond_add_cmd_trace(hba, index, "complete"); > result = ufshcd_transfer_rsp_status(hba, lrbp); > scsi_dma_unmap(cmd); > cmd->result = result; > @@ -3993,8 +4040,11 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba, > __ufshcd_release(hba); > } else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE || > lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE) { > - if (hba->dev_cmd.complete) > + if (hba->dev_cmd.complete) { > + ufshcd_cond_add_cmd_trace(hba, index, > + "dev_complete"); > complete(hba->dev_cmd.complete); > + } > } > } > > diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h > index 8bce504..d0ed0cf 100644 > --- a/include/trace/events/ufs.h > +++ b/include/trace/events/ufs.h > @@ -183,6 +183,44 @@ > TP_PROTO(const char *dev_name, int err, s64 usecs, > const char *dev_state, const char *link_state), > TP_ARGS(dev_name, err, usecs, dev_state, link_state)); > + > +TRACE_EVENT(ufshcd_command, > + TP_PROTO(const char *dev_name, const char *str, unsigned int tag, > + u32 doorbell, int transfer_len, u32 intr, u64 lba, > + u8 opcode), > + > + TP_ARGS(dev_name, str, tag, doorbell, transfer_len, intr, lba, opcode), > + > + TP_STRUCT__entry( > + __string(dev_name, dev_name) > + __string(str, str) > + __field(unsigned int, tag) > + __field(u32, doorbell) > + __field(int, transfer_len) > + __field(u32, intr) > + __field(u64, lba) > + __field(u8, opcode) > + ), > + > + TP_fast_assign( > + __assign_str(dev_name, dev_name); > + __assign_str(str, str); > + __entry->tag = tag; > + __entry->doorbell = doorbell; > + __entry->transfer_len = transfer_len; > + __entry->intr = intr; > + __entry->lba = lba; > + __entry->opcode = opcode; > + ), > + > + TP_printk( > + "%s: %s: tag: %u, DB: 0x%x, size: %d, IS: %u, LBA: %llu, opcode: 0x%x", > + __get_str(str), __get_str(dev_name), __entry->tag, > + __entry->doorbell, __entry->transfer_len, > + __entry->intr, __entry->lba, (u32)__entry->opcode > + ) > +); > + > #endif /* if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) */ > > /* This part must be outside protection */