Fixed the zero trace time stamps in the Linux ports' MISRA builds

[fdesbiens]

Fixes #748

Both Linux ports define TX_TRACE_TIME_SOURCE as _tx_misra_time_stamp_get() when TX_MISRA_ENABLE is set, and neither implements that function, so both inherit the generic return(0); from tx_misra.c. Every trace event is stamped zero. The buffer carries no timing at all, and the kernel's own check for an entry having been overwritten — if (time_stamp == entry_ptr -> tx_trace_buffer_entry_time_stamp) in the block and byte allocates and in the system suspend and resume — compares zero with zero. It is always true, so it never fires and a service patches whatever now occupies the slot rather than declining to.

Both ports now read, in MISRA builds, the clock they already read otherwise: _tx_linux_time_stamp.tv_nsec, which TX_TRACE_PORT_EXTENSION refreshes on every recorded event in both forms of the insert. The non-SMP port's non-MISRA macro carried a trailing semicolon, which made it a statement rather than an expression and is why the MISRA insert — which takes the time source as a function argument — could not reuse it; that semicolon is dropped and the two branches collapse to one definition. The SMP port's macro never had it. Both headers keep the _tx_misra_time_stamp_get declaration, because tx_misra.c still defines the function and is compiled for these ports; removing it breaks that translation unit under -Wmissing-declarations -Werror.

One consequence worth knowing before merging, because it is visible in the data and I would rather state it than have it found. The MISRA insert evaluates its time source at the call site, before _tx_misra_trace_event_insert runs TX_TRACE_PORT_EXTENSION, so each entry carries the clock as read at the previous recorded event rather than its own. The stamps are real, distinct and correctly ordered, which is what the overwrite check and the analysis tools need, but they lag by one event. Closing that gap properly means either implementing the shim in the port — which needs the build to stop compiling the generic one, and so is a bigger change than this — or refreshing the clock inside the macro, which puts a discarded return value in an expression. I have taken neither; say if you would prefer one.

Measured under misra_trace_build, first eight entries: 696535203, 696536011, 696536998, 696589316, 696590235, 696640587, 696641814, 696642517. On dev today the same eight read zero.

The trace entry update test gains an assertion that the buffer holds at least one entry the port actually stamped — it is the test that already owns these update blocks, so the check belongs with them. It fails on dev with ERROR #13 under misra_trace_build and passes with this change. Full suites green on the change: 7 of 7 ThreadX configurations, 5 of 5 SMP.

[fdesbiens]

Correcting something in the description above, and sharpening the open question with it.

The description says each entry "carries the reading taken at the previous recorded event", and quotes eight non-zero stamps as evidence. The claim is right; the evidence does not show it. The build those figures came from has a second writer for that clock which I had not accounted for: ports/linux/gnu/CMakeLists.txt defines TX_LINUX_DEBUG_ENABLE unconditionally, and _tx_linux_debug_entry_insert calls clock_gettime into the same _tx_linux_time_stamp on every interrupt disable and restore. In any build from that CMakeLists the value read at the call site was refreshed microseconds earlier by the enclosing TX_DISABLE, so there is no event-scale lag to see and those eight figures only show that the stamps are real.

Building the same configuration with TX_LINUX_DEBUG_ENABLE removed shows the actual behaviour, and it is sharper than I described. The first six entries read 0 732915213 732915304 732915814 732957553 732957783. The lag is exactly one recorded event, and the first entry in a fresh buffer is stamped zero, because nothing has refreshed the clock before it.

So the residual is this: with the change, a build that compiles the debug option out stamps its first trace entry zero and lags every entry by one recorded event. A build from the port's own CMakeLists does neither. Either way it is a large improvement on every entry reading zero, which is what happens today.

On what to do about it, my recommendation is to take this as it stands and not chase the residual here, for a reason that only became clear while measuring.

The obvious port-side fix is to make the time source refresh and read together so it stops depending on who else writes that variable. It works, and it costs more than it looks. The MISRA form evaluates TX_TRACE_TIME_SOURCE as a function argument, which happens whether or not the event's class is enabled, so a self-contained source would call clock_gettime on every attempted insert including every filtered one. Filtering exists to cut tracing overhead, and that would put a syscall back on exactly that path. The in-line form reads inside the class test and would not pay it, so the two builds would diverge again in the other direction.

The fix with no such cost is in common code rather than in the port: have _tx_misra_trace_event_insert read the time source itself after it runs TX_TRACE_PORT_EXTENSION, the way the in-line macro already does, instead of taking it as a parameter. That makes the two paths identical in ordering and costs nothing on filtered events. It also changes a common header and a signature every MISRA-enabled port uses, which is a wider decision than a port fix and yours rather than mine.

Happy to do either, or to leave the residual documented as it is.