AVR109 (butterfly) My Bootloader failed to read back at 2Mbps

[flyandancexo]

I have achieved a maximum upload speed of 31K bytes per second on my FDxboot_1.51x on an Atmega128a at 1Mbps, but when trying to operate at 2Mbps, it failed to read back correctly. Writing is good.

I read the source code of the butterfly, and I suspect these 2 lines are the cause of the problem. What is the exact delay between these 2 lines of code? Since it's very slow to read back a page of data, even one byte of flash memory, at 2Mbps, it simply timeouts and failed to response quickly.

butterfly_send(pgm, cmd, 4);
butterfly_recv(pgm, (char *)&m->buf[addr], blocksize);

Here when 4 command bytes have sent, it then expects to receive n amount of byte, but what exactly is the delay before it times out. It's very time consuming to read back 1 page of flash memory, and even sending back one byte to one byte basis doesn't seem to work.

[mcuee]

What if you reduce the speed?

The gain of flash writing/reading speed gets less and less from 115200bps to 250kbps to 500kbps and becomes almost non-existend at 1Mbps.

[flyandancexo]

Here is a screenshot at 2Mbps, and of course read-back failed. I want to write a better bootloader/programmer, and if I can't figure out how to get 2Mbps to readback correctly, I can't get them done. 0.6 second write speed different is significant to me.

1, I need to know the exactly delay between these 2 lines. 2, I need to know if there is something that I can do to add a delay between these 2 lines.

[MCUdude]

... But you aren't using the latest version of Avrdude! Why would we care about the 8-year-old 6.3 version? Try Avrdude 7.2. If that doesn't help, we might look at why this is...

[MCUdude]

Also, can you provide the source code for the bootloader, so it's possible to reproduce the limitation you've pointed out?

[MCUdude]

It may be related to your PC or your custom bootloader. 2M baud works fine on my Mac using the Xboot bootloader connected to an ATmega328p using a genuine FT232RL chip:

$ avrdude -cavr109 -patmega328p -b2000000 -P /dev/cu.usbserial-AH00M3HQ -Uflash:w:/Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec 
avrdude: AVR device initialized and ready to accept instructions
avrdude: device signature = 0x1e950f (probably m328p)
avrdude: Note: flash memory has been specified, an erase cycle will be performed.
         To disable this feature, specify the -D option.
avrdude: erasing chip

avrdude: processing -U flash:w:/Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec:s
avrdude: reading input file /Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec for flash
         with 16384 bytes in 1 section within [0, 0x3fff]
         using 128 pages and 0 pad bytes
avrdude: writing 16384 bytes flash ...
Writing | ################################################## | 100% 4.09 s 
avrdude: 16384 bytes of flash written
avrdude: verifying flash memory against /Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec
Reading | ################################################## | 100% 4.23 s 
avrdude: 16384 bytes of flash verified

avrdude done.  Thank you.

xboot_328p.zip

[flyandancexo]

It may be related to your PC or your custom bootloader. 2M baud works fine on my Mac using the Xboot bootloader connected to an ATmega328p using a genuine FT232RL chip:

$ avrdude -cavr109 -patmega328p -b2000000 -P /dev/cu.usbserial-AH00M3HQ -Uflash:w:/Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec 
avrdude: AVR device initialized and ready to accept instructions
avrdude: device signature = 0x1e950f (probably m328p)
avrdude: Note: flash memory has been specified, an erase cycle will be performed.
         To disable this feature, specify the -D option.
avrdude: erasing chip

avrdude: processing -U flash:w:/Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec:s
avrdude: reading input file /Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec for flash
         with 16384 bytes in 1 section within [0, 0x3fff]
         using 128 pages and 0 pad bytes
avrdude: writing 16384 bytes flash ...
Writing | ################################################## | 100% 4.09 s 
avrdude: 16384 bytes of flash written
avrdude: verifying flash memory against /Users/hans/Documents/avrdude-test-script/test_files/lorem_ipsum_16384B.srec
Reading | ################################################## | 100% 4.23 s 
avrdude: 16384 bytes of flash verified

avrdude done.  Thank you.

xboot_328p.zip

16384/4=4096. that is slow to the extreme. Here is a screen of my atmega328 upload. 2M baud works on my Atmega8 too. I know exactly why, because reading back an Atmega8 is faster than an Atmega128. It's not an issue with my CH340G chip. The bootloader is not the issue as well. If I change it to write back random data, then it read back fine, just doesn't pass verification, so instead of giving me suggestions. Why not just answer my 2 simple questions. It's probably a bug in AVRdude. The timeout delay is probably related to the baud rate, so higher 2M baud rate probably has a shorter timeout period. I am too dumb to actually understand how serial works, so I am here to ask for help.

