mutex not providing mutal exclusion

Kernel
1

bamos-cic wrote on Thursday, April 27, 2017:

Hi,

I’ve recently noticed some issues in my projects where mutex’s no longer seemed to provide mutual exclusion?

I created a small test application with two tasks that exemplifies the issue i’m seeing. This is running with freeRTOS 9.0.0

#include <FreeRTOS.h>
#include <platform.h>
#include <VirtualSerialPort.h>
#include <SEGGER_SYSVIEW.h>


VirtualSerialPort serial(0);
static void HighPriorityTask( void* Params);
static void LowPriorityTask( void* Params);

xSemaphoreHandle mutexPtr = NULL;

int main(void)
{
  SystemClock_Config();
	serial.Init();
	
	mutexPtr = xSemaphoreCreateMutex();
	
	if(mutexPtr == NULL)
	{
		while(1);
	}

	SEGGER_SYSVIEW_Conf();
	
	if (xTaskCreate( HighPriorityTask, ( const char * ) "HPT", 256, NULL, tskIDLE_PRIORITY + 2, NULL ) == pdTRUE)	
	{
		if(xTaskCreate( LowPriorityTask, ( const char * ) "LPT", 256, NULL, tskIDLE_PRIORITY + 1, NULL ) == pdTRUE)	
			vTaskStartScheduler();
	}
	
	
  while (1);//shouldn't get here
}

static void HighPriorityTask( void* Params)
{
	volatile uint32_t temp = 0;
	
	while(1)
	{
		printf("HPT\t mutex addr 0x%p\n", mutexPtr);
		for(int numItr = 0; numItr < 10; numItr++)
		{
			uint32_t sleepTime = rand() %500;
			printf("HPT\t sleeping for %i ms\n", sleepTime);
			vTaskDelay(sleepTime);
			printf("HPT\t take mutex, wait indefinitely\n");
			if(xSemaphoreTake(mutexPtr,portMAX_DELAY) == pdTRUE)
			{
				printf("HPT\t mutex taken\n");
				
				uint32_t sleepTime = rand() %500;
				printf("HPT\t sleeping for %i ms\n", sleepTime);
				vTaskDelay(sleepTime);
				for(int i = 0; i < 20000; i++)
				{
					temp += i;
				}
				if(xSemaphoreGive(mutexPtr) == pdTRUE)
				{
					printf("HPT\t mutex given\n");
				}
				else
				{
					printf("HPT\t mutex give failed\n");
				}
			}
			else
			{
				printf("HPT\t mutex take failed!\n");
			}
		}
		printf("HPT DONE, sleep for 2 sec\n");
		vTaskDelay(100);
	}
}

static void LowPriorityTask( void* Params)
{
	volatile uint32_t temp = 0;
	uint32_t num;
	
	while(1)
	{
		printf("\t\t\t\t\tLPT\tmutex addr 0x%p\n", mutexPtr);
		vTaskDelay(rand() %500);
		for(int numItr = 0; numItr < 10; numItr++)
		{
			printf("\t\t\t\t\tLPT\t take mutex, wait indefinitely\n");
			if(xSemaphoreTake(mutexPtr,portMAX_DELAY) == pdTRUE)
			{
				printf("\t\t\t\t\tLPT\t mutex taken\n");
				
				uint32_t sleepTime = rand() %500;
				printf("\t\t\t\t\tLPT\t sleeping for %i ms\n", sleepTime);
				vTaskDelay(sleepTime);
				
				if(xSemaphoreGive(mutexPtr) == pdTRUE)
				{
					printf("\t\t\t\t\tLPT\t mutex given\n");
				}
				else
				{
					printf("\t\t\t\t\tLPT\t mutex give failed\n");
				}
			}
			else
			{
				printf("\t\t\t\t\tLPT\t mutex take failed!\n");
			}
		}
		printf("\t\t\t\t\tLPT DONE, sleep for 2 sec\n");
		vTaskDelay(2000);
	}
}

Here’s an example of some output, with the problematic section in bold.

