MSP430FR5964: Console printf's appear to trip up EUSCI interrupt handling

Now I have it a bit more isolated, I've had more of a play.

First up, changed the EUSCI that was being used from 0 to 3 - no change.

Then tried varying the size of the printf message. A single non \n character works fine, but I suspect this is not actually being transmitted via the JTAG until the next \n is sent. A single \n is enough to cause the problem.

Hi Andrew，

You uesed library printf function directly?

Have you add some remaping code?

Thanks!

Best Regards

Johnson

Hi Johnson

Originally there was some extra code in the way, but I've now reduced it purely to raw printf calls. I've also had a play with both the standard fully bloated printf, and the -mtiny-printf option, and while these do behave differently, I think this is simply due to the more limited buffering in the tiny option. 

With the standard printf, if I call this without terminating the output string (a \n), the problem does not occur, presumably because the actual transmission of the formatted printf string to the console does not happen until a line terminator is subsequently sent. You can see this quite clearly in the console output - nothing appears until I printf a terminator following the successful reception of all the uart traffic. Executing the same logic after building with the tiny option, the unterminated string is transmitted immediately to the console, and the overrun error is picked up by the uart.

Something weird I have seen with the tiny option, is that if I just printf a single non terminator character, nothing is transmitted to the console. A single terminator is though?

Everything seems to point to the actual transmission of the data to the console as triggering the problems, rather than any formatting or buffering printf is doing prior to this. I'm unsure where in the gcc toolchain this is implemented, other than I guess it has to be part of the CCS suite rather than pure mspgcc. In the TI case it looks like __TI_printfi does the actual transmission, and this is jacketed by __TI_file_lock and unlock to manage access to stdout. I haven't (yet!) found any equivalent in the GCC toolchain.

Andrew

Hi Andrew,

I am not familar with default printf function, but you can try this example for printf:

#include <stdio.h>
#include <string.h>

#define UART_PRINTF

#ifdef UART_PRINTF
int fputc(int _c, register FILE *_fp);
int fputs(const char *_ptr, register FILE *_fp);
#endif

Main()
{
         ……………
}

#ifdef UART_PRINTF
int fputc(int _c, register FILE *_fp)
{
        while(!(UCA0IFG&UCTXIFG));
        UCA0TXBUF = (unsigned char) _c;

        return((unsigned char)_c);
}

int fputs(const char *_ptr, register FILE *_fp)
{
        unsigned int i, len;

        len = strlen(_ptr);

        for(i=0 ; i<len ; i++)
        {
                while(!(UCA0IFG&UCTXIFG));
                UCA0TXBUF = (unsigned char) _ptr[i];
        }

        return len;
}
#endif

Thanks!

Best Regards

Johnson

Hi Johnson,

Thanks for the suggestion. If I understand your intent correctly, the idea is to hijack the default puts and putc from underneath printf, and vector these off to somewhere they won't cause any damage. I'd then need some other independent logger outboard of the uart to capture and report these. Not quite as elegant as vectoring these via the JTAG to the console, but if I can't make that work it would definitely be an acceptable alternative.

If I'm missing something here, let me know! I normally just use these as black boxes without delving under the hood.

Andrew

Hi Andrew,

Could you shre your code about this?

Thanks!

Best Regards

Johnson

I've already pared a lot of the code back, but over the next couple of days I'll reduce it to something simple which will (hopefully!) demonstrate the problem. 

Hi Andrew,

After reduced your code to demonstrate this issue, please help to upload your code here, I can debug your code in my side.

Thanks!

Best Regards

Johnson

Finally found a bit of time to reduce this to something simple, and the problem is still exhibited ( I had a horrible feeling that it might be more timing related, and the simpler code would work fine!).