[flyandancexo]

... But you aren't using the latest version of Avrdude! Why would we care about the 8-year-old 6.3 version? Try Avrdude 7.2. If that doesn't help, we might look at why this is...

You absolutely have to care because if this bug is in 6.3 version, then it's probably still in Avrdude 7.2. Can you provide me with that timeout period that I am asking for? Also, I have checked the source code for AVR109 on 6.3 and 7.2. Guess what? They are the same, so another reason why you should can care.

[mcuee]

@flyandancexo

Please read the following FAQ when you are reporting an issue. https://github.com/avrdudes/avrdude/wiki/FAQ#how-to-report-an-issue-to-avrdude-project

Please try out avrdude 7.2 and report the output in any case, even if you think there is no change.

[mcuee]

@flyandancexo

Another thing, the avrdude avr109 code may be for generic AVR109 bootloader. If your bootloader needs something different, you may have to raise a PR to adapt to your programmer.

BTW, where is the source code of your AVR109 implementation?

[flyandancexo]

@flyandancexo

Another thing, the avrdude avr109 code may be for generic AVR109 bootloader. If your bootloader needs something different, you may have to raise a PR to adapt to your programmer.

BTW, where is the source code of your AVR109 implementation?

Here is nothing generic about an AVR109 bootloader, but if it really requires to be labeled as generic, then it is slow, outdated and dumb. If AVR109 bootloader is half good, then I wouldn't need to write my own. AVR109 bootloader is absolutely trash in many senses, but AVR109 protocol can still be salvageable to a very useful level, and that is what FDxboot is all about.

I am struck at 1.51x because of this not able to read back at 2Mbps problem, and this can be a bug in avrdude or just bad coding on my part, so this is really a on-going project in progress, and I can't move forward unless I overcome this obstacle, as I am not the type of person whom is content at doing thing slightly above mediocre. It works perfectly fine at 1Mbps, but if it works stable at 2Mbps, then it would be absolutely perfection at 1Mbps.

If you want to test my bootloader, and help me confirm that it's working properly and have your mind blown doing so, here are few compiled v1.50 firmware. 1.50 is outdated in comparison to the optimizations done on 1.51, but it's still fast. FDxboot 1.50

[MCUdude]

Why not just answer my 2 simple questions. It's probably a bug in AVRdude.

Because I didn't write the avr109 Avrdude implementation and don't know the avr109 code that well. All I know is that the avr109 implementation works perfectly for the Catarina bootloader (Arduino Leonardo/Pro micro) and the Xboot bootloader, Even at 2Mbaud. It might not be the most efficient of them all (we have Urboot for that), but it works. And remember; if you can't or won't use Urboot, and the avr109 implementation doesn't live up to your expectations, a fix is just a PR away. It's not necessarily a bug if Avrdude is slower than expected, or that your bootloader implementation doesn't work with 2Mbaud.

butterfly_send(pgm, cmd, 4);
butterfly_recv(pgm, (char *)&m->buf[addr], blocksize);

I need to know the exactly delay between these 2 lines.

@stefanrueger please correct me if I'm wrong, but AFAIK Avrdude doesn't add a delay between these lines.

https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/butterfly.c#L77-L79

https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/libavrdude.h#L848

https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/ser_win32.c#L384-L416

https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/butterfly.c#L82-L91

https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/libavrdude.h#L849

https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/ser_win32.c#L495-L537

[stefanrueger]

It is unclear whether what you observe is a bug in avrdude: 2 Mbps UART comms requires a hardware that runs at pretty much exactly 16 MHz, it requires a host PC with a driver that can do pretty much exactly 2 Mbps and, if the USART getchar() routine in the bootloader polls (as I guess it does) it will require a pretty tight bootloader code and assiduous comms planning. Assuming a data frame of 8N1 you have 5 µs to pick up a byte sent by the host before the next byte from the host overwrites it. If the bootloader code fails to manage that, the USART will exhibit a frame error, the bootloader will miss the next host byte and, hey presto, the protocol is out of sync and eventually times out. Does FDxboot 1.51 check for comms error? It could set a board LED if it encounters one.

1, I need to know the exactly delay between these 2 lines. 2, I need to know if there is something that I can do to add a delay between these 2 lines.

