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

[Joerg Wunsch]

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. ;-)