Re: [PATCH v2 02/12] scsi: ufs: add tracing support

2016-12-13 Thread Subhash Jadavani 

On 2016-12-13 12:10, Steven Rostedt wrote:

On Tue, 13 Dec 2016 11:48:45 -0800
Subhash Jadavani  wrote:


This change adds the ftrace support for following:
1. UFS initialization time
2. Clock gating states
3. Clock scaling states
4. Power management APIs latency
5. BKOPs enable/disable

Usage:
echo 1 > /sys/kernel/debug/tracing/events/ufs/enable
cat /sys/kernel/debug/tracing/trace_pipe

Reviewed-by: Sahitya Tummala 
Signed-off-by: Subhash Jadavani 
---
 drivers/scsi/ufs/ufshcd.c  | 133 

 include/trace/events/ufs.h | 149 
+

 2 files changed, 270 insertions(+), 12 deletions(-)
 create mode 100644 include/trace/events/ufs.h

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index fe516b2..73c5937 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -45,6 +45,9 @@
 #include "ufs_quirks.h"
 #include "unipro.h"

+#define CREATE_TRACE_POINTS
+#include 
+
 #define UFSHCD_REQ_SENSE_SIZE  18

 #define UFSHCD_ENABLE_INTRS(UTP_TRANSFER_REQ_COMPL |\
@@ -721,6 +724,40 @@ static void ufshcd_resume_clkscaling(struct 
ufs_hba *hba)

devfreq_resume_device(hba->devfreq);
 }

+static const char *ufschd_uic_link_state_to_string(
+   enum uic_link_state state)
+{
+   switch (state) {
+   case UIC_LINK_OFF_STATE:return "UIC_LINK_OFF_STATE";
+   case UIC_LINK_ACTIVE_STATE: return "UIC_LINK_ACTIVE_STATE";
+   case UIC_LINK_HIBERN8_STATE:return "UIC_LINK_HIBERN8_STATE";
+   default:return "UNKNOWN_STATE";
+   }
+}
+
+static const char *ufschd_ufs_dev_pwr_mode_to_string(
+   enum ufs_dev_pwr_mode state)
+{
+   switch (state) {
+   case UFS_ACTIVE_PWR_MODE:   return "UFS_ACTIVE_PWR_MODE";
+   case UFS_SLEEP_PWR_MODE:return "UFS_SLEEP_PWR_MODE";
+   case UFS_POWERDOWN_PWR_MODE:return "UFS_POWERDOWN_PWR_MODE";
+   default:return "UNKNOWN_STATE";
+   }
+}
+
+static const char *ufschd_clk_gating_state_to_string(
+   enum clk_gating_state state)
+{
+   switch (state) {
+   case CLKS_OFF:  return "CLKS_OFF";
+   case CLKS_ON:   return "CLKS_ON";
+   case REQ_CLKS_OFF:  return "REQ_CLKS_OFF";
+   case REQ_CLKS_ON:   return "REQ_CLKS_ON";
+   default:return "UNKNOWN_STATE";
+   }
+}
+


A much better way than the above is to use the TRACE_DEFINE_ENUM()
macros in the include/trace/events/ufs.h header. In fact, that's what
it was made for. Not only will it be much faster to record, it wont
waste as much space in the ring buffer.

.e.g.

#define UFS_LINK_STATES \
EM( UIC_LINK_OFF_STATE ) \
EM( UIC_LINK_ACTIVE_STATE ) \
EMe(UIC_LINK_HIBERN8_STATE )

#define UFS_PWR_MODES \
EM( UFS_ACTIVE_PWR_MODE ) \
EM( UFS_SLEEP_PWR_MODE ) \
EM( UFS_POWERDOWN_PWR_MODE) \
EMe(UFS_POWERDOWN_PWR_MODE)

#define UFSCHD_CLK_GATING_STATES \
EM( CLKS_OFF) \
EM( CLKS_ON) \
EM( REQ_CLKS_OFF) \
EMe(REQ_CLKS_ON)

#undef EM
#undef EMe

#define EM(a)   TRACE_DEFINE_ENUM(a);
#define EMe(a)  TRACE_DEFINE_ENUM(a);

