diff mbox series

[net-next,4/4] ice: add trace events for tx timestamps

Message ID 20220316204024.3201500-5-anthony.l.nguyen@intel.com (mailing list archive)
State Accepted
Commit 4c1202189e351bc99856805ee9c82ffca6594ba0
Delegated to: Netdev Maintainers
Headers show
Series 100GbE Intel Wired LAN Driver Updates 2022-03-16 | expand

Checks

Context Check Description
netdev/tree_selection success Clearly marked for net-next
netdev/fixes_present success Fixes tag not required for -next series
netdev/subject_prefix success Link
netdev/cover_letter success Series has a cover letter
netdev/patch_count success Link
netdev/header_inline success No static functions without inline keyword in header files
netdev/build_32bit success Errors and warnings before: 0 this patch: 0
netdev/cc_maintainers success CCed 3 of 3 maintainers
netdev/build_clang success Errors and warnings before: 0 this patch: 0
netdev/module_param success Was 0 now: 0
netdev/verify_signedoff success Signed-off-by tag matches author and committer
netdev/verify_fixes success No Fixes tag
netdev/build_allmodconfig_warn success Errors and warnings before: 0 this patch: 0
netdev/checkpatch success total: 0 errors, 0 warnings, 0 checks, 67 lines checked
netdev/kdoc success Errors and warnings before: 0 this patch: 0
netdev/source_inline success Was 0 now: 0

Commit Message

Tony Nguyen March 16, 2022, 8:40 p.m. UTC 
From: Jacob Keller <jacob.e.keller@intel.com>

We've previously run into many issues related to the latency of a Tx
timestamp completion with the ice hardware. It can be difficult to
determine the root cause of a slow Tx timestamp. To aid in this,
introduce new trace events which capture timing data about when the
driver reaches certain points while processing a transmit timestamp

 * ice_tx_tstamp_request: Trace when the stack initiates a new timestamp
   request.

 * ice_tx_tstamp_fw_req: Trace when the driver begins a read of the
   timestamp register in the work thread.

 * ice_tx_tstamp_fw_done: Trace when the driver finishes reading a
   timestamp register in the work thread.

 * ice_tx_tstamp_complete: Trace when the driver submits the skb back to
   the stack with a completed Tx timestamp.

These trace events can be enabled using the standard trace event
subsystem exposed by the ice driver. If they are disabled, they become
no-ops with no run time cost.

The following is a simple GNU AWK script which can highlight one
potential way to use the trace events to capture latency data from the
trace buffer about how long the driver takes to process a timestamp:

-----
  BEGIN {
      PREC=256
  }

  # Detect requests
  /tx_tstamp_request/ {
      time=strtonum($4)
      skb=$7

      # Store the time of request for this skb
      requests[skb] = time
      printf("skb %s: idx %d at %.6f\n", skb, idx, time)
  }

  # Detect completions
  /tx_tstamp_complete/ {
      time=strtonum($4)
      skb=$7
      idx=$9

      if (skb in requests) {
          latency = (time - requests[skb]) * 1000
          printf("skb %s: %.3f to complete\n", skb, latency)
          if (latency > 4) {
              printf(">>> HIGH LATENCY <<<\n")
          }
          printf("\n")
      } else {
          printf("!!! skb %s (idx %d) at %.6f\n", skb, idx, time)
      }
  }
-----

Signed-off-by: Jacob Keller <jacob.e.keller@intel.com>
Tested-by: Gurucharan <gurucharanx.g@intel.com> (A Contingent worker at Intel)
Signed-off-by: Tony Nguyen <anthony.l.nguyen@intel.com>
---
 drivers/net/ethernet/intel/ice/ice_ptp.c   |  8 ++++++++
 drivers/net/ethernet/intel/ice/ice_trace.h | 24 ++++++++++++++++++++++
 2 files changed, 32 insertions(+)

Comments

