Serial Port Debugging

Today I'm trying to use the AVR serial port on a custom ATMEGA328 board.

TL;DR

• Know your fuse settings! Incorrect settings can result in timing problems, including incorrect UART baud rates.
• RS232 Serial port UART decoding using Rigol DS1054z Oscilloscope
• How to fix bad baud rate timing with software.
• Programming AVR devices from Atmel Studio and Arduino IDE with Atmel ICE

Try as I might, I simply could not get it to work properly. The LED on the USB/TTL adapter would blink during data transfer, but no data shows up in Putty from the AVR.

After exhausting all obvious possibilities, it was time to get serious about looking at what's going on. Rigol oscilloscope debugging to the rescue!

I had not performed any signal decoding any time recently and needed to refresh my memory.  I tried reading the fine manual, but alas still could not get it to work quite the way I wanted. I found this really quite excellent YouTube video. (I have the DS1054z, but close enough)




In short, the most important thing is that the oscilloscope needs to be "zoomed out" (horizontal scale) when doing single trigger. The full capture is apparently the scale of the visible screen. I might have implemented that a bit differently but it is ok once understood.

Trigger: Menu Button (CH1, falling edge, single sweep). Adjust trigger level to halfway point, in my case 1.6V.

Decode: Math Button, (Decode 1, Decoder = RS232, Decode ON, Tx = CH1, Baud Rate, etc)

First, an example of a properly working H (from "Hello World") as sent by Putty:

Fairly straightforward serial port setup: 9600 8N1. I connected my oscilloscope probe to GND and Tx of a typical USB TTL adapter. Pressing the "H" on the keyboard when Putty has focus, sends a nice, clean RS232 digital sequence to the TTL adapter as shown:

Reminder that UART/TTL RS232 idle is normally high, transmission begins with low start bit, then (in our case) 8 data bits, least-significant-bit (LSB) first, then followed by stop bit (aka mark) which is high.

Note the scale here is 500 μs (0.5 ms) per division. We're seeing about 100 μs per bit. Actually at 9,600 baud, the expected time per bit is (1 bit / (9600 bits / sec)) = 0.0001041667 seconds or about 104 μs per bit.

The ASCII value of "H" is 72 = = 0x4c = = 0b01001000

