diff mbox series

[RFC,1/3] Bluetooth: add transmission latency tracking for ISO and ACL

Message ID c99ba1062eea9d1bd463bafc7f052bd2d93de172.1709150574.git.pav@iki.fi (mailing list archive)
State New, archived
Headers show
Series Bluetooth: add transmission latency tracking for ISO & L2CAP | expand

Checks

Context Check Description
tedd_an/pre-ci_am success Success
tedd_an/CheckPatch success CheckPatch PASS
tedd_an/GitLint success Gitlint PASS
tedd_an/SubjectPrefix success Gitlint PASS
tedd_an/BuildKernel success BuildKernel PASS
tedd_an/CheckAllWarning success CheckAllWarning PASS
tedd_an/CheckSparse warning CheckSparse WARNING net/bluetooth/hci_event.c: note: in included file (through include/net/bluetooth/hci_core.h):
tedd_an/CheckSmatch warning CheckSparse WARNING net/bluetooth/hci_event.c: note: in included file (through include/net/bluetooth/hci_core.h):
tedd_an/BuildKernel32 success BuildKernel32 PASS
tedd_an/TestRunnerSetup success TestRunnerSetup PASS
tedd_an/TestRunner_l2cap-tester success TestRunner PASS
tedd_an/TestRunner_iso-tester fail TestRunner_iso-tester: Total: 117, Passed: 116 (99.1%), Failed: 1, Not Run: 0
tedd_an/TestRunner_bnep-tester success TestRunner PASS
tedd_an/TestRunner_mgmt-tester fail TestRunner_mgmt-tester: Total: 492, Passed: 489 (99.4%), Failed: 1, Not Run: 2
tedd_an/TestRunner_rfcomm-tester success TestRunner PASS
tedd_an/TestRunner_sco-tester success TestRunner PASS
tedd_an/TestRunner_ioctl-tester success TestRunner PASS
tedd_an/TestRunner_mesh-tester success TestRunner PASS
tedd_an/TestRunner_smp-tester success TestRunner PASS
tedd_an/TestRunner_userchan-tester success TestRunner PASS
tedd_an/IncrementalBuild success Incremental Build PASS

Commit Message

Pauli Virtanen Feb. 28, 2024, 8:03 p.m. UTC
Add mechanism to track specific skbs from socket to controller packet
completion.

This will be used to allow users submitting packets to sockets, to find
for the latest completed packet: the total socket+controller queue
length (in packets they submitted), controller packet completion timing,
and current total transmission latency.

This handles fragmentation of user-submitted packets and flow control in
L2CAP, which make raw skb queue lengths not informative to the user, and
does not change skb life cycle.

Implementation:

Sockets may mark selected skbs.  When controller reports the
corresponding packet completed, information in struct tx_latency in the
corresponding hci_conn or hci_chan is updated.

Add struct tx_latency to hci_conn and hci_chan, to track last completed
packet status.

Add hci_tx_info_queue to each hci_conn, and use it to track which
packets they sent to controller.  In packet completion event, pop info
from the queues to find if the packet had marked skb and which hci_chan
it came from.

Allow safe concurrent reading of struct tx_latency.

Signed-off-by: Pauli Virtanen <pav@iki.fi>
---
 include/net/bluetooth/bluetooth.h |   2 +
 include/net/bluetooth/hci_core.h  |  30 ++++++++
 net/bluetooth/hci_conn.c          | 110 +++++++++++++++++++++++++++++-
 net/bluetooth/hci_core.c          |  14 ++++
 net/bluetooth/hci_event.c         |  66 ++++++++++++++++++
 5 files changed, 221 insertions(+), 1 deletion(-)

Comments

bluez.test.bot@gmail.com Feb. 28, 2024, 8:34 p.m. UTC | #1
This is automated email and please do not reply to this email!

Dear submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=830847

---Test result---

