How to solve MQX RTCS_time_get() problem?

[kaskasi]

Hello,

I'm working on project that uses K53 and MQX 3.8.0 with CW C++.

I have done diff with the MQX 3.8.1 and looks like there is no changes to the code that seems to be problematic.

Problem I'm seeing is that for some reason RTCS_time_get() function ( _time_get_elapsed() ) can return values from the past.

Early on when I was trying to bring up our custom board couldn't get DHCP messages going out. Reason was that messages did seem to timeout prior they even went out. During that time I noticed that for some reason timedelta from the calculation below was sometimes negative.

From TCPIP_task()

timeafter = RTCS_time_get();

timedelta = (timeafter - timebefore);

Which, I believe, made timedelta being huge positive number -> that made all the possible event timers to trigger.  And hence DHCP packet was never getting out since it timed out immediately.

To fix that I added code that would make timedelta being 0 in case timeafter was smaller than timebefore. That got us nicely forward during those crucial days of the board bringup.

Now I'm revisiting RTCS portion since we are seeing some extra RTCSERR_TCP_CONN_ABORTED errors. And when tracking down that one looks like same thing happened again in ticker.c

   newtime = RTCS_time_get();

   elapsed = newtime - tcp_cfg->lasttime; /* get elapsed msecs... */

   tcp_cfg->lasttime = newtime;

After reviewing the code from (PSP) ti_elapt.c I was just wondering what would be the best solution to my problem?

Think it all comes down to underlying calls to _time_get_elapsed_ticks() and PSP_NORMALIZE_TICKS() calls.

Since our Debug output is using  _time_get_elapsed_ticks() from various threads with different priorities.

And it looks like we are getting very interesting time stamps.

2189.378:[3,T=0x10002]

2189.479:[3,T=0x1000b]

2190.505:[3,T=0x10006]

2191.026:[3,T=0x10006]

2191.141:[3,T=0x10006]

2191.015:[3,T=0x10006] <-- This would affect negative time. Note this is within one thread!!!

2191.093:[3,T=0x10006]

2191.164:[3,T=0x10006]

2191.235:[0,T=0x10006]

2191.082:[3,T=0x10003]

Thanks,

Kari

[timias]

Try the code that MartinK just posted today in my thread, I bet it will help.

MQX 3.8 _time_get() -&gt;_time_to_date defect

[kaskasi]

Improved.

I don't see Socket error, but debug messages still show the problem.

2869.468:[3,T=0x10003]

2869.410:[0,T=0x1000b] <-- Still there

2869.503:[0,T=0x1000b]

2869.620:[3,T=0x1000b]

2869.535:[3,T=0x1000b] <-- Still there

2869.441:[3,T=0x1000b] <-- Still there

2869.537:[3,T=0x10002]

2869.476:[3,T=0x10002] <-- Still there

2869.563:[3,T=0x10002]

2869.664:[3,T=0x1000b]

2870.984:[3,T=0x10006]

2871.505:[3,T=0x10006]

2871.618:[3,T=0x10006]

2871.491:[3,T=0x10006] <-- Still there

2871.569:[3,T=0x10006]

2871.641:[3,T=0x10006]

2871.711:[0,T=0x10006]

2871.557:[3,T=0x10003] <-- Still there

Message was edited by: Kari Sipinen

[c0170]

Hi Kari,

glad it improved, but problem still persists somewhere. Can you debug and identify the problem why you are getting wrong timestamps.

I do not know much about your application , but what if you test to put in the fix I posted, in the beginning disable_int and enable_int in the end of the function. Let me know what happens.

Regards,

MartinK

[kaskasi]

Thanks Martin,

Will try later today.

Meanwhile can you review MQX code in time_get_elapsed_ticks() function ti_elapt.c. It calls _psp_normalize_ticks() from psp_tinm.c. That code seems to decrement HW_TICKS[0] while interrupts are enabled. Without knowing history of CR 1082 that looks somewhat suspicious.

Later,

Kari

[kaskasi]

Here is the latest.

After reviewing MQX code (maybe more than I ever wanted :smileyconfused: ) I have done following.

Left Martin's changes in _pspticks_to_time() as is (not protected with disa ena interrupts).

Did comment out code from the _time_get_elapsed_ticks() function in ti_elapt.c that was marked with comment /* Start CR 1082 */ and /* End CR 1082*/

Obviously added _INT_ENABLE() (which I first forgot).

Reason for change: Looks like in our application _time_get_elapsed_ticks() function gets called way too many times which affected PSP_NORMALIZE_TICKS be called all the time. In my opinion that should be called only by the _time_notify_kernel() in ti_krnl.c. Which pretty much is time keeper for whole system. _time_notify_kernel() also calls _timer_isr() which calls _time_get_elapsed_ticks() etc.

So for now in our application this seems to work much more reliably. Timestamps are now aligned. Interrupts are disabled less, which suddenly seems to make things work better. Obviously this is just day after I tried these changes so there might be some huge unwanted features around the corner... We shall see!!!

Later,

Kari

[kaskasi]

After debugging timing problem, which I think was unrelated one. Decided to go with "safer" implementation.

Created _time_get_elapsed_simple() that calls _time_get_elapsed_tics_simple() which has changed mentioned in my previous post.

Changed our application to call _time_get_elapsed_simple() to get timestamp for the debug messages. Timestamps seem to be correct. And so far I have not seen problems with the RTCS_time_get().