[Qemu-devel] [PATCH 09/14] uhci: tracing support

[Gerd Hoffmann <kraxel@redhat.com>]

Zap DPRINTF, add tracepoints instead.

Signed-off-by: Gerd Hoffmann <kraxel@redhat.com>
---
 hw/usb/hcd-uhci.c |   87 +++++++++++++++++++---------------------------------
 trace-events      |   31 +++++++++++++++++++
 2 files changed, 63 insertions(+), 55 deletions(-)

diff --git a/hw/usb/hcd-uhci.c b/hw/usb/hcd-uhci.c
index 5177e33..054ae19 100644
--- a/hw/usb/hcd-uhci.c
+++ b/hw/usb/hcd-uhci.c
@@ -31,6 +31,7 @@
 #include "qemu-timer.h"
 #include "iov.h"
 #include "dma.h"
+#include "trace.h"
 
 //#define DEBUG
 //#define DEBUG_DUMP_DATA
@@ -76,23 +77,6 @@
 
 #define NB_PORTS 2
 
-#ifdef DEBUG
-#define DPRINTF printf
-
-static const char *pid2str(int pid)
-{
-    switch (pid) {
-    case USB_TOKEN_SETUP: return "SETUP";
-    case USB_TOKEN_IN:    return "IN";
-    case USB_TOKEN_OUT:   return "OUT";
-    }
-    return "?";
-}
-
-#else
-#define DPRINTF(...)
-#endif
-
 typedef struct UHCIState UHCIState;
 typedef struct UHCIAsync UHCIAsync;
 typedef struct UHCIQueue UHCIQueue;
@@ -187,6 +171,7 @@ static UHCIQueue *uhci_queue_get(UHCIState *s, UHCI_TD *td)
     queue->token = token;
     QTAILQ_INIT(&queue->asyncs);
     QTAILQ_INSERT_HEAD(&s->queues, queue, next);
+    trace_usb_uhci_queue_add(queue->token);
     return queue;
 }
 
@@ -194,6 +179,7 @@ static void uhci_queue_free(UHCIQueue *queue)
 {
     UHCIState *s = queue->uhci;
 
+    trace_usb_uhci_queue_del(queue->token);
     QTAILQ_REMOVE(&s->queues, queue, next);
     g_free(queue);
 }
@@ -206,12 +192,14 @@ static UHCIAsync *uhci_async_alloc(UHCIQueue *queue, uint32_t addr)
     async->td = addr;
     usb_packet_init(&async->packet);
     pci_dma_sglist_init(&async->sgl, &queue->uhci->dev, 1);