// Bit of logic preceding this to set up the MSP

    GPIO_setAsPeripheralModuleFunctionOutputPin (
            GPIO_PORT_P2,
            (BIT0 | BIT1),
            GPIO_SECONDARY_MODULE_FUNCTION);

    // Configure UART for 9600 baud
    EUSCI_A_UART_initParam param = {0};
    param.selectClockSource = EUSCI_A_UART_CLOCKSOURCE_ACLK;
    param.clockPrescalar = 3;
    param.firstModReg = 0;
    param.secondModReg = 146;
    param.parity = EUSCI_A_UART_NO_PARITY;
    param.msborLsbFirst = EUSCI_A_UART_LSB_FIRST;
    param.numberofStopBits = EUSCI_A_UART_ONE_STOP_BIT;
    param.uartMode = EUSCI_A_UART_MODE;
    param.overSampling = 0;

    // Configure the port
    status = EUSCI_A_UART_init(EUSCI_A0_BASE, &param);
    EUSCI_A_UART_enable(EUSCI_A0_BASE);
    EUSCI_A_UART_enableInterrupt(EUSCI_A0_BASE,
                                 EUSCI_A_UART_RECEIVE_INTERRUPT);

    context.count = 0;
    context.uartStatus = 0;
    loop = true;

    printf ("Started\n");
    while (loop) {
        // Wait for something to happen
        _low_power_mode_0 ();
        if (context.uartStatus != 0) {        // Overrun error
            printf ("Overrun!\n");
        } else if (context.count == 3) {    // First 3 bytes successfully received
            // This is the critical printf - if it's included, the message is
            // output, but the uart immediately overruns. If its commented out
            // it all works fine
            printf ("First 3 bytes received\n");
        } else {                            // 10 bytes received
            printf ("%d bytes successfully received - exiting\n", context.count);
            loop = false;
        }
    }

    while (1) {
        catch = context.count;      // Somewhere to breakpoint
    }        // Loop forever

    return (0);
}

void __attribute__ ((interrupt (EUSCI_A0_VECTOR))) EUSCI_A0_ServiceRoutine (void) {
    uint8_t nextByte;
    bool activateMainline;

    activateMainline = false;
    nextByte = HWREG8 (EUSCI_A0_BASE + OFS_UCAxRXBUF);

    // Check for any errors
    context.uartStatus = HWREG8 (EUSCI_A0_BASE + OFS_UCAxSTATW)
                         & (UCFE | UCOE | UCPE | UCBRK);
    if (context.uartStatus) {
        activateMainline = true;
    } else {
        context.count++;
        context.byte[context.count] = nextByte;
        if (context.count == 3 || context.count == 10) {
            activateMainline = true;
        }
    }

    if (activateMainline) {
        __low_power_mode_off_on_exit();
    }

    return;
}

I'm using EUSCI A0 on the 5964, but from the earlier play with the full code base, it seems irrelevant which USCI is actually used. The UART is configured for 9600 baud, MSP at 16 MHz. I haven't used the same device to generate the input stream, because there is some likelihood that the issue would impact the TX side as well, and it it suppressed this, it might never show the overrun on he RX. On the particular board I'm using, EUSCI A0 is connected to a serial Bluetooth module, so I've used that to inject the input stream.

The code is quite simple.

