monitor: Print channel latency information with -a/--analyze

This prints channel latency information and use gnuplot when using
-a/--analyze to plot a graph of channels:

  Found TX L2CAP channel with CID 68
        PSM 25
        22490 packets
        7-50 msec (~11 msec) TX Latency
        850-850 octets TX packet size
        ~569 Kb/s TX transfer speed

  10000 +-+----------------------------------------------------------------+
         +|     ++                                                         |
         +|     || +                                       Packets +-----+ |
         +|   + || |                                                       |
   1000 +-|   | || |+ ++                                                   |
         +|   | || || ||   +                                               |
         +|   | || || ||+ +|                                               |
         +|   | || || ||| || ++ ++                                         |
    100 +-|   | || || ||| || || ||   +                                     |
         +|   | || || ||| || || || ++| +   +                               |
         +|   | || || ||| || || || ||| |   |                               |
         +|   | || || ||| || || || ||| |+ +| +                             |
          |   | || || ||| || || || ||| || || |+ +                          |
     10 +-|   | || || ||| || || || ||| || || || |+                         |
         +|   | || || ||| || || || ||| || || || ||     +                   |
         +|  +| || || ||| || || || ||| || || || ||+ ++ |+ ++ +             |
          |  || || || ||| || || || ||| || || || ||| || || || |             |
      1 +-|  || || || ||| || || || ||| || || || ||| || || || |   +     +   |
         ++----------------------------------------------------------------+
          +      +      +       +      +      +      +       +      +      +
          5      10     15      20     25     30     35      40     45     50
                                    Latency (ms)

1 files changed, 100 insertions, 55 deletions

diff --git a/monitor/analyze.c b/monitor/analyze.c
index b9f7eded..80763fa4 100755
--- a/monitor/analyze.c
+++ b/monitor/analyze.c
@@ -80,6 +80,11 @@ struct hci_conn {
 	struct queue *chan_list;
 };
 