Jacob Keller March 16, 2022, 9:02 p.m. UTC | #1 
> -----Original Message-----
> From: Nguyen, Anthony L <anthony.l.nguyen@intel.com>
> Sent: Wednesday, March 16, 2022 1:40 PM
> To: davem@davemloft.net; kuba@kernel.org; pabeni@redhat.com
> Cc: Keller, Jacob E <jacob.e.keller@intel.com>; netdev@vger.kernel.org; Nguyen,
> Anthony L <anthony.l.nguyen@intel.com>; Drewek, Wojciech
> <wojciech.drewek@intel.com>; pablo@netfilter.org; laforge@gnumonks.org;
> osmocom-net-gprs@lists.osmocom.org; G, GurucharanX
> <gurucharanx.g@intel.com>
> Subject: [PATCH net-next 4/4] ice: add trace events for tx timestamps
> 
> From: Jacob Keller <jacob.e.keller@intel.com>
> 
> We've previously run into many issues related to the latency of a Tx
> timestamp completion with the ice hardware. It can be difficult to
> determine the root cause of a slow Tx timestamp. To aid in this,
> introduce new trace events which capture timing data about when the
> driver reaches certain points while processing a transmit timestamp
> 
>  * ice_tx_tstamp_request: Trace when the stack initiates a new timestamp
>    request.
> 
>  * ice_tx_tstamp_fw_req: Trace when the driver begins a read of the
>    timestamp register in the work thread.
> 
>  * ice_tx_tstamp_fw_done: Trace when the driver finishes reading a
>    timestamp register in the work thread.
> 
>  * ice_tx_tstamp_complete: Trace when the driver submits the skb back to
>    the stack with a completed Tx timestamp.
> 
> These trace events can be enabled using the standard trace event
> subsystem exposed by the ice driver. If they are disabled, they become
> no-ops with no run time cost.
> 
> The following is a simple GNU AWK script which can highlight one
> potential way to use the trace events to capture latency data from the
> trace buffer about how long the driver takes to process a timestamp:
> 
> -----
>   BEGIN {
>       PREC=256
>   }
> 

Another engineer recently asked me about this script so I wanted to clarify here: this is a GNU awk script intended to be invoked with "gawk -f <script>". It relies on the trace events already being enabled and that it is reading the trace (or trace_pipe) file as its standard input.

Thanks,
Jake

