Optimization crazyness (H733, STM32CubeIDE 1.10.1)

[LCE]

Heyho,

I had some really strange error, which went away when turning optimization from "fast" to "off".

The function EthPhyInit() always returned 166 = 0xA6 - it should return "HAL_StatusTypeDef", something between 0 .. 3.

So I changed all the return values to some integer between 1..8 to find out where things go wrong, then added the last line:

uart_printf("EthPhyInit() good ->return 0\n\r");

before returning 0 when all went well.
Still, always got 166 back, even when I got "EthPhyInit() good ->return 0\n\r" on the terminal.

Until I turned optimization OFF, now all is good.

WTF is happening there? Can optimization be that bad?

 

/* +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ */
 /**
 * @brief all PHY, ETH MAC & DMA reset and init:
 *			1) EthBaseInit()	GPIO, clocks, basic stuff
 *			2) EthPhyInit()		PHY
 *			3) EthMacInit()		MAC registers
 *			4) EthDmaInit()		DMA registers
 * @PAram -
 * @retval HAL status
 */
uint8_t EthAllInit(uint8_t u8SkipBase)
{
	static uint32_t u32CallCount = 0;
	uint8_t u8RetInit = 0xFF;

	u32CallCount++;

/* ++++++++++++++++++++++++++++++++++++++++++++++++++++++ */
/* base init */
	if( 0 == u8SkipBase )
	{
		u8RetInit = EthBaseInit();
		if( u8RetInit != HAL_OK )
		{
			#if( 1 )	// DEBUG_ETHNETIF
				uart_printf(SZC_TEXT_ERR "EthBaseInit() = %u\n\r", u8RetInit);
			#endif 	/* DEBUG_ETHNETIF */

			return u8RetInit;
		}
	}

/* ++++++++++++++++++++++++++++++++++++++++++++++++++++++ */
/* PHY initialization and configuration */
	u8RetInit = EthPhyInit();
	if( u8RetInit != HAL_OK )
	{
		#if( 1 )	// DEBUG_ETHNETIF
			uart_printf(SZC_TEXT_ERR "EthPhyInit() = %u\n\r", u8RetInit);	// ##### <- always 166 = 0xA6
			uart_printf("u32CallCount = %lu\n\r", u32CallCount);
		#endif 	/* DEBUG_ETHNETIF */

		/* do NOT return error
		 *	-> to NOT block other inits
		 */
		//return u8RetInit;
	}

/* ++++++++++++++++++++++++++++++++++++++++++++++++++++++ */
/* MACCR: more MAC registers */
	u8RetInit = EthMacInit();

...

	return u8RetInit;
}


/* +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++*/
 /**
 * @brief ETH PHY initialization and configuration
 * @PAram 	none
 * @retval HAL status
 */