The interrupt handler just sits and collects incoming byes into a buffer (context.byte[]), and an ongoing count. After the first 3 bytes are received, it reactivates the mainline (this guarantees it's in the middle of an incoming byte stream). If the mainline executes a printf at this point, the next thing the interrupt handler will see is an overrun. If the mainline doesn't execute this printf, everything works fine, and the next mainline activation with be to advise the end of the incoming stream (arbitrarily set at 10 bytes).

This isn't behaving itself completely though. If the interrupt handler detects an overrun, it should also reactivate the mainline and printf an Overrun message, but this isn't happening!. I can follow the overrun detection through to the __low_power_mode_off_on_exit();, but this never reactivates the mainline. Haven't a clue why, and haven't tried delving deeper into this (I have my suspicions).

Andrew

A bit more behind the scenes investigation;

First up, the lack of reporting the overrun makes total sense - this is being generated while the printf in still in progress, so the mainline activation simply returns to that, it completes, and puts the MSP back to sleep. If the test and report of overrun is done immediately the problem printf is completed, the overrun has already been detected at this point.

To try and get some idea what is happening behind the scenes, I've set a timer block running in continuous mode, and logged the ticks on each activation of the RX handler. 9600 baud should give around a byte per mS, so set the timer block to source off ACLK /8, which gives around 244 uS per tick. I'd expect around 4 to 5 ticks per byte, but was expecting to see a major jump when the printf was executed, and the overrun was detected (anything much over 8 ticks should be pushing us into overrun territory) - this was based on my expectation that the printf was somehow suppressing the EUSCI interrupts.

With no printf in the middle of the stream, the ticks came in pretty much as expected;

4,5,4,4,4,5,4,4,4    - roughly 1 mS/byte as expected

However, the situation with the printf active was not expected. This gave the following for the first 3 bytes followed by the overrun (we are only measuring the intervals, so the first 2 are the 1-2, and 2-3 intervals, the third the 3-overrun)

4,5,0

So what gives here! It appears that either the timer has been stopped, or the 'overrun' happens immediately the printf commences. The timer is just maintaining the timer block in the background, and should be totally independent of any playing with interrupts that printf might do. From looking at the timer registers when the overrun occurs, it still looks totally active (MC is still set to continuous - I don't believe there is any other way of stopping it?).

Next step was to have a good look at the incoming data being logged - as this is from a known source and structure, it's totally deterministic and repeatable. Even though I'd ignored it previously, the 4th byte should have been captured and buffered correctly by the Uart, and the overrun triggered by the incoming 5th byte (with the RX buffer full and unread, the EUSCI has nowhere to write the 5th byte, hence the overrun).

The expected sequence of bytes (and what is captured by the no-printf logic), is;

255, 2, 30, 1, 32, 185, ...

With the printf in place, the captured data is

255, 2, 30, 3

More head scratching. The overrun (and have verified its really the OE flag that is set) doesn't really make sense - I would have expected the RX buffer to have the 1 buffered. But if the timer is still active, and if this is correct, there would not have been enough time for even the 4th byte to have been transmitted, let alone a 5th byte to trigger the overrun. Haven't any idea where the buffered 3 came from, but it is repeatable.

At this point I'm unsure what else I can check. For posterity, I'll include the latest variant of my test logic here;

Andrew

    GPIO_setAsPeripheralModuleFunctionOutputPin (
            GPIO_PORT_P2,
            (BIT0 | BIT1),
            GPIO_SECONDARY_MODULE_FUNCTION);

    // Configure UART for 9600 baud
    EUSCI_A_UART_initParam param = {0};
    param.selectClockSource = EUSCI_A_UART_CLOCKSOURCE_ACLK;
    param.clockPrescalar = 3;
    param.firstModReg = 0;
    param.secondModReg = 146;
    param.parity = EUSCI_A_UART_NO_PARITY;
    param.msborLsbFirst = EUSCI_A_UART_LSB_FIRST;
    param.numberofStopBits = EUSCI_A_UART_ONE_STOP_BIT;
    param.uartMode = EUSCI_A_UART_MODE;
    param.overSampling = 0;

    // Configure the port using DriverLib. It returns true on failure.
    status = EUSCI_A_UART_init(EUSCI_A0_BASE, &param);
    EUSCI_A_UART_enable(EUSCI_A0_BASE);
    EUSCI_A_UART_enableInterrupt(EUSCI_A0_BASE,
                                 EUSCI_A_UART_RECEIVE_INTERRUPT);

    // Set up TIMERA to run continuously, at a tick interval of approx 244 uS
    Timer_A_initContinuousModeParam paramT = {0};
    paramT.clockSource = TIMER_A_CLOCKSOURCE_ACLK;
    paramT.clockSourceDivider = TIMER_A_CLOCKSOURCE_DIVIDER_8;
    paramT.timerInterruptEnable_TAIE = TIMER_A_TAIE_INTERRUPT_DISABLE;
    paramT.timerClear = TIMER_A_DO_CLEAR;
    paramT.startTimer = true;
    Timer_A_initContinuousMode (TA0_BASE, &paramT);
    Timer_A_startCounter(TA0_BASE, TIMER_A_CONTINUOUS_MODE);

    context.count = 0;
    context.uartStatus = 0;
    loop = true;

    printf ("Started\n");
    while (loop) {
        // Wait for something to happen
        _low_power_mode_0 ();
        if (context.uartStatus != 0) {        // Overrun error
            printf ("Overrun!\n");
            loop = false;
        } else if (context.count == 3) {    // First 3 bytes successfully received
            // This is the critical printf - if it's included, the message is
            // output, but the uart immediately overruns. If its commented out
            // it all works fine
            printf ("First 3 bytes received\n");
            if (context.uartStatus != 0) {        // Overrun error while doing printf
                printf ("Overrun!\n");
                loop = false;
            }
        } else {                            // 10 bytes received
            printf ("%d bytes successfully received - exiting\n", context.count);
            loop = false;
        }
    }

    while (1) {
    }        // Loop forever

    return (0);
}

void __attribute__ ((interrupt (EUSCI_A0_VECTOR))) EUSCI_A0_ServiceRoutine (void) {
    uint8_t nextByte;

    context.bytes[context.count] = HWREG8 (EUSCI_A0_BASE + OFS_UCAxRXBUF);
    context.timerTicks[context.count] = Timer_A_getCounterValue (TA0_BASE);

    // Check for any errors
    context.uartStatus = HWREG16 (EUSCI_A0_BASE + OFS_UCAxSTATW)
                         & (UCFE | UCOE | UCPE | UCBRK);
    if (context.uartStatus) {
        __low_power_mode_off_on_exit();
    } else {
        context.count++;
       if (context.count == 3 || context.count == 10) {
           __low_power_mode_off_on_exit();
        }
    }

    return;
}

Hi Andrew,

Let me try to understand your debug information & result.

Thanks!

Best Regards

Johnson

I just found the following at https://43oh.com/2015/05/how-to-add-printf-support-for-the-msp432-launchpad-serial-port/ which, if true, would help explain what's happening;

If you use printf() in your code without setting it up for channeling it through the UART, the strings will be viewable on the debug console of the IDE.  The way this works is that the compiler/debugger adds a breakpoint right after the code converting the strings finishes, and then pull the strings out the memory via JTAG and displays it on the console.

If the whole mechanism is depending on a breakpoint being executed behind the scenes while the console message is being retrieved from memory, this will definitely halt the processor clocks, which would affect both my background timer (will be stopped), plus the ability of any of the ISR's to trigger. In fact, anything that has a timing constraint will be potentially impacted while the retrieval part of the printf is executing.

This is a real pity, as I was hoping this printf would allow me to leave the code executing through some timing critical sections but still leave a trace for subsequent debugging. This leaves me back at your earlier suggestion - revector puts() to output via a uart, and capture this externally to the IDE. Not quite as convenient, but should allow the target processor to continue without interruption.

This is the only comment I've found which gives any clue of the printf implementation. I've got no basis to question its validity, other than it seems to explain  the scenario I am seeing. Anyone else have any insight to printf implementation?

Andrew

Now that I have a bit of a clue what I'm searching for, I've found other TI references to CIO functions using a breakpoint behind the scenes, such as this one from slau157as (CCS users guide for V10.x)

Console I/O (CIO) functions, such as printf, require the use of a breakpoint. If these functions are compiled in, but you do not wish to use a breakpoint, disable CIO functionality by changing the option in Project → Properties → Debug → Program/Memory Load Options → Program/Memory Load Options → Enable CIO function use (requires setting a breakpoint).

Hi Andrew,

Sorry for this thread, I am in business travle this week, I can try this question next week when I get back to office,

Thanks!

Best Regards

Johnson

Hi Andrew,

I agree the point:

Andrew McLaren said:

If you use printf() in your code without setting it up for channeling it through the UART, the strings will be viewable on the debug console of the IDE.  The way this works is that the compiler/debugger adds a breakpoint right after the code converting the strings finishes, and then pull the strings out the memory via JTAG and displays it on the console.

 If you use this printf function, maybe will add some break point in your code.

Thanks!

Best Regards

Johnson