RE: [avrdude-dev] Time Problem Avrdude 5.3.1 on mac

[Yannick PODGORSKI]

Thanks for answer.
I try to find the decription of CFRunLoopRunInMode function but I can't.
I use ktrace on mac and I get this :

 25137 avrdude  0.000066 RET   pread 4096/0x1000
 25137 avrdude  0.000076 CALL  mmap(0xcc000,0xf000,0x5,0x12,0x4,0)
 25137 avrdude  0.000093 RET   mmap 835584/0xcc000
 25137 avrdude  0.000016 CALL  mmap(0xdb000,0x1000,0x3,0x12,0x4,0xf000)
 25137 avrdude  0.000036 RET   mmap 897024/0xdb000
 25137 avrdude  0.000009 CALL  mmap(0xdc000,0x900c,0x1,0x12,0x4,0x10000)
 25137 avrdude  0.000029 RET   mmap 901120/0xdc000
 25137 avrdude  0.000041 CALL  close(0x4)
 25137 avrdude  0.000015 RET   close 0
 25137 avrdude  0.327948 CALL  write(0x2,0xbfffe6e0,0x3f)
 25137 avrdude  0.000084 GIO   fd 2 wrote 63 bytes
       "avrdude: usbdev_open(): Found AVRISP mkII, serno: 0000B0009933
       "
 25137 avrdude  0.000016 RET   write 63/0x3f
 25137 avrdude  12.109464 CALL  write(0x2,0xbfffe8f0,0x257)
 25137 avrdude  0.000088 GIO   fd 2 wrote 599 bytes
       "         AVR Part              : ATMEGA64
                 Chip Erase delay      : 9000 us
                 PAGEL                 : PD7
                 BS2                   : PA0
                 RESET disposition     : dedicated 

It's different from your trace.
For me, I don't understand why there is a 10 s timeout in function 
usb_bulk_read in file usb_libusb.c (line 362)
and why the function in this case goes out with a kCFRunLoopRunTimedOut value 
and not a kCFRunLoopRunHandledSource value (as all
other cases)
I check the code on avrdude 5.1 and libusb-0.1.11 and it is the same.

Thanks.

Yannick PODGORSKI.

-----Message d'origine-----
De : Joerg Wunsch [mailto:address@hidden 
Envoyé : jeudi 3 mai 2007 00:05
À : address@hidden
Cc : Yannick PODGORSKI
Objet : Re: [avrdude-dev] Time Problem Avrdude 5.3.1 on mac

As Yannick PODGORSKI wrote:

> I try to check "the way of functions" :
>  - "usbdev_recv_frame" in usb_libusb.c (line 445)
>  - "usb_bulk_read" in usb_libusb.c (line 362) 
>       => where the timeout is 10 000 ms (10s)
>  - "usb_bulk_transfer" in darwin.c (line 913 libusb-0.1.12)
>  - "CFRunLoopRunInMode" in darwin.c (line 841 libusb-0.1.12)

> Maybe the timeout is too long (how was it decided ? I try with 5s or 
> 2s, it works.  Can I change it without problems or create a variable 
> to modify it in the avrdude command ?

The timeout I see on FreeBSD for the same part is *way* smaller:

   612 avrdude  0.000038 GIO   fd 2 wrote 63 bytes
       "avrdude: usbdev_open(): Found AVRISP mkII, serno: 00B00000011B
       "
   612 avrdude  0.000001 RET   write 63/0x3f
   612 avrdude  0.000390 CALL  ioctl(0x3,USB_SET_CONFIG,0xbfbfdbc4)
   612 avrdude  0.000077 RET   ioctl 0
   612 avrdude  0.001172 CALL  open(0xbfbfdd40,0x2,0x28084488)
   612 avrdude  0.000029 NAMI  "/dev/ugen0.2"
   612 avrdude  0.000522 RET   open 4
   612 avrdude  0.000638 CALL  ioctl(0x4,USB_SET_TIMEOUT,0xbfbfddc0)
   612 avrdude  0.000013 RET   ioctl 0
   612 avrdude  0.000841 CALL  ioctl(0x4,USB_SET_SHORT_XFER,0xbfbfdd98)
   612 avrdude  0.000006 RET   ioctl 0
   612 avrdude  0.001580 CALL  read(0x4,0x807dd80,0x40)
   612 avrdude  0.121655 RET   read -1 errno 60 Operation timed out
                ^^^^^^^^
   612 avrdude  0.000256 CALL  ioctl(0x4,USB_SET_TIMEOUT,0xbfbfdbf0)
   612 avrdude  0.000019 RET   ioctl 0
   612 avrdude  0.000044 CALL  write(0x4,0xbfbfddeb,0x1)
   612 avrdude  0.001655 GIO   fd 4 wrote 1 byte
       0x0000 01                                       |.|

   612 avrdude  0.000003 RET   write 1
   612 avrdude  0.001802 CALL  ioctl(0x4,USB_SET_TIMEOUT,0xbfbfdcf0)
   612 avrdude  0.000026 RET   ioctl 0
   612 avrdude  0.002629 CALL  ioctl(0x4,USB_SET_SHORT_XFER,0xbfbfdcc8)
   612 avrdude  0.000017 RET   ioctl 0
   612 avrdude  0.000550 CALL  read(0x4,0x807dd80,0x40)
   612 avrdude  0.001988 GIO   fd 4 read 13 bytes
       0x0000 0100 0a41 5652 4953 505f 4d4b 32         |...AVRISP_MK2|

   612 avrdude  0.000002 RET   read 13/0xd
   612 avrdude  0.000062 CALL  ioctl(0x4,USB_SET_TIMEOUT,0xbfbfddc0)
   612 avrdude  0.000007 RET   ioctl 0
   612 avrdude  0.000026 CALL  ioctl(0x4,USB_SET_SHORT_XFER,0xbfbfdd98)
   612 avrdude  0.000005 RET   ioctl 0
   612 avrdude  0.000022 CALL  read(0x4,0x807dd80,0x40)
   612 avrdude  0.122846 RET   read -1 errno 60 Operation timed out
   612 avrdude  0.000174 CALL  write(0x2,0xbfbfd620,0x259)
   612 avrdude  0.000058 GIO   fd 2 wrote 601 bytes
       "         AVR Part              : ATMEGA2561
                 Chip Erase delay      : 9000 us
                 PAGEL                 : PD7
...

So it's 120 ms instead of 12 s.  That heavily smells like an off by 100 error 
in the MacOS X libusb implementation to me.

Somehow, your traces and mine don't match though.  It appears to me your trace 
lacks some entries.  If you look at mine, the 120 ms
wait part matches:

  serial_open(port, baud, &pgm->fd);

  /*
   * drain any extraneous input
   */
  stk500v2_drain(pgm, 0);

which is then followed by:

  stk500v2_getsync(pgm);

  stk500v2_drain(pgm, 0);

This part is completely missing in your trace.  It sends a 0x01
(CMD_SIGN_ON) to the device, and gets the AVRISP_MK2 reply string.
The printout of the AVR part features only happens after the sign-on command.  
The stk500v2_drain() timeout is set to 100 ms (it
correlates to usbdev_drain() in usb_libusb.c), so returning after 120 ms looks 
reasonable to me.

-- 
cheers, J"org               .-.-.   --... ...--   -.. .  DL8DTL

http://www.sax.de/~joerg/                        NIC: JW11-RIPE
Never trust an operating system you don't have sources for. ;-)