Patchwork EHCI support - device recognized, but no data

login
register
mail settings
Submitter David S. Ahern
Date March 5, 2010, 3:17 a.m.
Message ID <4B9077C9.4040309@cisco.com>
Download mbox | patch
Permalink /patch/46989/
State New
Headers show

Comments

David S. Ahern - March 5, 2010, 3:17 a.m.
Jan:

I spent some more time on the EHCI support today. With the attached
patch (delta to the patch from yesterday) a USB key is recognized within
the guest (FC-12):

scsi 2:0:0:0: Direct-Access     Kingston DT HyperX        PMAP PQ: 0
ANSI: 0 CCS
sd 2:0:0:0: Attached scsi generic sg1 type 0
sd 2:0:0:0: [sda] 15646720 512-byte logical blocks: (8.01 GB/7.46 GiB)
sd 2:0:0:0: [sda] Write Protect is off
sd 2:0:0:0: [sda] Mode Sense: 23 00 00 00
sd 2:0:0:0: [sda] Assuming drive cache: write through
sd 2:0:0:0: [sda] Assuming drive cache: write through
 sda: sda1 sda2
sd 2:0:0:0: [sda] Assuming drive cache: write through
sd 2:0:0:0: [sda] Attached SCSI removable disk


Unfortunately, fdisk fails to show any data. I'll be out for a few days,
so I won't get back to this until next week.

David
Jan Kiszka - March 6, 2010, 4:42 p.m.
David S. Ahern wrote:
> Jan:
> 
> I spent some more time on the EHCI support today. With the attached
> patch (delta to the patch from yesterday) a USB key is recognized within
> the guest (FC-12):
> 
> scsi 2:0:0:0: Direct-Access     Kingston DT HyperX        PMAP PQ: 0
> ANSI: 0 CCS
> sd 2:0:0:0: Attached scsi generic sg1 type 0
> sd 2:0:0:0: [sda] 15646720 512-byte logical blocks: (8.01 GB/7.46 GiB)
> sd 2:0:0:0: [sda] Write Protect is off
> sd 2:0:0:0: [sda] Mode Sense: 23 00 00 00
> sd 2:0:0:0: [sda] Assuming drive cache: write through
> sd 2:0:0:0: [sda] Assuming drive cache: write through
>  sda: sda1 sda2
> sd 2:0:0:0: [sda] Assuming drive cache: write through
> sd 2:0:0:0: [sda] Attached SCSI removable disk
> 
> 
> Unfortunately, fdisk fails to show any data. I'll be out for a few days,
> so I won't get back to this until next week.
> 

Cool! Actually, I'm more lucky: I can access the flash of my mobile as a
mass storage. Performance (linear reading) is half of native if
debugging is disabled (0.5 vs. 1 MByte/s). But one try also caused an
"USB stall".

Patch committed. I will also look for some cleanups (build breaks for
non-x86 targets) and more tests soon.

Jan
Kevin Wolf - March 6, 2010, 6:25 p.m.
Am Freitag, 5. März 2010 04:17 schrieb David S. Ahern:
> Jan:
> 
> I spent some more time on the EHCI support today. With the attached
> patch (delta to the patch from yesterday) a USB key is recognized within
> the guest (FC-12):

Looks very nice. Actually I could access the file system on my USB stick. I 
have pushed your patch along with some additional minor changes to 
git://repo.or.cz/qemu/kevin.git ehci. Jan, you might want to pull from there.

Kevin
Jan Kiszka - March 7, 2010, 11:32 a.m.
Kevin Wolf wrote:
> Am Freitag, 5. März 2010 04:17 schrieb David S. Ahern:
>> Jan:
>>
>> I spent some more time on the EHCI support today. With the attached
>> patch (delta to the patch from yesterday) a USB key is recognized within
>> the guest (FC-12):
> 
> Looks very nice. Actually I could access the file system on my USB stick. I 
> have pushed your patch along with some additional minor changes to 
> git://repo.or.cz/qemu/kevin.git ehci. Jan, you might want to pull from there.
> 

Merged, thanks.

Meanwhile I played with some more devices, and I think I found one
scenario that should be handy to debug: -usbdevice net. Apparently, it
does not work yet, my console is just flooded with

>>>>> ASYNC STATE MACHINE execute
000.005 exec: ctr is 1
000.004 exec: frindex is 488,3
000.004 setting qh.current from 0E0B21E0 to 0x0E0B21E0
000.005 Active non-interrupt QH, executing
000.003 pid is  1
000.00000.222 periodic state adv fr=490.  [0E0B37A8] -> 00000001
000.009 periodic state adv fr=490.  [0E0B37A8] -> 00000001
000.009

>>>>> ASYNC STATE MACHINE execute
000.006 exec: ctr is 1
000.003 exec: frindex is 490,2
000.005 setting qh.current from 0E0B21E0 to 0x0E0B21E0
000.004 Active non-interrupt QH, executing
000.004 pid is  1
000.004 calling dev->info->handle_packet
000.004 exit loop dev->info->handle_packet
000.003 Enter EXECUTING
000.004 USBTRAN RSP NAK, returning without clear active
000.004 finishing exec
000.004 Nak occured and RL != 0, dec NakCnt to -1
000.004 write QH to VM memory
000.203 periodic state adv fr=490.  [0E0B37A8] -> 00000001
000.008 periodic state adv fr=490.  [0E0B37A8] -> 00000001
000.009

Messages. The guest reports that it received one Ethernet packet, but
that's all, dhcpcd fails with a timeout. Already "ifconfig ethX up"
starts this flooding.

Jan
David S. Ahern - March 9, 2010, 5:44 p.m.
On 03/07/2010 04:32 AM, Jan Kiszka wrote:
> Kevin Wolf wrote:
>> Am Freitag, 5. März 2010 04:17 schrieb David S. Ahern:
>>> Jan:
>>>
>>> I spent some more time on the EHCI support today. With the attached
>>> patch (delta to the patch from yesterday) a USB key is recognized within
>>> the guest (FC-12):
>>
>> Looks very nice. Actually I could access the file system on my USB stick. I 
>> have pushed your patch along with some additional minor changes to 
>> git://repo.or.cz/qemu/kevin.git ehci. Jan, you might want to pull from there.
>>
> 
> Merged, thanks.
> 
> Meanwhile I played with some more devices, and I think I found one
> scenario that should be handy to debug: -usbdevice net. Apparently, it
> does not work yet, my console is just flooded with
> 
>>>>>> ASYNC STATE MACHINE execute
> 000.005 exec: ctr is 1
> 000.004 exec: frindex is 488,3
> 000.004 setting qh.current from 0E0B21E0 to 0x0E0B21E0
> 000.005 Active non-interrupt QH, executing
> 000.003 pid is  1
> 000.00000.222 periodic state adv fr=490.  [0E0B37A8] -> 00000001
> 000.009 periodic state adv fr=490.  [0E0B37A8] -> 00000001
> 000.009
> 
>>>>>> ASYNC STATE MACHINE execute
> 000.006 exec: ctr is 1
> 000.003 exec: frindex is 490,2
> 000.005 setting qh.current from 0E0B21E0 to 0x0E0B21E0
> 000.004 Active non-interrupt QH, executing
> 000.004 pid is  1
> 000.004 calling dev->info->handle_packet
> 000.004 exit loop dev->info->handle_packet
> 000.003 Enter EXECUTING
> 000.004 USBTRAN RSP NAK, returning without clear active
> 000.004 finishing exec
> 000.004 Nak occured and RL != 0, dec NakCnt to -1
> 000.004 write QH to VM memory
> 000.203 periodic state adv fr=490.  [0E0B37A8] -> 00000001
> 000.008 periodic state adv fr=490.  [0E0B37A8] -> 00000001
> 000.009
> 
> Messages. The guest reports that it received one Ethernet packet, but
> that's all, dhcpcd fails with a timeout. Already "ifconfig ethX up"
> starts this flooding.
> 
> Jan
> 

What guest OS were you successful with for storage devices - windows or
linux, 32-bit or 64? I've been mainly using FC-12, x86_64 as the guest
OS, and an external (ie., physical) key of recent vintage. Qemu's msd
device does not work with FC-12 (and UHCI).

I played around with Qemu's usb-net device a bit, but not sure I am
configuring it correctly (using monitor commands to attach).