The maximal delay between the following lines https://github.com/avrdudes/avrdude/blob/2f89aece1e551582223440e07e07047b526a6c25/src/butterfly.c#L660-L661 is determined by the external variable serial_recv_timeout (and probably between 100 ms and 5 s). This won't be your problem if the bootloader works at 1 Mbps. I guess the bootloader isn't quick enough to pick up the 4 command bytes sent in the first line (as discussed above).

As much as we like to help with AVRDUDE issues, we won't be able to debug fresh bootloader code for you.

Let us know if you have evidence of avrdude problems but please give us useful info.

[flyandancexo]

@mcuee I have checked out V7.2, and it still doesn't work with 2Mbps, but it's impressively faster than older version. Now my FDxboot 1.51x can upload at a speed of 126226/3.28=38483 bytes/second At 1Mbps and read back correctly, but if I can get it read back at 2Mbps, the upload speed is 59261 bytes/second, and this is a little unreal, but that is what V7.2 reported.

@MCUdude I have confirmed that the cause the problem is not from those 2 lines of code, but there could still be a bug from AVRdude, and here is my logic: The 1Mbps bootloader works on one USB port, but if plugged into another USB port, the same type of not reading back error occurs. Normally it could just be the problem for that USB port, but when writing is good, but reading is not good, this could not just be the problem of the USB port, and I have tested that USB port, it works fine on even 2Mpbs. Of course, you can then assume my bootloader is not working probably, but remember I have tested it on other USB port at 1Mbps, and it works perfectly.

@stefanrueger At 2Mbps, the time to read back a command after a page has send out is: 1/2000000(8+2+8+2+8+1)=0.0000145s or 14.5us. You forget to account for the 2-byte buffer and 1 byte shift-register. This is irreverent, but the numbers of CPU clock cycles are more important in practice. 16/2(8+2+8+2+8+1)=232 clock cycles to read back next command, and that is plenty of headroom. The cause of problem is probably from how AVRdude read back the page data. There appears to be an out of sync bug.

2Mbps still doesn't work with AVRdude 7.2, but it's upload speed has increased to 2.13 second or 126226/2.13=59261 Bytes/second. The Write is done correctly, but readback is the issue.

1Mbps screen:

[stefanrueger]

Good point about the HW FIFO buffer in the AVR part. Effectively three bytes buffer still fall short of the 4-byte command that the host sends in line 660 of avrdude/src/butterfly.c. You could try a small delay before that line to test whether the bootloader is too slow to catch the comms. And you could also test reading only -AU flash:r:myflash.hex:I. If that works, then something might happen when switching between writing and reading in one session (as in your tests).

Other than that, given that

• The AVR109 implementation is 21 years old
• @MCUdude reports that 2 Mbps work fine in his setup
• The observed behaviour is with a fresh bootloader development

where do you think we would recommend to keep looking for a solution?

[flyandancexo]

Good point about the HW FIFO buffer in the AVR part. Effectively three bytes buffer still fall short of the 4-byte command that the host sends in line 660 of avrdude/src/butterfly.c. You could try a small delay before that line to test whether the bootloader is too slow to catch the comms. And you could also test reading only -AU flash:r:myflash.hex:I. If that works, then something might happen when switching between writing and reading in one session (as in your tests).

Other than that, given that

• The AVR109 implementation is 21 years old
• @MCUdude reports that 2 Mbps work fine in his setup
• The observed behaviour is with a fresh bootloader development

where do you think we would recommend to keep looking for a solution?

Just read back doesn't work either. Here is the log for it. What the log doesn't show is how slow it's. The cause of the problem is probably how AVRdude's serial driver is not properly tuned for different USB port at high baud rate. I will try to get a new computer to see if it works or not, but either way, this should work on any USB 2.0 port. log.log

