[PATCH 0/5] firewire: add tracepoints events for asynchronous transaction

[PATCH 0/5] firewire: add tracepoints events for asynchronous transaction

[Takashi Sakamoto]

Hi,

The series of changes in this patchse is to revise the previous RFC:
https://lore.kernel.org/lkml/20240418092303.19725-1-o-takashi@sakamocchi.jp/

In a view of IEEE 1394 bus, the main function of kernel core is to
provide transaction service to the bus. It is helpful to have some
mechanisms to trace any action of the service.

This series of changes adds some tracepoints events for the purpose.
It adds the following tracepoints events via 'firewire' subsystem:

* For outbound transactions (e.g. initiated by user process)
    * async_request_outbound_initiate
    * async_request_outbound_complete
    * async_response_inbound
* For inbound transactions (e.g. initiated by the other nodes in the bus)
    * async_request_inbound
    * async_response_outbound_initiate
    * async_response_outbound_complete

When probing these tracepoints events, the content of 'struct fw_packet'
passed between the core function and 1394 OHCI driver is recorded with
the fields of header and packet data. For example of the outbound
split transaction:

async_request_outbound_initiate: \
    transaction=0xffff955fc6a07b30 generation=5 scode=2 dst_id=0xffc0 \
    tlabel=18 tcode=9 src_id=0xffc1 offset=0xfffff0000984 \
    header={0xffc04990,0xffc1ffff,0xf0000984,0x80002} data={0x81,0x80}
async_request_outbound_complete: \
    transaction=0xffff955fc6a07b30 generation=5 scode=2 status=2 \
    timestamp=0xeabf
async_response_inbound: \
    transaction=0xffff955fc6a07b30 generation=5 scode=2 status=1 \
    timestamp=0xeac2 dst_id=0xffc1 tlabel=18 tcode=11 src_id=0xffc0 \
    rcode=0 header={0xffc149b0,0xffc00000,0x0,0x40002} data={0x81}

Takashi Sakamoto (5):
  firewire: core: add support for Linux kernel tracepoints
  firewire: core: add tracepoints events for asynchronous outbound
    request
  firewire: core: add tracepoints event for asynchronous inbound
    response
  firewire: core: add tracepoint event for asynchronous inbound request
  firewire: core: add tracepoints events for asynchronous outbound
    response

 drivers/firewire/Makefile           |   2 +-
 drivers/firewire/core-trace.c       |   5 +
 drivers/firewire/core-transaction.c |  93 +++++++-----
 include/trace/events/firewire.h     | 211 ++++++++++++++++++++++++++++
 4 files changed, 276 insertions(+), 35 deletions(-)
 create mode 100644 drivers/firewire/core-trace.c
 create mode 100644 include/trace/events/firewire.h

-- 
2.43.0

[PATCH 1/5] firewire: core: add support for Linux kernel tracepoints

[Takashi Sakamoto]

The Linux Kernel Tracepoints framework is enough useful to trace
packet data inbound to and outbound from core.

This commit adds firewire subsystem to use the framework.

Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
---
 drivers/firewire/Makefile       |  2 +-
 drivers/firewire/core-trace.c   |  5 +++++
 include/trace/events/firewire.h | 15 +++++++++++++++
 3 files changed, 21 insertions(+), 1 deletion(-)
 create mode 100644 drivers/firewire/core-trace.c
 create mode 100644 include/trace/events/firewire.h

diff --git a/drivers/firewire/Makefile b/drivers/firewire/Makefile
index bbde29a0fba6..013e1f2641bd 100644
--- a/drivers/firewire/Makefile
+++ b/drivers/firewire/Makefile
@@ -3,7 +3,7 @@
 # Makefile for the Linux IEEE 1394 implementation
 #
 
-firewire-core-y += core-card.o core-cdev.o core-device.o \
+firewire-core-y += core-trace.o core-card.o core-cdev.o core-device.o \
                    core-iso.o core-topology.o core-transaction.o
 firewire-ohci-y += ohci.o
 firewire-sbp2-y += sbp2.o