David
Jan Kiszka - March 10, 2010, 7:38 a.m.
David S. Ahern wrote:
> On 03/07/2010 04:32 AM, Jan Kiszka wrote:
>> Kevin Wolf wrote:
>>> Am Freitag, 5. März 2010 04:17 schrieb David S. Ahern:
>>>> Jan:
>>>>
>>>> I spent some more time on the EHCI support today. With the attached
>>>> patch (delta to the patch from yesterday) a USB key is recognized within
>>>> the guest (FC-12):
>>> Looks very nice. Actually I could access the file system on my USB stick. I 
>>> have pushed your patch along with some additional minor changes to 
>>> git://repo.or.cz/qemu/kevin.git ehci. Jan, you might want to pull from there.
>>>
>> Merged, thanks.
>>
>> Meanwhile I played with some more devices, and I think I found one
>> scenario that should be handy to debug: -usbdevice net. Apparently, it
>> does not work yet, my console is just flooded with
>>
>>>>>>> ASYNC STATE MACHINE execute
>> 000.005 exec: ctr is 1
>> 000.004 exec: frindex is 488,3
>> 000.004 setting qh.current from 0E0B21E0 to 0x0E0B21E0
>> 000.005 Active non-interrupt QH, executing
>> 000.003 pid is  1
>> 000.00000.222 periodic state adv fr=490.  [0E0B37A8] -> 00000001
>> 000.009 periodic state adv fr=490.  [0E0B37A8] -> 00000001
>> 000.009
>>
>>>>>>> ASYNC STATE MACHINE execute
>> 000.006 exec: ctr is 1
>> 000.003 exec: frindex is 490,2
>> 000.005 setting qh.current from 0E0B21E0 to 0x0E0B21E0
>> 000.004 Active non-interrupt QH, executing
>> 000.004 pid is  1
>> 000.004 calling dev->info->handle_packet
>> 000.004 exit loop dev->info->handle_packet
>> 000.003 Enter EXECUTING
>> 000.004 USBTRAN RSP NAK, returning without clear active
>> 000.004 finishing exec
>> 000.004 Nak occured and RL != 0, dec NakCnt to -1
>> 000.004 write QH to VM memory
>> 000.203 periodic state adv fr=490.  [0E0B37A8] -> 00000001
>> 000.008 periodic state adv fr=490.  [0E0B37A8] -> 00000001
>> 000.009
>>
>> Messages. The guest reports that it received one Ethernet packet, but
>> that's all, dhcpcd fails with a timeout. Already "ifconfig ethX up"
>> starts this flooding.
>>
>> Jan
>>
> 
> What guest OS were you successful with for storage devices - windows or
> linux, 32-bit or 64? I've been mainly using FC-12, x86_64 as the guest
> OS, and an external (ie., physical) key of recent vintage. Qemu's msd
> device does not work with FC-12 (and UHCI).

I was using an OpenSuse 11.1 guest image with 2.6.27 kernel. Host and
guest were 64 bit.

> 
> I played around with Qemu's usb-net device a bit, but not sure I am
> configuring it correctly (using monitor commands to attach).

"-usbdevice net -net user" should switch completely to USB based
networking and make the guest issue dchp request over that NIC. Works
like that for me with UHCI, fails with EHCI.

Jan

Patch

diff --git a/hw/usb-ehci.c b/hw/usb-ehci.c
index aa8ed9e..07eea11 100644
--- a/hw/usb-ehci.c
+++ b/hw/usb-ehci.c
@@ -28,17 +28,16 @@ 
 #include "usb-ehci.h"
 #include "monitor.h"
 
-#define EHCI_DEBUG 1
-#if EHCI_DEBUG
-//#define DEBUG(x) timed_printf x 
-#define DEBUG(x) printf x
+#define EHCI_DEBUG   1
+#define TDEBUG       0
+#define DEBUG_PACKET 1
+
+#if EHCI_DEBUG || TDEBUG || DEBUG_PACKET
+//#define DPRINTF printf
+#define DPRINTF timed_printf
 #else
-#define DEBUG(x)
+#define DPRINTF(...) 
 #endif
-//static int timed_printf(const char *fmt, ...);
-
-// #define TDEBUG
-// #define DEBUG_PACKET
 
 #define ASSERT(x) { if (!(x)) { printf("Assertion failed in usb-echi.c line %d\n", __LINE__); exit(1); } }
 
@@ -135,6 +134,7 @@ 
 #else
 #define FRAME_TIMER_FREQ 8000
 #endif
+#define FRAME_TIMER_USEC (1000000 / FRAME_TIMER_FREQ)
 
 #define NB_MAXINTRATE    8        // Max rate at which controller issues ints
 #define NB_PORTS         4        // Number of downstream ports
@@ -376,6 +376,8 @@  typedef struct {
     uint32_t frame_end_usec;
 } EHCIState;
 
+#define SET_LAST_RUN_CLOCK(s)  (s)->last_run_usec = qemu_get_clock(vm_clock) / 1000;
+
 static inline uint32_t get_field(uint32_t data, uint32_t mask, int shift)
 {
     return((data & mask) >> shift);
@@ -388,23 +390,95 @@  static inline void set_field(uint32_t *data, uint32_t val,
     *data |=(val << shift);
 }
 
+#if EHCI_DEBUG
+static int timed_printf(const char *fmt, ...)
+{
+    int msec, usec;
+    static int usec_last;
+    va_list ap;
+
+    usec = qemu_get_clock(vm_clock) / 1000;
+
+    msec = usec - usec_last;
+    usec_last = usec;
+    usec = msec;
+
+    msec /= 1000;
+    msec %= 1000;
+
+    usec %= 1000;
+
+    va_start(ap, fmt);
+    printf("%03d.%03d ", msec, usec);
+    vprintf(fmt, ap);
+    va_end(ap);
+
+    return 0;
+}
+
+static const char *addr2str(unsigned addr)
+{
+    const char *r = "   unknown";
+
+    switch(addr) {
+        case CAPLENGTH:
+            r = " CAPLENGTH";
+            break;
+
+        case HCIVERSION:
+            r = "HCIVERSION";
+            break;
+
+        case HCSPARAMS:
+            r = " HCSPARAMS";
+            break;
+
+        case HCCPARAMS:
+            r = " HCCPARAMS";
+            break;
+
+        case USBCMD:
+            r = "   COMMAND";
+            break;
+
+        case USBSTS:
+            r = "    STATUS";
+            break;
+
+        case USBINTR:
+            r = " INTERRUPT";
+            break;
+
+        case FRINDEX:
+            r = " FRAME IDX";
+            break;
+    }
+    
+    return r;
+}
+
 static void dump_ptr(const char *s, uint32_t ptr, int has_type)
 {
     int t = NLPTR_TYPE_GET(ptr);
-
-    printf("%s%08X", s, NLPTR_GET(ptr));
+    DPRINTF("%s%08X", s, NLPTR_GET(ptr));
 
     if (has_type) {
-        printf("(PTR type is %s)",
+        DPRINTF("(PTR type is %s)",
             t == NLPTR_TYPE_ITD ? "ITD" :
            (t == NLPTR_TYPE_QH ? "QH" :
            (t == NLPTR_TYPE_STITD ? "STITD" :
            (t == NLPTR_TYPE_FSTN ? "FSTN" : "****"))));
     }
 
-    printf("%s\n", NLPTR_TBIT(ptr) ? " TBIT set" : "");
+    DPRINTF("%s\n", NLPTR_TBIT(ptr) ? " TBIT set" : "");
 }
+#else
+static inline void dump_ptr(const char *s, uint32_t ptr, int has_type)
+{
+}
+#endif
 
+#if EHCI_DEBUG || DEBUG_PACKET
 static void dump_qtd(EHCIqtd *qtd, uint32_t qtdaddr)
 {
     int pid;
@@ -445,7 +519,8 @@  static void dump_qtd(EHCIqtd *qtd, uint32_t qtdaddr)
               qtd->bufptr[0] & BUFPTR_CURROFF_MASK);
     printf("    === ========      ========\n");
 }
-
+#endif
+#if EHCI_DEBUG
 static void dump_qh(EHCIqh *qh, uint32_t qhaddr)
 {
     int speed =(qh->epchar & QH_EPCHAR_EPS_MASK) >> QH_EPCHAR_EPS_SH;
@@ -496,8 +571,13 @@  static void dump_qh(EHCIqh *qh, uint32_t qhaddr)
              (qh->bufptr[2] & BUFPTR_SBYTES_MASK) >> BUFPTR_SBYTES_SH);
     printf("== ========       ========\n");
 }
+#else
+static inline void dump_qh(EHCIqh *qh, uint32_t qhaddr)
+{
+}
+#endif
 