avrdude.exe: Send: A [41] . [ba] . [00] 
avrdude.exe: Recv: . [0d] 
avrdude.exe: Send: g [67] . [01] . [00] F [46] 
avrdude.exe: Recv: . [06] ? [3f] . [f6] . [cc] . [9f] . [cc] " [22] ? [3f] . [d0] . [8c] x [78] . [bd] v [76] . [b9] & [26] . [0c] h [68] . [1b] . [dd] . [8f] . [e9] . [9f] ^ [5e] . [93] . [ca] ^ [5e] Y [59] . [b7] . [b9] . [d2] . [f5] k [6b] ] [5d] k [6b] . [ca] . [fe] \ [5c] . [d3] ! [21] . [d1] . [ad] . [a6] . [f2] . [c6] . [b9] * [2a] . [ae] . [bb] n [6e] . [a8] . [f3] % [25] . [f3] . [2e] . [99] ( [28] { [7b] P [50] . [f6] . [d6] . [c1] V [56] . [17] . [fb] ~ [7e] . [a5] . [c2] . [ff] . [00] . [a4] . [c1] c [63] < [3c] . [1a] \ [5c] . [bd] . [8b] . [ad] . [1a] . [8c] . [a4] b [62] . [91] . [86] \ [5c] . [b3] . [e3] < [3c] p [70] . [fe] . [e2] W [57] . [c3] . [e1] ~ [7e] . [f2] 5 [35] . [93] . [86] y [79] > [3e] . [be] . [9c] 8 [38] . [ff] . [00] . [bb] . [9e] x [78] N [4e] . [c1] . [92] 4 [34] 7 [37] . [e4] . [19] w [77] . [9a] < [3c] . [d3] . [2e] . [a3] . [ad] y [79] N [4e] . [f3] I [49] . [d1] . [b5] i [69] , [2c] . [b4] m [6d] N [4e] K [4b] . [fd] I [49] . [ae] . [b4] . [1f] 1 [31] . [db] . [cb] . [e9] I [49] c [63] s [73] c [63] H [48] U [55] 4 [34] . [89] . [95] . [d8] . [0b] . [a7] . [92] . [8e] . [f1] o [6f] . [12] . [c7] . [fe] . [ec] 2 [32] G [47] . [a9] . [d2] { [7b] 5 [35] . [ae] . [86] < [3c] . [d1] . [9e] 9 [39] \ [5c] . [e1] . [c3] . [1e] . [13] . [8a] _ [5f] . [c7] . [1c] . [9e] . [af] . [de] . [c7] . [87] . [fb] . [be] . [1e] R [52] . [fa] . [b8] . [bf] . [87] . [86] V [56] . [cb] 4 [34] I [49] . [1b] . [fe] > [3e] I [49] F [46] . [9b] } [7d] 5 [35] . [be] . [b1] . [a7] C [43] s [73] . [a7] j [6a] . [c3] @ [40] . [d1] . [b5] . [ad] W [57] . [cc] v [76] . [b7] . [d1] . [f9] . [7f] . [cc] . [8d] y [79] q [71] . [2e] . [b0] / [2f] . [eb] o [6f] % [25] . [b1] . [d2] . [95] " [22] X [58] . [ce] . [a2] . [ff] . [00] . [bd] . [17] . [12] . [fa] . [9e] . [8a] . [fe] 
avrdude.exe: Send: A [41] . [ba] . [80] 
avrdude.exe: ser_recv(): programmer is not responding
avrdude.exe: butterfly_recv(): programmer is not responding
avrdude.exe: error: programmer did not respond to command: set addr
avrdude.exe: Send: g [67] . [01] . [00] F [46] 

Just read back failed:

Here shows that my USB port works perfectly fine at 2Mbps:

[stefanrueger]

The logs look good and initially the setup reads and compares OK. Except that at some point the host doesn't get a response from the board. So, in principle, comms seems to work, the protocol seems to work etc. Is it always at the same point at which read fails? Or do different runs break at different percentages of reading back?

How much current does your board draw? How good is your connecting cable? Perhaps the setup is at the edge of what the USB port can cope with? Have you measured the voltage of your board/processor? Is it well above what the brownout fuse setting sees? It is not a good sign that sometimes you have to switch to a different USB port: in theory the port shouldn't matter as it's a bus, but it could matter that some ports can drive more current than others or have slightly higher voltage etc. Ripple voltages and other hardware effects show more at higher speed.

how slow it is

It shouldn't: once the recv() function has gotten all the bytes it requests it returns. If not it waits until it times out. Look at the ser_win32.c implementation of the ser_recv() function as pointed out by @MCUdude to check whether all is how it should be.

[flyandancexo]

The logs look good and initially the setup reads and compares OK. Except that at some point the host doesn't get a response from the board. So, in principle, comms seems to work, the protocol seems to work etc. Is it always at the same point at which read fails? Or do different runs break at different percentages of reading back?

How much current does your board draw? How good is your connecting cable? Perhaps the setup is at the edge of what the USB port can cope with? Have you measured the voltage of your board/processor? Is it well above what the brownout fuse setting sees? It is not a good sign that sometimes you have to switch to a different USB port: in theory the port shouldn't matter as it's a bus, but it could matter that some ports can drive more current than others or have slightly higher voltage etc. Ripple voltages and other hardware effects show more at higher speed.

