SPE: GTE provided TSC sometimes goes backwards

maxe777 · June 27, 2023, 5:10pm

Hello,

I’m working with the following setup:

Jetson Orin Nano 4GB module
Custom carrier board
Jetpack 5.1.1 / L4T 35.3.1
Sources for the SPE part of the same release

The GPIO & GTE example apps are now running fine (thanks for the help on: GTE configuration and usage on SPE).

I modified them to try to rely on the GTE FIFO, and stamp both rising and falling edge events. So far the changes I did are:

enable the GPIO interrupt on both edge: tegra_gpio_set_irq_type(GPIO_APP_IN, TEGRA_GPIO_IRQ_DOUBLE_EDGE, TEGRA_GPIO_IRQ_RISING_EDGE | TEGRA_GPIO_IRQ_FALLING_EDGE);
only set the GPIO to low in the IRQ handler when the GPIO was set to high
Set GTE_TEST_FIFO_OCCUPANCY to 3

It kind of works, but I observe some weird glitches.

If I monitor the line on the scope, my signal follows this periodic pattern:
low for 280 ms – high for 19 ms – low for 280ms – high 1ms – low for 298 ms – high for 1ms
This distribution is expected since I have a couple of debug prints in the GTE IRQ, which every 3 interrupts impacts the GPIO toggle time (19ms instead of 1 ms).

The GTE reports consistent timings with this pattern, except at some occasion. Sometimes (can be every 20-40 readouts), I do observe that the readout of TSC_low (GTE_APS_TETSCL_0 from tegra_gte_read_fifo) is going backwards (while TSC_high is stable). A time serie of TSC_low can look like this:
-74d23db
-7d2a7ab // +280 ms
-7dbb722 // +19 ms
-8613ab1 // +280 ms
-861b4a1 // +1ms
-8efcdbb // +298 ms
-8f047a9 // +1ms
-975cb79 // +280 ms
-a7edaef // + 555 ms – unexpected
-a045e7f // - 256 ms – unexpected
-a04d871 // + 1ms

The occupancy reported by tegra_gte_get_status is always 3.

Would you have an idea about what is going on?

I made multiple experiments, and I noticed that the least often I trigger the pulse, the more often it seems that some events get reported incorrectly or get lost by the GTE.

Also, I could not find the description of the involved GTE registers in the TRM, and the readout procedure on the linux driver (kernel/nvidia/drivers/staging/platform/tegra/gte/tegra194_gte.c) looks a bit different - but the TSC readout follows the same approach.

Some help would be welcome. Thanks.

jachen · June 28, 2023, 1:47am

Hello,
You mean that you have print code in ISR? If then, please remove those print, which may have bad impact on logic.
You can record the timestamp to array in ISR, and print at normal task for debug.

From you log, it seems that something’s wrong with fifo, and new TS is retrieved.

br
ChenJian

maxe777 · June 28, 2023, 11:12am

Hi @jachen,

Thanks for the input and your fast reply. To be clear, I used the print_isr function, in the same way the NVidia provided examples are doing.

To be on the safe side this time, I removed all prints from the ISRs, and I used a threaded IRQ approach as you suggested; I basically store the TSC values in an array from the GTE ISR, and maintain read and write counters. The prints are now done from a FreeRTOS task I added in the GTE example.

My signal is now a 1 ms pulse, which repeats every T ms.
So before the 3 events are reached, the IRQ raised, and the GTE FIFO read out, the events in the FIFO will have a time span of T+1ms

My observations remain similar:

If the interval T is “short” (250ms or less), everything seems to be alright
If the T gets larger, then I observe timestamps I can’t explain. Some look correct, some go backwards and some events seem to be dropped. The larger T gets, the worse the behavior seems to be.

As far as I understand from the TRM, , even if the full TSC value (64 bits over 2 registers) is exposed by the GTE for the captured events, it seems like the GTE is only latching a smaller part of the TSC.
In section 2.9.2 of the TRM, the diagram shows that the capture record is made from TSC[TBD:0]. I guess if TBD would be around 22, this could explain the observed behavior.

Could you please let me know if you suspect that my test case on the SPE is flawed, or if this bevahior may be linked to some HW restrictions.