-#ifdef DEBUG_PACKET
+#if DEBUG_PACKET
 
 static void dump_itd(EHCIitd *itd, uint32_t addr)
 {
@@ -554,49 +634,22 @@  static void dump_itd(EHCIitd *itd, uint32_t addr)
 
 #endif
 
-#if 0
-static int timed_printf(const char *fmt, ...)
-{
-    int msec, usec;
-    static int usec_last;
-    va_list ap;
-
-    usec = qemu_get_clock(vm_clock) / 1000;
 
-    msec = usec - usec_last;
-    usec_last = usec;
-    usec = msec;
-
-    msec /= 1000;
-    msec %= 1000;
-
-    usec %= 1000;
-
-    va_start(ap, fmt);
-    printf("%03d.%03d ", msec, usec);
-    vprintf(fmt, ap);
-    va_end(ap);
-
-    return 0;
-}
-#endif
-
-static inline void ehci_set_interrupt(EHCIState *ehci, int intr)
+static inline void ehci_set_interrupt(EHCIState *s, int intr)
 {
     int level = 0;
 
     // TODO honour interrupt threshold requests
 
-    ehci->usbsts |= intr;
+    s->usbsts |= intr;
 
-    if ((ehci->usbsts & USBINTR_MASK) & ehci->usbintr)
+    if ((s->usbsts & USBINTR_MASK) & s->usbintr)
         level = 1;
 
-#ifdef TDEBUG
-    DEBUG(("ehci: setting interrupt level %d(st/en)=(%02X/%02X)\n", level,
-            ehci->usbsts & USBINTR_MASK, ehci->usbintr));
-#endif
-    qemu_set_irq(ehci->irq, level);
+    DPRINTF("ehci_set_interrupt: intr x%x, STS x%x, INTR x%x, level %d\n",
+            intr, s->usbsts & USBINTR_MASK, s->usbintr, level);
+
+    qemu_set_irq(s->irq, level);
 }
 
 /* Attach or detach a device on root hub */
@@ -606,8 +659,8 @@  static void ehci_attach(USBPort *port, USBDevice *dev)
     EHCIState *s = port->opaque;
     uint32_t *portsc = &s->portsc[port->index];
 
-    DEBUG(("ehci_attach invoked for index %d, desc %s\n",
-           port->index, dev ? dev->product_desc : "undefined"));
+    DPRINTF("ehci_attach invoked for index %d, portsc 0x%x, desc %s\n",
+           port->index, *portsc, dev ? dev->product_desc : "undefined");
 
     if (dev) {
         if (port->dev) {
@@ -647,7 +700,6 @@  static void ehci_reset(void *opaque)
     uint8_t *pci_conf;
     int i;
 
-    DEBUG(("ehci_reset\n"));
     pci_conf = s->dev.config;
 
     memset(&s->mmio[OPREGBASE], 0x00, MMIO_SIZE - OPREGBASE);
@@ -676,7 +728,8 @@  static uint32_t ehci_mem_readb(void *ptr, target_phys_addr_t addr)
     uint32_t val;
 
     val = s->mmio[addr];
-    DEBUG(("mem_readb : addr=0x%08X, val=%02X\n",(int)addr,(int)val));
+    DPRINTF("ehci_mem_readb:  %s (addr 0x%08X), val 0x%02X\n",
+            addr2str((unsigned) addr), (unsigned) addr, val);
 
     return val;
 }
@@ -687,7 +740,8 @@  static uint32_t ehci_mem_readw(void *ptr, target_phys_addr_t addr)
     uint32_t val;
 
     val = s->mmio[addr] |(s->mmio[addr+1] << 8);
-    DEBUG(("mem_readw : addr=0x%08X, val=0x%04X\n",(int)addr,(int)val));
+    DPRINTF("ehci_mem_readw:  %s (addr 0x%08X), val 0x%04X\n",
+            addr2str((unsigned) addr), (unsigned) addr, val);
 
     return val;
 }
@@ -700,20 +754,22 @@  static uint32_t ehci_mem_readl(void *ptr, target_phys_addr_t addr)
     val = s->mmio[addr] |(s->mmio[addr+1] << 8) |
           (s->mmio[addr+2] << 16) |(s->mmio[addr+3] << 24);
 
-    DEBUG(("ehci_mem_readl : addr=0x%08X, val=0x%08X\n",(unsigned) addr, val));
+    if (addr != USBSTS)
+    DPRINTF("ehci_mem_readl:  %s (addr 0x%08X), val 0x%08X\n",
+            addr2str((unsigned) addr), (unsigned) addr, val);
 
     return val;
 }
 
 static void ehci_mem_writeb(void *ptr, target_phys_addr_t addr, uint32_t val)
 {
-    printf("EHCI doesn't handle byte writes to MMIO\n");
+    fprintf(stderr, "EHCI doesn't handle byte writes to MMIO\n");
     exit(1);
 }
 
 static void ehci_mem_writew(void *ptr, target_phys_addr_t addr, uint32_t val)
 {
-    printf("EHCI doesn't handle 16-bit writes to MMIO\n");
+    fprintf(stderr, "EHCI doesn't handle 16-bit writes to MMIO\n");
     exit(1);
 }
 
@@ -723,9 +779,9 @@  static void handle_port_status_write(EHCIState *s, int port, uint32_t val)
     int rwc;
     USBDevice *dev = s->ports[port].dev;
 
-    DEBUG(("PORTSC  %08X->%08X  rwc=%08X  rw=%08X\n", *portsc, val,
-          (val & PORTSC_RWC_MASK),
-           val & PORTSC_RO_MASK));
+    DPRINTF("port_status_write: "
+            "PORTSC (port %d) curr %08X new %08X rw-clear %08X rw %08X\n",
+            port, *portsc, val, (val & PORTSC_RWC_MASK), val & PORTSC_RO_MASK);
 
     rwc = val & PORTSC_RWC_MASK;
     val &= PORTSC_RO_MASK;
@@ -734,14 +790,12 @@  static void handle_port_status_write(EHCIState *s, int port, uint32_t val)
 
     *portsc &= ~rwc;
 
-    DEBUG(("PORTSC  ->  %08X\n", *portsc));
-
     if ((val & PORTSC_PRESET) && !(*portsc & PORTSC_PRESET)) {
-        DEBUG(("USBTRAN Port %d reset begin\n", port));
+        DPRINTF("port_status_write: USBTRAN Port %d reset begin\n", port);
     }
 
     if (!(val & PORTSC_PRESET) &&(*portsc & PORTSC_PRESET)) {
-        DEBUG(("USBTRAN Port %d reset done\n", port));
+        DPRINTF("port_status_write: USBTRAN Port %d reset done\n", port);
         ehci_attach(&s->ports[port], dev);
 
         // TODO how to handle reset of ports with no device
@@ -749,7 +803,8 @@  static void handle_port_status_write(EHCIState *s, int port, uint32_t val)
             usb_send_msg(dev, USB_MSG_RESET);
 
         if (s->ports[port].dev) {
-            DEBUG(("Device was connected before reset, clearing CSC bit\n"));
+            DPRINTF("port_status_write: "
+                    "Device was connected before reset, clearing CSC bit\n");
             *portsc &= ~PORTSC_CSC;
         }
 
@@ -764,7 +819,7 @@  static void handle_port_status_write(EHCIState *s, int port, uint32_t val)
 
     *portsc &= ~PORTSC_RO_MASK;
     *portsc |= val;
-    DEBUG(("Port status set to 0x%08x\n", *portsc));
+    DPRINTF("port_status_write: Port %d status set to 0x%08x\n", port, *portsc);
 }
 
 static void ehci_mem_writel(void *ptr, target_phys_addr_t addr, uint32_t val)
@@ -774,13 +829,11 @@  static void ehci_mem_writel(void *ptr, target_phys_addr_t addr, uint32_t val)
 
     /* Only aligned reads are allowed on OHCI */
     if (addr & 3) {
-        printf("usb-ehci: Mis-aligned write\n");
+        fprintf(stderr, "usb-ehci: Mis-aligned write to addr 0x%lx\n", addr);
         return;
     }
 
     if (addr >= PORTSC && addr < PORTSC + 4 * NB_PORTS) {
-        DEBUG(("ehci_mem_writel : PORTSC%d->0x%08X \n",
-               (int)(addr-PORTSC)/4, val));
         handle_port_status_write(s, (addr-PORTSC)/4, val);
         return;
     }