diff --git a/drivers/firewire/core-trace.c b/drivers/firewire/core-trace.c
new file mode 100644
index 000000000000..96cbd9d384dc
--- /dev/null
+++ b/drivers/firewire/core-trace.c
@@ -0,0 +1,5 @@
+// SPDX-License-Identifier: GPL-2.0-or-later
+// Copyright (c) 2024 Takashi Sakamoto
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/firewire.h>
diff --git a/include/trace/events/firewire.h b/include/trace/events/firewire.h
new file mode 100644
index 000000000000..bc55eaabf695
--- /dev/null
+++ b/include/trace/events/firewire.h
@@ -0,0 +1,15 @@
+// SPDX-License-Identifier: GPL-2.0-or-later
+// Copyright (c) 2024 Takashi Sakamoto
+
+#define TRACE_SYSTEM	firewire
+
+#if !defined(_FIREWIRE_TRACE_EVENT_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _FIREWIRE_TRACE_EVENT_H
+
+#include <linux/tracepoint.h>
+
+// Placeholder for future use.
+
+#endif // _FIREWIRE_TRACE_EVENT_H
+
+#include <trace/define_trace.h>
-- 
2.43.0

[PATCH 2/5] firewire: core: add tracepoints events for asynchronous outbound request

[Takashi Sakamoto]

In a view of core transaction service, the asynchronous outbound request
consists of two stages; initiation and completion. This commit adds a pair
of event for them.

The following example is for asynchronous lock request with compare_swap
code to offset 0x'ffff'f000'0904 in node 0xffc0.

async_request_outbound_initiate: \
  transaction=0xffff955fc6a07a10 generation=5 scode=2 dst_id=0xffc0 \
  tlabel=54 tcode=9 src_id=0xffc1 offset=0xfffff0000904 \
  header={0xffc0d990,0xffc1ffff,0xf0000904,0x80002}
  data={0x80,0x940181}
async_request_outbound_complete: \
  transaction=0xffff955fc6a07a10 generation=5 scode=2 status=2 \
  timestamp=0xd887

Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
---
 drivers/firewire/core-transaction.c |   7 ++
 include/trace/events/firewire.h     | 103 +++++++++++++++++++++++++++-
 2 files changed, 109 insertions(+), 1 deletion(-)

diff --git a/drivers/firewire/core-transaction.c b/drivers/firewire/core-transaction.c
index 3ecb0b945083..c9318024386f 100644
--- a/drivers/firewire/core-transaction.c
+++ b/drivers/firewire/core-transaction.c
@@ -29,6 +29,7 @@
 #include <asm/byteorder.h>
 
 #include "core.h"
+#include <trace/events/firewire.h>
 #include "packet-header-definitions.h"
 
 #define HEADER_DESTINATION_IS_BROADCAST(header) \
