[PATCH v2 3/4] net/mlx5: fix Tx tracing to use single clock source

[Viacheslav Ovsiienko <viacheslavo@nvidia.com>]

From: Tim Martin <timothym@nvidia.com>

The prior commit introduced tracing for mlx5, but there is a mixture of
two unrelated clocks used: the TSC for host work submission timestamps
and the NIC HW clock for CQE completion times. It is necessary to have
timestamps from a single common clock, and the NIC HW clock is the
better choice since it can be used with externally synchronized clocks.

This patch adds the NIC HW clock as an additional logged parameter for
trace_tx_entry, trace_tx_exit, and trace_tx_wqe.  The included trace
analysis python script is also updated to use the new clock when
it is available.

Fixes: a1e910f5b8d4 ("net/mlx5: introduce tracepoints")
Fixes: 9725191a7e14 ("net/mlx5: add Tx datapath trace analyzing script")
Cc: stable@dpdk.org

Signed-off-by: Tim Martin <timothym@nvidia.com>
Acked-by: Viacheslav Ovsiienko <viacheslavo@nvidia.com>
---
 drivers/net/mlx5/mlx5_trace.h        |  9 ++++++---
 drivers/net/mlx5/mlx5_tx.h           | 21 +++++++++++++++++----
 drivers/net/mlx5/tools/mlx5_trace.py | 12 +++++++++---
 3 files changed, 32 insertions(+), 10 deletions(-)

diff --git a/drivers/net/mlx5/mlx5_trace.h b/drivers/net/mlx5/mlx5_trace.h
index a8f0b372c8..4fc3584acc 100644
--- a/drivers/net/mlx5/mlx5_trace.h
+++ b/drivers/net/mlx5/mlx5_trace.h
@@ -22,21 +22,24 @@ extern "C" {
 /* TX burst subroutines trace points. */
 RTE_TRACE_POINT_FP(
 	rte_pmd_mlx5_trace_tx_entry,
-	RTE_TRACE_POINT_ARGS(uint16_t port_id, uint16_t queue_id),
+	RTE_TRACE_POINT_ARGS(uint64_t real_time, uint16_t port_id, uint16_t queue_id),
+	rte_trace_point_emit_u64(real_time);
 	rte_trace_point_emit_u16(port_id);
 	rte_trace_point_emit_u16(queue_id);
 )
 
 RTE_TRACE_POINT_FP(
 	rte_pmd_mlx5_trace_tx_exit,
-	RTE_TRACE_POINT_ARGS(uint16_t nb_sent, uint16_t nb_req),
+	RTE_TRACE_POINT_ARGS(uint64_t real_time, uint16_t nb_sent, uint16_t nb_req),
+	rte_trace_point_emit_u64(real_time);
 	rte_trace_point_emit_u16(nb_sent);
 	rte_trace_point_emit_u16(nb_req);
 )
 
 RTE_TRACE_POINT_FP(
 	rte_pmd_mlx5_trace_tx_wqe,
-	RTE_TRACE_POINT_ARGS(uint32_t opcode),
+	RTE_TRACE_POINT_ARGS(uint64_t real_time, uint32_t opcode),
+	rte_trace_point_emit_u64(real_time);
 	rte_trace_point_emit_u32(opcode);
 )
 
diff --git a/drivers/net/mlx5/mlx5_tx.h b/drivers/net/mlx5/mlx5_tx.h
index 587e6a9f7d..55568c41b1 100644
--- a/drivers/net/mlx5/mlx5_tx.h
+++ b/drivers/net/mlx5/mlx5_tx.h
@@ -404,6 +404,14 @@ static __rte_always_inline uint64_t mlx5_read_pcibar_clock(struct rte_eth_dev *d
 	return 0;
 }
 
+static __rte_always_inline uint64_t mlx5_read_pcibar_clock_from_txq(struct mlx5_txq_data *txq)
+{
+	struct mlx5_txq_ctrl *txq_ctrl = container_of(txq, struct mlx5_txq_ctrl, txq);
+	struct rte_eth_dev *dev = ETH_DEV(txq_ctrl->priv);
+
+	return mlx5_read_pcibar_clock(dev);
+}
+
 /**
  * Set Software Parser flags and offsets in Ethernet Segment of WQE.
  * Flags must be preliminary initialized to zero.
@@ -841,6 +849,7 @@ mlx5_tx_cseg_init(struct mlx5_txq_data *__rte_restrict txq,
 		  unsigned int olx)
 {
 	struct mlx5_wqe_cseg *__rte_restrict cs = &wqe->cseg;
+	uint64_t real_time;
 
 	/* For legacy MPW replace the EMPW by TSO with modifier. */
 	if (MLX5_TXOFF_CONFIG(MPW) && opcode == MLX5_OPCODE_ENHANCED_MPSW)
@@ -854,9 +863,12 @@ mlx5_tx_cseg_init(struct mlx5_txq_data *__rte_restrict txq,
 		cs->flags = RTE_BE32(MLX5_COMP_ONLY_FIRST_ERR <<
 				     MLX5_COMP_MODE_OFFSET);
 	cs->misc = RTE_BE32(0);
-	if (__rte_trace_point_fp_is_enabled())
-		rte_pmd_mlx5_trace_tx_entry(txq->port_id, txq->idx);
-	rte_pmd_mlx5_trace_tx_wqe((txq->wqe_ci << 8) | opcode);
+	if (__rte_trace_point_fp_is_enabled()) {
+		real_time = mlx5_read_pcibar_clock_from_txq(txq);
+		if (!loc->pkts_sent)
+			rte_pmd_mlx5_trace_tx_entry(real_time, txq->port_id, txq->idx);
+		rte_pmd_mlx5_trace_tx_wqe(real_time, (txq->wqe_ci << 8) | opcode);
+	}
 }
 
 /**
@@ -3818,7 +3830,8 @@ mlx5_tx_burst_tmpl(struct mlx5_txq_data *__rte_restrict txq,
 		__mlx5_tx_free_mbuf(txq, pkts, loc.mbuf_free, olx);
 	/* Trace productive bursts only. */
 	if (__rte_trace_point_fp_is_enabled() && loc.pkts_sent)
-		rte_pmd_mlx5_trace_tx_exit(loc.pkts_sent, pkts_n);
+		rte_pmd_mlx5_trace_tx_exit(mlx5_read_pcibar_clock_from_txq(txq),
+					   loc.pkts_sent, pkts_n);
 	return loc.pkts_sent;
 }
 