HPT mutex addr 0x20021e50
HPT sleeping for 432 ms
HPT take mutex, wait indefinitely
HPT mutex taken
HPT sleeping for 5 ms
HPT mutex given
HPT sleeping for 490 ms
HPT take mutex, wait indefinitely
HPT mutex taken
HPT sleeping for 29 ms
HPT mutex given
HPT sleeping for 104 ms
HPT take mutex, wait indefinitely
HPT mutex taken
HPT sleeping for 492 ms
HPT mutex given
HPT sleeping for 497 ms
LPT mutex addr 0x20021e50
HPT take mutex, wait indefinitely
HPT mutex taken
HPT sleeping for 172 ms
LPT take mutex, wait indefinitely
HPT mutex given
HPT sleeping for 235 ms
LPT mutex taken
LPT sleeping for 268 ms
HPT take mutex, wait indefinitely
HPT mutex taken
HPT sleeping for 341 ms
LPT mutex given
LPT take mutex, wait indefinitely
HPT mutex given
HPT DONE, sleep for 2 sec
LPT mutex taken
LPT sleeping for 476 ms
HPT mutex addr 0x20021e50
HPT sleeping for 258 ms
HPT take mutex, wait indefinitely
HPT mutex taken
HPT sleeping for 489 ms
LPT mutex given
LPT take mutex, wait indefinitely
HPT mutex given
HPT sleeping for 451 ms

Am I making an incorrected assumption or setting/using something incorrectly? I’m guessing there’s a stupid mistake in there somewhere that I’m not seeing.

This is on a Cortex M7 port compiled with Keil (RVDS).

Any suggestions are greately appriciated.

thanks!

2

rtel wrote on Thursday, April 27, 2017:

How is your printf() writing its output? Is it possible some print()
statements are missing (and do you need mutual exclusion on the printf()
too?)?

Which port are you using? If your Cortex-M7 has an r0p1 core then you
need to use the port layer in the
FreeRTOS/source/portable/RVDS/ARM_CM7/r0p1 directory to work around a
silicon errata, otherwise you need to use the code in the
FreeRTOS/source/portable/RVDS/ARM_CM4F directory.

3

bamos-cic wrote on Thursday, April 27, 2017:

I’ve tried both the r0p1 port and ARM_CM4F port with identical results

printf does single byte transfers through fputc, which gets forwarded to a ring buffer (which is thread-safe) and eventually out to a USB stack. It’s possible for two different strings characters to be interleaved with one another, but there won’t be any dropped data. I’ll hook up two different LED’s to eliminate printf as a possible culprit.

4

bamos-cic wrote on Thursday, April 27, 2017:

Here’s updated code with LED calls inside the area expected to be protected by the mutex. I would expect only one LED to be on at a time, but occassionally both LED’s are on at the same time.

#include <FreeRTOS.h>
#include <platform.h>
#include <VirtualSerialPort.h>
#include <SEGGER_SYSVIEW.h>
#include <stm32f7xxGpio.h>


VirtualSerialPort serial(0);
static void HighPriorityTask( void* Params);
static void LowPriorityTask( void* Params);

gpio led1(GPIOJ, gpio::PIN0, true);
gpio led2(GPIOJ, gpio::PIN1, true);

xSemaphoreHandle mutexPtr = NULL;

int main(void)
{
	InitMCU(false);
  SystemClock_Config();
	serial.Init();
	
	mutexPtr = xSemaphoreCreateMutex();
	
	if(mutexPtr == NULL)
	{
		while(1);
	}

	SEGGER_SYSVIEW_Conf();
	
	if (xTaskCreate( HighPriorityTask, ( const char * ) "HPT", 256, NULL, tskIDLE_PRIORITY + 2, NULL ) == pdTRUE)	
	{
		if(xTaskCreate( LowPriorityTask, ( const char * ) "LPT", 256, NULL, tskIDLE_PRIORITY + 1, NULL ) == pdTRUE)	
			vTaskStartScheduler();
	}
	
	
  while (1);//shouldn't get here
}

void HighPriorityTask( void* Params)
{
	volatile uint32_t temp = 0;
	
	led1.Clear();
	
	while(1)
	{
		printf("HPT\t mutex addr 0x%p\n", mutexPtr);
		for(int numItr = 0; numItr < 10; numItr++)
		{
			uint32_t sleepTime = rand() %500;
			printf("HPT\t sleeping for %i ms\n", sleepTime);
			vTaskDelay(sleepTime);
			printf("HPT\t take mutex, wait indefinitely\n");
			if(xSemaphoreTake(mutexPtr,portMAX_DELAY) == pdTRUE)
			{
				led1.Set();
				printf("HPT\t mutex taken\n");
				
				uint32_t sleepTime = rand() %500;
				printf("HPT\t working for %i\n", sleepTime);
				for(int w = 0; w < sleepTime*100000; w++)
				{
					temp += w;
				}
				led1.Clear();
//				printf("HPT\t sleeping for %i ms\n", sleepTime);
//				vTaskDelay(sleepTime);
				if(xSemaphoreGive(mutexPtr) == pdTRUE)
				{
					printf("HPT\t mutex given\n");
				}
				else
				{
					printf("HPT\t mutex give failed\n");
				}
			}
			else
			{
				printf("HPT\t mutex take failed!\n");
			}
		}
		printf("HPT DONE, sleep for 2 sec\n");
		vTaskDelay(100);
	}
}

