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.