diff --git a/drivers/net/mlx5/tools/mlx5_trace.py b/drivers/net/mlx5/tools/mlx5_trace.py
index 67461520a9..5eb634a490 100755
--- a/drivers/net/mlx5/tools/mlx5_trace.py
+++ b/drivers/net/mlx5/tools/mlx5_trace.py
@@ -174,7 +174,9 @@ def do_tx_entry(msg, trace):
         return
     # allocate the new burst and append to the queue
     burst = MlxBurst()
-    burst.call_ts = msg.default_clock_snapshot.ns_from_origin
+    burst.call_ts = event["real_time"]
+    if burst.call_ts == 0:
+        burst.call_ts = msg.default_clock_snapshot.ns_from_origin
     trace.tx_blst[cpu_id] = burst
     pq_id = event["port_id"] << 16 | event["queue_id"]
     queue = trace.tx_qlst.get(pq_id)
@@ -194,7 +196,9 @@ def do_tx_exit(msg, trace):
     burst = trace.tx_blst.get(cpu_id)
     if burst is None:
         return
-    burst.done_ts = msg.default_clock_snapshot.ns_from_origin
+    burst.done_ts = event["real_time"]
+    if burst.done_ts == 0:
+        burst.done_ts = msg.default_clock_snapshot.ns_from_origin
     burst.req = event["nb_req"]
     burst.done = event["nb_sent"]
     trace.tx_blst.pop(cpu_id)
@@ -210,7 +214,9 @@ def do_tx_wqe(msg, trace):
     wqe = MlxWqe()
     wqe.wait_ts = trace.tx_wlst.get(cpu_id)
     if wqe.wait_ts is None:
-        wqe.wait_ts = msg.default_clock_snapshot.ns_from_origin
+        wqe.wait_ts = event["real_time"]
+        if wqe.wait_ts == 0:
+            wqe.wait_ts = msg.default_clock_snapshot.ns_from_origin
     wqe.opcode = event["opcode"]
     burst.wqes.append(wqe)
 
-- 
2.34.1