void LowPriorityTask( void* Params)
{
	volatile uint32_t temp = 0;
	uint32_t num;
	
	led2.Clear();
	
	while(1)
	{
		printf("\t\t\t\t\tLPT\tmutex addr 0x%p\n", mutexPtr);
		vTaskDelay(rand() %500);
		for(int numItr = 0; numItr < 10; numItr++)
		{
			printf("\t\t\t\t\tLPT\t take mutex, wait indefinitely\n");
			if(xSemaphoreTake(mutexPtr,portMAX_DELAY) == pdTRUE)
			{
				led2.Set();
				printf("\t\t\t\t\tLPT\t mutex taken\n");
				
				uint32_t sleepTime = rand() %500;
				printf("\t\t\t\t\tLPT\t working for %i\n", sleepTime);
				for(int w = 0; w < sleepTime*100000; w++)
				{
					temp += w;
				}
//				printf("\t\t\t\t\tLPT\t sleeping for %i ms\n", sleepTime);
//				vTaskDelay(sleepTime);
				
				led2.Clear();
				if(xSemaphoreGive(mutexPtr) == pdTRUE)
				{
					printf("\t\t\t\t\tLPT\t mutex given\n");
				}
				else
				{
					printf("\t\t\t\t\tLPT\t mutex give failed\n");
				}
			}
			else
			{
				printf("\t\t\t\t\tLPT\t mutex take failed!\n");
			}
		}
		printf("\t\t\t\t\tLPT DONE, sleep for 2 sec\n");
		vTaskDelay(2000);
	}
}
5

bamos-cic wrote on Thursday, April 27, 2017:

It was all instrumentation issues - in the code above, the “mutex given” text was written after the mutex had been given (which suggests overlap when viewed on the screen). To add insult to injury, the polarity of the LED’s was active low, so they were being turned “off” when each was inside the critical section and on when outside the critical section.

After moving the print outputs to be inside the mutex and correcting for active low LED outputs, everything is showing up as expected for the critical sections.

Here are the code changes for the slim chance that anyone is interested:

#include <FreeRTOS.h>
#include <platform.h>
#include <VirtualSerialPort.h>
#include <SEGGER_SYSVIEW.h>
#include <stm32f7xxGpio.h>


VirtualSerialPort serial(0);
static void HighPriorityTask( void* Params);
static void LowPriorityTask( void* Params);

gpio led1(GPIOJ, gpio::PIN0, true);
gpio led2(GPIOJ, gpio::PIN1, true);

xSemaphoreHandle mutexPtr = NULL;
StaticSemaphore_t xMutexBuffer;

int main(void)
{
	InitMCU(false);
  SystemClock_Config();
	serial.Init();
	
	mutexPtr = xSemaphoreCreateMutexStatic(&xMutexBuffer);

	if(mutexPtr == NULL)
	{
		while(1);
	}

	led1.Set();
	led2.Set();
	SEGGER_SYSVIEW_Conf();
	
	uint8_t cBuff[2];
	serial.CheckLastByte(cBuff, -1);
	
	if (xTaskCreate( HighPriorityTask, ( const char * ) "HPT", 256, NULL, tskIDLE_PRIORITY + 2, NULL ) == pdTRUE)	
	{
		if(xTaskCreate( LowPriorityTask, ( const char * ) "LPT", 256, NULL, tskIDLE_PRIORITY + 1, NULL ) == pdTRUE)	
			vTaskStartScheduler();
	}
	
	
  while (1);//shouldn't get here
}