uint8_t EthPhyInit(void)
{
	/* KSZ8863RLL dual port PHY */

	/* wait after reset */
	HAL_Delay(50);

/* ++++++++++++++++++++++++++++++++++++++++++++++++ */
	if( EthPhyKszAlive() != HAL_OK )
	{
uart_printf(SZC_TEXT_ERR "EthPhyInit() 1\n\r");
		return 1U;	//HAL_ERROR;
	}

	/* ++++++++++++++++++++++++++++++++++++++++++++++++ */
	#if DEBUG_ETHNETIF
		uart_printf("PHY KSZ set RMII clock to internal...\n\r");
	#endif 	/* DEBUG_ETHNETIF */

	if( EthPhyKszClockSource(1) != HAL_OK )
	{
uart_printf(SZC_TEXT_ERR "EthPhyInit() 2\n\r");
		return 2U;	//HAL_ERROR;
	}

	/* PHY needs a little time after clock change */
	HAL_Delay(50);

	/* ++++++++++++++++++++++++++++++++++++++++++++++++ */
	/* check LINK status of BOTH PHY ports */
	#if DEBUG_ETHNETIF
		uart_printf("PHY link check...\n\r");
	#endif 	/* DEBUG_ETHNETIF */

	u8PhyPortActive = PHY_PORT_NONE;

	/* ETH */
	if( EthPhyLinkStatus((uint8_t)PHY_PORT_ETH, ETH_LINK_CHECK_LONG) == HAL_OK )
	{
		u8PhyPortActive = PHY_PORT_ETH;
	}

	/* USB if ETH not LINKed */
	if( PHY_PORT_NONE == u8PhyPortActive )
	{
		if( EthPhyLinkStatus((uint8_t)PHY_PORT_USB, ETH_LINK_CHECK_LONG) == HAL_OK )
		{
			u8PhyPortActive = PHY_PORT_USB;
		}
	}

	#if( 1 )	// DEBUG_ETHNETIF
		uart_printf("u8PhyPortActive = %u\n\r", u8PhyPortActive);
	#endif 	/* DEBUG_ETHNETIF */


	/* ++++++++++++++++++++++++++++++++++++++++++++++++ */
	/* power down unused port */
	if( PHY_PORT_NONE != u8PhyPortActive )
	{
		uint32_t u32PhyRegVal = 0;
		volatile uint8_t u8PhyPortUnused = PHY_PORT_NONE;
		uint8_t u8RetVal = 0;
		UNUSED(u8RetVal);

		if( PHY_PORT_ETH == u8PhyPortActive ) u8PhyPortUnused = PHY_PORT_USB;
		else u8PhyPortUnused = PHY_PORT_ETH;

		u8RetVal = EthPhyPowerDown(u8PhyPortUnused);
		#if DEBUG_ETHNETIF
			if( u8RetVal != HAL_OK ) uart_printf(SZC_TEXT_ERR "EthPhyPowerDown()\n\r");
			else uart_printf("PWRDWN unused port set\n\r");
		#endif 	/* DEBUG_ETHNETIF */

		/* check */
		HAL_Delay(10);
		u8RetVal = EthPhyReadReg(PHY_REG_PWR_DOWN, &u32PhyRegVal, u8PhyPortUnused);
		#if DEBUG_ETHNETIF
			if( u8RetVal != HAL_OK ) uart_printf(SZC_TEXT_ERR "EthPhyReadReg(PHY_REG_PWR_DOWN)\n\r");
			else
			{
				uart_printf("PHY_REG_PWR_DOWN = %04lX of unused port\n\r", u32PhyRegVal);
				if( (u32PhyRegVal & (uint32_t)PHY_REG_BIT_PWR_DOWN) == 0 ) uart_printf(SZC_TEXT_ERR "EthPhyPowerDown() failed\n\r");
			}
		#endif 	/* DEBUG_ETHNETIF */
	}

	/* ++++++++++++++++++++++++++++++++++++++++++++++++ */
	/* wait for auto-negotiation complete */
	if( PHY_PORT_NONE != u8PhyPortActive )
	{
		if( EthPhyAutoNegStatus(u8PhyPortActive) == HAL_OK )
		{
			#if DEBUG_ETHNETIF
				uart_printf("AUTO-NEGOTIATION 0 complete\n\r");
			#endif 	/* DEBUG_ETHNETIF */
		}
		else
		{
			/* re-start Auto-Negotiation */
			if( EthPhyAutoNegRestart(u8PhyPortActive) != HAL_OK )
			{
				#if( 1 )	// DEBUG_ETHNETIF
					uart_printf(SZC_TEXT_ERR "EthPhyAutoNegRestart()\n\r");
				#endif 	/* DEBUG_ETHNETIF */

				return 6U;	//HAL_ERROR;
			}

		/* wait for auto-negotiation complete */
			if( EthPhyAutoNegStatus(u8PhyPortActive) == HAL_OK )
			{
				#if DEBUG_ETHNETIF
					uart_printf("AUTO-NEGOTIATION 1 complete\n\r");
				#endif 	/* DEBUG_ETHNETIF */
			}
			else
			{
				#if( 1 )	// DEBUG_ETHNETIF
					uart_printf(SZC_TEXT_ERR "EthPhyAutoNegStatus() TIMEOUT\n\r");
				#endif 	/* DEBUG_ETHNETIF */

				return 7U;	//HAL_TIMEOUT;
			}
		}
	}
	else
	{
		#if( 1 )	// DEBUG_ETHNETIF
			uart_printf(SZC_TEXT_ERR "u8PhyPortActive = PHY_PORT_NONE\n\r");
		#endif 	/* DEBUG_ETHNETIF */

		return 8U;	//HAL_ERROR;
	}

uart_printf("EthPhyInit() good ->return 0\n\r");

	return 0U;	//HAL_OK;
}

 

PS:

- STM32H733 on a custom board

- working with that for > 1 year now, with lots of printf for debugging (UART DMA), never had something like this

- same on other boards

- still using STM32CubeIDE 1.10.1

[Ozone]

> Until I turned optimization OFF, now all is good.
> WTF is happening there? Can optimization be that bad?

Rarely.
But code can be that "bad".

Just drop e.g. a few "volatile" specifiers for peripheral registers or variables in interrupt code, and any optimisation level > 0 will "break" it.

 

[LCE]

... I played a lot with that.

In this case, all of the problems not happening in ISRs, just simple non-OS start-up code / inits, even before the main loop.

The horrifying thing is that this is so simple, telling a function to return 0, but what's coming back is some seemingly random number.

