[PATCH BlueZ v1 05/10] monitor: Report command latency in analyze mode

[Luiz Augusto von Dentz <luiz.dentz@gmail.com>]

From: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

A trace shows every command and every response, but not how quickly the
controller answered, and a command that was never answered at all leaves
no trace beyond its absence.

Measure the interval between a command and the Command Complete or
Command Status that acknowledges it, and report it per controller along
with the number of commands still unanswered at the end of the trace:

  Command latency: 0-215 msec (~55 msec +/- 70 msec)
  Commands without response: 3

Commands that are only acknowledged by a Command Status and complete much
later through a separate event are measured up to the acknowledgement
only. A Create Connection waiting three seconds for its Connect Complete
is waiting on the remote device, not on the controller, and folding that
in would swamp both the average and the deviation and leave the figure
describing how many connections the trace happened to contain.

Commands are matched on the opcode, oldest first, since several may be
outstanding at once and they need not complete in order. The queue is
bounded so commands that never get a response cannot pile up.

The model wrote the tracking, which the author reviewed and verified
against a trace with a known latency spread and known unanswered
commands.

Assisted-by: opencode:claude-opus-5
---
 monitor/analyze.c | 99 +++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 99 insertions(+)

diff --git a/monitor/analyze.c b/monitor/analyze.c
index 9742981ec21a..59c7e91b8758 100644
--- a/monitor/analyze.c
+++ b/monitor/analyze.c
@@ -57,8 +57,20 @@ struct hci_dev {
 	unsigned long unknown;
 	uint16_t manufacturer;
 	struct queue *conn_list;
+	struct queue *cmd_list;
+	struct packet_latency cmd_latency;
+	unsigned long num_cmd_rsp;
 };
 
+/* Command awaiting a Command Complete or a Command Status */
+struct hci_cmd {
+	uint16_t opcode;
+	struct timeval tv;
+};
+
+/* Bound the queue so commands that never get a response cannot pile up */
+#define CMD_LIST_MAX 64
+
 struct hci_stats {
 	size_t bytes;
 	size_t num;
@@ -488,6 +500,21 @@ static void dev_destroy(void *data)
 	printf("  %lu user logs\n", dev->user_log);
 	printf("  %lu control messages \n", dev->ctrl_msg);
 	printf("  %lu unknown opcodes\n", dev->unknown);
+
+	if (dev->num_cmd_rsp)
+		printf("  Command latency: %lld-%lld msec "
+				"(~%lld msec +/- %lld msec)\n",
+				TV_MSEC(dev->cmd_latency.min),
+				TV_MSEC(dev->cmd_latency.max),
+				TV_MSEC(dev->cmd_latency.med),
+				packet_latency_stddev(&dev->cmd_latency));
+
+	/* Whatever is left never got a Command Complete or Command Status */
+	if (!queue_isempty(dev->cmd_list))
+		printf("  Commands without response: %u\n",
+					queue_length(dev->cmd_list));
+
+	queue_destroy(dev->cmd_list, free);
 	queue_destroy(dev->conn_list, conn_destroy);
 	printf("\n");
 
@@ -504,6 +531,7 @@ static struct hci_dev *dev_alloc(uint16_t index)
 	dev->manufacturer = 0xffff;
 
 	dev->conn_list = queue_new();
+	dev->cmd_list = queue_new();
 
 	return dev;
 }
@@ -739,10 +767,20 @@ static void del_index(struct timeval *tv, uint16_t index,
 	dev_destroy(dev);
 }
 
+static bool match_cmd_opcode(const void *data, const void *user_data)
+{
+	const struct hci_cmd *cmd = data;
+
+	return cmd->opcode == PTR_TO_UINT(user_data);
+}
+
 static void command_pkt(struct timeval *tv, uint16_t index,
 					const void *data, uint16_t size)
 {
+	const struct bt_hci_cmd_hdr *hdr = data;
 	struct hci_dev *dev;
+	struct hci_cmd *cmd;
+	uint16_t opcode;
 
 	dev = dev_lookup(index);
 	if (!dev)
@@ -750,6 +788,51 @@ static void command_pkt(struct timeval *tv, uint16_t index,
 
 	dev->num_hci++;
 	dev->num_cmd++;
+
+	if (size < sizeof(*hdr))
+		return;
+
+	opcode = le16_to_cpu(hdr->opcode);
+
+	/* NOP carries no request and is only used to update ncmd */
+	if (opcode == BT_HCI_CMD_NOP)
+		return;
+
+	if (queue_length(dev->cmd_list) >= CMD_LIST_MAX)
+		free(queue_pop_head(dev->cmd_list));
+
+	cmd = new0(struct hci_cmd, 1);
+	cmd->opcode = opcode;
+	cmd->tv = *tv;
+
+	queue_push_tail(dev->cmd_list, cmd);
+}
+
+/*
+ * Measure how long the controller took to acknowledge a command. Commands
+ * that are only acknowledged here and complete later through a separate
+ * event are still measured up to the acknowledgement, so that the figure
+ * stays a property of the controller rather than of the remote device.
+ */
+static void cmd_rsp(struct hci_dev *dev, struct timeval *tv, uint16_t opcode)
+{
+	struct hci_cmd *cmd;
+	struct timeval res;
+
+	/*
+	 * Several commands may be outstanding at once and they need not
+	 * complete in order, so match on the opcode and take the oldest.
+	 */
+	cmd = queue_remove_if(dev->cmd_list, match_cmd_opcode,
+							UINT_TO_PTR(opcode));
+	if (!cmd)
+		return;
+
+	timersub(tv, &cmd->tv, &res);
+	packet_latency_add(&dev->cmd_latency, &res);
+	dev->num_cmd_rsp++;
+
+	free(cmd);
 }
 
 static void evt_conn_complete(struct hci_dev *dev, struct timeval *tv,
@@ -812,6 +895,8 @@ static void evt_cmd_complete(struct hci_dev *dev, struct timeval *tv,
 
 	opcode = le16_to_cpu(evt->opcode);
 
+	cmd_rsp(dev, tv, opcode);
+
 	switch (opcode) {
 	case BT_HCI_CMD_READ_BD_ADDR:
 		rsp_read_bd_addr(dev, tv, data, size);
@@ -819,6 +904,17 @@ static void evt_cmd_complete(struct hci_dev *dev, struct timeval *tv,
 	}
 }
 
+static void evt_cmd_status(struct hci_dev *dev, struct timeval *tv,
+					const void *data, uint16_t size)
+{
+	const struct bt_hci_evt_cmd_status *evt = data;
+
+	if (size < sizeof(*evt))
+		return;
+
+	cmd_rsp(dev, tv, le16_to_cpu(evt->opcode));
+}
+
 static bool match_plot_latency(const void *data, const void *user_data)
 {
 	const struct plot *plot = data;
@@ -1114,6 +1210,9 @@ static void event_pkt(struct timeval *tv, uint16_t index,
 	case BT_HCI_EVT_CMD_COMPLETE:
 		evt_cmd_complete(dev, tv, data, size);
 		break;
+	case BT_HCI_EVT_CMD_STATUS:
+		evt_cmd_status(dev, tv, data, size);
+		break;
 	case BT_HCI_EVT_NUM_COMPLETED_PACKETS:
 		evt_num_completed_packets(dev, tv, data, size);
 		break;
-- 
2.55.0