Regards

jachen · June 29, 2023, 7:21am

Hello,
Per your input:

If the interval T is “short” (250ms or less), everything seems to be alright
If the T gets larger, then I observe timestamps I can’t explain. Some look correct, some go backwards and some events seem to be dropped. The larger T gets, the worse the behavior seems to be.

You mean with bigger T, the timestamps go wrong, whereas smaller T, everything’s good? I’m a little surprised by that.

From the original timestamp you pasted, it looks that some timestamps are mis-ordered, dropped, or overwritten.

122,495,963
131,245,995	280.001024
131,839,778	19.001056
140,589,745	279.998944
140,620,961	0.998912
149,933,499	298.001216
149,964,713	0.998848
158,714,745	280.001024
168,058,495	299
168,089,713	0.998976
176,085,743	255.87296

So far, I have no idea about why.
Can you do another test, that to compare timestamps by GTE, together with software (reading TSC)?

In addition, if the GPIO is toggled regularly, like 500ms or so, between 0 and 1, can you still observe the error?

br
ChenJian

maxe777 · June 29, 2023, 8:42am

Hi @jachen ,

Thanks for your follow up.

You mean with bigger T, the timestamps go wrong, whereas smaller T, everything’s good? I’m a little surprised by that.

This is indeed what I observe. The time serie you posted illustrate the kind of corruption I can get. Depending on the exact period T, I may have only missed events and no mis-ordering (when increasing the period to 1s for instance).

I collected the TSC (using tegra_tke_get_tsc64()) when toggling the GPIO, and I observed the following:

In a working case (GTE timestamps are as expected), the software collected TSC are consistent with the GTE timestamps (the offset between the series is in the microsecond range).
In a case with corrupted GTE timestamps (eg 1ms pulse every 500 ms), the software collected TSC look fine

Switching to a symetric pulse does not change the overall picture.
The software collected TSC are fine, irrespectively of the period. The GTE timestamps show the same behavior. For a periodic toggle every 100ms everything looks good. When increasing the toggle period to 200ms, then the same artifacts appear on the GTE timestamps.

Please let me know if you have further idea for investigation. Otherwise I can offer to prepare patches to apply on top of the Nvidia provided code to help to reproduce.

Best regards

jachen · June 30, 2023, 7:30am

Hello,
Can we start with a simple case first?
Per your comment:

When increasing the toggle period to 200ms, then the same artifacts appear on the GTE timestamps.

Just keep the original code, (with print_isr at gte_irq_callback). Make GPIO_IN toggle 0 1 0 1 …, with 200ms interval.
Please upload the logs if issue appears.

My bandwidth and platform may be limited to debug this issue locally. If possible, please help to test and collect more logs.

Thanks.

br
ChenJian

maxe777 · July 4, 2023, 10:47am

Dear @jachen,

Thanks for your reply. I followed your recommendations.

I started with the original code, as released by Nvidia, with the minimal changes to get it working on my HW. See this attached file to see the diff custom_board.diff (1.8 KB)
Then I modified the example to have a square pulse, toggling every 200ms. Here is the patch: toggle_200ms.patch (662 Bytes)
And finally, I set the GTE FIFO occupancy to 3: gte_fifo_occupancy_3.patch (428 Bytes)

Please let me know if you see any issue with the submitted patches. Below are all the logs I gathered, including for a case with the issue present.

Also, in case you wonder, all binaries are generated with the toolchain recommended by Nvidia for SPE development.

Looking forward to your feedback.

Logs for the initial state

Console output

gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 5369c725
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec 5e9ee838
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 69d40949
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec 75092a5b
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 803e4b6c
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0

Summary

Raw value (hex)	Ticks (hex2dec)	Delta	Interval in seconds (* 32/1e9)
5369c725	1399441189	-	-
5e9ee838	1587472440	188031251	6.017000032
69d40949	1775503689	188031249	6.016999968
75092a5b	1963534939	188031250	6.017
803e4b6c	2151566188	188031249	6.016999968

The line is set to toggle every 3s (checked with the scope), the GTE stamps on the rising edge (i believe the ISR print provided in the example is not correct - the rising/falling edge report is incorrect, and the unit is ticks and not nanoseconds).