Test Summary:
CheckPatch                    PASS      2.92 seconds
GitLint                       PASS      0.64 seconds
SubjectPrefix                 PASS      0.22 seconds
BuildKernel                   PASS      28.25 seconds
CheckAllWarning               PASS      30.98 seconds
CheckSparse                   WARNING   36.36 seconds
CheckSmatch                   WARNING   98.52 seconds
BuildKernel32                 PASS      26.86 seconds
TestRunnerSetup               PASS      493.62 seconds
TestRunner_l2cap-tester       PASS      17.87 seconds
TestRunner_iso-tester         FAIL      32.55 seconds
TestRunner_bnep-tester        PASS      4.78 seconds
TestRunner_mgmt-tester        FAIL      112.87 seconds
TestRunner_rfcomm-tester      PASS      7.27 seconds
TestRunner_sco-tester         PASS      10.88 seconds
TestRunner_ioctl-tester       PASS      7.79 seconds
TestRunner_mesh-tester        PASS      5.82 seconds
TestRunner_smp-tester         PASS      7.17 seconds
TestRunner_userchan-tester    PASS      4.92 seconds
IncrementalBuild              PASS      73.74 seconds

Details
##############################
Test: CheckSparse - WARNING
Desc: Run sparse tool with linux kernel
Output:
net/bluetooth/hci_event.c: note: in included file (through include/net/bluetooth/hci_core.h):
##############################
Test: CheckSmatch - WARNING
Desc: Run smatch tool with source
Output:
net/bluetooth/hci_event.c: note: in included file (through include/net/bluetooth/hci_core.h):
##############################
Test: TestRunner_iso-tester - FAIL
Desc: Run iso-tester with test-runner
Output:
Total: 117, Passed: 116 (99.1%), Failed: 1, Not Run: 0

Failed Test Cases
ISO Connect Suspend - Success                        Failed       6.215 seconds
##############################
Test: TestRunner_mgmt-tester - FAIL
Desc: Run mgmt-tester with test-runner
Output:
Total: 492, Passed: 489 (99.4%), Failed: 1, Not Run: 2

Failed Test Cases
LL Privacy - Start Discovery 2 (Disable RL)          Failed       0.182 seconds


---
Regards,
Linux Bluetooth
diff mbox series

Patch