[TDK]

There's no problems with the code presented as far as I can tell, even with optimization or cache turned on.

How does uart_printf work? If you use DMA, you will need to handle cache appropriately. Technically, you should cast u8RetInit to (int) in your printf call, though I don't think that's the issue.

[Andrew Neil]

Have you tried stepping it at the instruction level ?

Have you tried any other optimisation settings ?

[LCE]

Thanks to all!

@TDK 

uart_printf: DMA yes, cache no, no buffer overwrite possible

casting the u8 doesn't change anything.

BTW, what's the appropriate specifier for printf for a single unsigned byte in gcc?
So far %u / %X worked quite well.

@Andrew Neil 

stepping: yes, I see EthPhyInit() might even get to the last uart_printf("EthPhyInit() good ->return 0\n\r") before "return 0", then still seeing "u8RetInit = EthPhyInit();" = 166 :D

other optimization: tried size, that resulted in ... some other problems.

... which makes me check some sources again. Shoot...

[Andrew Neil]

I meant stepping at the machine (assembler) instruction level - not the C source line level.

[LCE]

Oops, okay, don't know how to do that...

Meanwhile, I found some more strange things that do not happen without optimization:

There's a function with a timeout check using HAL_GetTick(), and I was wondering why I got timeouts so quickly, should have been 5 seconds. Then I checked the Ticks and these were all "wrong".

 

uint8_t EthPhyLinkStatus(volatile uint8_t u8PhyPortIn, uint8_t u8QuickCheck)
{
	if( (u8PhyPortIn < PHY_PORT_ETH) || (u8PhyPortIn > PHY_PORT_USB) ) return HAL_ERROR;

	uint32_t u32PhyRegVal = 0;
	volatile uint32_t u32TickStart;
	volatile uint32_t u32TickNow;
	volatile uint32_t u32Timeout;

	if( ETH_LINK_CHECK_QUICK == u8QuickCheck ) u32Timeout = ETH_TIMEOUT_LINKSTATE_QUICK_MS;
	else u32Timeout = ETH_TIMEOUT_LINKSTATE_MS;

	u32TickStart = HAL_GetTick();
 u32TickNow = HAL_GetTick();
	do
	{
		EthPhyReadReg(PHY_REG_LINK_STATUS, &u32PhyRegVal, u8PhyPortIn);
		/* timeout ? */
		u32TickNow = HAL_GetTick();
		if( (u32TickNow - u32TickStart ) > u32Timeout )
		{
			break;
		}
		HAL_Delay(5);
	} while( (u32PhyRegVal & (uint32_t)PHY_REG_BIT_LINK_UP) == 0 );

	if( (u32PhyRegVal & (uint32_t)PHY_REG_BIT_LINK_UP) == 0 )
	{
		#if DEBUG_ETHNETIF_ERR
			uart_printf(SZC_TEXT_ERR "EthPhyLinkStatus(%u) TIMEOUT %lu ms, u32PhyRegVal = %04lX\n\r", u8PhyPortIn, u32Timeout, u32PhyRegVal);
			uart_printf("u32TickStart = %lu\n\r", u32TickStart);
			uart_printf("u32TickNow = %lu\n\r", u32TickNow);
		#endif	/* DEBUG_ETHNETIF_ERR */

		return HAL_ERROR;
	}

	return HAL_OK;
}

Here's the UART output I get:

#E EthPhyLinkStatus(1) TIMEOUT 5000 ms, u32PhyRegVal = 008F
u32TickStart = 1190
u32TickNow = 1093

I don't understand anything anymore... why's u32TickStart > u32TickNow ?

[LCE]

... and when I remove the "volatile" from the ticks, it's working.

I thought there might be a problem without volatile and optimization, had something like this in a do / while before.

Not a software guy here... 

[LCE]

Okay, I changed some variables to volatile for communication with the PHY using I2C with interrupts.

Now all works fine, even with opt. "fast".

I have to keep an eye on some more variables...

 

Still, I don't get:

1) When stepping through (on C level) I see "return 0;", then the return value in the above function gets some other seemingly random value.

2) The timing stuff above using volatile that does not work.

[TDK]

Ticks should definitely have a volatile qualifier on it, as it's modified within an interrupt. The code for ticks is dirt simple, no bugs there. If your ticks are going backwards, there has to be a bug somewhere in there. Perhaps an out of bounds write. I suspect an issue with something else messing with the stack variable rather than the underlying tick variable.

Careful of making random changes to get it to "work". You may be sweeping larger issues under the rug, which will come up later.

> When stepping through (on C level) I see "return 0;", then the return value in the above function gets some other seemingly random value.

Also suggests stack corruption.