FreeRTOS misleading tick

Kernel
1

Hi everyone.

I’m building a project on the ARM side of an Smartfusion2. The project itself is as simple as receiving I2C commands, reading some sensors, and answering back with the results, using some task and queues in the process.

The problem I am facing is that it takes too long to do the whole process, so the requester triggers a time out error (250 ms, which I think it is time enough time to make it all).

To understand what is happening, I placed some xTaskGetTickCount() and prints throughout the code. I don’t know if it is the best way to check it but is the one I used. Here are the results (configTICK_RATE_HZ = 1000):

  • I placed one xTaskGetTickCount() just before placing data on a queue, and another one in the task (with higher priority) that reads the queue, just after reading from it. The difference between those ticks is 16 to 18 ticks. It happens to me in every queue and semaphore I tested.
  • I placed them at the beginning (unblocking) and the end (blocking) of the tasks I used. The less time-consuming task is 18 ticks, the second one is 34 ticks, and the big one is 152 (17 x 9) ticks.
  • Just for testing purposes, I placed them just before and after vTaskDelay(pdMS_TO_TICKS(1000)) and vTaskDelay(1000) somewhere in the code. The result is the same: 1017 ticks.

It would seem that I have a 17 ms tick, but configTICK_RATE_HZ is set to 1000 and vTaskDelay(1000) also stands for 1 second.

While configTICK_RATE_HZ = 1000, the freertos tick and each context change should be 1 ms, right?

What am I missing? Where does this offset/tick come from? Is my tick increasing by 17?

Thanks in advance.

2

This is an interesting puzzle. I have questions, I apologize ahead of time if they are basic, but I need to understand what you have already done.

What value is configCPU_CLOCK_HZ and is this value correct?

When you instrumented vTaskDelay(1000), how much “real time” was taken? I would expect 1s like you mentioned.

I will often use a loop to toggle a pin and measure with a `scope or a logic analyzer.

void testTask(void *param){
   for(;;){
      set_gpio(1);
      vTaskDelay(100);
      clear_gpio(1);
      vTaskDelay(pdMS_TO_TICKS(100));
   }
}

this may be trivial but it ensures I know the tick size and the clock speed. Both are determined by the on-time of the GPIO and the off-time.

What do you mean by the unblocking and blocking parts of your tasks? Could you provide some code?

Why do you think your tick size is 17ms? Did your vTaskDelay(1000) take 17 seconds to complete?

1 Like
3

What value is configCPU_CLOCK_HZ and is this value correct?

It takes the value from SystemCoreClock, which is 50000000 (50 Mhz). In addition, the sys tick timer is set up on Libero to CoreClock / 32. Should I use this value instead?

What do you mean by the unblocking and blocking parts of your tasks? Could you provide some code?

I was talking about the places in the task where it begins active and blocked again. Here is a simplified task sample code where you can see where I placed those marks:

void sample_task( void *pvParameters )
{
	for( ;; )
	{
		// Blocks until receive something
		xSemaphoreTake (ipmb_rec_semphr, portMAX_DELAY);

		tick_start = xTaskGetTickCount();
		print("Task unblocked from SEM on tick number = %d\r\n", tick_start);

		// Some code to check the data received

		tick_end = xTaskGetTickCount();
		print("Data sent to Queue on tick number = %d\r\n", tick_end);

		xQueueSendToBack(queue_out, &data, 0UL);
	}
}

This is how I measured the ticks across the 4 tasks that make up this workflow.

Why do you think your tick size is 17ms? Did your vTaskDelay(1000) take 17 seconds to complete?

My vTaskDelay(1000) functions last about one second to my eyes. As I mentioned earlier, when I check the ticks before and after this delay, I get 1017 ticks. Furthermore, when I measure the ticks before I place an item on a queue and get it in another task I also get 16 to 18 ticks. As far as I know, context switches should be as fast as one freeRTOS tick, so I don’t know why it takes 17 ticks for me. (or 17 ms in the case 1 tick = 1 ms)

I will often use a loop to toggle a pin and measure with a `scope or a logic analyzer.

I’ll make this test tomorrow. I will come back as soon as I have checked it!

Thanks for your reply!

4

Are you taking into account the timing of the print statements? If they use blocking I/O printing before sending could significantly delay the send.

5

Thank you all.

I made the test with the oscilloscope. vTaskDelay’s are working great, 100 ms both. I also measure the prints… and there was the problem. They were lasting at least 17 ms, and there were a lot because I want to hunt this timing problem. (my bad).

6

Thank you for reporting back!

1 Like