>   # Detect requests
>   /tx_tstamp_request/ {
>       time=strtonum($4)
>       skb=$7
> 
>       # Store the time of request for this skb
>       requests[skb] = time
>       printf("skb %s: idx %d at %.6f\n", skb, idx, time)
>   }
> 
>   # Detect completions
>   /tx_tstamp_complete/ {
>       time=strtonum($4)
>       skb=$7
>       idx=$9
> 
>       if (skb in requests) {
>           latency = (time - requests[skb]) * 1000
>           printf("skb %s: %.3f to complete\n", skb, latency)
>           if (latency > 4) {
>               printf(">>> HIGH LATENCY <<<\n")
>           }
>           printf("\n")
>       } else {
>           printf("!!! skb %s (idx %d) at %.6f\n", skb, idx, time)
>       }
>   }
> -----
> 
> Signed-off-by: Jacob Keller <jacob.e.keller@intel.com>
> Tested-by: Gurucharan <gurucharanx.g@intel.com> (A Contingent worker at
> Intel)
> Signed-off-by: Tony Nguyen <anthony.l.nguyen@intel.com>
> ---
>  drivers/net/ethernet/intel/ice/ice_ptp.c   |  8 ++++++++
>  drivers/net/ethernet/intel/ice/ice_trace.h | 24 ++++++++++++++++++++++
>  2 files changed, 32 insertions(+)
> 
> diff --git a/drivers/net/ethernet/intel/ice/ice_ptp.c
> b/drivers/net/ethernet/intel/ice/ice_ptp.c
> index 000c39d163a2..a1cd33273ca4 100644
> --- a/drivers/net/ethernet/intel/ice/ice_ptp.c
> +++ b/drivers/net/ethernet/intel/ice/ice_ptp.c
> @@ -3,6 +3,7 @@
> 
>  #include "ice.h"
>  #include "ice_lib.h"
> +#include "ice_trace.h"
> 
>  #define E810_OUT_PROP_DELAY_NS 1
> 
> @@ -2063,11 +2064,15 @@ static void ice_ptp_tx_tstamp_work(struct
> kthread_work *work)
>  		struct sk_buff *skb;
>  		int err;
> 
> +		ice_trace(tx_tstamp_fw_req, tx->tstamps[idx].skb, idx);
> +
>  		err = ice_read_phy_tstamp(hw, tx->quad, phy_idx,
>  					  &raw_tstamp);
>  		if (err)
>  			continue;
> 
> +		ice_trace(tx_tstamp_fw_done, tx->tstamps[idx].skb, idx);
> +
>  		/* Check if the timestamp is invalid or stale */
>  		if (!(raw_tstamp & ICE_PTP_TS_VALID) ||
>  		    raw_tstamp == tx->tstamps[idx].cached_tstamp)
> @@ -2093,6 +2098,8 @@ static void ice_ptp_tx_tstamp_work(struct
> kthread_work *work)
>  		tstamp = ice_ptp_extend_40b_ts(pf, raw_tstamp);
>  		shhwtstamps.hwtstamp = ns_to_ktime(tstamp);
> 
> +		ice_trace(tx_tstamp_complete, skb, idx);
> +
>  		skb_tstamp_tx(skb, &shhwtstamps);
>  		dev_kfree_skb_any(skb);
>  	}
> @@ -2131,6 +2138,7 @@ s8 ice_ptp_request_ts(struct ice_ptp_tx *tx, struct
> sk_buff *skb)
>  		tx->tstamps[idx].start = jiffies;
>  		tx->tstamps[idx].skb = skb_get(skb);
>  		skb_shinfo(skb)->tx_flags |= SKBTX_IN_PROGRESS;
> +		ice_trace(tx_tstamp_request, skb, idx);
>  	}
> 
>  	spin_unlock(&tx->lock);
> diff --git a/drivers/net/ethernet/intel/ice/ice_trace.h
> b/drivers/net/ethernet/intel/ice/ice_trace.h
> index cf685247c07a..ae98d5a8ff60 100644
> --- a/drivers/net/ethernet/intel/ice/ice_trace.h
> +++ b/drivers/net/ethernet/intel/ice/ice_trace.h
> @@ -216,6 +216,30 @@ DEFINE_EVENT(ice_xmit_template, name, \
>  DEFINE_XMIT_TEMPLATE_OP_EVENT(ice_xmit_frame_ring);
>  DEFINE_XMIT_TEMPLATE_OP_EVENT(ice_xmit_frame_ring_drop);
> 
> +DECLARE_EVENT_CLASS(ice_tx_tstamp_template,
> +		    TP_PROTO(struct sk_buff *skb, int idx),
> +
> +		    TP_ARGS(skb, idx),
> +
> +		    TP_STRUCT__entry(__field(void *, skb)
> +				     __field(int, idx)),
> +
> +		    TP_fast_assign(__entry->skb = skb;
> +				   __entry->idx = idx;),
> +
> +		    TP_printk("skb %pK idx %d",
> +			      __entry->skb, __entry->idx)
> +);
> +#define DEFINE_TX_TSTAMP_OP_EVENT(name) \
> +DEFINE_EVENT(ice_tx_tstamp_template, name, \
> +	     TP_PROTO(struct sk_buff *skb, int idx), \
> +	     TP_ARGS(skb, idx))
> +
> +DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_request);
> +DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_fw_req);
> +DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_fw_done);
> +DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_complete);
> +
>  /* End tracepoints */
> 
>  #endif /* _ICE_TRACE_H_ */
> --
> 2.31.1
diff mbox series

Patch