void HighPriorityTask( void* Params)
{
	volatile uint32_t temp = 0;
	
	while(1)
	{
		printf("HPT\t mutex addr 0x%p\n", mutexPtr);
		for(int numItr = 0; numItr < 10; numItr++)
		{
			printf("HPT itr %i\n", numItr);
			uint32_t sleepTime = rand() %500 + 500;
			printf("HPT\t sleeping for %i ms\n", sleepTime);
			vTaskDelay(sleepTime);
			uint8_t hptWait[] = "HPT\t take mutex, wait indefinitely\n";
			serial.Output(hptWait, sizeof(hptWait), true);
			if(xSemaphoreTake(mutexPtr,portMAX_DELAY) == pdTRUE)
			{
				led1.Clear();
				
				printf("HPT\t mutex taken\n");
				
				uint32_t sleepTime = rand() %500 + 500;
				printf("HPT\t working for %i\n", sleepTime);
				for(int w = 0; w < sleepTime*100000; w++)
				{
					temp += w;
				}
				led1.Set();
				uint8_t given[] = "HPT\t mutex given\n";
				serial.Output(given, sizeof(given), true);
				if(xSemaphoreGive(mutexPtr) == pdTRUE)
				{
						uint8_t giveDone[] = "HPT\t give done\n";
						serial.Output(giveDone, sizeof(giveDone), true);
				}
				else
				{
					printf("HPT\t mutex give failed\n");
				}
			}
			else
			{
				printf("HPT\t mutex take failed!\n");
			}
		}
		printf("HPT DONE, sleep for 2 sec\n");
		vTaskDelay(100);
	}
}

void LowPriorityTask( void* Params)
{
	volatile uint32_t temp = 0;
	uint32_t num;
	
	while(1)
	{
		printf("\t\t\t\t\tLPT\tmutex addr 0x%p\n", mutexPtr);
		vTaskDelay(rand() %500 + 500);
		for(int numItr = 0; numItr < 10; numItr++)
		{
			printf("\t\t\t\t\tLPT itr %i\n", numItr);
			uint8_t msg[] = "\t\t\t\t\tLPT\t take mutex, wait indefinitely\n";
			serial.Output(msg, sizeof(msg), true);
			if(xSemaphoreTake(mutexPtr,portMAX_DELAY) == pdTRUE)
			{
				led2.Clear();
				printf("\t\t\t\t\tLPT\t mutex taken\n");
				
				uint32_t sleepTime = rand() %500 + 500;
				printf("\t\t\t\t\tLPT\t working for %i\n", sleepTime);
				for(int w = 0; w < sleepTime*100000; w++)
				{
					temp += w;
				}
				
				uint8_t giveMsg[] = "\t\t\t\t\tLPT\t give mutex\n";
				serial.Output(giveMsg, sizeof(giveMsg), true);
				led2.Set();
				if(xSemaphoreGive(mutexPtr) == pdTRUE)
				{
					uint8_t giveDone[] = "\t\t\t\t\tLPT\t give done\n";
					serial.Output(giveDone, sizeof(giveDone), true);
				}
				else
				{
					printf("\t\t\t\t\tLPT\t mutex give failed\n");
				}
			}
			else
			{
				printf("\t\t\t\t\tLPT\t mutex take failed!\n");
			}
		}
		printf("\t\t\t\t\tLPT DONE, sleep for 2 sec\n");
		vTaskDelay(2000);
	}
}

Some example output looks like this:

HPT mutex addr 0x20020ac0
HPT itr 0
HPT sleeping for 768 ms
LPT mutex addr 0x20020ac0
LPT itr 0
LPT take mutex, wait indefinitely
LPT mutex taken
LPT working for 909
HPT take mutex, wait indefinitely
LPT give mutex
HPT mutex taken
HPT working for 660
HPT mutex given
LPT give done
HPT give done
HPT itr 1
HPT sleeping for 583 ms
LPT itr 1
LPT take mutex, wait indefinitely
LPT mutex taken
LPT working for 741
HPT take mutex, wait indefinitely
LPT give mutex
HPT mutex taken
HPT working for 760
HPT mutex given
LPT give done
HPT give done
HPT itr 2
HPT sleeping for 967 ms
LPT itr 2
LPT take mutex, wait indefinitely
LPT mutex taken
LPT working for 807
HPT take mutex, wait indefinitely
LPT give mutex
HPT mutex taken
HPT working for 764
HPT mutex given
LPT give done
HPT give done
HPT itr 3
HPT sleeping for 648 ms
LPT itr 3
LPT take mutex, wait indefinitely
LPT mutex taken
LPT working for 747
HPT take mutex, wait indefinitely
LPT give mutex
HPT mutex taken
HPT working for 574
HPT mutex given
LPT give done
HPT give done
HPT itr 4
HPT sleeping for 973 ms
LPT itr 4
LPT take mutex, wait indefinitely
LPT mutex taken
LPT working for 957

At first glance, it looks like “LPT give done” should not show up HPT is running, but this is because calls to serial.Output(x,x,true) are blocking calls that block/sleep the calling thread until that output is fully flushed.

Thanks for the help Real Time Engineers ltd - getting another set of eyes was helpful.

6

rtel wrote on Thursday, April 27, 2017:

Great - thanks for taking the time to report back.