Cycles out of sync

[thelison]

Hi!
Trying to use trice on our target over RTT, but seem to get out of sync, getting:
Jun 14 15:48:55.933737 JLINK: Testit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testCYCLE: 57 not equal expected value 56 - adjusting. Now 57 CycleEvents
Any hints on why I get this?

Attached a log file with RTT output:
RTTLogger_Channel_Terminal.log

Running one single FreeRTOS thread with a loop calling trice twice with a second sleep in between:

while (rval == 0) {
        trice( iD(4715), "Testit!");
        os_task_sleep(1000);
        trice( iD(5913), "test");
        os_task_sleep(1000);
}

Printing ascii messages over RTT works fine, displayed in RTT Viewer.

BR
/Thomas

[rokath]

Viewing the provided log file:

$ trice l -p FILEBUFFER -args RTTLogger_Channel_Terminal.log
2024/06/15 11:48:57 fn=til.json, maybe need to create an empty file first? (Safety feature)
2024/06/15 11:48:57 Error in manage.go:155: func 'github.com/rokath/trice/internal/id.TriceIDLookUp.fromFile' -> open til.json: The system cannot find the file specified.

EDIT: When providing a binary Log file, the til.json file is necessary to read it.

Please provide your triceConfig.h file and the command line you use. Otherwise it is hard to help.

In the experimentalProtectOption branch the test folder contains several successful tested configuration variants. Also you can check trice/examples/vsCode_NucleoF030R8_instrumented. This is a working hardware example. Just look at the RTT settings.

EDIT: The Trice tool command line for the RTT output is:
trice l -p jlink -args "-Device STM32F030R8 -if SWD -Speed 4000 -RTTChannel 0" -pf NONE -d16"

[thelison]

Hi

Thanks for your support.

The config file:
triceConfig.txt

The til file :
til.json

My command line:
trice.exe l -pf none -p JLINK -args "-Device NETX90_APP -if SWD -Speed 4000 -RTTChannel 0
I also tested with -d16 option

When checking the file offline I used:
trice.exe l -pf none -p FILE -args RTTLogger_Channel_Terminal.log

I'll double check the RTT setting.

/Thomas

[rokath]

Are you going to use both: direct AND deferred output? That is possible, but I guess you are just wont the direct output via SEGGER_RTT. So I recommend to change #define TRICE_BUFFER TRICE_RING_BUFFER into #define TRICE_BUFFER TRICE_STATIC_BUFFER. That probably will solve your problem. When you write into the ring buffer without reading it, it will be filled and then the last Trices get overwritten. Because your Trice messages are all equal, there is no data garbage, just missing messages. Currently is work in progress (#462) to protect against such wrong use cases.

If you want also deferred output you need to call TriceTransfer() cyclicylly to serve deferred output.

Analyzing:

$ trice l -p FILEBUFFER -args RTTLogger_Channel_Terminal.log -pf none -d16
Jun 16 19:38:29.103331  FILEBUFFER:              CYCLE: 121 not equal expected value 192 - adjusting. Now 1 CycleEvents
Jun 16 19:38:29.103331  FILEBUFFER: testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!testTestit!CYCLE: 148 not equal expected value 147 - adjusting. Now 2 CycleEvents
Jun 16 19:38:29.103949  FILEBUFFER: Testit!testTestit!testTestit!CYCLE: 154 not equal expected value 153 - adjusting.
...

• The first cycle error is ok, because we start in the middle of nowhere.
• The second cycle error is CYCLE: 148 not equal expected value 147 - adjusting. Now 2 CycleEvents.
• Lets look in a different way: Without -pf NONE, the Trice tool cannot get the trice messages because it is package framing NONE but assumes package framing TCOBS per default. So we can see the byte stream in a convenient way.

$ trice l -p FILEBUFFER -args RTTLogger_Channel_Terminal.log -debug
TCOBSv1: 19 57 79 00
->TRICE:
TCOBSv1: 6b 52 7a 00
->TRICE:
TCOBSv1: 19 57 7b 00
->TRICE:
TCOBSv1: 6b 52 7c 00
->TRICE:
TCOBSv1: 19 57 7d 00
->TRICE:
TCOBSv1: 6b 52 7e 00
->TRICE:
TCOBSv1: 19 57 7f 00
->TRICE:
TCOBSv1: 6b 52 80 00
->TRICE:
TCOBSv1: 19 57 81 00
->TRICE:
TCOBSv1: 6b 52 82 00
->TRICE: 6b 52 ff ff ff ff
Jun 16 19:42:56.088229  FILEBUFFER:              len(p.B) = 0 < p.ParamSpace =  32767 - ignoring package []
Jun 16 19:42:56.088229  FILEBUFFER: Hints:Baudrate? Encoding? Interrupt? Overflow? Parameter count? Format specifier? Password? til.json? Version?
Jun 16 19:42:56.088229  FILEBUFFER: ERROR:ignoring data garbage
Jun 16 19:42:56.088229  FILEBUFFER: Hints:Baudrate? Encoding? Interrupt? Overflow? Parameter count? Format specifier? Password? til.json? Version?
TCOBSv1: 19 57 83 00
->TRICE:
TCOBSv1: 6b 52 84 00
->TRICE:
TCOBSv1: 19 57 85 00
->TRICE:
TCOBSv1: 6b 52 86 00
->TRICE:
TCOBSv1: 19 57 87 00
->TRICE:
TCOBSv1: 6b 52 88 00
->TRICE:
TCOBSv1: 19 57 89 00
->TRICE:
TCOBSv1: 6b 52 8a 00
->TRICE:
TCOBSv1: 19 57 8b 00
->TRICE:
TCOBSv1: 6b 52 8c 00
->TRICE
TCOBSv1: 19 57 8d 00
->TRICE:
TCOBSv1: 6b 52 8e 00
->TRICE:
TCOBSv1: 19 57 8f 00
->TRICE:
TCOBSv1: 6b 52 90 00
->TRICE:
TCOBSv1: 19 57 91 00
->TRICE:
TCOBSv1: 6b 52 92 00
->TRICE:
TCOBSv1: 6b 52 94 00
->TRICE:
TCOBSv1: 19 57 95 00
->TRICE:

• We can ignore the error messages here. They come from "successful" decoded "TCOBS" packages resulting in data garbage.

• The 3rd bytes are the cycle counter states.

• As you can see, the cycle 0x93 = 147 is missing.

• That tells us, the problem is in the target code.

• Would you please add target time stamps and a newline like TRice( "TestIt\n");?

• Just to be curious: What is the BUFFER_SIZE_UP value in your SEGGER_RTT_Conf.h?

• Please try also TRICE_SEGGER_RTT_8BIT_DIRECT_WRITE==1 with TRICE_SEGGER_RTT_32BIT_DIRECT_WRITE==0 to use the original SEGGER code just for investigation.

• One more hint: In the 1ms interrupt you could write for a global uint16_t ms16 variable

    ms16++;
    ms16 = ms16 < 10000 ? ms16 : 0; 

and in your triceConfig.h use

#define TriceStamp16() ms16

That allows you to use 16-bit time stamps most of the time and only at least every 10s a 32-bit time stamp Trice message is needed.

[thelison]

Hi!

Simply adding newline at end of string solved the problem.
Even with a ring buffer.
Is it some kind of flush problem?

Added timestamps with TRice and now I get like:
Jun 17 15:21:12.789900 JLINK: pn_task.c 64 0,689_200 test 3
Jun 17 15:21:13.593590 JLINK: pn_task.c 62 0,690_050 Testit 2!
Jun 17 15:21:14.604789 JLINK: pn_task.c 64 0,691_050 test 3
Jun 17 15:21:15.409675 JLINK: pn_task.c 62 0,691_900 Testit 2!
Jun 17 15:21:16.521866 JLINK: pn_task.c 64 0,692_900 test 3
Jun 17 15:21:17.231593 JLINK: pn_task.c 62 0,693_750 Testit 2!

BTW we haven't decided on deferred output or not, trying with RTT to start with, and maybe will try UART too.

The RTT BUFFER_SIZE_UP is set to 1024

FYI, it also worked fine with TRICE_SEGGER_RTT_8BIT_DIRECT_WRITE=1 and TRICE_SEGGER_RTT_32BIT_DIRECT_WRITE=0.

Thanks for your quick support!
/Thomas

[rokath]

Yes, it works also with the ring buffer, even when not reading it out. During the direct trice transfer, the trice data are written immediately and the copy into the ring buffer is not used at all. Sorry for my wrong sayings. Weird is, that adding \n solved the problem, as you reported. The target does not know anything about the strings. So when you edit the til.json file, for example adding/removing \\n there, the target code is not influenced at all. But we have seen missing Trice packages in the binary logfile. Would you please have a closer look at this again. Maybe there is a hidden issue. BTW: How exactly did you generate the binary logfile? BR Thomas

[thelison]

Hi!

Sorry for the delayed answer, had to do other stuff :)
The binary log file was created using JLinkRTTLogger.exe.
Sending a zip with log and json files.
trice.zip

Works fine both listening directly and when reviewing a logged file.
Commands:
trice.exe l -pf NONE -d16 -p JLINK -args "-Device NETX90_APP -if SWD -Speed 4000 -RTTChannel 0"
and
trice.exe l -pf NONE -p FILE -d16 -args RTTLogger_Channel_Terminal.log

When trying to remove the \n characters, it hangs with one output line, both 'live' and when reading from file.
Attached output
trice2.zip

Interesting finding: If I manually add \\n to the strings in til.json it seems to work!
I.e. seems to be the host side tool having problems.

BR
/Thomas

[rokath]

The Trice tool collects all Trices until one Trice ends with a newline and then it emits the concatenated line in one shot. So your observation is as expected: No newline = no output. You can do anything with the til.json. The strings inside it are used for logging. For example you could translate it in different languages, also allowing different outputs without changing a bit in the target binary. Is there any useful case, not to have Trices ending with a newline at all? If yes, I would open an issue to change that behaviour.

[thelison]

Hi!
As you ask, is there a use case not to have a newline?
Might indicate that trice itself could maybe add a newline, always?
BR
/Thomas

[rokath]

Good idea. This would allow to write trice( "hi" ); like logs without \n at the end all the time. But you loose the capability to concatenate several trice messages into a single line. An additional command line switch could be invented for that, so the user can choose.