how slow it is

It shouldn't: once the recv() function has gotten all the bytes it requests it returns. If not it waits until it times out. Look at the ser_win32.c implementation of the ser_recv() function as pointed out by @MCUdude to check whether all is how it should be.

It's the lack of clarity that is stopping me from moving forward. My hardware should be fine, so as my bootloader. I am expert in Atmega128. Here is the setup using my Mega pro board.

The log looks good, but it's not good. It's too slow for it to be consider good even if it's really good, and I am not sure if it's really good, so here I try to rewrite the block send back code and try to spoof the AVRdude a bit, and I instantly have some clarity....

// ####################################################################
// Start Block Flash Read
// Expect to receive 3 bytes and send back requested data
// void BlockRead(uint16_t Blocksize, uint8_t memtype, uint16_t address);
case 'g':
  readSize =(serialRead()<<8) | serialRead();
  dummyByte = serialRead();  // Discard: receive memory type: 'F' or 'E'

  serialWrite( readSize>>8 );
  serialWrite( 0xff&readSize );
  readSize =readSize-2;
  for (uint16_t i=0; i<(readSize); i++ ){
    serialWrite( (uint8_t)i );
  }
break;

Here is the returned log in image. You can see that AVRdude failed to receive one byte from previous block, and that could be the reason or the bug: AVRdude is probably not optimized to receive at fast rate. It has no problem sending at 2Mbps because sending data is easier than receiving. Of course this is only my guess. At 2Mbps, AVRdude is responding so slow that this log is probably not valid, and even if AVRdude failed to receive one byte, my bootloader should still be able to respond with an new address request.

Here is the actual log for 2M: log2M.log

To make sure my code is fine, I have a 1M log too, this 1M log has been done very fast, and error free: log1M.log

[stefanrueger]

hardware should be fine

1. Have you looked at the TX/RX signal with an oscilloscope? Or the USB signal that enters the PC? Is that sharp and well-defined?

my USB port works perfectly fine at 2Mbps

2. Have you written a sketch for your board that sends a sustained known data stream ("The quick brown fox ..." or similar) without delays between characters and used some software on the PC to receive it? Does the full stream arrive OK all the time?

3. Have you used a C-program that is based on the AVRDUDE ser_recv() to read above full stream? Does that read OK all the time?

If the answers to 1 and 2 are yes and to 3 is no then you may have a case.

Note that sometimes the -vvvv log interferes with the timing of AVRDUDE, so it's not always a great tool to find problems at high speed.

[flyandancexo]

hardware should be fine

1. Have you looked at the TX/RX signal with an oscilloscope? Or the USB signal that enters the PC? Is that sharp and well-defined?

my USB port works perfectly fine at 2Mbps

2. Have you written a sketch for your board that sends a sustained known data stream ("The quick brown fox ..." or similar) without delays between characters and used some software on the PC to receive it? Does the full stream arrive OK all the time?
3. Have you used a C-program that is based on the AVRDUDE ser_recv() to read above full stream? Does that read OK all the time?

If the answers to 1 and 2 are yes and to 3 is no then you may have a case.

Note that sometimes the -vvvv log interferes with the timing of AVRDUDE, so it's not always a great tool to find problems at high speed.

Asking the correct question could be the key to solve this bug. 1, why is avrdude responding that slow at 2Mbps? what could possibly caused it to slow down? 2, more importantly how even after it has been freezing that long and still managed to receive that many pages without errors?

Here I added another option to send back 1000 bytes, and 1000 bytes are received fine. PS. this is tested on my slower USB 2.0 port hub. The hardware seems perfectly fine. If I take a look at RX and TX pin, it's probably the same as shown in the log file. I did an observation of -v -v -v -v at real time, and AVRdude is randomly paused at g 00 00 00, so the block command has been sent, but it's not receiving back the block data. Can you provide me a AVRDUDE ser_recv() for me to test it out? I don't think this is the cause of the bug.

The same bootloader and hardware at 1Mbps work fine on my USB 3.0 hub, but not on this USB 2.0 hub. By not working, it's just read back that is not reliable. The upload is fine.

case 'Z':
  for (uint16_t i=0; i<1000; i++ ){
    serialWrite( (uint8_t)0xff&i );
  }
break;

[mcuee]

Move this to discussion as it is not confirmed to be an avrdude issue.