I do observe consistently a 6s interval report, this is matching my expectations.

Logs for the requested test case (toggle every 200ms)

Console output

gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 3a340c9a
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec 3afae3ed
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 3bc1bb3e
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec 3c889290
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 3d4f69e2
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec 3e164132
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec 3edd1886

Summary

Raw value (hex)	Ticks (hex2dec)	Delta	Interval in seconds (* 32/1e9)
3a340c9a	976489626	-	-
3afae3ed	989520877	13031251	0.417000032
3bc1bb3e	1002552126	13031249	0.416999968
3c889290	1015583376	13031250	0.417
3d4f69e2	1028614626	13031250	0.417
3e164132	1041645874	13031248	0.416999936
3edd1886	1054677126	13031252	0.417000064

I do observe consistently a 0.4s interval report, this is matching my expectations. I also checked the line on the scope to make sure the pulse is generated as expected.

Logs for the toggle every 200ms - with GTE FIFO occupancy set to 3

Console output

can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec c42524b1
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec c4e82b73
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec c4ab3234
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec c77a9ecb
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec c73da58d
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec c700ac4e
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec c8d018e5
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 0 Time Stamp in nanosec c8931fa7
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 0 Time Stamp in nanosec c9562668

The settings seems to be effective since now the GTE output is present only 1 time out of 3, and 3 GTE timestamps are reported.

Summary

Raw value (hex)	Ticks (hex2dec)	Delta	Interval in seconds (* 32/1e9)
c42524b1	3290768561	-	-
c4e82b73	3303549811	12781250	0.409
c4ab3234	3299553844	-3995967	-0.127870944
c77a9ecb	3346702027	47148183	1.508741856
c73da58d	3342706061	-3995966	-0.127870912
c700ac4e	3338710094	-3995967	-0.127870944
c8d018e5	3369081061	30370967	0.971870944
c8931fa7	3365085095	-3995966	-0.127870912
c9562668	3377866344	12781249	0.408999968

Now the interval is sometimes correct, sometimes not, or negative jumps appear.

jachen · July 7, 2023, 6:41am

Hello,
So only with ’ GTE FIFO occupancy set to 3’, the timestamp looks weird?
Why you try that config? Configurations other than default may have to accompany with other changes.

br
Chenjian

maxe777 · July 7, 2023, 9:16am

Hi @jachen,

So far the issue was only visible with the GTE FIFO occupancy set to 3. But I did more tests, and I can trigger it without changing this flag.

I know in my application I will have multiple events to stamp (across 6 different GPIOs) happening in a short time frame, and it’s unlikely that each GTE timestamp will be read out before the next one comes in. In other words:

I do expect to face situations where the GTE FIFO occupancy will be greater than one. I wanted to validate that this works - and setting the FIFO occupancy to a higher threshold looked like the easiest to trigger that test case.
I also know how many events are expected. So I do not need to get the interrupt for the first available timestamp - it would help to reduce the amount of interrupt to process, but this is not a must.

But definitely, checking that the GTE timestamps come out as expected when multiple of them are in the FIFO was my primary scenario to validate.

So far, I did this only by changing the define GTE_TEST_FIFO_OCCUPANCY from 1 to 3.

Today, I tried a different approach, and I basically enabled/disabled the GTE IRQ periodically to get multiple elements in the FIFO- to emulate a busy CPU which could not service the GTE IRQ fast enough to guarantee that only a single timestamp is in the FIFO. My attempt to do this is in this patch: gte_irq_toggle.patch (1.1 KB)

In this test, GTE_TEST_FIFO_OCCUPANCY is set to 1.

