System time in logging functions?
Posted: Sat Dec 26, 2020 11:11 pm
I'm starting to use queuing functions, so one of the things I wanted to check was whether it is any slower to use the queues compared to some other ways of data exchange between two tasks.
I created two tasks - Task A queues up a structure into the queue and Task B reads is. To test how fast this happens, I added a member to a structure where I put a "system time" - (xTaskGetTickCount() * portTICK_PERIOD_MS) right before Task A writes the structure into the queue. After receiving the queued structure, Task B gets current "system time" and compares it with the one received from Task A.
Task B is always ready to read from the queue - that's all it does. The difference between these two times is usually 0, but sometimes it is 10 mSec. Since my configTICK_RATE_HZ is 100 and portTICK_PERIOD_MS = 1000/100 = 10, the difference is always a multiple of 10. So - everything is clear, no problems here.
What I don't understand is my log where I see all these results. I'm using ESP_LOGI() function to make log entries. Every entry starts with a number that looks like what I earlier called a "system time" - number of ticks from the start of the scheduler. It would make sense that this number is close to the time that Task B got from the system. However, every time there is about 700 (most likely mSec) difference between these two numbers. I understand that it takes some time to create a log entry, but it most certainly doesn't take 700 mSec fo do that.
My question is - do you know what is this number provided by the log functions and why is it different from the one supplied by xTaskGetTickCount().
Thanks a lot.
Examples of log entries from Task B:
I (17542) Data In - 16900, Data Out - 16900.
I (17592) Data In - 16950, Data Out - 16950.
I (17632) Data In - 16990, Data Out - 16990.
I created two tasks - Task A queues up a structure into the queue and Task B reads is. To test how fast this happens, I added a member to a structure where I put a "system time" - (xTaskGetTickCount() * portTICK_PERIOD_MS) right before Task A writes the structure into the queue. After receiving the queued structure, Task B gets current "system time" and compares it with the one received from Task A.
Task B is always ready to read from the queue - that's all it does. The difference between these two times is usually 0, but sometimes it is 10 mSec. Since my configTICK_RATE_HZ is 100 and portTICK_PERIOD_MS = 1000/100 = 10, the difference is always a multiple of 10. So - everything is clear, no problems here.
What I don't understand is my log where I see all these results. I'm using ESP_LOGI() function to make log entries. Every entry starts with a number that looks like what I earlier called a "system time" - number of ticks from the start of the scheduler. It would make sense that this number is close to the time that Task B got from the system. However, every time there is about 700 (most likely mSec) difference between these two numbers. I understand that it takes some time to create a log entry, but it most certainly doesn't take 700 mSec fo do that.
My question is - do you know what is this number provided by the log functions and why is it different from the one supplied by xTaskGetTickCount().
Thanks a lot.
Examples of log entries from Task B:
I (17542) Data In - 16900, Data Out - 16900.
I (17592) Data In - 16950, Data Out - 16950.
I (17632) Data In - 16990, Data Out - 16990.