diff --git a/include/net/bluetooth/bluetooth.h b/include/net/bluetooth/bluetooth.h
index 7ffa8c192c3f..f6bdd040adaa 100644
--- a/include/net/bluetooth/bluetooth.h
+++ b/include/net/bluetooth/bluetooth.h
@@ -462,6 +462,8 @@  struct bt_skb_cb {
 	u8 pkt_type;
 	u8 force_active;
 	u16 expect;
+	u16 user_sn;
+	u8 have_user_sn:1;
 	u8 incoming:1;
 	u8 pkt_status:2;
 	union {
diff --git a/include/net/bluetooth/hci_core.h b/include/net/bluetooth/hci_core.h
index 56fb42df44a3..e84a37c1e8b1 100644
--- a/include/net/bluetooth/hci_core.h
+++ b/include/net/bluetooth/hci_core.h
@@ -29,6 +29,7 @@ 
 #include <linux/idr.h>
 #include <linux/leds.h>
 #include <linux/rculist.h>
+#include <linux/seqlock.h>
 
 #include <net/bluetooth/hci.h>
 #include <net/bluetooth/hci_sync.h>
@@ -267,6 +268,26 @@  struct adv_info {
 	struct delayed_work	rpa_expired_cb;
 };
 
+struct tx_latency {
+	seqcount_t	seq;
+	struct {
+		ktime_t		time;
+		__s64		offset;
+		unsigned int	queue;
+	} now;
+	__u16		sn;
+};
+
+struct tx_info_queue {
+	struct {
+		__u16	sn;
+		void	*data;
+	} *info;
+	unsigned int	size;
+	unsigned int	head;
+	unsigned int	num;
+};
+
 #define HCI_MAX_ADV_INSTANCES		5
 #define HCI_DEFAULT_ADV_DURATION	2
 
@@ -746,6 +767,9 @@  struct hci_conn {
 	struct bt_iso_qos iso_qos;
 	unsigned long	flags;
 
+	struct tx_latency tx_latency;
+	struct tx_info_queue tx_info_queue;
+
 	enum conn_reasons conn_reason;
 	__u8		abort_reason;
 
@@ -803,6 +827,7 @@  struct hci_chan {
 	unsigned int	sent;
 	__u8		state;
 	bool		amp;
+	struct tx_latency tx_latency;
 };
 
 struct hci_conn_params {
@@ -1546,6 +1571,11 @@  void hci_conn_enter_active_mode(struct hci_conn *conn, __u8 force_active);
 void hci_conn_failed(struct hci_conn *conn, u8 status);
 u8 hci_conn_set_handle(struct hci_conn *conn, u16 handle);
 
+void hci_conn_tx_info_push(struct hci_conn *conn, void *ptr, __u16 sn);
+void *hci_conn_tx_info_pop(struct hci_conn *conn, __u16 *sn);
+void hci_mark_tx_latency(struct tx_latency *tx, struct sk_buff *skb);
+void hci_copy_tx_latency(struct tx_latency *dst, struct tx_latency *src);
+
 /*
  * hci_conn_get() and hci_conn_put() are used to control the life-time of an
  * "hci_conn" object. They do not guarantee that the hci_conn object is running,
diff --git a/net/bluetooth/hci_conn.c b/net/bluetooth/hci_conn.c
index 3ad74f76983b..2c557eb63b93 100644
--- a/net/bluetooth/hci_conn.c
+++ b/net/bluetooth/hci_conn.c
@@ -138,6 +138,12 @@  void hci_connect_le_scan_cleanup(struct hci_conn *conn, u8 status)
 	hci_update_passive_scan(hdev);
 }
 
+static void hci_conn_tx_info_cleanup(struct hci_conn *conn)
+{
+	kfree(conn->tx_info_queue.info);
+	conn->tx_info_queue.info = NULL;
+}
+
 static void hci_conn_cleanup(struct hci_conn *conn)
 {
 	struct hci_dev *hdev = conn->hdev;
@@ -158,6 +164,8 @@  static void hci_conn_cleanup(struct hci_conn *conn)
 	if (conn->cleanup)
 		conn->cleanup(conn);
 
+	hci_conn_tx_info_cleanup(conn);
+
 	if (conn->type == SCO_LINK || conn->type == ESCO_LINK) {
 		switch (conn->setting & SCO_AIRMODE_MASK) {
 		case SCO_AIRMODE_CVSD:
@@ -904,6 +912,39 @@  static int hci_conn_hash_alloc_unset(struct hci_dev *hdev)
 			       U16_MAX, GFP_ATOMIC);
 }
 
+static int hci_conn_tx_info_init(struct hci_conn *conn)
+{
+	struct tx_info_queue *txq = &conn->tx_info_queue;
+	size_t size = 0;
+
+	switch (conn->type) {
+	case ISO_LINK:
+		size = conn->hdev->iso_pkts;
+		if (!size)
+			size = conn->hdev->le_pkts;
+		if (!size)
+			size = conn->hdev->acl_pkts;
+		break;
+	case ACL_LINK:
+		size = conn->hdev->acl_pkts;
+		break;
+	}
+
+	if (size) {
+		txq->info = kcalloc(size, sizeof(txq->info[0]), GFP_KERNEL);
+		if (!txq->info)
+			return -ENOMEM;
+	} else {
+		txq->info = NULL;
+	}
+
+	txq->size = size;
+	txq->head = 0;
+	txq->num = 0;
+
+	return 0;
+}
+
 struct hci_conn *hci_conn_add(struct hci_dev *hdev, int type, bdaddr_t *dst,
 			      u8 role, u16 handle)
 {
@@ -932,6 +973,12 @@  struct hci_conn *hci_conn_add(struct hci_dev *hdev, int type, bdaddr_t *dst,
 	conn->max_tx_power = HCI_TX_POWER_INVALID;
 	conn->sync_handle = HCI_SYNC_HANDLE_INVALID;
 
+	seqcount_init(&conn->tx_latency.seq);
+	if (hci_conn_tx_info_init(conn) < 0) {
+		kfree(conn);
+		return NULL;
+	}
+
 	set_bit(HCI_CONN_POWER_SAVE, &conn->flags);
 	conn->disc_timeout = HCI_DISCONN_TIMEOUT;
 
@@ -1005,6 +1052,7 @@  struct hci_conn *hci_conn_add(struct hci_dev *hdev, int type, bdaddr_t *dst,
 struct hci_conn *hci_conn_add_unset(struct hci_dev *hdev, int type,
 				    bdaddr_t *dst, u8 role)
 {
+	struct hci_conn *conn;
 	int handle;
 
 	bt_dev_dbg(hdev, "dst %pMR", dst);
@@ -1013,7 +1061,11 @@  struct hci_conn *hci_conn_add_unset(struct hci_dev *hdev, int type,
 	if (unlikely(handle < 0))
 		return NULL;
 
-	return hci_conn_add(hdev, type, dst, role, handle);
+	conn = hci_conn_add(hdev, type, dst, role, handle);
+	if (!conn)
+		ida_free(&hdev->unset_handle_ida, handle);
+
+	return conn;
 }
 
 static void hci_conn_cleanup_child(struct hci_conn *conn, u8 reason)
@@ -2711,6 +2763,8 @@  struct hci_chan *hci_chan_create(struct hci_conn *conn)
 	skb_queue_head_init(&chan->data_q);
 	chan->state = BT_CONNECTED;
 
+	seqcount_init(&chan->tx_latency.seq);
+
 	list_add_rcu(&chan->list, &conn->chan_list);
 
 	return chan;
@@ -2928,3 +2982,57 @@  int hci_abort_conn(struct hci_conn *conn, u8 reason)
 
 	return hci_cmd_sync_queue_once(hdev, abort_conn_sync, conn, NULL);
 }
+
+void hci_conn_tx_info_push(struct hci_conn *conn, void *ptr, __u16 sn)
+{
+	struct tx_info_queue *txq = &conn->tx_info_queue;
+	unsigned int tail;
+
+	if (!txq->num && !ptr)
+		return;
+	if (txq->num >= txq->size || !txq->info)
+		return;
+
+	tail = (txq->head + txq->num) % txq->size;
+	txq->info[tail].data = ptr;
+	txq->info[tail].sn = sn;
+	txq->num++;
+}
+
+void *hci_conn_tx_info_pop(struct hci_conn *conn, __u16 *sn)
+{
+	struct tx_info_queue *txq = &conn->tx_info_queue;
+	void *ptr;
+
+	if (!txq->num || !txq->info || !txq->size)
+		return NULL;
+
+	ptr = txq->info[txq->head].data;
+	*sn = txq->info[txq->head].sn;
+	txq->head = (txq->head + 1) % txq->size;
+	txq->num--;
+
+	return ptr;
+}
+
+void hci_mark_tx_latency(struct tx_latency *tx, struct sk_buff *skb)
+{
+	if (!skb)
+		return;
+
+	/* Reads may be concurrent */
+	WRITE_ONCE(tx->sn, tx->sn + 1u);
+
+	bt_cb(skb)->user_sn = tx->sn;
+	bt_cb(skb)->have_user_sn = true;
+}
+
+void hci_copy_tx_latency(struct tx_latency *dst, struct tx_latency *src)
+{
+	unsigned int seq;
+
+	do {
+		seq = read_seqcount_begin(&src->seq);
+		dst->now = src->now;
+	} while (read_seqcount_retry(&src->seq, seq));
+}
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index 6ca4c0df9f9c..bbdd8b28fb2c 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -3703,6 +3703,9 @@  static void hci_sched_acl_pkt(struct hci_dev *hdev)
 	       (chan = hci_chan_sent(hdev, ACL_LINK, &quote))) {
 		u32 priority = (skb_peek(&chan->data_q))->priority;
 		while (quote-- && (skb = skb_peek(&chan->data_q))) {
+			u16 sn = bt_cb(skb)->user_sn;
+			bool have_sn = bt_cb(skb)->have_user_sn;
+
 			BT_DBG("chan %p skb %p len %d priority %u", chan, skb,
 			       skb->len, skb->priority);
 
@@ -3722,6 +3725,11 @@  static void hci_sched_acl_pkt(struct hci_dev *hdev)
 			chan->sent++;
 			chan->conn->sent++;
 
+			if (have_sn)
+				hci_conn_tx_info_push(chan->conn, chan, sn);
+			else
+				hci_conn_tx_info_push(chan->conn, NULL, 0);
+
 			/* Send pending SCO packets right away */
 			hci_sched_sco(hdev);
 			hci_sched_esco(hdev);
@@ -3875,9 +3883,15 @@  static void hci_sched_iso(struct hci_dev *hdev)
 		hdev->le_pkts ? &hdev->le_cnt : &hdev->acl_cnt;
 	while (*cnt && (conn = hci_low_sent(hdev, ISO_LINK, &quote))) {
 		while (quote-- && (skb = skb_dequeue(&conn->data_q))) {
+			u16 sn = bt_cb(skb)->user_sn;
+			bool have_sn = bt_cb(skb)->have_user_sn;
+
 			BT_DBG("skb %p len %d", skb, skb->len);
+
 			hci_send_frame(hdev, skb);
 
+			hci_conn_tx_info_push(conn, UINT_PTR(have_sn), sn);
+
 			conn->sent++;
 			if (conn->sent == ~0)
 				conn->sent = 0;
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index bffd2c7ff608..144d4b481309 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -4417,10 +4417,72 @@  static void hci_role_change_evt(struct hci_dev *hdev, void *data,
 	hci_dev_unlock(hdev);
 }
 
+static void update_acl_tx_latency(struct hci_conn *conn, int count, ktime_t now)
+{
+	unsigned int i;
+
+	rcu_read_lock();
+
+	for (i = 0; i < count; ++i) {
+		struct hci_chan *chan;
+		void *ptr;
+		u16 sn;
+
+		ptr = hci_conn_tx_info_pop(conn, &sn);
+		if (!ptr)
+			continue;
+
+		list_for_each_entry_rcu(chan, &conn->chan_list, list) {
+			struct tx_latency *tx = &chan->tx_latency;
+
+			if (chan != ptr)
+				continue;
+
+			preempt_disable();
+			write_seqcount_begin(&tx->seq);
+			tx->now.time = now;
+			tx->now.queue = (u16)(READ_ONCE(tx->sn) - sn);
+			tx->now.offset = 0;
+			write_seqcount_end(&tx->seq);
+			preempt_enable();
+		}
+	}
+
+	rcu_read_unlock();
+}
+
+static void update_iso_tx_latency(struct hci_conn *conn, int count, ktime_t now)
+{
+	struct tx_latency *tx = NULL;
+	u16 sn;
+	unsigned int i;
+
+	for (i = 0; i < count; ++i) {
+		u16 tx_sn;
+
+		if (hci_conn_tx_info_pop(conn, &tx_sn)) {
+			tx = &conn->tx_latency;
+			sn = tx_sn;
+		}
+	}
+
+	if (!tx)
+		return;
+
+	preempt_disable();
+	write_seqcount_begin(&tx->seq);
+	tx->now.time = now;
+	tx->now.queue = (u16)(READ_ONCE(tx->sn) - sn);
+	tx->now.offset = 0;
+	write_seqcount_end(&tx->seq);
+	preempt_enable();
+}
+
 static void hci_num_comp_pkts_evt(struct hci_dev *hdev, void *data,
 				  struct sk_buff *skb)
 {
 	struct hci_ev_num_comp_pkts *ev = data;
+	ktime_t now = ktime_get();
 	int i;
 
 	if (!hci_ev_skb_pull(hdev, skb, HCI_EV_NUM_COMP_PKTS,
@@ -4450,6 +4512,8 @@  static void hci_num_comp_pkts_evt(struct hci_dev *hdev, void *data,
 
 		switch (conn->type) {
 		case ACL_LINK:
+			update_acl_tx_latency(conn, count, now);
+
 			hdev->acl_cnt += count;
 			if (hdev->acl_cnt > hdev->acl_pkts)
 				hdev->acl_cnt = hdev->acl_pkts;
@@ -4474,6 +4538,8 @@  static void hci_num_comp_pkts_evt(struct hci_dev *hdev, void *data,
 			break;
 
 		case ISO_LINK:
+			update_iso_tx_latency(conn, count, now);
+
 			if (hdev->iso_pkts) {
 				hdev->iso_cnt += count;
 				if (hdev->iso_cnt > hdev->iso_pkts)