@@ -173,6 +174,9 @@ static void transmit_complete_callback(struct fw_packet *packet,
 	struct fw_transaction *t =
 	    container_of(packet, struct fw_transaction, packet);
 
+	trace_async_request_outbound_complete((uintptr_t)t, packet->generation, packet->speed,
+					      status, packet->timestamp);
+
 	switch (status) {
 	case ACK_COMPLETE:
 		close_transaction(t, card, RCODE_COMPLETE, packet->timestamp);
@@ -394,6 +398,9 @@ void __fw_send_request(struct fw_card *card, struct fw_transaction *t, int tcode
 
 	spin_unlock_irqrestore(&card->lock, flags);
 
+	trace_async_request_outbound_initiate((uintptr_t)t, generation, speed, t->packet.header, payload,
+					      tcode_is_read_request(tcode) ? 0 : length / 4);
+
 	card->driver->send_request(card, &t->packet);
 }
 EXPORT_SYMBOL_GPL(__fw_send_request);
diff --git a/include/trace/events/firewire.h b/include/trace/events/firewire.h
index bc55eaabf695..063695874cfb 100644
--- a/include/trace/events/firewire.h
+++ b/include/trace/events/firewire.h
@@ -7,8 +7,109 @@
 #define _FIREWIRE_TRACE_EVENT_H
 
 #include <linux/tracepoint.h>
+#include <linux/firewire.h>
 
-// Placeholder for future use.
+#include <linux/firewire-constants.h>
+
+#include "../../../drivers/firewire/packet-header-definitions.h"
+
+// The content of TP_printk field is preprocessed, then put to the module binary.
+#define ASYNC_HEADER_GET_DESTINATION(header)	\
+	(((header)[0] & ASYNC_HEADER_Q0_DESTINATION_MASK) >> ASYNC_HEADER_Q0_DESTINATION_SHIFT)
+
+#define ASYNC_HEADER_GET_TLABEL(header)	\
+	(((header)[0] & ASYNC_HEADER_Q0_TLABEL_MASK) >> ASYNC_HEADER_Q0_TLABEL_SHIFT)
+
+#define ASYNC_HEADER_GET_TCODE(header)	\
+	(((header)[0] & ASYNC_HEADER_Q0_TCODE_MASK) >> ASYNC_HEADER_Q0_TCODE_SHIFT)
+
+#define ASYNC_HEADER_GET_SOURCE(header)	\
+	(((header)[1] & ASYNC_HEADER_Q1_SOURCE_MASK) >> ASYNC_HEADER_Q1_SOURCE_SHIFT)
+
+#define ASYNC_HEADER_GET_OFFSET(header)	\
+	((((unsigned long long)((header)[1] & ASYNC_HEADER_Q1_OFFSET_HIGH_MASK)) >> ASYNC_HEADER_Q1_OFFSET_HIGH_SHIFT) << 32)| \
+	(header)[2]
+
+#define QUADLET_SIZE	4
+
+DECLARE_EVENT_CLASS(async_outbound_initiate_template,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, const u32 *header, const u32 *data, unsigned int data_count),
+	TP_ARGS(transaction, generation, scode, header, data, data_count),
+	TP_STRUCT__entry(
+		__field(u64, transaction)
+		__field(u8, generation)
+		__field(u8, scode)
+		__array(u32, header, ASYNC_HEADER_QUADLET_COUNT)
+		__dynamic_array(u32, data, data_count)
+	),
+	TP_fast_assign(
+		__entry->transaction = transaction;
+		__entry->generation = generation;
+		__entry->scode = scode;
+		memcpy(__entry->header, header, QUADLET_SIZE * ASYNC_HEADER_QUADLET_COUNT);
+		memcpy(__get_dynamic_array(data), data, __get_dynamic_array_len(data));
+	),
+	// This format is for the request subaction.
+	TP_printk(
+		"transaction=0x%llx generation=%u scode=%u dst_id=0x%04x tlabel=%u tcode=%u src_id=0x%04x offset=0x%012llx header=%s data=%s",
+		__entry->transaction,
+		__entry->generation,
+		__entry->scode,
+		ASYNC_HEADER_GET_DESTINATION(__entry->header),
+		ASYNC_HEADER_GET_TLABEL(__entry->header),
+		ASYNC_HEADER_GET_TCODE(__entry->header),
+		ASYNC_HEADER_GET_SOURCE(__entry->header),
+		ASYNC_HEADER_GET_OFFSET(__entry->header),
+		__print_array(__entry->header, ASYNC_HEADER_QUADLET_COUNT, QUADLET_SIZE),
+		__print_array(__get_dynamic_array(data),
+			      __get_dynamic_array_len(data) / QUADLET_SIZE, QUADLET_SIZE)
+	)
+);
+
+// The value of status is one of ack codes and rcodes specific to Linux FireWire subsystem.
+DECLARE_EVENT_CLASS(async_outbound_complete_template,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, unsigned int status, unsigned int timestamp),
+	TP_ARGS(transaction, generation, scode, status, timestamp),
+	TP_STRUCT__entry(
+		__field(u64, transaction)
+		__field(u8, generation)
+		__field(u8, scode)
+		__field(u8, status)
+		__field(u16, timestamp)
+	),
+	TP_fast_assign(
+		__entry->transaction = transaction;
+		__entry->generation = generation;
+		__entry->scode = scode;
+		__entry->status = status;
+		__entry->timestamp = timestamp;
+	),
+	TP_printk(
+		"transaction=0x%llx generation=%u scode=%u status=%u timestamp=0x%04x",
+		__entry->transaction,
+		__entry->generation,
+		__entry->scode,
+		__entry->status,
+		__entry->timestamp
+	)
+);
+
+DEFINE_EVENT(async_outbound_initiate_template, async_request_outbound_initiate,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, const u32 *header, const u32 *data, unsigned int data_count),
+	TP_ARGS(transaction, generation, scode, header, data, data_count)
+);
+
+DEFINE_EVENT(async_outbound_complete_template, async_request_outbound_complete,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, unsigned int status, unsigned int timestamp),
+	TP_ARGS(transaction, generation, scode, status, timestamp)
+);
+
+#undef ASYNC_HEADER_GET_DESTINATION
+#undef ASYNC_HEADER_GET_TLABEL
+#undef ASYNC_HEADER_GET_TCODE
+#undef ASYNC_HEADER_GET_SOURCE
+#undef ASYNC_HEADER_GET_OFFSET
+#undef QUADLET_SIZE
 
 #endif // _FIREWIRE_TRACE_EVENT_H
 