diff --git a/drivers/net/ethernet/intel/ice/ice_ptp.c b/drivers/net/ethernet/intel/ice/ice_ptp.c
index 000c39d163a2..a1cd33273ca4 100644
--- a/drivers/net/ethernet/intel/ice/ice_ptp.c
+++ b/drivers/net/ethernet/intel/ice/ice_ptp.c
@@ -3,6 +3,7 @@ 
 
 #include "ice.h"
 #include "ice_lib.h"
+#include "ice_trace.h"
 
 #define E810_OUT_PROP_DELAY_NS 1
 
@@ -2063,11 +2064,15 @@  static void ice_ptp_tx_tstamp_work(struct kthread_work *work)
 		struct sk_buff *skb;
 		int err;
 
+		ice_trace(tx_tstamp_fw_req, tx->tstamps[idx].skb, idx);
+
 		err = ice_read_phy_tstamp(hw, tx->quad, phy_idx,
 					  &raw_tstamp);
 		if (err)
 			continue;
 
+		ice_trace(tx_tstamp_fw_done, tx->tstamps[idx].skb, idx);
+
 		/* Check if the timestamp is invalid or stale */
 		if (!(raw_tstamp & ICE_PTP_TS_VALID) ||
 		    raw_tstamp == tx->tstamps[idx].cached_tstamp)
@@ -2093,6 +2098,8 @@  static void ice_ptp_tx_tstamp_work(struct kthread_work *work)
 		tstamp = ice_ptp_extend_40b_ts(pf, raw_tstamp);
 		shhwtstamps.hwtstamp = ns_to_ktime(tstamp);
 
+		ice_trace(tx_tstamp_complete, skb, idx);
+
 		skb_tstamp_tx(skb, &shhwtstamps);
 		dev_kfree_skb_any(skb);
 	}
@@ -2131,6 +2138,7 @@  s8 ice_ptp_request_ts(struct ice_ptp_tx *tx, struct sk_buff *skb)
 		tx->tstamps[idx].start = jiffies;
 		tx->tstamps[idx].skb = skb_get(skb);
 		skb_shinfo(skb)->tx_flags |= SKBTX_IN_PROGRESS;
+		ice_trace(tx_tstamp_request, skb, idx);
 	}
 
 	spin_unlock(&tx->lock);
diff --git a/drivers/net/ethernet/intel/ice/ice_trace.h b/drivers/net/ethernet/intel/ice/ice_trace.h
index cf685247c07a..ae98d5a8ff60 100644
--- a/drivers/net/ethernet/intel/ice/ice_trace.h
+++ b/drivers/net/ethernet/intel/ice/ice_trace.h
@@ -216,6 +216,30 @@  DEFINE_EVENT(ice_xmit_template, name, \
 DEFINE_XMIT_TEMPLATE_OP_EVENT(ice_xmit_frame_ring);
 DEFINE_XMIT_TEMPLATE_OP_EVENT(ice_xmit_frame_ring_drop);
 
+DECLARE_EVENT_CLASS(ice_tx_tstamp_template,
+		    TP_PROTO(struct sk_buff *skb, int idx),
+
+		    TP_ARGS(skb, idx),
+
+		    TP_STRUCT__entry(__field(void *, skb)
+				     __field(int, idx)),
+
+		    TP_fast_assign(__entry->skb = skb;
+				   __entry->idx = idx;),
+
+		    TP_printk("skb %pK idx %d",
+			      __entry->skb, __entry->idx)
+);
+#define DEFINE_TX_TSTAMP_OP_EVENT(name) \
+DEFINE_EVENT(ice_tx_tstamp_template, name, \
+	     TP_PROTO(struct sk_buff *skb, int idx), \
+	     TP_ARGS(skb, idx))
+
+DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_request);
+DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_fw_req);
+DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_fw_done);
+DEFINE_TX_TSTAMP_OP_EVENT(ice_tx_tstamp_complete);
+
 /* End tracepoints */
 
 #endif /* _ICE_TRACE_H_ */