UFS_LINK_STATES
UFS_PWR_MODES
UFSCHD_CLK_GATING_STATES

#undef EM
#undef EMe

#define EM(a)   { a, #a },
#define EMe(a)  { a, #a }


DECLARE_EVENT_CLASS(ufshcd_template,
TP_PROTO(const char *dev_name int err, s64 usecs,
 int state, int link_state);

[..]

TP_printk(
"%s: took %lld, dev_state: %s, link_state: %s, err %d",
get_str(dev_name),
__entry->usecs,
__print_symbolic(__entry->state, UFS_PWR_MODES),
__print_symbolic(__entry->link_state, UFS_LINK_STATES),
__entry->err
)

Not to mention, I think some of the strings may not be matching what
was passed in.


Thanks for the suggestion. Let me check this.



-- Steve




+DECLARE_EVENT_CLASS(ufshcd_template,
+   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),
+
+   TP_STRUCT__entry(
+   __field(s64, usecs)
+   __field(int, err)
+   __string(dev_name, dev_name)
+   __string(dev_state, dev_state)
+   __string(link_state, link_state)
+   ),
+
+   TP_fast_assign(
+   __entry->usecs = usecs;
+   __entry->err = err;
+   __assign_str(dev_name, dev_name);
+   __assign_str(dev_state, dev_state);
+   __assign_str(link_state, link_state);
+   ),
+
+   TP_printk(
+   "%s: took %lld usecs, dev_state: %s, link_state: %s, err %d",
+

Re: [PATCH v2 02/12] scsi: ufs: add tracing support

2016-12-13 Thread Steven Rostedt 
On Tue, 13 Dec 2016 11:48:45 -0800
Subhash Jadavani  wrote:

> This change adds the ftrace support for following:
> 1. UFS initialization time
> 2. Clock gating states
> 3. Clock scaling states
> 4. Power management APIs latency
> 5. BKOPs enable/disable
> 
> Usage:
>   echo 1 > /sys/kernel/debug/tracing/events/ufs/enable
>   cat /sys/kernel/debug/tracing/trace_pipe
> 
> Reviewed-by: Sahitya Tummala 
> Signed-off-by: Subhash Jadavani 
> ---
>  drivers/scsi/ufs/ufshcd.c  | 133 
>  include/trace/events/ufs.h | 149 
> +
>  2 files changed, 270 insertions(+), 12 deletions(-)
>  create mode 100644 include/trace/events/ufs.h
> 
> diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> index fe516b2..73c5937 100644
> --- a/drivers/scsi/ufs/ufshcd.c
> +++ b/drivers/scsi/ufs/ufshcd.c
> @@ -45,6 +45,9 @@
>  #include "ufs_quirks.h"
>  #include "unipro.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include 
> +
>  #define UFSHCD_REQ_SENSE_SIZE18
>  
>  #define UFSHCD_ENABLE_INTRS  (UTP_TRANSFER_REQ_COMPL |\
> @@ -721,6 +724,40 @@ static void ufshcd_resume_clkscaling(struct ufs_hba *hba)
>   devfreq_resume_device(hba->devfreq);
>  }
>  
> +static const char *ufschd_uic_link_state_to_string(
> + enum uic_link_state state)
> +{
> + switch (state) {
> + case UIC_LINK_OFF_STATE:return "UIC_LINK_OFF_STATE";
> + case UIC_LINK_ACTIVE_STATE: return "UIC_LINK_ACTIVE_STATE";
> + case UIC_LINK_HIBERN8_STATE:return "UIC_LINK_HIBERN8_STATE";
> + default:return "UNKNOWN_STATE";
> + }
> +}
> +
> +static const char *ufschd_ufs_dev_pwr_mode_to_string(
> + enum ufs_dev_pwr_mode state)
> +{
> + switch (state) {
> + case UFS_ACTIVE_PWR_MODE:   return "UFS_ACTIVE_PWR_MODE";
> + case UFS_SLEEP_PWR_MODE:return "UFS_SLEEP_PWR_MODE";
> + case UFS_POWERDOWN_PWR_MODE:return "UFS_POWERDOWN_PWR_MODE";
> + default:return "UNKNOWN_STATE";
> + }
> +}
> +
> +static const char *ufschd_clk_gating_state_to_string(
> + enum clk_gating_state state)
> +{
> + switch (state) {
> + case CLKS_OFF:  return "CLKS_OFF";
> + case CLKS_ON:   return "CLKS_ON";
> + case REQ_CLKS_OFF:  return "REQ_CLKS_OFF";
> + case REQ_CLKS_ON:   return "REQ_CLKS_ON";
> + default:return "UNKNOWN_STATE";
> + }
> +}
> +

A much better way than the above is to use the TRACE_DEFINE_ENUM()
macros in the include/trace/events/ufs.h header. In fact, that's what
it was made for. Not only will it be much faster to record, it wont
waste as much space in the ring buffer.

.e.g.

#define UFS_LINK_STATES \
EM( UIC_LINK_OFF_STATE ) \
EM( UIC_LINK_ACTIVE_STATE ) \
EMe(UIC_LINK_HIBERN8_STATE )

#define UFS_PWR_MODES \
EM( UFS_ACTIVE_PWR_MODE ) \
EM( UFS_SLEEP_PWR_MODE ) \
EM( UFS_POWERDOWN_PWR_MODE) \
EMe(UFS_POWERDOWN_PWR_MODE)

#define UFSCHD_CLK_GATING_STATES \
EM( CLKS_OFF) \
EM( CLKS_ON) \
EM( REQ_CLKS_OFF) \
EMe(REQ_CLKS_ON)

#undef EM
#undef EMe

#define EM(a)   TRACE_DEFINE_ENUM(a);
#define EMe(a)  TRACE_DEFINE_ENUM(a);

UFS_LINK_STATES
UFS_PWR_MODES
UFSCHD_CLK_GATING_STATES

#undef EM
#undef EMe

#define EM(a)   { a, #a },
#define EMe(a)  { a, #a }


DECLARE_EVENT_CLASS(ufshcd_template,
TP_PROTO(const char *dev_name int err, s64 usecs,
 int state, int link_state);

[..]

TP_printk(
"%s: took %lld, dev_state: %s, link_state: %s, err %d",
get_str(dev_name),
__entry->usecs,
__print_symbolic(__entry->state, UFS_PWR_MODES),
__print_symbolic(__entry->link_state, UFS_LINK_STATES),
__entry->err
)

Not to mention, I think some of the strings may not be matching what
was passed in.

-- Steve



> +DECLARE_EVENT_CLASS(ufshcd_template,
> + 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),
> +
> + TP_STRUCT__entry(
> + __field(s64, usecs)
> + __field(int, err)
> + __string(dev_name, dev_name)
> + __string(dev_state, dev_state)
> + __string(link_state, link_state)
> + ),
> +
> + TP_fast_assign(
> + __entry->usecs = usecs;
> + __entry->err = err;
> + __assign_str(dev_name, dev_name);
> + __assign_str(dev_state, dev_state);
> + __assign_str(link_state, link_state);
> + ),
> +
> + TP_printk(
> + "%s: took %lld usecs, dev_state: %s, link_state: %s, err

[PATCH v2 02/12] scsi: ufs: add tracing support

2016-12-13 Thread Subhash Jadavani 
This change adds the ftrace support for following:
1. UFS initialization time
2. Clock gating states
3. Clock scaling states
4. Power management APIs latency
5. BKOPs enable/disable

Usage:
echo 1 > /sys/kernel/debug/tracing/events/ufs/enable
cat /sys/kernel/debug/tracing/trace_pipe

Reviewed-by: Sahitya Tummala 
Signed-off-by: Subhash Jadavani 
---
 drivers/scsi/ufs/ufshcd.c  | 133 
 include/trace/events/ufs.h | 149 +
 2 files changed, 270 insertions(+), 12 deletions(-)
 create mode 100644 include/trace/events/ufs.h

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index fe516b2..73c5937 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -45,6 +45,9 @@
 #include "ufs_quirks.h"
 #include "unipro.h"
 
+#define CREATE_TRACE_POINTS
+#include 
+
 #define UFSHCD_REQ_SENSE_SIZE  18
 
 #define UFSHCD_ENABLE_INTRS(UTP_TRANSFER_REQ_COMPL |\
@@ -721,6 +724,40 @@ static void ufshcd_resume_clkscaling(struct ufs_hba *hba)
devfreq_resume_device(hba->devfreq);
 }
 
+static const char *ufschd_uic_link_state_to_string(
+   enum uic_link_state state)
+{
+   switch (state) {
+   case UIC_LINK_OFF_STATE:return "UIC_LINK_OFF_STATE";
+   case UIC_LINK_ACTIVE_STATE: return "UIC_LINK_ACTIVE_STATE";
+   case UIC_LINK_HIBERN8_STATE:return "UIC_LINK_HIBERN8_STATE";
+   default:return "UNKNOWN_STATE";
+   }
+}
+
+static const char *ufschd_ufs_dev_pwr_mode_to_string(
+   enum ufs_dev_pwr_mode state)
+{
+   switch (state) {
+   case UFS_ACTIVE_PWR_MODE:   return "UFS_ACTIVE_PWR_MODE";
+   case UFS_SLEEP_PWR_MODE:return "UFS_SLEEP_PWR_MODE";
+   case UFS_POWERDOWN_PWR_MODE:return "UFS_POWERDOWN_PWR_MODE";
+   default:return "UNKNOWN_STATE";
+   }
+}
+
+static const char *ufschd_clk_gating_state_to_string(
+   enum clk_gating_state state)
+{
+   switch (state) {
+   case CLKS_OFF:  return "CLKS_OFF";
+   case CLKS_ON:   return "CLKS_ON";
+   case REQ_CLKS_OFF:  return "REQ_CLKS_OFF";
+   case REQ_CLKS_ON:   return "REQ_CLKS_ON";
+   default:return "UNKNOWN_STATE";
+   }
+}
+
 static void ufshcd_ungate_work(struct work_struct *work)
 {
int ret;
@@ -801,6 +838,9 @@ int ufshcd_hold(struct ufs_hba *hba, bool async)
case REQ_CLKS_OFF:
if (cancel_delayed_work(>clk_gating.gate_work)) {
hba->clk_gating.state = CLKS_ON;
+   trace_ufshcd_clk_gating(dev_name(hba->dev),
+   ufschd_clk_gating_state_to_string(
+   hba->clk_gating.state));
break;
}
/*
@@ -811,6 +851,9 @@ int ufshcd_hold(struct ufs_hba *hba, bool async)
case CLKS_OFF:
scsi_block_requests(hba->host);
hba->clk_gating.state = REQ_CLKS_ON;
+   trace_ufshcd_clk_gating(dev_name(hba->dev),
+   ufschd_clk_gating_state_to_string(
+   hba->clk_gating.state));
schedule_work(>clk_gating.ungate_work);
/*
 * fall through to check if we should wait for this
@@ -855,6 +898,9 @@ static void ufshcd_gate_work(struct work_struct *work)
if (hba->clk_gating.is_suspended ||
(hba->clk_gating.state == REQ_CLKS_ON)) {
hba->clk_gating.state = CLKS_ON;
+   trace_ufshcd_clk_gating(dev_name(hba->dev),
+   ufschd_clk_gating_state_to_string(
+   hba->clk_gating.state));
goto rel_lock;
}
 
@@ -870,6 +916,9 @@ static void ufshcd_gate_work(struct work_struct *work)
if (ufshcd_can_hibern8_during_gating(hba)) {
if (ufshcd_uic_hibern8_enter(hba)) {
hba->clk_gating.state = CLKS_ON;
+   trace_ufshcd_clk_gating(dev_name(hba->dev),
+   ufschd_clk_gating_state_to_string(
+   hba->clk_gating.state));
goto out;
}
ufshcd_set_link_hibern8(hba);
@@ -893,9 +942,12 @@ static void ufshcd_gate_work(struct work_struct *work)
 * new requests arriving before the current cancel work is done.
 */
spin_lock_irqsave(hba->host->host_lock, flags);
-   if (hba->clk_gating.state == REQ_CLKS_OFF)
+   if (hba->clk_gating.state == REQ_CLKS_OFF) {
hba->clk_gating.state = CLKS_OFF;
-
+   trace_ufshcd_clk_gating(dev_name(hba->dev),
+