-- 
2.43.0

[PATCH 3/5] firewire: core: add tracepoints event for asynchronous inbound response

[Takashi Sakamoto]

In the transaction of IEEE 1394, the node to receive the asynchronous
request transfers any response packet to the requester except for the
unified transaction.

This commit adds an event for the inbound packet. Note that the code to
decode the packet header is moved, against the note about the sanity
check.

The following example is for asynchronous lock response with
compare_and_swap code.

async_response_inbound: \
  transaction=0xffff955fc6a07a10 generation=5 scode=2 status=1 \
  timestamp=0x0089 dst_id=0xffc1 tlabel=54 tcode=11 src_id=0xffc0 \
  rcode=0 header={0xffc1d9b0,0xffc00000,0x0,0x40002} data={0x50800080}

Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
---
 drivers/firewire/core-transaction.c | 55 +++++++++++++++--------------
 include/trace/events/firewire.h     | 50 ++++++++++++++++++++++++++
 2 files changed, 79 insertions(+), 26 deletions(-)

diff --git a/drivers/firewire/core-transaction.c b/drivers/firewire/core-transaction.c
index c9318024386f..56510d305564 100644
--- a/drivers/firewire/core-transaction.c
+++ b/drivers/firewire/core-transaction.c
@@ -1011,32 +1011,10 @@ void fw_core_handle_response(struct fw_card *card, struct fw_packet *p)
 	source = async_header_get_source(p->header);
 	rcode = async_header_get_rcode(p->header);
 
-	spin_lock_irqsave(&card->lock, flags);
-	list_for_each_entry(iter, &card->transaction_list, link) {
-		if (iter->node_id == source && iter->tlabel == tlabel) {
-			if (!try_cancel_split_timeout(iter)) {
-				spin_unlock_irqrestore(&card->lock, flags);
-				goto timed_out;
-			}
-			list_del_init(&iter->link);
-			card->tlabel_mask &= ~(1ULL << iter->tlabel);
-			t = iter;
-			break;
-		}
-	}
-	spin_unlock_irqrestore(&card->lock, flags);
-
-	if (!t) {
- timed_out:
-		fw_notice(card, "unsolicited response (source %x, tlabel %x)\n",
-			  source, tlabel);
-		return;
-	}
-
-	/*
-	 * FIXME: sanity check packet, is length correct, does tcodes
-	 * and addresses match.
-	 */
+	// FIXME: sanity check packet, is length correct, does tcodes
+	// and addresses match to the transaction request queried later.
+	//
+	// For the tracepoints event, let us decode the header here against the concern.
 
 	switch (tcode) {
 	case TCODE_READ_QUADLET_RESPONSE:
@@ -1062,6 +1040,31 @@ void fw_core_handle_response(struct fw_card *card, struct fw_packet *p)
 		break;
 	}
 