Indeed we see about 400 μs of zero (1 start bit, and then 3 LSB's of the "H"), a one, 2 more zeros, followed by a one, zero, then return to high for stop.

So ok, the TTL adapter is working. Actually, I already knew that, as I used it to login to the serial port of my Raspberry Pi just to confirm. Ok, so that's the easy one. Now on to the data coming from the AVR. Much more interesting:

Here's the source code in Atmel Studio. Also pretty straightforward:

Here too, 9600, (default 8N1). But with a much different result:

The first curious thing I observed was that the delay(milliseconds) function was off by an order of 16 (as measured by eye).  Note the scale here is 5mS per division; 10x slower that the trace above!

A coding delay(1000) actually waited for approximately 16 seconds. So the first thing I thought was perhaps the timescale was simply off, so I tried scaling the baud rate by 16. No luck.

Ok, this certainly explains why nothing is showing up in putty! First: notice there seems to be a duplicate character! (there's no echo; nothing connected to the Tx pin other than the oscilloscope probe) Next: notice the scale on the properly decoded character above on CH2 is 500 μs/div.  The scale on this AVR data is 5 ms/div.  The first low pulse on CH1 is 400 μs, but on CH2 more like nearly 7 ms (7,000 μs!)

Quick note on the math, assuming we're really off by exactly 16x:

400 μs * 16 = 6400 (or 6.4 ms); more precisely (4 * 104.17) * 16 = 6,666.67 μs (or 6.67 ms)

Unfortunately 9600 * 16 =  153,600 is not a valid baud rate. However 2400 * 16 = 38,400 baud is!

So I tried changing the source code to send a character at 2400 * 16 baud (38,400). However it too could not be decoded.

The AVR serial port does indeed look like it is approximately 16x slower. Zooming in on that first low pulse to confirm:

It appears that that first 4 bit pulse is actually 6.3 ms long. Interestingly it is not 6.4 ms (or more precisely not 6.67 ms). That makes a difference of  (6,300 μS / (4 * 100 μS) = 15.75x, not the nice round 16.  More precisely: (6,300 μS / (4 * 104.17 μS) = 15.12x.

So ok, the good old Microsoft Paint program (glad to hear it will not be retired!)... a quick copy / paste / scale of the non-working (10x scale; recall 500μs/dev vs 5ms/div ) waveform on top of the properly decoded signal shows we're not going to get from here to there with a simple baud rate scale. The data is not just duplicated at the wrong speed, something weird is going on with a lot more data than just a single character:

So it would seem my AVR is not going to be doing any useful Serial Port Communication anytime soon. Perhaps there's something weird going on in Atmel Studio. But of all the people that would know how to properly program an ATMEGA328, one would think it would be the ones that built Atmel Studio, eh? Time to go back to bed, just in time for the sunrise.

UPDATE: Ok, so after getting some sleep I thought more about this problem. I was wrong about the math! I needed a target that is 15.75 (more precisely 15.12) times faster than the oscilloscope is capturing. So I simply scaled the baud rate in the app:

And setting the decode frequency to the un-scaled value... TADA! Perfectly decoded. <Happy dance>.

I've kept the estimated and precise numbers above, as the initial estimate of 15.75x worked, even though 15.12x is the more precise answer. Somewhere buried in the RS232/UART spec is probably a timing tolerance range.

Oh and look at that "extra" data: I'm doing a Serial.println() that includes extra carriage return and line feed chars! <sigh>

Here's a lesson I've repeatedly learned: walking away from a problem can sometimes solve it ten times faster as compared to attempting to brute-force it non-stop. (particularly at 4:00 in the morning, time change day)

Still it is curious that I needed to scale the baud rate by an odd value of 15.75 (?)

So a little bit of googling (ok, imagine being an embedded programmer before the internet, say in the 80's. crazy)... I found this YouTube video on ISP programming problems due to wrong clock frequency:



But that's not really my problem - as I can program it using ISP or debugWIRE, but the clock is still wrong by a factor of 15.12x.

There's still the ISP Clock Frequency setting in Atmel Studio:

But that's just the clock speed at which the ISP is doing the programming; this is not the clock speed of the processor. Eventually I found this interesting clip (starting at about the 1:50 mark):



This does seem like a reasonable solution. Perhaps I should have known there's a frequency setting. How else would the code "know" how long a millisecond is?

But I've never needed to manually set the processor speed ever before and never had any serial problem quite like this. In any case - first time for everything. So I tried values of 16000000UL and 1600000UL, and others. No values of #define F_CPU seemed to help. Ok, at this point I'm glad it was not something so obvious.

I'm think it might be something with the fuse settings, but even with the online fuse calculator, nothing jumps out as the obvious answer.

Stay tuned for an update if I figure this one out. In the meantime to set a baud rate, I'll simply multiple by 15.12 (certainly makes for some not-very-portable code  :|  meh)

/*Begining of Auto generated code by Atmel studio */
#include 
/*End of auto generated code by Atmel studio */

#define  F_CPU 16000000UL # does this actually do anything?

//Beginning of Auto generated function prototypes by Atmel Studio
//End of Auto generated function prototypes by Atmel Studio

void setup() {
  // put your setup code here, to run once:
  //pinMode(2, OUTPUT);
  delay(100);
  Serial.begin(2400 * 15.12); // originally estimated at 15.75
}

void loop() {
  // put your main code here, to run repeatedly:
  Serial.println("H");       // Hello World. (just the "H" to keep things simple)
  //digitalWrite(2, HIGH);   // turn the LED on (HIGH is the voltage level)
  //delay(10);               // wait  
  //digitalWrite(2, LOW);    // turn the LED off by making the voltage LOW
  delay(200);                // wait  HH
}

I've posted my entire Atmel Studio Solution here. (note that it is in the M5-RadioHead branch of my LoRa-GPIO project)

Thanks to this post on the AVR Freaks forum, I did find this setting in Atmel Studio for F_CPU:

Although this certainly does not clarify why the problems exists in the first place. Perhaps if I had found the value something like 1,058,236 here, it would have been more of an AHA moment.  (1.0582 * 15.1195 = 16).  At this point I am thinking perhaps all this may be caused by a bad crystal oscillator. (?)

It was suggested that I use the Arduino IDE to program the M5Stack AVR chip instead of Atmel Studio. I found this forum thread that has the solution for using the Atmel ICE with the Arduino IDE. In particular, the input device, data gateway, and composite devices with hex Id's: 03EB and 2141 need to be selected with the install-filter-win.exe tool:

The Arduino IDE uses avrdude to program the ATmega328; the resultant output looks like this:

avrdude: Version 6.3, compiled on Jan 17 2017 at 12:00:53
         Copyright (c) 2000-2005 Brian Dean, http://www.bdmicro.com/
         Copyright (c) 2007-2014 Joerg Wunsch

         System wide configuration file is "C:\Users\gojimmypi\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino9/etc/avrdude.conf"

         Using Port                    : usb
         Using Programmer              : atmelice_isp
avrdude: usbdev_open(): Found Atmel-ICE CMSIS-DAP, serno: J4180007xxxx
avrdude: Found CMSIS-DAP compliant device, using EDBG protocol
         AVR Part                      : ATmega328P
         Chip Erase delay              : 9000 us
         PAGEL                         : PD7
         BS2                           : PC2
         RESET disposition             : dedicated
         RETRY pulse                   : SCK
         serial program mode           : yes
         parallel program mode         : yes
         Timeout                       : 200
         StabDelay                     : 100
         CmdexeDelay                   : 25
         SyncLoops                     : 32
         ByteDelay                     : 0
         PollIndex                     : 3
         PollValue                     : 0x53
         Memory Detail                 :

                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           eeprom        65    20     4    0 no       1024    4      0  3600  3600 0xff 0xff
           flash         65     6   128    0 yes     32768  128    256  4500  4500 0xff 0xff
           lfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           hfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           efuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           lock           0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           calibration    0     0     0    0 no          1    0      0     0     0 0x00 0x00
           signature      0     0     0    0 no          3    0      0     0     0 0x00 0x00

         Programmer Type : JTAG3_ISP
         Description     : Atmel-ICE (ARM/AVR) in ISP mode
         Vtarget         : 3.3 V
         SCK period      : 125.00 us

avrdude: AVR device initialized and ready to accept instructions

Reading | ################################################## | 100% 0.02s

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: reading input file "C:\Users\GOJIMM~1\AppData\Local\Temp\arduino_build_159166/M5Stack_LoRa_AVR.ino.ino.hex"
avrdude: writing flash (1694 bytes):

Writing | ################################################## | 100% 6.94s

avrdude: 1694 bytes of flash written
avrdude: verifying flash memory against C:\Users\GOJIMM~1\AppData\Local\Temp\arduino_build_159166/M5Stack_LoRa_AVR.ino.ino.hex:
avrdude: load data flash data from input file C:\Users\GOJIMM~1\AppData\Local\Temp\arduino_build_159166/M5Stack_LoRa_AVR.ino.ino.hex:
avrdude: input file C:\Users\GOJIMM~1\AppData\Local\Temp\arduino_build_159166/M5Stack_LoRa_AVR.ino.ino.hex contains 1694 bytes
avrdude: reading on-chip flash data:

Reading | ################################################## | 100% 7.33s

avrdude: verifying ...
avrdude: 1694 bytes of flash verified

avrdude done.  Thank you.

However I had the same result in needing the baud rate to be scaled by 15x in order for it to work properly. So this was still not the solution.

Many thanks to Jimmy Lai at M5Stack for sending me fuse selection setting pics (there are many settings to choose from!):

In the second and third pic, it is important to note that the DIVCK8 needs to be left unchecked, despite the value here showing 4E in that first pic. The desired values are: CE D9 FF

My fuse settings before:

Notice LOW.SUT_CKSEL! It is set to an internal clock! There's actually an external clock on the board:

Ok, one would think that even with an external clock, if the fuse settings say to use an internal clock - and this is in fact the default value, that it would work properly with the ATmega328p, eh? Apparently not. As seen above, the clock was wildly off.

When changing the fuses, there's a nice indication of what has been changed, but not written to the chip:

When pressing the Program button, there's a warning that if you don't know what you are doing, you might brick the target:

Braving the ominous warning dialog box... My final fuses look like this:

TADA! <big Happy Dance> Serial.println("Hello world") at 2400 baud actually streams out the UART at 2400 baud. Go figure. This was a tremendous amount of time spent on a couple of fuse bit settings. However it was also an awesome learning opportunity.

More coming soon.... now to get those RadioHead drivers onto the AVR...


Resources, Inspiration, Credits, and Other Links::

• Twelve tips for using the Rigol DS1052E Oscilloscope
• Arduino time keeping using millis() is not accurate or correct?
• Debugging AVR Applications with Atmel Studio (YouTube) 
• Atmel: megaAVR Clock Sources and Potential Errors (YouTube)
• How to Use Crystal Oscillators and Write the Fuse Bits to the AVR MCU (YouTube)
• NefitSerial.cpp - Hardware serial library for Wiring
• Fuse Calc
• DS1000z I2C Decoding and Triggering (covers DS1054Z, DS1074Z, DS1100Z, MSO1074Z, MSO1104Z)
• Rigol MSO1000Z/DS1000Z Series Digital Oscilloscope User Guide