+struct hci_conn_tx {
+	struct timeval tv;
+	struct l2cap_chan *chan;
+};
+
 struct plot {
 	long long x_msec;
 	size_t y_count;
@@ -90,19 +95,81 @@ struct l2cap_chan {
 	uint16_t psm;
 	bool out;
 	unsigned long num;
+	size_t tx_bytes;
+	struct packet_latency tx_l;
+	struct queue *plot;
+	uint16_t tx_pkt_min;
+	uint16_t tx_pkt_max;
 };
 
 static struct queue *dev_list;
 
+static void tmp_write(void *data, void *user_data)
+{
+	struct plot *plot = data;
+	FILE *tmp = user_data;
+
+	fprintf(tmp, "%lld %zu\n", plot->x_msec, plot->y_count);
+}
+
+static void plot_draw(struct queue *queue)
+{
+	const char *filename = "analyze.tmp";
+	FILE *gplot = popen("gnuplot", "w");
+	FILE *tmp;
+
+	if (!gplot)
+		return;
+
+	if (queue_isempty(queue))
+		goto done;
+
+	tmp = fopen(filename, "w");
+	if (!tmp)
+		goto done;
+
+	queue_foreach(queue, tmp_write, tmp);
+
+	fprintf(gplot, "set terminal dumb enhanced ansi\n");
+	fprintf(gplot, "set xlabel 'Latency (ms)'\n");
+	fprintf(gplot, "set tics out nomirror\n");
+	fprintf(gplot, "set log y\n");
+	fprintf(gplot, "set yrange [0.5:*]\n");
+	fprintf(gplot, "plot './%s' using 1:2 t 'Packets' w impulses\n",
+								filename);
+	fflush(gplot);
+
+	fclose(tmp);
+done:
+	pclose(gplot);
+	unlink(filename);
+}
+
 static void chan_destroy(void *data)
 {
 	struct l2cap_chan *chan = data;
 
-	printf("    Found %s L2CAP channel with CID %u\n",
+	printf("  Found %s L2CAP channel with CID %u\n",
 					chan->out ? "TX" : "RX", chan->cid);
 	if (chan->psm)
-		printf("      PSM %u\n", chan->psm);
-	printf("      %lu packets\n", chan->num);
+		print_field("PSM %u", chan->psm);
+
+	print_field("%lu packets", chan->num);
+
+	if (!queue_isempty(chan->plot)) {
+		print_field("%lld-%lld msec (~%lld msec) TX Latency",
+			TV_MSEC(chan->tx_l.min), TV_MSEC(chan->tx_l.max),
+			TV_MSEC(chan->tx_l.med));
+		print_field("%u-%u octets TX packet size",
+				chan->tx_pkt_min, chan->tx_pkt_max);
+	}
+
+	if (TV_MSEC(chan->tx_l.total))
+		print_field("~%lld Kb/s TX transfer speed",
+				chan->tx_bytes * 8 / TV_MSEC(chan->tx_l.total));
+
+	if (chan->num > 1)
+		plot_draw(chan->plot);
 
 	free(chan);
 }
@@ -116,6 +183,7 @@ static struct l2cap_chan *chan_alloc(struct hci_conn *conn, uint16_t cid,
 
 	chan->cid = cid;
 	chan->out = out;
+	chan->plot = queue_new();
 
 	return chan;
 }
@@ -145,47 +213,6 @@ static struct l2cap_chan *chan_lookup(struct hci_conn *conn, uint16_t cid,
 	return chan;
 }
 
-static void tmp_write(void *data, void *user_data)
-{
-	struct plot *plot = data;
-	FILE *tmp = user_data;
-
-	fprintf(tmp, "%lld %zu\n", plot->x_msec, plot->y_count);
-}
-
-static void plot_draw(struct queue *queue)
-{
-	const char *filename = "analyze.tmp";
-	FILE *gplot = popen("gnuplot", "w");
-	FILE *tmp;
-
-	if (!gplot)
-		return;
-
-	if (queue_isempty(queue))
-		goto done;
-
-	tmp = fopen(filename, "w");
-	if (!tmp)
-		goto done;
-
-	queue_foreach(queue, tmp_write, tmp);
-
-	fprintf(gplot, "set terminal dumb enhanced ansi\n");
-	fprintf(gplot, "set xlabel 'Latency (ms)'\n");
-	fprintf(gplot, "set tics out nomirror\n");
-	fprintf(gplot, "set log y\n");
-	fprintf(gplot, "set yrange [0.5:*]\n");
-	fprintf(gplot, "plot './%s' using 1:2 t 'Packets' w impulses\n",
-								filename);
-	fflush(gplot);
-
-	fclose(tmp);
-done:
-	pclose(gplot);
-	unlink(filename);
-}
-
 static void conn_destroy(void *data)
 {
 	struct hci_conn *conn = data;
@@ -508,9 +535,11 @@ static void plot_add(struct queue *queue, struct timeval *latency,
 {
 	struct plot *plot;
 
-	plot = queue_find(queue, match_plot_latency, latency);
+	/* Use LRU ordering */
+	plot = queue_remove_if(queue, match_plot_latency, latency);
 	if (plot) {
 		plot->y_count += count;
+		queue_push_head(queue, plot);
 		return;
 	}
 
@@ -535,7 +564,7 @@ static void evt_num_completed_packets(struct hci_dev *dev, struct timeval *tv,
 		uint16_t count = get_le16(data + 2);
 		struct hci_conn *conn;
 		struct timeval res;
-		struct timeval *last_tx;
+		struct hci_conn_tx *last_tx;
 		int j;
 
 		data += 4;
@@ -550,11 +579,17 @@ static void evt_num_completed_packets(struct hci_dev *dev, struct timeval *tv,
 		for (j = 0; j < count; j++) {
 			last_tx = queue_pop_head(conn->tx_queue);
 			if (last_tx) {
-				timersub(tv, last_tx, &res);
+				struct l2cap_chan *chan = last_tx->chan;
+
+				timersub(tv, &last_tx->tv, &res);
 
 				packet_latency_add(&conn->tx_l, &res);
+				plot_add(conn->plot, &res, 1);
 
-				plot_add(conn->plot, &res, count);
+				if (chan) {
+					packet_latency_add(&chan->tx_l, &res);
+					plot_add(chan->plot, &res, 1);
+				}
 
 				free(last_tx);
 			}
@@ -603,14 +638,15 @@ static void event_pkt(struct timeval *tv, uint16_t index,
 }
 
 static void conn_pkt_tx(struct hci_conn *conn, struct timeval *tv,
-					uint16_t size)
+				uint16_t size, struct l2cap_chan *chan)
 {
-	struct timeval *last_tx;
+	struct hci_conn_tx *last_tx;
 
 	conn->tx_num++;
 
-	last_tx = new0(struct timeval, 1);
+	last_tx = new0(struct hci_conn_tx, 1);
 	memcpy(last_tx, tv, sizeof(*tv));
+	last_tx->chan = chan;
 	queue_push_tail(conn->tx_queue, last_tx);
 	conn->tx_bytes += size;
 
@@ -618,6 +654,15 @@ static void conn_pkt_tx(struct hci_conn *conn, struct timeval *tv,
 		conn->tx_pkt_min = size;
 	if (!conn->tx_pkt_max || size > conn->tx_pkt_max)
 		conn->tx_pkt_max = size;
+
+	if (chan) {
+		chan->tx_bytes += size;
+
+		if (!chan->tx_pkt_min || size < chan->tx_pkt_min)
+			chan->tx_pkt_min = size;
+		if (!chan->tx_pkt_max || size > chan->tx_pkt_max)
+			chan->tx_pkt_max = size;
+	}
 }
 
 static void acl_pkt(struct timeval *tv, uint16_t index, bool out,
@@ -626,7 +671,7 @@ static void acl_pkt(struct timeval *tv, uint16_t index, bool out,
 	const struct bt_hci_acl_hdr *hdr = data;
 	struct hci_dev *dev;
 	struct hci_conn *conn;
-	struct l2cap_chan *chan;
+	struct l2cap_chan *chan = NULL;
 	uint16_t cid;
 
 	data += sizeof(*hdr);
@@ -657,7 +702,7 @@ static void acl_pkt(struct timeval *tv, uint16_t index, bool out,
 	}
 
 	if (out) {
-		conn_pkt_tx(conn, tv, size);
+		conn_pkt_tx(conn, tv, size, chan);
 	} else {
 		conn->rx_num++;
 	}
@@ -683,7 +728,7 @@ static void sco_pkt(struct timeval *tv, uint16_t index, bool out,
 		return;
 
 	if (out) {
-		conn_pkt_tx(conn, tv, size - sizeof(*hdr));
+		conn_pkt_tx(conn, tv, size - sizeof(*hdr), NULL);
 	} else {
 		conn->rx_num++;
 	}
@@ -770,7 +815,7 @@ static void iso_pkt(struct timeval *tv, uint16_t index, bool out,
 		return;
 
 	if (out) {
-		conn_pkt_tx(conn, tv, size - sizeof(*hdr));
+		conn_pkt_tx(conn, tv, size - sizeof(*hdr), NULL);
 	} else {
 		conn->rx_num++;
 	}