+	spin_lock_irqsave(&card->lock, flags);
+	list_for_each_entry(iter, &card->transaction_list, link) {
+		if (iter->node_id == source && iter->tlabel == tlabel) {
+			if (!try_cancel_split_timeout(iter)) {
+				spin_unlock_irqrestore(&card->lock, flags);
+				goto timed_out;
+			}
+			list_del_init(&iter->link);
+			card->tlabel_mask &= ~(1ULL << iter->tlabel);
+			t = iter;
+			break;
+		}
+	}
+	spin_unlock_irqrestore(&card->lock, flags);
+
+	trace_async_response_inbound((uintptr_t)t, p->generation, p->speed, p->ack, p->timestamp,
+				     p->header, data, data_length / 4);
+
+	if (!t) {
+ timed_out:
+		fw_notice(card, "unsolicited response (source %x, tlabel %x)\n",
+			  source, tlabel);
+		return;
+	}
+
 	/*
 	 * The response handler may be executed while the request handler
 	 * is still pending.  Cancel the request handler.
diff --git a/include/trace/events/firewire.h b/include/trace/events/firewire.h
index 063695874cfb..2d5f6b196a22 100644
--- a/include/trace/events/firewire.h
+++ b/include/trace/events/firewire.h
@@ -30,6 +30,9 @@
 	((((unsigned long long)((header)[1] & ASYNC_HEADER_Q1_OFFSET_HIGH_MASK)) >> ASYNC_HEADER_Q1_OFFSET_HIGH_SHIFT) << 32)| \
 	(header)[2]
 
+#define ASYNC_HEADER_GET_RCODE(header)	\
+	(((header)[1] & ASYNC_HEADER_Q1_RCODE_MASK) >> ASYNC_HEADER_Q1_RCODE_SHIFT)
+
 #define QUADLET_SIZE	4
 
 DECLARE_EVENT_CLASS(async_outbound_initiate_template,
@@ -94,6 +97,47 @@ DECLARE_EVENT_CLASS(async_outbound_complete_template,
 	)
 );
 
+// The value of status is one of ack codes and rcodes specific to Linux FireWire subsystem.
+DECLARE_EVENT_CLASS(async_inbound_template,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, unsigned int status, unsigned int timestamp, const u32 *header, const u32 *data, unsigned int data_count),
+	TP_ARGS(transaction, generation, scode, status, timestamp, header, data, data_count),
+	TP_STRUCT__entry(
+		__field(u64, transaction)
+		__field(u8, generation)
+		__field(u8, scode)
+		__field(u8, status)
+		__field(u8, timestamp)
+		__array(u32, header, ASYNC_HEADER_QUADLET_COUNT)
+		__dynamic_array(u32, data, data_count)
+	),
+	TP_fast_assign(
+		__entry->transaction = transaction;
+		__entry->generation = generation;
+		__entry->scode = scode;
+		__entry->status = status;
+		__entry->timestamp = timestamp;
+		memcpy(__entry->header, header, QUADLET_SIZE * ASYNC_HEADER_QUADLET_COUNT);
+		memcpy(__get_dynamic_array(data), data, __get_dynamic_array_len(data));
+	),
+	// This format is for the response subaction.
+	TP_printk(
+		"transaction=0x%llx generation=%u scode=%u status=%u timestamp=0x%04x dst_id=0x%04x tlabel=%u tcode=%u src_id=0x%04x rcode=%u header=%s data=%s",
+		__entry->transaction,
+		__entry->generation,
+		__entry->scode,
+		__entry->status,
+		__entry->timestamp,
+		ASYNC_HEADER_GET_DESTINATION(__entry->header),
+		ASYNC_HEADER_GET_TLABEL(__entry->header),
+		ASYNC_HEADER_GET_TCODE(__entry->header),
+		ASYNC_HEADER_GET_SOURCE(__entry->header),
+		ASYNC_HEADER_GET_RCODE(__entry->header),
+		__print_array(__entry->header, ASYNC_HEADER_QUADLET_COUNT, QUADLET_SIZE),
+		__print_array(__get_dynamic_array(data),
+			      __get_dynamic_array_len(data) / QUADLET_SIZE, QUADLET_SIZE)
+	)
+);
+
 DEFINE_EVENT(async_outbound_initiate_template, async_request_outbound_initiate,
 	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, const u32 *header, const u32 *data, unsigned int data_count),
 	TP_ARGS(transaction, generation, scode, header, data, data_count)
@@ -104,11 +148,17 @@ DEFINE_EVENT(async_outbound_complete_template, async_request_outbound_complete,
 	TP_ARGS(transaction, generation, scode, status, timestamp)
 );
 
+DEFINE_EVENT(async_inbound_template, async_response_inbound,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, unsigned int status, unsigned int timestamp, const u32 *header, const u32 *data, unsigned int data_count),
+	TP_ARGS(transaction, generation, scode, status, timestamp, header, data, data_count)
+);
+
 #undef ASYNC_HEADER_GET_DESTINATION
 #undef ASYNC_HEADER_GET_TLABEL
 #undef ASYNC_HEADER_GET_TCODE
 #undef ASYNC_HEADER_GET_SOURCE
 #undef ASYNC_HEADER_GET_OFFSET
+#undef ASYNC_HEADER_GET_RCODE
 #undef QUADLET_SIZE
 
 #endif // _FIREWIRE_TRACE_EVENT_H
-- 
2.43.0

[PATCH 4/5] firewire: core: add tracepoint event for asynchronous inbound request

[Takashi Sakamoto]

This commit adds an event for asynchronous inbound request.

The following example is for asynchronous block write request as IEC
61883-1 FCP request from node 0xffc1.

async_request_inbound: \
  transaction=0xffff89fa08cf16c0 generation=4 scode=2 status=2 \
  timestamp=0x00b3 dst_id=0xffc0 tlabel=19 tcode=1 src_id=0xffc1 \
  offset=0xfffff0000d00 header={0xffc04d10,0xffc1ffff,0xf0000d00,0x80000} \
  data={0x19ff08,0xffff0090}

Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
---
 drivers/firewire/core-transaction.c |  8 +++++++-
 include/trace/events/firewire.h     | 21 +++++++++++++++++++++
 2 files changed, 28 insertions(+), 1 deletion(-)

diff --git a/drivers/firewire/core-transaction.c b/drivers/firewire/core-transaction.c
index 56510d305564..8c13f996a938 100644
--- a/drivers/firewire/core-transaction.c
+++ b/drivers/firewire/core-transaction.c
@@ -973,11 +973,13 @@ void fw_core_handle_request(struct fw_card *card, struct fw_packet *p)
 {
 	struct fw_request *request;
 	unsigned long long offset;
+	unsigned int tcode;
 
 	if (p->ack != ACK_PENDING && p->ack != ACK_COMPLETE)
 		return;
 
-	if (tcode_is_link_internal(async_header_get_tcode(p->header))) {
+	tcode = async_header_get_tcode(p->header);
+	if (tcode_is_link_internal(tcode)) {
 		fw_cdev_handle_phy_packet(card, p);
 		return;
 	}
@@ -988,6 +990,10 @@ void fw_core_handle_request(struct fw_card *card, struct fw_packet *p)
 		return;
 	}
 
+	trace_async_request_inbound((uintptr_t)request, p->generation, p->speed, p->ack,
+				    p->timestamp, p->header, request->data,
+				    tcode_is_read_request(tcode) ? 0 : request->length / 4);
+
 	offset = async_header_get_offset(p->header);
 
 	if (!is_in_fcp_region(offset, request->length))
diff --git a/include/trace/events/firewire.h b/include/trace/events/firewire.h
index 2d5f6b196a22..a30cebed119a 100644
--- a/include/trace/events/firewire.h
+++ b/include/trace/events/firewire.h
@@ -153,6 +153,27 @@ DEFINE_EVENT(async_inbound_template, async_response_inbound,
 	TP_ARGS(transaction, generation, scode, status, timestamp, header, data, data_count)
 );
 
+DEFINE_EVENT_PRINT(async_inbound_template, async_request_inbound,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, unsigned int status, unsigned int timestamp, const u32 *header, const u32 *data, unsigned int data_count),
+	TP_ARGS(transaction, generation, scode, status, timestamp, header, data, data_count),
+	TP_printk(
+		"transaction=0x%llx generation=%u scode=%u status=%u timestamp=0x%04x dst_id=0x%04x tlabel=%u tcode=%u src_id=0x%04x offset=0x%012llx header=%s data=%s",
+		__entry->transaction,
+		__entry->generation,
+		__entry->scode,
+		__entry->status,
+		__entry->timestamp,
+		ASYNC_HEADER_GET_DESTINATION(__entry->header),
+		ASYNC_HEADER_GET_TLABEL(__entry->header),
+		ASYNC_HEADER_GET_TCODE(__entry->header),
+		ASYNC_HEADER_GET_SOURCE(__entry->header),
+		ASYNC_HEADER_GET_OFFSET(__entry->header),
+		__print_array(__entry->header, ASYNC_HEADER_QUADLET_COUNT, QUADLET_SIZE),
+		__print_array(__get_dynamic_array(data),
+			      __get_dynamic_array_len(data) / QUADLET_SIZE, QUADLET_SIZE)
+	)
+);
+
 #undef ASYNC_HEADER_GET_DESTINATION
 #undef ASYNC_HEADER_GET_TLABEL
 #undef ASYNC_HEADER_GET_TCODE
-- 
2.43.0

[PATCH 5/5] firewire: core: add tracepoints events for asynchronous outbound response

[Takashi Sakamoto]

In a view of core transaction service, the asynchronous outbound response
consists of two stages; initiation and completion.

This commit adds a pair of events for the asynchronous outbound response.
The following example is for asynchronous write quadlet request as IEC
61883-1 FCP response to node 0xffc1.

async_response_outbound_initiate: \
  transaction=0xffff89fa08cf16c0 generation=4 scode=2 dst_id=0xffc1 \
  tlabel=25 tcode=2 src_id=0xffc0 rcode=0 \
  header={0xffc16420,0xffc00000,0x0,0x0} data={}
async_response_outbound_complete: \
  transaction=0xffff89fa08cf16c0 generation=4 scode=2 status=1 \
  timestamp=0x0000

Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
---
 drivers/firewire/core-transaction.c | 23 ++++++++++++++++-------
 include/trace/events/firewire.h     | 24 ++++++++++++++++++++++++
 2 files changed, 40 insertions(+), 7 deletions(-)

diff --git a/drivers/firewire/core-transaction.c b/drivers/firewire/core-transaction.c
index 8c13f996a938..0e49ebf52500 100644
--- a/drivers/firewire/core-transaction.c
+++ b/drivers/firewire/core-transaction.c
@@ -668,6 +668,9 @@ static void free_response_callback(struct fw_packet *packet,
 {
 	struct fw_request *request = container_of(packet, struct fw_request, response);
 
+	trace_async_response_outbound_complete((uintptr_t)request, packet->generation,
+					       packet->speed, status, packet->timestamp);
+
 	// Decrease the reference count since not at in-flight.
 	fw_request_put(request);
 
@@ -850,6 +853,9 @@ static struct fw_request *allocate_request(struct fw_card *card,
 void fw_send_response(struct fw_card *card,
 		      struct fw_request *request, int rcode)
 {
+	u32 *data = NULL;
+	unsigned int data_length = 0;
+
 	/* unified transaction or broadcast transaction: don't respond */
 	if (request->ack != ACK_PENDING ||
 	    HEADER_DESTINATION_IS_BROADCAST(request->request_header)) {
@@ -857,17 +863,20 @@ void fw_send_response(struct fw_card *card,
 		return;
 	}
 
-	if (rcode == RCODE_COMPLETE)
-		fw_fill_response(&request->response, request->request_header,
-				 rcode, request->data,
-				 fw_get_response_length(request));
-	else
-		fw_fill_response(&request->response, request->request_header,
-				 rcode, NULL, 0);
+	if (rcode == RCODE_COMPLETE) {
+		data = request->data;
+		data_length = fw_get_response_length(request);
+	}
+
+	fw_fill_response(&request->response, request->request_header, rcode, data, data_length);
 
 	// Increase the reference count so that the object is kept during in-flight.
 	fw_request_get(request);
 
+	trace_async_response_outbound_initiate((uintptr_t)request, request->response.generation,
+					       request->response.speed, request->response.header,
+					       data, data ? data_length / 4 : 0);
+
 	card->driver->send_response(card, &request->response);
 }
 EXPORT_SYMBOL(fw_send_response);