@@ -790,28 +843,25 @@  static void ehci_mem_writel(void *ptr, target_phys_addr_t addr, uint32_t val)
     switch(addr)
     {
     case USBCMD:
+        DPRINTF("ehci_mem_writel: USBCMD val=0x%08X\n", val);
         if ((val & USBCMD_RUNSTOP) && !(s->usbcmd & USBCMD_RUNSTOP)) {
-            DEBUG(("ehci_mem_writel : USBCMD run, clear halt\n"));
-            // printf("Call mod_timer for %p\n", s->frame_timer);
+            DPRINTF("                        run, clear halt\n");
             qemu_mod_timer(s->frame_timer, qemu_get_clock(vm_clock));
-            s->last_run_usec = qemu_get_clock(vm_clock) / 1000;
+            SET_LAST_RUN_CLOCK(s);
             s->usbsts &= ~USBSTS_HALT;
         }
 
-        if (!(val & USBCMD_RUNSTOP) &&(s->usbcmd & USBCMD_RUNSTOP)) {
-            DEBUG(("ehci_mem_writel : USBCMD  ** STOP **\n"));
-            // printf("Call del_timer for %p\n", s->frame_timer);
-#if 0
+        if (!(val & USBCMD_RUNSTOP) && (s->usbcmd & USBCMD_RUNSTOP)) {
+            DPRINTF("                         ** STOP **\n");
             qemu_del_timer(s->frame_timer);
-#endif
             // TODO - should finish out some stuff before setting halt
             s->usbsts |= USBSTS_HALT;
         }
 
         if (val & USBCMD_HCRESET) {
-            DEBUG(("ehci_mem_writel : USBCMD resetting ...\n"));
+            DPRINTF("                        resetting ...\n");
             ehci_reset(s);
-            DEBUG(("ehci_mem_writel: USBCMD reset done, clear reset request bit\n"));
+            DPRINTF("                        reset done, clear reset request bit\n");
             val &= ~USBCMD_HCRESET;
         }
 
@@ -819,26 +869,26 @@  static void ehci_mem_writel(void *ptr, target_phys_addr_t addr, uint32_t val)
 
     case USBSTS:
         val &= USBSTS_RO_MASK;              // bits 6 thru 31 are RO
-        DEBUG(("ehci_mem_writel : USBSTS RWC set to 0x%08X\n", val));
+        DPRINTF("mem_writel : USBSTS RWC set to 0x%08X\n", val);
 
         val =(s->usbsts &= ~val);         // bits 0 thru 5 are R/WC
-        DEBUG(("ehci_mem_writel : USBSTS updating interrupt condition\n"));
+        DPRINTF("mem_writel : USBSTS updating interrupt condition\n");
         ehci_set_interrupt(s, 0);
-
         break;
 
     case USBINTR:
         val &= USBINTR_MASK;
-        // DEBUG(("ehci_mem_writel : USBINTR set to 0x%08X\n", val));
+        DPRINTF("ehci_mem_writel: USBINTR set to 0x%08X\n", val);
         break;
 
     case FRINDEX:
         s->sofv = val >> 3;
+        DPRINTF("ehci_mem_writel: FRAME index set to 0x%08X\n",(unsigned) addr, val);
         break;
 
     case CONFIGFLAG:
+        DPRINTF("ehci_mem_writel: CONFIGFLAG set to 0x%08X\n",(unsigned) addr, val);
         val &= 0x1;
-
         if (val) {
             for(i = 0; i < NB_PORTS; i++)
                 s->portsc[i] &= ~PORTSC_POWNER;
@@ -847,10 +897,6 @@  static void ehci_mem_writel(void *ptr, target_phys_addr_t addr, uint32_t val)
         break;
     }
 
-    if (addr != 0x28) {
-        DEBUG(("ehci_mem_writel : addr=0x%08X, val=0x%08X\n",(unsigned) addr, val));
-    }
-
     *(uint32_t *)(&s->mmio[addr]) = val;
 }
 
@@ -896,15 +942,15 @@  static void ehci_qh_do_overlay(EHCIState *ehci, EHCIqh *qh, EHCIqtd *qtd)
     dtoggle = qh->token & QTD_TOKEN_DTOGGLE;
     ping = qh->token & QTD_TOKEN_PING;
 
-    DEBUG(("setting qh.current from %08X to 0x%08X\n", qh->current,
-            ehci->qtdaddr));
+    DPRINTF("setting qh.current from %08X to 0x%08X\n", qh->current,
+            ehci->qtdaddr);
     qh->current  = ehci->qtdaddr;
     qh->qtdnext  = qtd->next;
     qh->altnext  = qtd->altnext;
     qh->token    = qtd->token;
 
     if (qh->current < 0x1000) {
-#ifdef DEBUG_PACKET
+#if DEBUG_PACKET
         dump_qh(qh, qh->current);
 #endif
         ASSERT(1==2);
@@ -940,8 +986,8 @@  static void ehci_buffer_rw(EHCIState *ehci, EHCIqh *qh, int bytes, int rw)
     cpage = get_field(qh->token, QTD_TOKEN_CPAGE_MASK, QTD_TOKEN_CPAGE_SH);
     ASSERT(cpage == 0);
 
-    DEBUG(("exec: %sing %d bytes to/from %08x\n",
-           rw ? "writ" : "read", bytes, qh->bufptr[0]));
+    DPRINTF("exec: %sing %d bytes to/from %08x\n",
+           rw ? "writ" : "read", bytes, qh->bufptr[0]);
 
     if (!bytes)
         return;
@@ -953,8 +999,8 @@  static void ehci_buffer_rw(EHCIState *ehci, EHCIqh *qh, int bytes, int rw)
         if (bytes <=(tail - head))
             tail = head + bytes;
 
-        DEBUG(("DATA %s cpage:%d head:%08X tail:%08X target:%08X\n",
-                rw ? "WRITE" : "READ ", cpage, head, tail, bufpos));
+        DPRINTF("DATA %s cpage:%d head:%08X tail:%08X target:%08X\n",
+                rw ? "WRITE" : "READ ", cpage, head, tail, bufpos);
 
         ASSERT(bufpos + tail - head <= BUFF_SIZE);
         ASSERT(tail - head > 0);
@@ -977,19 +1023,23 @@  static void ehci_buffer_rw(EHCIState *ehci, EHCIqh *qh, int bytes, int rw)
 static void ehci_async_complete_packet(USBPacket *packet, void *opaque)
 {
     EHCIState *ehci = opaque;
-#ifdef DEBUG_PACKET
-    dprintf("Async packet complete\n");
+#if DEBUG_PACKET
+    DPRINTF("Async packet complete\n");
 #endif
     ehci->async_complete = 1;
     ehci->exec_status = packet->len;
 }
 
+#if TDEBUG
+static int transactid;
+#endif
+
 static int ehci_execute_complete(EHCIState *ehci,
                                   EHCIqh *qh,
                                   int ret)
 {
     if (ret == USB_RET_ASYNC && !ehci->async_complete) {
-        DEBUG(("not done yet\n"));
+        DPRINTF("not done yet\n");
         return ret;
     }
 
@@ -999,37 +1049,36 @@  static int ehci_execute_complete(EHCIState *ehci,
     if (ret < 0) {
         switch(ret) {
         case USB_RET_NODEV:
-            printf("USB no device\n");
+            fprintf(stderr, "USB no device\n");
             break;
         case USB_RET_STALL:
-            printf("USB stall\n");
+            fprintf(stderr, "USB stall\n");
             qh->token |= QTD_TOKEN_HALT;
             break;
         case USB_RET_NAK:
-            DEBUG(("USBTRAN RSP NAK, returning without clear active\n"));
+            DPRINTF("USBTRAN RSP NAK, returning without clear active\n");
             return USB_RET_NAK;
             break;
         case USB_RET_BABBLE:
-            printf("USB babble TODO\n");
+            fprintf(stderr, "USB babble TODO\n");
             ASSERT(ret >= 0);
             break;
         default:
-            printf("USB invalid response %d to handle\n",
-                    ret);
+            fprintf(stderr, "USB invalid response %d to handle\n", ret);
             ASSERT(ret >= 0);
             break;
         }
     } else {
         // if (ret < maxpkt)
         // {
-        //     DEBUG(("Short packet condition\n"));
+        //     DPRINTF("Short packet condition\n");
         //     // TODO check 4.12 for splits
          // }
 
         if (ehci->tbytes && ehci->pid == USB_TOKEN_IN) {
             ASSERT(ret > 0);
             ehci_buffer_rw(ehci, qh, ret, 1);
-#ifdef TDEBUG
+#if TDEBUG
             printf("Data after execution:\n");
             // dump_data(ehci->buffer, ehci->tbytes < 64 ? ehci->tbytes : 64);
             // decode_data(ehci->pid, ehci->buffer, ret);
@@ -1051,23 +1100,23 @@  static int ehci_execute_complete(EHCIState *ehci,
         // TODO should do this after writeback to memory
         ehci_set_interrupt(ehci, USBSTS_INT);
     }
-#ifdef DEBUG_PACKET
-    DEBUG(("QH after execute:-\n"));
+#if DEBUG_PACKET
+    DPRINTF("QH after execute:-\n");
     dump_qh(qh, NLPTR_GET(ehci->qhaddr));
 #endif
 
-#ifdef TDEBUG
-    printf("USBTRAN RSP %3d                          return:(%5d) ",
+#if TDEBUG
+    DPRINTF("USBTRAN RSP %3d                          return:(%5d) ",
             transactid,
             ret);
 
     if (ehci->pid == USB_TOKEN_IN) {
-        printf("[%02X %02X %02X %02X ...]\n",
+        DPRINTF("[%02X %02X %02X %02X ...]\n",
             *ehci->buffer, *(ehci->buffer+1),
             *(ehci->buffer+2), *(ehci->buffer+3));
     }
     else
-        printf("\n");
+        DPRINTF("\n");
 #endif
     return ret;
 }
@@ -1095,46 +1144,46 @@  static int ehci_execute(EHCIState *ehci,
     devadr = get_field(qh->epchar, QH_EPCHAR_DEVADDR_MASK, 0);
 
     if ( !(qh->token & QTD_TOKEN_ACTIVE)) {
-        printf("Attempting to execute inactive QH\n");
+        fprintf(stderr, "Attempting to execute inactive QH\n");
         exit(1);;
     }
 
     if (smask) {
-        DEBUG(("active interrupt transfer frindex %d for dev %d EP %d\n",
-                ehci->frindex, devadr, endp));
+        DPRINTF("active interrupt transfer frindex %d for dev %d EP %d\n",
+                ehci->frindex, devadr, endp);
         // TODO are interrupt always IN ?
         ehci->pid = USB_TOKEN_IN;
     } else {
-        DEBUG(("Active non-interrupt QH, executing\n"));
+        DPRINTF("Active non-interrupt QH, executing\n");
 
-        DEBUG(("pid is %2X\n", ehci->pid));
+        DPRINTF("pid is %2X\n", ehci->pid);
 
         switch(ehci->pid) {
         case 0: ehci->pid = USB_TOKEN_OUT; break;
         case 1: ehci->pid = USB_TOKEN_IN; break;
         case 2: ehci->pid = USB_TOKEN_SETUP; break;
-        default: printf("bad token\n"); break;
+        default: fprintf(stderr, "bad token\n"); break;
         }
     }
 
     // TODO set reclam
 
-#ifdef DEBUG_PACKET
-    DEBUG(("QH before execute:-\n"));
+#if DEBUG_PACKET
+    DPRINTF("QH before execute:-\n");
     dump_qh(qh, NLPTR_GET(qhaddr));
 #endif
 
     if (ehci->tbytes && ehci->pid != USB_TOKEN_IN) {
         ehci_buffer_rw(ehci, qh, ehci->tbytes, 0);
-#ifdef TDEBUG
-        printf("Data before execution:\n");
+#if TDEBUG
+        DPRINTF("Data before execution:\n");
         // dump_data(ehci->buffer, ehci->tbytes < 64 ? ehci->tbytes : 64);
         // decode_data(ehci->pid, ehci->buffer, ehci->tbytes);
 #endif
     }
 
-#ifdef TDEBUG
-    printf("\nUSBTRAN REQ %3d dev:%d ep:%d pid:%02X %s bytes:(%5d) ",
+#if TDEBUG
+    DPRINTF("\nUSBTRAN REQ %3d dev:%d ep:%d pid:%02X %s bytes:(%5d) ",
             ++transactid,
             devadr,
             endp,
@@ -1145,12 +1194,12 @@  static int ehci_execute(EHCIState *ehci,
             ehci->tbytes);
 
     if (ehci->pid != USB_TOKEN_IN) {
-        printf("[%02X %02X %02X %02X ...]\n",
+        DPRINTF("[%02X %02X %02X %02X ...]\n",
             *ehci->buffer, *(ehci->buffer+1),
             *(ehci->buffer+2), *(ehci->buffer+3));
     }
     else
-        printf("\n");
+        DPRINTF("\n");
 #endif
 
     ret = USB_RET_NODEV;
@@ -1162,8 +1211,8 @@  static int ehci_execute(EHCIState *ehci,
         // TODO sometime we will also need to check if we are the port owner
 
         if (!(ehci->portsc[i] &(PORTSC_CONNECT))) {
-            DEBUG(("Port %d, no exec, not connected(%08X)\n",
-                    i, ehci->portsc[i]));
+            DPRINTF("Port %d, no exec, not connected(%08X)\n",
+                    i, ehci->portsc[i]);
             continue;
         }
 
@@ -1175,17 +1224,17 @@  static int ehci_execute(EHCIState *ehci,
         ehci->usb_packet.complete_cb = ehci_async_complete_packet;
         ehci->usb_packet.complete_opaque = ehci;
 
-        DEBUG(("calling dev->info->handle_packet\n"));
+        DPRINTF("calling dev->info->handle_packet\n");
         ret = dev->info->handle_packet(dev, &ehci->usb_packet);
 
         if (ret != USB_RET_NODEV)
             break;
     }
 
-    DEBUG(("exit loop dev->info->handle_packet\n"));
+    DPRINTF("exit loop dev->info->handle_packet\n");
 
     if (ret > BUFF_SIZE || ehci->tbytes > BUFF_SIZE) {
-        printf("bogus QH byte count\n");
+        fprintf(stderr, "bogus QH byte count\n");
         dump_qh(qh, NLPTR_GET(qhaddr));
         ASSERT(ret <= BUFF_SIZE && ehci->tbytes <= BUFF_SIZE);
     }
@@ -1231,8 +1280,8 @@  static void ehci_process_itd(EHCIState *ehci,
 #endif
 
     if (itd->transact[i] & ITD_XACT_ACTIVE) {
-        DEBUG(("ISOCHRONOUS active for frame %d, interval %d\n",
-                ehci->frindex >> 3, i));
+        DPRINTF("ISOCHRONOUS active for frame %d, interval %d\n",
+                ehci->frindex >> 3, i);
 
         pg = get_field(itd->transact[i], ITD_XACT_PGSEL_MASK,
                         ITD_XACT_PGSEL_SH);
@@ -1243,7 +1292,7 @@  static void ehci_process_itd(EHCIState *ehci,
 
         ASSERT(len <= BUFF_SIZE);
 
-        DEBUG(("ISOCH: buffer %08X len %d\n", ptr, len));
+        DPRINTF("ISOCH: buffer %08X len %d\n", ptr, len);
 
         if (!dir) {
             cpu_physical_memory_rw(ptr, &ehci->buffer[0], len, 0);
@@ -1260,8 +1309,8 @@  static void ehci_process_itd(EHCIState *ehci,
             // TODO sometime we will also need to check if we are the port owner
 
             if (!(ehci->portsc[j] &(PORTSC_CONNECT))) {
-                DEBUG(("Port %d, no exec, not connected(%08X)\n",
-                        j, ehci->portsc[j]));
+                DPRINTF("Port %d, no exec, not connected(%08X)\n",
+                        j, ehci->portsc[j]);
                 continue;
             }
 
@@ -1273,7 +1322,7 @@  static void ehci_process_itd(EHCIState *ehci,
             ehci->usb_packet.complete_cb = ehci_async_complete_packet;
             ehci->usb_packet.complete_opaque = ehci;
 
-            DEBUG(("calling dev->info->handle_packet\n"));
+            DPRINTF("calling dev->info->handle_packet\n");
             ret = dev->info->handle_packet(dev, &ehci->usb_packet);
 
             if (ret != USB_RET_NODEV)
@@ -1287,21 +1336,21 @@  static void ehci_process_itd(EHCIState *ehci,
 
         if (ret == USB_RET_NAK) {
             if (ehci->isoch_pause > 0) {
-                DEBUG(("ISOCH: received a NAK but paused so returning\n"));
+                DPRINTF("ISOCH: received a NAK but paused so returning\n");
                 ehci->isoch_pause--;
                 return;
             } else if (ehci->isoch_pause == -1) {
-                DEBUG(("ISOCH: recv NAK & isoch pause inactive, setting\n"));
+                DPRINTF("ISOCH: recv NAK & isoch pause inactive, setting\n");
                 // Pause frindex for up to 50 msec waiting for data from
                 // remote
                 ehci->isoch_pause = 50;
                 return;
             } else {
-                DEBUG(("ISOCH: isoch pause timeout! return 0\n"));
+                DPRINTF("ISOCH: isoch pause timeout! return 0\n");
                 ret = 0;
             }
         } else {
-            DEBUG(("ISOCH: received ACK, clearing pause\n"));
+            DPRINTF("ISOCH: received ACK, clearing pause\n");
             ehci->isoch_pause = -1;
         }
 
@@ -1318,8 +1367,8 @@  static void ehci_process_itd(EHCIState *ehci,
             cpu_physical_memory_rw(ptr, &ehci->buffer[0], len, 1);
 
             if (ret != len) {
-                DEBUG(("ISOCH IN expected %d, got %d\n",
-                        len, ret));
+                DPRINTF("ISOCH IN expected %d, got %d\n",
+                        len, ret);
                 set_field(&itd->transact[i],
                            ret,
                            ITD_XACT_LENGTH_MASK,
@@ -1351,7 +1400,7 @@  static int ehci_advance_state(EHCIState *ehci,
     int nakcnt;
 
     do {
-        DEBUG(("advance_state: again=%d\n", again));
+        DPRINTF("advance_state: again=%d\n", again);
         again = 0;
         // ASSERT(loopcount++ < MAX_ITERATIONS);
 
@@ -1360,7 +1409,7 @@  static int ehci_advance_state(EHCIState *ehci,
          *  processing.  Entry here consitutes a EHCI start event state(4.8.5)
          */
         case EST_WAITLISTHEAD:
-            DEBUG(("WAITLISTHEAD\n"));
+            DPRINTF("WAITLISTHEAD\n");
 
             if (async)
                 ehci->usbsts |= USBSTS_REC;
@@ -1373,11 +1422,11 @@  static int ehci_advance_state(EHCIState *ehci,
                             sizeof(EHCIqh) >> 2);
 
                 if (qh->epchar & QH_EPCHAR_H) {
-                    DEBUG(("QH %08X is the HEAD of the list\n", entry));
+                    DPRINTF("QH %08X is the HEAD of the list\n", entry);
                     break;
                 }
 
-                DEBUG(("QH %08X is NOT the HEAD of the list\n", entry));
+                DPRINTF("QH %08X is NOT the HEAD of the list\n", entry);
                 entry = qh->next;
             }
 
@@ -1394,15 +1443,15 @@  static int ehci_advance_state(EHCIState *ehci,
          *  processing.
          */
         case EST_FETCHENTRY:
-            DEBUG(("FETCHENTRY\n"));
+            DPRINTF("FETCHENTRY\n");
 
             if (qemu_get_clock(vm_clock) / 1000 > ehci->frame_end_usec) {
                 if (async) {
-                    DEBUG(("FRAME timer elapsed, exit state machine\n"));
+                    DPRINTF("FRAME timer elapsed, exit state machine\n");
                     state = EST_ACTIVE;
                     break;
                 } else
-                    DEBUG(("WARNING - frame timer elapsed during periodic\n"));
+                    DPRINTF("WARNING - frame timer elapsed during periodic\n");
             }
 
             if (NLPTR_TBIT(entry)) {
@@ -1431,11 +1480,11 @@  static int ehci_advance_state(EHCIState *ehci,
         case EST_FETCHQH:
             get_dwords(NLPTR_GET(ehci->qhaddr),(uint32_t *) qh, 
                        sizeof(EHCIqh) >> 2);
-            DEBUG(("FETCHQH: Fetched QH at address %08X "
+            DPRINTF("FETCHQH: Fetched QH at address %08X "
                     "(next is %08X, h-bit is %d)\n",
-                    ehci->qhaddr, qh->next, qh->epchar & QH_EPCHAR_H));
+                    ehci->qhaddr, qh->next, qh->epchar & QH_EPCHAR_H);
 
-#ifdef DEBUG_PACKET
+#if DEBUG_PACKET
             dump_qh(qh, NLPTR_GET(ehci->qhaddr));
 #endif
 
@@ -1443,10 +1492,10 @@  static int ehci_advance_state(EHCIState *ehci,
                 /*  EHCI spec version 1.0 Section 4.8.3
                  */
                 if (qh->epchar & QH_EPCHAR_H) {
-                    DEBUG(("h-bit set\n"));
+                    DPRINTF("h-bit set\n");
 
                     if (!(ehci->usbsts & USBSTS_REC)) {
-                        DEBUG(("h-bit and !reclam, done\n"));
+                        DPRINTF("h-bit and !reclam, done\n");
                         state = EST_ACTIVE;
                         break;
                     }
@@ -1454,42 +1503,42 @@  static int ehci_advance_state(EHCIState *ehci,
                 /*  EHCI spec version 1.0 Section 4.10.1
                  */
                 if ( !(qh->epcap & QH_EPCAP_SMASK_MASK)) {
-                    DEBUG(("not intr, clear reclam\n"));
+                    DPRINTF("not intr, clear reclam\n");
                     ehci->usbsts &= ~USBSTS_REC;
                 }
             } else {
-                DEBUG(("exec: qh check, frindex is %d,%d\n",
-                         (ehci->frindex >> 3),(ehci->frindex & 7)));
+                DPRINTF("exec: qh check, frindex is %d,%d\n",
+                         (ehci->frindex >> 3),(ehci->frindex & 7));
             }
 
             reload = get_field(qh->epchar, QH_EPCHAR_RL_MASK, QH_EPCHAR_RL_SH);
 
             if (reload) {
-                DEBUG(("reloading nakcnt to %d\n",
-                        reload));
+                DPRINTF("reloading nakcnt to %d\n",
+                        reload);
                 set_field(&qh->altnext, reload, QH_ALTNEXT_NAKCNT_MASK,
                            QH_ALTNEXT_NAKCNT_SH);
             }
 
             if (qh->token & QTD_TOKEN_ACTIVE) {
                 if ((qh->token & QTD_TOKEN_HALT)) {
-                    printf("Active, Halt, ** ILLEGAL **\n");
+                    fprintf(stderr, "Active, Halt, ** ILLEGAL **\n");
                     state = EST_ACTIVE;
                 } else {
-                    DEBUG(("Active, !Halt, execute - fetchqtd\n"));
+                    DPRINTF("Active, !Halt, execute - fetchqtd\n");
                     ehci->qtdaddr = qh->current;
                     state = EST_FETCHQTD;
                     again = 1;
                 }
             } else {
                 if (qh->token & QTD_TOKEN_HALT) {
-                    DEBUG(("!Active, Halt, go horiz\n"));
+                    DPRINTF("!Active, Halt, go horiz\n");
                     state = EST_HORIZONTALQH;
                     again = 1;
                 } else {
                     /*  EHCI spec version 1.0 Section 4.10.2
                      */
-                    DEBUG(("!Active, !Halt, adv q\n"));
+                    DPRINTF("!Active, !Halt, adv q\n");
                     state = EST_ADVANCEQUEUE;
                     again = 1;
                 }
@@ -1500,16 +1549,16 @@  static int ehci_advance_state(EHCIState *ehci,
         case EST_FETCHITD:
             get_dwords(NLPTR_GET(ehci->itdaddr),(uint32_t *) &itd,
                         sizeof(EHCIitd) >> 2);
-            DEBUG(("FETCHITD: Fetched ITD at address %08X "
+            DPRINTF("FETCHITD: Fetched ITD at address %08X "
                     "(next is %08X)\n",
-                    ehci->itdaddr, itd.next));
+                    ehci->itdaddr, itd.next);
 
-#ifdef DEBUG_PACKET
+#if DEBUG_PACKET
             dump_itd(&itd, NLPTR_GET(ehci->itdaddr));
 #endif
 
             ehci_process_itd(ehci, &itd);
-#ifdef DEBUG_PACKET
+#if DEBUG_PACKET
             dump_itd(&itd, NLPTR_GET(ehci->itdaddr));
 #endif
             put_dwords(NLPTR_GET(ehci->itdaddr),(uint32_t *) &itd,
@@ -1520,11 +1569,11 @@  static int ehci_advance_state(EHCIState *ehci,
             break;
 
         case EST_ADVANCEQUEUE:
-            DEBUG(("ADVANCEQUEUE\n"));
+            DPRINTF("ADVANCEQUEUE\n");
             if ((qh->token & QTD_TOKEN_TBYTES_MASK) != 0 &&
                 NLPTR_TBIT(qh->altnext) == 0) {
                 ehci->qtdaddr = qh->altnext;
-                DEBUG(("tbytes!=0 and tbit = 0, go with altnext\n"));
+                DPRINTF("tbytes!=0 and tbit = 0, go with altnext\n");
             } else {
                 if (NLPTR_TBIT(qh->qtdnext)) {
                     state = EST_HORIZONTALQH;
@@ -1539,7 +1588,7 @@  static int ehci_advance_state(EHCIState *ehci,
             break;
 
         case EST_FETCHQTD:
-            DEBUG(("FETCHQTD: Fetching QTD at address %08X\n", ehci->qtdaddr));
+            DPRINTF("FETCHQTD: Fetching QTD at address %08X\n", ehci->qtdaddr);
             get_dwords(NLPTR_GET(ehci->qtdaddr),(uint32_t *) qtd,
                         sizeof(EHCIqtd) >> 2);
 
@@ -1548,7 +1597,7 @@  static int ehci_advance_state(EHCIState *ehci,
                 again = 1;
                 break;
             } else {
-                DEBUG(("abort advance, not active\n"));
+                DPRINTF("abort advance, not active\n");
                 state = EST_HORIZONTALQH;
                 again = 1;
                 break;
@@ -1564,12 +1613,12 @@  static int ehci_advance_state(EHCIState *ehci,
 
         case EST_EXECUTE:
             if (async) {
-                DEBUG(("\n\n>>>>> ASYNC STATE MACHINE execute\n"));
+                DPRINTF("\n\n>>>>> ASYNC STATE MACHINE execute\n");
             } else {
-                DEBUG(("\n\n>>>>> PERIODIC STATE MACHINE execute\n"));
+                DPRINTF("\n\n>>>>> PERIODIC STATE MACHINE execute\n");
             }
 
-#ifdef DEBUG_PACKET
+#if DEBUG_PACKET
             dump_qh(qh, NLPTR_GET(ehci->qhaddr));
             dump_qtd(qtd, NLPTR_GET(ehci->qtdaddr));
 #endif
@@ -1578,11 +1627,11 @@  static int ehci_advance_state(EHCIState *ehci,
 
 #ifndef EHCI_NOMICROFRAMES
             if (smask &&(smask &(1 <<(ehci->frindex & 7))) == 0) {
-                DEBUG(("PERIODIC active not interval: "
+                DPRINTF("PERIODIC active not interval: "
                         "mask is %d, "
                         "frindex is %d,%d\n",
                         smask,
-                        (ehci->frindex >> 3),(ehci->frindex & 7)));
+                        (ehci->frindex >> 3),(ehci->frindex & 7));
 
                 state = EST_HORIZONTALQH;
                 again = 1;
@@ -1591,18 +1640,18 @@  static int ehci_advance_state(EHCIState *ehci,
 #endif
 
             if (smask) {
-                DEBUG(("PERIODIC active !!! "
+                DPRINTF("PERIODIC active !!! "
                         "mask is %d, "
                         "frindex is %d,%d\n",
                         smask,
-                        (ehci->frindex >> 3),(ehci->frindex & 7)));
+                        (ehci->frindex >> 3),(ehci->frindex & 7));
             }
 
             reload = get_field(qh->epchar, QH_EPCHAR_RL_MASK, QH_EPCHAR_RL_SH);
             nakcnt = get_field(qh->altnext, QH_ALTNEXT_NAKCNT_MASK, 
                                QH_ALTNEXT_NAKCNT_SH);
             if (reload && !nakcnt) {
-                DEBUG(("RL != 0 but NakCnt == 0, no execute\n"));
+                DPRINTF("RL != 0 but NakCnt == 0, no execute\n");
                 state = EST_HORIZONTALQH;
                 again = 1;
                 break;
@@ -1620,7 +1669,7 @@  static int ehci_advance_state(EHCIState *ehci,
 #if 0
             if (!transactCtr &&(qh->epcap & QH_EPCAP_SMASK_MASK) > 0)
             {
-                DEBUG(("ZERO transactctr for int qh, go HORIZ\n"));
+                DPRINTF("ZERO transactctr for int qh, go HORIZ\n");
                 *state = EST_HORIZONTALQH;
                 again = 1;
                 break;
@@ -1631,12 +1680,12 @@  static int ehci_advance_state(EHCIState *ehci,
                 transactCtr = 1; // TODO - check at what level do we repeat
 
                 if (qh->epcap & QH_EPCAP_SMASK_MASK)
-                    DEBUG(("WARN - ZERO transactctr force to 1 for intr\n"));
+                    DPRINTF("WARN - ZERO transactctr force to 1 for intr\n");
             }
 
-            DEBUG(("exec: ctr is %d\n", transactCtr));
-            DEBUG(("exec: frindex is %d,%d\n",
-                   (ehci->frindex >> 3),(ehci->frindex & 7)));
+            DPRINTF("exec: ctr is %d\n", transactCtr);
+            DPRINTF("exec: frindex is %d,%d\n",
+                   (ehci->frindex >> 3),(ehci->frindex & 7));
 
             ehci_qh_do_overlay(ehci, qh, qtd);
             ehci->exec_status = ehci_execute(ehci, ehci->qhaddr, qh);
@@ -1648,14 +1697,14 @@  static int ehci_advance_state(EHCIState *ehci,
             break;
 
         case EST_EXECUTING:
-            DEBUG(("Enter EXECUTING\n"));
+            DPRINTF("Enter EXECUTING\n");
             ehci->exec_status = ehci_execute_complete(ehci, qh,
                                                        ehci->exec_status);
 
             if (ehci->exec_status == USB_RET_ASYNC)
                 break;
 
-            DEBUG(("finishing exec\n"));
+            DPRINTF("finishing exec\n");
             transactCtr = get_field(qh->epcap,
                                      QH_EPCAP_MULT_MASK, QH_EPCAP_MULT_SH);
 
@@ -1673,13 +1722,13 @@  static int ehci_advance_state(EHCIState *ehci,
                 if (ehci->exec_status == USB_RET_NAK) {
                     nakcnt--;
 
-                    DEBUG(("Nak occured and RL != 0, dec NakCnt to %d\n",
-                            nakcnt));
+                    DPRINTF("Nak occured and RL != 0, dec NakCnt to %d\n",
+                            nakcnt);
                 } else {
                     nakcnt = reload;
 
-                    DEBUG(("Nak didn't occur, reloading to %d\n",
-                            nakcnt));
+                    DPRINTF("Nak didn't occur, reloading to %d\n",
+                            nakcnt);
                 }
 
                 set_field(&qh->altnext, nakcnt, QH_ALTNEXT_NAKCNT_MASK,
@@ -1692,8 +1741,8 @@  static int ehci_advance_state(EHCIState *ehci,
              *  physical memory with our guest VM.
              */
 
-            DEBUG(("write QH to VM memory\n"));
-#ifdef DEBUG_PACKET
+            DPRINTF("write QH to VM memory\n");
+#if DEBUG_PACKET
             dump_qh(qh, NLPTR_GET(ehci->qhaddr));
 #endif
             put_dwords(NLPTR_GET(ehci->qhaddr),(uint32_t *) qh,
@@ -1711,7 +1760,7 @@  static int ehci_advance_state(EHCIState *ehci,
 
         case EST_WRITEBACK:
             /*  Write back the QTD from the QH area */
-            DEBUG(("write QTD to VM memory\n"));
+            DPRINTF("write QTD to VM memory\n");
             put_dwords(NLPTR_GET(ehci->qtdaddr),(uint32_t *) &qh->qtdnext,
                         sizeof(EHCIqtd) >> 2);
             /* TODO confirm next state.  For now, keep going if async
@@ -1727,7 +1776,7 @@  static int ehci_advance_state(EHCIState *ehci,
             break;
 
         default:
-            printf("Bad state!\n");
+            fprintf(stderr, "Bad state!\n");
             break;
             }
     }
@@ -1741,7 +1790,7 @@  static void ehci_advance_async_state(EHCIState *ehci)
     switch(ehci->astate) {
     case EST_INACTIVE:
         if (ehci->usbcmd & USBCMD_ASE) {
-            DEBUG(("ASYNC going active\n"));
+            DPRINTF("ASYNC going active\n");
             ehci->usbsts |= USBSTS_ASS;
             ehci->astate = EST_ACTIVE;
             // No break, fall through to ACTIVE
@@ -1750,13 +1799,13 @@  static void ehci_advance_async_state(EHCIState *ehci)
 
     case EST_ACTIVE:
         if ( !(ehci->usbcmd & USBCMD_ASE)) {
-            DEBUG(("ASYNC going inactive\n"));
+            DPRINTF("ASYNC going inactive\n");
             ehci->usbsts &= ~USBSTS_ASS;
             ehci->astate = EST_INACTIVE;
             break;
         }
 
-        DEBUG(("\n    ===   ===   ===   ===   ===   ===\n\n"));
+        DPRINTF("\n    ===   ===   ===   ===   ===   ===\n\n");
         if (ehci->usbcmd & USBCMD_IAAD) {
             /*  Async advance doorbell interrupted requested
              */
@@ -1770,13 +1819,13 @@  static void ehci_advance_async_state(EHCIState *ehci)
         break;
 
     case EST_EXECUTING:
-        DEBUG(("async state adv for executing\n"));
+        DPRINTF("async state adv for executing\n");
         ehci->astate = ehci_advance_state(ehci, 1,
                                            EST_EXECUTING, ehci->qhaddr);
         break;
 
     default:
-        printf("Bad asynchronous state %d\n",
+        fprintf(stderr, "Bad asynchronous state %d\n",
                 ehci->astate);
         ASSERT(1==2);
     }
@@ -1792,7 +1841,7 @@  static void ehci_advance_periodic_state(EHCIState *ehci)
     switch(ehci->pstate) {
     case EST_INACTIVE:
         if ( !(ehci->frindex & 7) &&(ehci->usbcmd & USBCMD_PSE)) {
-            DEBUG(("PERIODIC going active\n"));
+            DPRINTF("PERIODIC going active\n");
             ehci->usbsts |= USBSTS_PSS;
             ehci->pstate = EST_ACTIVE;
             // No break, fall through to ACTIVE
@@ -1801,7 +1850,7 @@  static void ehci_advance_periodic_state(EHCIState *ehci)
 
     case EST_ACTIVE:
         if ( !(ehci->frindex & 7) && !(ehci->usbcmd & USBCMD_PSE)) {
-            DEBUG(("PERIODIC going inactive\n"));
+            DPRINTF("PERIODIC going inactive\n");
             ehci->usbsts &= ~USBSTS_PSS;
             ehci->pstate = EST_INACTIVE;
             break;
@@ -1813,20 +1862,20 @@  static void ehci_advance_periodic_state(EHCIState *ehci)
         cpu_physical_memory_rw(list,(uint8_t *) &entry, sizeof entry, 0);
         entry = le32_to_cpu(entry);
 
-        DEBUG(("periodic state adv fr=%d.  [%08X] -> %08X\n",
-                ehci->frindex / 8, list, entry));
+        DPRINTF("periodic state adv fr=%d.  [%08X] -> %08X\n",
+                ehci->frindex / 8, list, entry);
         ehci->pstate = ehci_advance_state(ehci, 0,
                                            EST_FETCHENTRY, entry);
         break;
 
     case EST_EXECUTING:
-        DEBUG(("periodic state adv for executing\n"));
+        DPRINTF("periodic state adv for executing\n");
         ehci->pstate = ehci_advance_state(ehci, 0,
                                            EST_EXECUTING, ehci->qhaddr);
         break;
 
     default:
-        printf("Bad periodic state %d\n",
+        fprintf(stderr, "Bad periodic state %d\n",
                 ehci->pstate);
         ASSERT(1==2);
     }
@@ -1850,19 +1899,12 @@  static void ehci_frame_timer(void *opaque)
 
     usec_now = t_now / 1000;
     usec_elapsed = usec_now - ehci->last_run_usec;
-    ehci->frame_end_usec = usec_now + 1000;
+    frames = usec_elapsed / FRAME_TIMER_USEC;
+    ehci->frame_end_usec = usec_now + FRAME_TIMER_USEC;
 
-#ifdef EHCI_NOMICROFRAMES
-    frames = usec_elapsed / 1000;
-    ehci->frame_end_usec = usec_now + 1000;
-#else
-    frames = usec_elapsed / 125;
-    ehci->frame_end_usec = usec_now + 125;
-#endif
-
-#ifdef TDEBUG
-    DEBUG(("Frame timer, usec elapsed since last %d, frames %d\n",
-            usec_elapsed, frames));
+#if TDEBUG
+    DPRINTF("Frame timer, usec elapsed since last %d, frames %d\n",
+            usec_elapsed, frames);
 #endif
 
     for(i = 0; i < frames; i++) {
@@ -1877,8 +1919,8 @@  static void ehci_frame_timer(void *opaque)
 
             if (ehci->frindex > 0x00001fff) {
                 ehci->frindex = 0;
-#ifdef TDEBUG
-                DEBUG(("PERIODIC frindex rollover\n"));
+#if TDEBUG
+                DPRINTF("PERIODIC frindex rollover\n");
 #endif
                 ehci_set_interrupt(ehci, USBSTS_FLR);
             }
@@ -1896,16 +1938,12 @@  static void ehci_frame_timer(void *opaque)
                 ehci_advance_periodic_state(ehci);
         }
 
-#ifdef EHCI_NOMICROFRAMES
-        ehci->last_run_usec += 1000;
-#else
-        ehci->last_run_usec += 125;
-#endif
+        ehci->last_run_usec += FRAME_TIMER_USEC;
     }
 
 #if 0
     if (skipped_frames)
-        DEBUG(("WARNING - EHCI skipped %d frames\n", skipped_frames));
+        DPRINTF("WARNING - EHCI skipped %d frames\n", skipped_frames);
 #endif
 
     /*  Async is not inside loop since it executes everything it can once
@@ -1916,10 +1954,9 @@  static void ehci_frame_timer(void *opaque)
 
     qemu_mod_timer(ehci->frame_timer, expire_time);
 
+#if TDEBUG
     usec_elapsed = qemu_get_clock(vm_clock) / 1000 - usec_now;
-
-#ifdef TDEBUG
-    DEBUG(("TIMING: frame_timer used %d usec\n", usec_elapsed));
+    DPRINTF("TIMING: frame_timer used %d usec\n", usec_elapsed);
 #endif
 }
 
@@ -1940,8 +1977,8 @@  static void ehci_map(PCIDevice *pci_dev, int region_num,
 {
     EHCIState *s =(EHCIState *)pci_dev;
 
-    DEBUG(("ehci_map: region %d, addr %08lX, size %ld, s->mem %08X\n",
-            region_num, addr, size, s->mem));
+    DPRINTF("ehci_map: region %d, addr %08lX, size %ld, s->mem %08X\n",
+            region_num, addr, size, s->mem);
     s->mem_base = addr;
     cpu_register_physical_memory(addr, size, s->mem);
 }
@@ -1987,26 +2024,26 @@  static int usb_ehci_initfn(PCIDevice *dev)
 
     pci_config_set_vendor_id(pci_conf, PCI_VENDOR_ID_INTEL);
     pci_config_set_device_id(pci_conf, PCI_DEVICE_ID_INTEL_82801D);
-    pci_conf[PCI_REVISION_ID] = 0x10;
-    pci_conf[PCI_CLASS_PROG] = 0x20;
+    pci_set_byte(&pci_conf[PCI_REVISION_ID], 0x10);
+    pci_set_byte(&pci_conf[PCI_CLASS_PROG], 0x20);
     pci_config_set_class(pci_conf, PCI_CLASS_SERIAL_USB);
+    pci_set_byte(&pci_conf[PCI_HEADER_TYPE], PCI_HEADER_TYPE_NORMAL);
 
-    pci_conf[PCI_HEADER_TYPE] = PCI_HEADER_TYPE_NORMAL;
-    pci_conf[PCI_CAPABILITY_LIST] = 0x00; // capabilities pointer
-
-    // pci_conf[0x34] = 0x50; // capabilities pointer
+    /* capabilities pointer */
+    pci_set_byte(&pci_conf[PCI_CAPABILITY_LIST], 0x00);
+    //pci_set_byte(&pci_conf[PCI_CAPABILITY_LIST], 0x50);
 
-    pci_conf[0x3d] = 4; // interrupt pin 3
-    pci_conf[0x3e] = 0; // MaxLat
-    pci_conf[0x3f] = 0; // MinGnt
+    pci_set_byte(&pci_conf[PCI_INTERRUPT_PIN], 4); // interrupt pin 3
+    pci_set_byte(&pci_conf[PCI_MIN_GNT], 0); // MaxLat
+    pci_set_byte(&pci_conf[PCI_MAX_LAT], 0); // MinGnt
 
     // pci_conf[0x50] = 0x01; // power management caps
 
-    pci_conf[0x60] = 0x20;  // SBRN
-    pci_conf[0x61] = 0x20;  // FLADJ
-    pci_conf[0x62] = 0x7f;
-    pci_conf[0x63] = 0x00;  // PORTWAKECAP
-    pci_conf[0x64] = 0x00;
+    pci_set_byte(&pci_conf[0x60], 0x20);  // spec release number (2.1.4)
+    pci_set_byte(&pci_conf[0x61], 0x20);  // frame length adjustment (2.1.5)
+    pci_set_word(&pci_conf[0x62], 0x00);  // port wake up capability (2.1.6)
+
+    pci_conf[0x64] = 0x00;  
     pci_conf[0x65] = 0x00;
     pci_conf[0x66] = 0x00;
     pci_conf[0x67] = 0x00;
@@ -2019,20 +2056,19 @@  static int usb_ehci_initfn(PCIDevice *dev)
     pci_conf[0x6e] = 0x00;
     pci_conf[0x6f] = 0xc0;  // USBLEFCTLSTS
 
-    s->mmio[0x00] = OPREGBASE;
-    s->mmio[0x01] = 0x00;
-    s->mmio[0x02] = 0x00;
-    s->mmio[0x03] = 0x01;    // HC version
-    s->mmio[0x04] = NB_PORTS;  // Number of downstream ports
-    s->mmio[0x05] = 0x00;    // No companion ports at present
-    s->mmio[0x06] = 0x00;
-    s->mmio[0x07] = 0x00;
-    s->mmio[0x08] = 0x80;    // We can cache whole frame, not 64-bit capable
-    s->mmio[0x09] = 0x68;    // EECP
-    s->mmio[0x0a] = 0x00;
-    s->mmio[0x0b] = 0x00;
-
-    s->irq = s->dev.irq[0];
+    // 2.2.2 host controller interface version
+    pci_set_byte(&s->mmio[CAPLENGTH], OPREGBASE);
+    pci_set_word(&s->mmio[HCIVERSION], 0x0100);
+
+    // 2.2.3 host controller structural parameters
+    pci_set_word(&s->mmio[HCSPARAMS], NB_PORTS);
+
+    // 2.2.4 host controller capability parameters
+    // - 0x80 = can cache whole frame, not 64-bit capable
+    pci_set_word(&s->mmio[HCCPARAMS], 0x00000080);
+
+
+    s->irq = s->dev.irq[3];
 
     // TODO - port registration is going to need an overhaul since ports
     // can be low, full or high speed and are not tied to UHCI or EHCI.
@@ -2040,7 +2076,7 @@  static int usb_ehci_initfn(PCIDevice *dev)
     // list but really all ports need to be owned by EHCI and it should
     // hand off to companion controllers if device is full or low speed.
 
-    DEBUG(("ehci init : registering USB ports with no device attached\n"));
+    DPRINTF("ehci_init : registering USB ports with no device attached\n");
 
     // TODO come up with a better port allocation scheme
     // added ehci->bus, need to find ehci->DeviceState
@@ -2052,15 +2088,16 @@  static int usb_ehci_initfn(PCIDevice *dev)
 
     s->frame_timer = qemu_new_timer(vm_clock, ehci_frame_timer, s);
 
+    DPRINTF("ehci_init: calling ehci_reset\n");
     qemu_register_reset(ehci_reset, s);
 
     s->mem = cpu_register_io_memory(ehci_readfn, ehci_writefn, s);
 
-    DEBUG(("ehci init : registering MMIO size %d\n", MMIO_SIZE));
+    DPRINTF("ehci_init: registering MMIO size %d\n", MMIO_SIZE);
     pci_register_bar(&s->dev, 0, MMIO_SIZE, PCI_BASE_ADDRESS_SPACE_MEMORY,
                                                             ehci_map);
 
-    DEBUG(("*** ehci init : under development 16-OCT-08 *** \n"));
+    fprintf(stderr, "\n\n*** EHCI support is under development *** \n\n");
 
     return 0;
 }