The high level behavior is the one I expect (3 timestamps are coming at once) as you can see in this output example:

Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 2 Time Stamp in nanosec 94a8f620
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 2 Time Stamp in nanosec 956bfce2
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 2 Time Stamp in nanosec 952f03a2
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 2 Time Stamp in nanosec 97fe703b
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 2 Time Stamp in nanosec 97c176fc
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 2 Time Stamp in nanosec 97847dbe
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
gpio_app_task - Setting GPIO_APP_OUT to 1 - IRQ should trigger
can_gpio_irq_handler - gpio irq triggered - setting GPIO_APP_OUT to 0 
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 2 Time Stamp in nanosec 9953ea55
Slice Id: 2, Event Id: 14 (Other), Edge = falling, Raw Time stamp = 2 Time Stamp in nanosec 9916f116
Slice Id: 2, Event Id: 14 (Other), Edge = rising, Raw Time stamp = 2 Time Stamp in nanosec 99d9f7d8

It is quite obvious that the issue is also present is this time series. The GPIO was still set to toggle every 200ms, and I checked it on the scope.

Please let me know if you see anything which may explain why the values do not appear to be the correct one. This is critical for our application.

maxe777 · July 20, 2023, 11:59am

Hi @jachen,

Would you have a status update to share? Anything else I could do to clarify or support better this ticket?

Many thanks

jachen · July 21, 2023, 5:46am

Hello, maxe777:
Sorry that I still got no chance to check this issue locally. The change you made is not verified internally.
Please give me more time to check locally.

br
ChenJian

maxe777 · July 21, 2023, 7:17am

Hi @jachen,

Thanks for your reply and the update. Sure, I understand. Looking forward to your feedback.

Best regards

jachen · July 26, 2023, 11:18am

Hello,
Can you add debounce code in GPIO app and try again?

val = gpio_set_irq_type(GPIO_APP_IN, GPIO_IRQ_SINGLE_EDGE,
GPIO_IRQ_RISING_EDGE);
if (val) {
error_hook(“gpio_set_irq_type failed\r\n”);
return;
}
++ val = gpio_set_debounce(GPIO_APP_IN, 0xff);
val = gpio_set_irq_handler(GPIO_APP_IN, can_gpio_irq_handler, NULL);
if (val) {
error_hook(“gpio_set_irq_handler failed\r\n”);
return;
}

br
ChenJian

maxe777 · August 2, 2023, 8:51am

Dear @jachen,

I checked your proposal, and the observed behavior remains unchanged.

Please note that in your suggestion, the debounce value is 0xff (= 255), which I had to lower since the signal for this test is toggling every 200ms. While a value of 255 was not allowing the GTE interrupt to trigger anymore, using a value of 180 (<200) was possible, but did not affect the outcome of the test.

Were you able to reproduce on your side?

Best regards

jachen · August 3, 2023, 8:31am

Hello,
Let’s work on it step by step. So far, I still don’t know why ‘GTE FIFO occupancy set to 3’ will result in timestamp backward.
My local test shows similar issue (timestamp backward) without debounce setting.
But after that, timestamp looks good.

So can you reduce the GPIO toggle frequency to a very low value, like 1HZ or 0.5Hz, and ‘GTE FIFO occupancy set to 3’. If you get same result with mine, we can go forward for next move.
If not, we should find out the gap first.

br
ChenJian

maxe777 · August 4, 2023, 8:58am

Hi @jachen,

Thanks a lot for taking the time to reproduce and confirming that you observe the same

I lowered the frequency to toggle the ligne every 2s, with a debounce value of 0xff and I cannot replicate your results.
As soon as the FIFO occupancy is set to 3 instead of 1, the values appear to be quite stochastic.

With a FIFO occupancy of 1, I get a consistent delta of 4.015s.
With a FIFO occupancy of 3, I got the following time delta (in seconds):


-0.287967296000005
0.248903616000007
12.08506368
-0.287967295999991
0.248903615999993
11.548192768
0.248903615999993
0.248903616000007
-125.890760704
0.248903616
0.248903616

Just in case it can help, please find my current version of the gpio-app file. gpio-app.c (3.6 KB)

Regards

maxe777 · August 18, 2023, 7:14am

Hi @jachen,

Would you have an update to share?

Thanks

jachen · August 18, 2023, 7:23am

Hello,
Sorry for late reply.
I need more time to check this issue locally.

More updates later.

br
Chenjian

maxe777 · August 18, 2023, 9:20am

Hi @jachen,

Thanks for the prompt confirmation.

Best regards

system · September 1, 2023, 9:20am

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.