+    trace_usb_uhci_packet_add(async->queue->token, async->td);
 
     return async;
 }
 
 static void uhci_async_free(UHCIAsync *async)
 {
+    trace_usb_uhci_packet_del(async->queue->token, async->td);
     usb_packet_cleanup(&async->packet);
     qemu_sglist_destroy(&async->sgl);
     g_free(async);
@@ -221,19 +209,19 @@ static void uhci_async_link(UHCIAsync *async)
 {
     UHCIQueue *queue = async->queue;
     QTAILQ_INSERT_TAIL(&queue->asyncs, async, next);
+    trace_usb_uhci_packet_link_async(async->queue->token, async->td);
 }
 
 static void uhci_async_unlink(UHCIAsync *async)
 {
     UHCIQueue *queue = async->queue;
     QTAILQ_REMOVE(&queue->asyncs, async, next);
+    trace_usb_uhci_packet_unlink_async(async->queue->token, async->td);
 }
 
 static void uhci_async_cancel(UHCIAsync *async)
 {
-    DPRINTF("uhci: cancel td 0x%x token 0x%x done %u\n",
-           async->td, async->token, async->done);
-
+    trace_usb_uhci_packet_cancel(async->queue->token, async->td, async->done);
     if (!async->done)
         usb_cancel_packet(&async->packet);
     uhci_async_free(async);
@@ -351,7 +339,7 @@ static void uhci_reset(void *opaque)
     int i;
     UHCIPort *port;
 
-    DPRINTF("uhci: full reset\n");
+    trace_usb_uhci_reset();
 
     pci_conf = s->dev.config;
 
@@ -451,12 +439,13 @@ static void uhci_ioport_writew(void *opaque, uint32_t addr, uint32_t val)
     UHCIState *s = opaque;
 
     addr &= 0x1f;
-    DPRINTF("uhci: writew port=0x%04x val=0x%04x\n", addr, val);
+    trace_usb_uhci_mmio_writew(addr, val);
 
     switch(addr) {
     case 0x00:
         if ((val & UHCI_CMD_RS) && !(s->cmd & UHCI_CMD_RS)) {
             /* start frame processing */
+            trace_usb_uhci_schedule_start();
             s->expire_time = qemu_get_clock_ns(vm_clock) +
                 (get_ticks_per_sec() / FRAME_TIMER_FREQ);
             qemu_mod_timer(s->frame_timer, qemu_get_clock_ns(vm_clock));
@@ -561,7 +550,7 @@ static uint32_t uhci_ioport_readw(void *opaque, uint32_t addr)
         break;
     }
 
-    DPRINTF("uhci: readw port=0x%04x val=0x%04x\n", addr, val);
+    trace_usb_uhci_mmio_readw(addr, val);
 
     return val;
 }
@@ -571,7 +560,7 @@ static void uhci_ioport_writel(void *opaque, uint32_t addr, uint32_t val)
     UHCIState *s = opaque;
 
     addr &= 0x1f;
-    DPRINTF("uhci: writel port=0x%04x val=0x%08x\n", addr, val);
+    trace_usb_uhci_mmio_writel(addr, val);
 
     switch(addr) {
     case 0x08:
@@ -594,6 +583,7 @@ static uint32_t uhci_ioport_readl(void *opaque, uint32_t addr)
         val = 0xffffffff;
         break;
     }
+    trace_usb_uhci_mmio_readl(addr, val);
     return val;
 }
 
@@ -729,12 +719,14 @@ static int uhci_complete_td(UHCIState *s, UHCI_TD *td, UHCIAsync *async, uint32_
         if ((td->ctrl & TD_CTRL_SPD) && len < max_len) {
             *int_mask |= 0x02;
             /* short packet: do not update QH */
-            DPRINTF("uhci: short packet. td 0x%x token 0x%x\n", async->td, async->token);
+            trace_usb_uhci_packet_complete_shortxfer(async->queue->token,
+                                                    async->td);
             return 1;
         }
     }
 
     /* success */
+    trace_usb_uhci_packet_complete_success(async->queue->token, async->td);
     return 0;
 
 out:
@@ -747,6 +739,7 @@ out:
             *int_mask |= 0x01;
         }
         uhci_update_irq(s);
+        trace_usb_uhci_packet_complete_stall(async->queue->token, async->td);
         return 1;
 
     case USB_RET_BABBLE:
@@ -758,6 +751,7 @@ out:
         }
         uhci_update_irq(s);
         /* frame interrupted */
+        trace_usb_uhci_packet_complete_babble(async->queue->token, async->td);
         return -1;
 
     case USB_RET_NAK:
@@ -784,6 +778,8 @@ out:
             if (td->ctrl & TD_CTRL_IOC)
                 *int_mask |= 0x01;
             uhci_update_irq(s);
+            trace_usb_uhci_packet_complete_error(async->queue->token,
+                                                 async->td);
         }
     }
     td->ctrl = (td->ctrl & ~(3 << TD_CTRL_ERROR_SHIFT)) |
@@ -874,8 +870,6 @@ static void uhci_async_complete(USBPort *port, USBPacket *packet)
     UHCIAsync *async = container_of(packet, UHCIAsync, packet);
     UHCIState *s = async->queue->uhci;
 
