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)

diff --git a/monitor/analyze.c b/monitor/analyze.c
index b9f7ede..80763fa 100755 (executable)
--- 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++;
        }