diff --git a/include/trace/events/firewire.h b/include/trace/events/firewire.h
index a30cebed119a..d4688e341837 100644
--- a/include/trace/events/firewire.h
+++ b/include/trace/events/firewire.h
@@ -174,6 +174,30 @@ DEFINE_EVENT_PRINT(async_inbound_template, async_request_inbound,
 	)
 );
 
+DEFINE_EVENT_PRINT(async_outbound_initiate_template, async_response_outbound_initiate,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, const u32 *header, const u32 *data, unsigned int data_count),
+	TP_ARGS(transaction, generation, scode, header, data, data_count),
+	TP_printk(
+		"transaction=0x%llx generation=%u scode=%u dst_id=0x%04x tlabel=%u tcode=%u src_id=0x%04x rcode=%u header=%s data=%s",
+		__entry->transaction,
+		__entry->generation,
+		__entry->scode,
+		ASYNC_HEADER_GET_DESTINATION(__entry->header),
+		ASYNC_HEADER_GET_TLABEL(__entry->header),
+		ASYNC_HEADER_GET_TCODE(__entry->header),
+		ASYNC_HEADER_GET_SOURCE(__entry->header),
+		ASYNC_HEADER_GET_RCODE(__entry->header),
+		__print_array(__entry->header, ASYNC_HEADER_QUADLET_COUNT, QUADLET_SIZE),
+		__print_array(__get_dynamic_array(data),
+			      __get_dynamic_array_len(data) / QUADLET_SIZE, QUADLET_SIZE)
+	)
+);
+
+DEFINE_EVENT(async_outbound_complete_template, async_response_outbound_complete,
+	TP_PROTO(u64 transaction, unsigned int generation, unsigned int scode, unsigned int status, unsigned int timestamp),
+	TP_ARGS(transaction, generation, scode, status, timestamp)
+);
+
 #undef ASYNC_HEADER_GET_DESTINATION
 #undef ASYNC_HEADER_GET_TLABEL
 #undef ASYNC_HEADER_GET_TCODE