-    DPRINTF("uhci: async complete. td 0x%x token 0x%x\n", async->td, async->token);
-
     if (async->isoc) {
         UHCI_TD td;
         uint32_t link = async->td;
@@ -963,6 +957,7 @@ static void uhci_fill_queue(UHCIState *s, UHCI_TD *td)
         if (uhci_queue_token(&ptd) != token) {
             break;
         }
+        trace_usb_uhci_td_queue(plink & ~0xf, ptd.ctrl, ptd.token);
         ret = uhci_handle_td(s, plink, &ptd, &int_mask);
         assert(ret == 2); /* got USB_RET_ASYNC */
         assert(int_mask == 0);
@@ -981,8 +976,6 @@ static void uhci_process_frame(UHCIState *s)
 
     frame_addr = s->fl_base_addr + ((s->frnum & 0x3ff) << 2);
 
-    DPRINTF("uhci: processing frame %d addr 0x%x\n" , s->frnum, frame_addr);
-
     pci_dma_read(&s->dev, frame_addr, &link, 4);
     le32_to_cpus(&link);
 
@@ -994,6 +987,7 @@ static void uhci_process_frame(UHCIState *s)
     for (cnt = FRAME_MAX_LOOPS; is_valid(link) && cnt; cnt--) {
         if (is_qh(link)) {
             /* QH */
+            trace_usb_uhci_qh_load(link & ~0xf);
 
             if (qhdb_insert(&qhdb, link)) {
                 /*
@@ -1006,14 +1000,14 @@ static void uhci_process_frame(UHCIState *s)
                  *  (b) we've reached the usb 1.1 bandwidth, which is
                  *      1280 bytes/frame.
                  */
-                DPRINTF("uhci: detected loop. qh 0x%x\n", link);
                 if (td_count == 0) {
-                    DPRINTF("uhci: no transaction last round, stop\n");
+                    trace_usb_uhci_frame_loop_stop_idle();
                     break;
                 } else if (bytes_count >= 1280) {
-                    DPRINTF("uhci: bandwidth limit reached, stop\n");
+                    trace_usb_uhci_frame_loop_stop_bandwidth();
                     break;
                 } else {
+                    trace_usb_uhci_frame_loop_continue();
                     td_count = 0;
                     qhdb_reset(&qhdb);
                     qhdb_insert(&qhdb, link);
@@ -1024,9 +1018,6 @@ static void uhci_process_frame(UHCIState *s)
             le32_to_cpus(&qh.link);
             le32_to_cpus(&qh.el_link);
 
-            DPRINTF("uhci: QH 0x%x load. link 0x%x elink 0x%x\n",
-                    link, qh.link, qh.el_link);
-
             if (!is_valid(qh.el_link)) {
                 /* QH w/o elements */
                 curr_qh = 0;
@@ -1045,9 +1036,7 @@ static void uhci_process_frame(UHCIState *s)
         le32_to_cpus(&td.ctrl);
         le32_to_cpus(&td.token);
         le32_to_cpus(&td.buffer);
-
-        DPRINTF("uhci: TD 0x%x load. link 0x%x ctrl 0x%x token 0x%x qh 0x%x\n", 
-                link, td.link, td.ctrl, td.token, curr_qh);
+        trace_usb_uhci_td_load(curr_qh & ~0xf, link & ~0xf, td.ctrl, td.token);
 
         old_td_ctrl = td.ctrl;
         ret = uhci_handle_td(s, link, &td, &int_mask);
@@ -1062,16 +1051,12 @@ static void uhci_process_frame(UHCIState *s)
             goto out;
 
         case 1: /* goto next queue */
-            DPRINTF("uhci: TD 0x%x skip. "
-                    "link 0x%x ctrl 0x%x token 0x%x qh 0x%x\n",
-                    link, td.link, td.ctrl, td.token, curr_qh);
+            trace_usb_uhci_td_nextqh(curr_qh & ~0xf, link & ~0xf);
             link = curr_qh ? qh.link : td.link;
             continue;
 
         case 2: /* got USB_RET_ASYNC */
-            DPRINTF("uhci: TD 0x%x async. "
-                    "link 0x%x ctrl 0x%x token 0x%x qh 0x%x\n",
-                    link, td.link, td.ctrl, td.token, curr_qh);
+            trace_usb_uhci_td_async(curr_qh & ~0xf, link & ~0xf);
             if (is_valid(td.link)) {
                 uhci_fill_queue(s, &td);
             }
@@ -1079,10 +1064,7 @@ static void uhci_process_frame(UHCIState *s)
             continue;
 
         case 0: /* completed TD */
-            DPRINTF("uhci: TD 0x%x done. "
-                    "link 0x%x ctrl 0x%x token 0x%x qh 0x%x\n",
-                    link, td.link, td.ctrl, td.token, curr_qh);
-
+            trace_usb_uhci_td_complete(curr_qh & ~0xf, link & ~0xf);
             link = td.link;
             td_count++;
             bytes_count += (td.ctrl & 0x7ff) + 1;
@@ -1095,10 +1077,6 @@ static void uhci_process_frame(UHCIState *s)
 
                 if (!depth_first(link)) {
                     /* done with this QH */
-
-                    DPRINTF("uhci: QH 0x%x done. link 0x%x elink 0x%x\n",
-                            curr_qh, qh.link, qh.el_link);
-
                     curr_qh = 0;
                     link    = qh.link;
                 }
@@ -1125,12 +1103,11 @@ static void uhci_frame_timer(void *opaque)
 
     if (!(s->cmd & UHCI_CMD_RS)) {
         /* Full stop */
+        trace_usb_uhci_schedule_stop();
         qemu_del_timer(s->frame_timer);
         uhci_async_cancel_all(s);
         /* set hchalted bit in status - UHCI11D 2.1.2 */
         s->status |= UHCI_STS_HCHALTED;
-
-        DPRINTF("uhci: halted\n");
         return;
     }
 
@@ -1145,7 +1122,7 @@ static void uhci_frame_timer(void *opaque)
     /* Start new frame */
     s->frnum = (s->frnum + 1) & 0x7ff;
 
-    DPRINTF("uhci: new frame #%u\n" , s->frnum);
+    trace_usb_uhci_frame_start(s->frnum);
 
     uhci_async_validate_begin(s);
 
diff --git a/trace-events b/trace-events
index 301374e..c8317a0 100644
--- a/trace-events
+++ b/trace-events
@@ -258,6 +258,37 @@ usb_ehci_port_reset(uint32_t port, int enable) "reset port #%d - %d"
 usb_ehci_data(int rw, uint32_t cpage, uint32_t offset, uint32_t addr, uint32_t len, uint32_t bufpos) "write %d, cpage %d, offset 0x%03x, addr 0x%08x, len %d, bufpos %d"
 usb_ehci_queue_action(void *q, const char *action) "q %p: %s"
 
+# hw/usb/hcd-uhci.c
+usb_uhci_reset(void) "=== RESET ==="
+usb_uhci_schedule_start(void) ""
+usb_uhci_schedule_stop(void) ""
+usb_uhci_frame_start(uint32_t num) "nr %d"
+usb_uhci_frame_loop_stop_idle(void) ""
+usb_uhci_frame_loop_stop_bandwidth(void) ""
+usb_uhci_frame_loop_continue(void) ""
+usb_uhci_mmio_readw(uint32_t addr, uint32_t val) "addr %04x, ret 0x04%x"
+usb_uhci_mmio_writew(uint32_t addr, uint32_t val) "addr %04x, val 0x04%x"
+usb_uhci_mmio_readl(uint32_t addr, uint32_t val) "addr %04x, ret 0x08%x"
+usb_uhci_mmio_writel(uint32_t addr, uint32_t val) "addr %04x, val 0x08%x"
+usb_uhci_queue_add(uint32_t token) "token 0x%x"
+usb_uhci_queue_del(uint32_t token) "token 0x%x"
+usb_uhci_packet_add(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_link_async(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_unlink_async(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_cancel(uint32_t token, uint32_t addr, int done) "token 0x%x, td 0x%x, done %d"
+usb_uhci_packet_complete_success(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_complete_shortxfer(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_complete_stall(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_complete_babble(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_complete_error(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_packet_del(uint32_t token, uint32_t addr) "token 0x%x, td 0x%x"
+usb_uhci_qh_load(uint32_t qh) "qh 0x%x"
+usb_uhci_td_load(uint32_t qh, uint32_t td, uint32_t ctrl, uint32_t token) "qh 0x%x, td 0x%x, ctrl 0x%x, token 0x%x"
+usb_uhci_td_queue(uint32_t td, uint32_t ctrl, uint32_t token) "td 0x%x, ctrl 0x%x, token 0x%x"
+usb_uhci_td_nextqh(uint32_t qh, uint32_t td) "qh 0x%x, td 0x%x"
+usb_uhci_td_async(uint32_t qh, uint32_t td) "qh 0x%x, td 0x%x"
+usb_uhci_td_complete(uint32_t qh, uint32_t td) "qh 0x%x, td 0x%x"
+
 # hw/usb-desc.c
 usb_desc_device(int addr, int len, int ret) "dev %d query device, len %d, ret %d"
 usb_desc_device_qualifier(int addr, int len, int ret) "dev %d query device qualifier, len %d, ret %d"
-- 
1.7.1