Wierd timing error

timonm wrote on Wednesday, March 11, 2015:

I got a wierd timing problem.

I have two tasks. There is a constant task switch between these two tasks.
I use the cycle counter timer to measure the total length of the task switch. But here is the wierd part.

When i add one line of code, the code is faster, than when i remove the line. How is this possible?

when i add the code. the total cycles is: 4846.
When i remove the line. the total cycles is: 4897.

Below the source code:

/*******************************************************************
* Includes
*******************************************************************/
#include "FreeRTOS.h"
#include "task.h"
#include "queue.h"
#include "swv.h"
/*******************************************************************
* Defines
*******************************************************************/
#define COUNTER

#define MAX_LOOPS 10

#define DEMCR           (*((volatile uint32_t *)0xE000EDFC))
#define DWT_CTRL        (*(volatile uint32_t *)0xe0001000)

#define mainFIRST_TASK_PRIORITY (tskIDLE_PRIORITY + 2)
#define mainSECOND_TASK_PRIORITY (tskIDLE_PRIORITY + 2)

/*******************************************************************
* Types
*******************************************************************/
xTaskHandle xHandleFirst;
xTaskHandle xHandleSecond;
/*******************************************************************
* Data
*******************************************************************/
uint32_t m_nStart;               //DEBUG Stopwatch start cycle counter value
uint32_t m_nStop;                //DEBUG Stopwatch stop cycle counter value

/*******************************************************************
* Local Function Prototypes
*******************************************************************/
static void prvFirst(void *pvParameters);
static void prvSecond(void *pvParameters);

int main(void)
{
    /* Enable DWT */
    DEMCR |= 0x01000000;
    /* Enable CPU cycle counter */
    DWT_CTRL |= 1;

    while(1)
    {
        xTaskCreate(prvSecond, (const char *) "S",
                    configMINIMAL_STACK_SIZE,NULL,
                    mainSECOND_TASK_PRIORITY, &xHandleSecond);
        xTaskCreate(prvFirst, (const char *) "F",
                    configMINIMAL_STACK_SIZE,NULL,
                    mainFIRST_TASK_PRIORITY, &xHandleFirst);
        vTaskStartScheduler();
    }
}

//Task 1
static void prvFirst(void *pvParameters)
{
    while(1)
    {
        m_nStart = *((volatile uint32_t *)0xE0001004); // save clockcycle count
        for(uint32_t count1 = 0; count1 < MAX_LOOPS; count1++)
        {
            taskYIELD();
        }
        vTaskDelete(xHandleFirst);
    }
}

//task 2
static void prvSecond(void *pvParameters)
{
    while(1)
    {
        for (uint32_t count2 = 0; count2 < MAX_LOOPS-1; count2++)
        {
            taskYIELD();
        }
        m_nStop = *((volatile uint32_t *)0xE0001004); // save clockcycle count
        
// ADD ONE LINE OF CODE AFTER THIS. THE CODE RUNS FASTER
        SWV_printnum(m_nStop);
        SWV_puts("\r\n");
        SWV_printnum(m_nStart);
        SWV_puts("\r\n"); 
        
        vTaskDelete(xHandleSecond);
    }
    
}

rtel wrote on Wednesday, March 11, 2015:

When you say “// ADD ONE LINE OF CODE AFTER THIS. THE CODE RUNS FASTER” do you mean add a line of code between that comment and the call to SWV_printnum()? If so, what is the line?

If you are trying to get the switch as fast as possible then:

  • ensure configCHECK_FOR_STACK_OVERFLOW is 0
  • ensure no trace macros are enabled
  • ensure run-time stats are disable
  • ensure configUSE_PORT_OPTIMISED_TASK_SELECTION is set to 1.

Regards.

timonm wrote on Wednesday, March 11, 2015:

Thanks for the answer.

When i remove one line of code below the "//ADD ONE LINE etc… “the code runs faster. for example the line “SWV_puts(”\r\n”);

With the settings you send i get the following timing:

code:
SWV_printnum(m_nStop);
SWV_puts("\r\n");
SWV_printnum(m_nStart);
SWV_puts("\r\n");

The timing is: 4542

code:
SWV_printnum(m_nStop);
SWV_puts("\r\n");
SWV_printnum(m_nStart);
// SWV_puts("\r\n");

The timing is: 4488

So then its the other way aroud… but its still wierd, because i already saved the clockcyclecounter…

rtel wrote on Wednesday, March 11, 2015:

Do you have compiler optimisation turned on? I suspect so. With
optimisation turned off I would not expect any difference.

Regards.

timonm wrote on Wednesday, March 11, 2015:

Compiler optimalisation and optiimize for time are turned off

Compiler settings:
–c99 -c --cpu Cortex-M4.fp -D__EVAL -D__MICROLIB -g -O0 --apcs=interwork --split_sections

timonm wrote on Friday, March 13, 2015:

After enabeling Flash prefetch, Instruction cache, Data cache, the delay is 50 ns instead of 5 ms