-- 
2.43.0

Re: [PATCH 0/5] firewire: add tracepoints events for asynchronous transaction

[Takashi Sakamoto]

On Mon, Apr 29, 2024 at 01:32:13PM +0900, Takashi Sakamoto wrote:
> Hi,
> 
> The series of changes in this patchse is to revise the previous RFC:
> https://lore.kernel.org/lkml/20240418092303.19725-1-o-takashi@sakamocchi.jp/
> 
> In a view of IEEE 1394 bus, the main function of kernel core is to
> provide transaction service to the bus. It is helpful to have some
> mechanisms to trace any action of the service.
> 
> This series of changes adds some tracepoints events for the purpose.
> It adds the following tracepoints events via 'firewire' subsystem:
> 
> * For outbound transactions (e.g. initiated by user process)
>     * async_request_outbound_initiate
>     * async_request_outbound_complete
>     * async_response_inbound
> * For inbound transactions (e.g. initiated by the other nodes in the bus)
>     * async_request_inbound
>     * async_response_outbound_initiate
>     * async_response_outbound_complete
> 
> When probing these tracepoints events, the content of 'struct fw_packet'
> passed between the core function and 1394 OHCI driver is recorded with
> the fields of header and packet data. For example of the outbound
> split transaction:
> 
> async_request_outbound_initiate: \
>     transaction=0xffff955fc6a07b30 generation=5 scode=2 dst_id=0xffc0 \
>     tlabel=18 tcode=9 src_id=0xffc1 offset=0xfffff0000984 \
>     header={0xffc04990,0xffc1ffff,0xf0000984,0x80002} data={0x81,0x80}
> async_request_outbound_complete: \
>     transaction=0xffff955fc6a07b30 generation=5 scode=2 status=2 \
>     timestamp=0xeabf
> async_response_inbound: \
>     transaction=0xffff955fc6a07b30 generation=5 scode=2 status=1 \
>     timestamp=0xeac2 dst_id=0xffc1 tlabel=18 tcode=11 src_id=0xffc0 \
>     rcode=0 header={0xffc149b0,0xffc00000,0x0,0x40002} data={0x81}
> 
> Takashi Sakamoto (5):
>   firewire: core: add support for Linux kernel tracepoints
>   firewire: core: add tracepoints events for asynchronous outbound
>     request
>   firewire: core: add tracepoints event for asynchronous inbound
>     response
>   firewire: core: add tracepoint event for asynchronous inbound request
>   firewire: core: add tracepoints events for asynchronous outbound
>     response
> 
>  drivers/firewire/Makefile           |   2 +-
>  drivers/firewire/core-trace.c       |   5 +
>  drivers/firewire/core-transaction.c |  93 +++++++-----
>  include/trace/events/firewire.h     | 211 ++++++++++++++++++++++++++++
>  4 files changed, 276 insertions(+), 35 deletions(-)
>  create mode 100644 drivers/firewire/core-trace.c
>  create mode 100644 include/trace/events/firewire.h

Applied to for-next branch.


Regards

Takashi Sakamoto