• State Resolved
  • Locked Locked
  • Replies 2 replies
  • Subscribers 100 subscribers
  • Views 410 views
  • Users 0 members are here
Support feedback
Options
Options
Similar topics

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

RTOS/TDA2: TI-RTOS/XDC/TDA2: Timestamp not synchronized with multiple LoggerBuf

Piyali Goswami
Mastermind 30235 points
Part Number: TDA2
Other Parts Discussed in Thread: SYSBIOS

Tool/software: TI-RTOS

Hi Team,

I am trying to enable Task and Semaphore event logging on the C66x DSP core of the TDA2x. I have added the following lines to my cfg file.

/* set default diags mask */
var Diags = xdc.useModule('xdc.runtime.Diags');
var Task = xdc.useModule('ti.sysbios.knl.Task');
Task.common$.diags_ENTRY = Diags.ALWAYS_ON;
Task.common$.diags_EXIT = Diags.ALWAYS_ON;
Task.common$.diags_LIFECYCLE = Diags.ALWAYS_ON;
Task.common$.diags_USER1 = Diags.ALWAYS_ON;
Task.common$.diags_USER2 = Diags.ALWAYS_ON;
Task.common$.diags_USER3 = Diags.ALWAYS_ON;
var Semaphore = xdc.useModule('ti.sysbios.knl.Semaphore');
Semaphore.common$.diags_ENTRY = Diags.ALWAYS_ON;
Semaphore.common$.diags_EXIT = Diags.ALWAYS_ON;
Semaphore.common$.diags_LIFECYCLE = Diags.ALWAYS_ON;
Semaphore.common$.diags_USER1 = Diags.ALWAYS_ON;
Semaphore.common$.diags_USER2 = Diags.ALWAYS_ON;
Semaphore.common$.diags_USER3 = Diags.ALWAYS_ON;
/* override diags mask for selected modules */
xdc.useModule('xdc.runtime.Main');
Diags.setMaskMeta(
 "xdc.runtime.Main",
 Diags.ENTRY | Diags.EXIT | Diags.INFO,
 Diags.RUNTIME_ON
);
var Registry = xdc.useModule('xdc.runtime.Registry');
Registry.common$.diags_ENTRY = Diags.RUNTIME_OFF;
Registry.common$.diags_EXIT = Diags.RUNTIME_OFF;
Registry.common$.diags_INFO = Diags.RUNTIME_OFF;
Registry.common$.diags_USER1 = Diags.RUNTIME_OFF;
/* create a logger instance */
var LoggerBuf = xdc.useModule('xdc.runtime.LoggerBuf');
LoggerBuf.TimestampProxy = DMTimestampProvider;
var loggerBufP = new LoggerBuf.Params();
loggerBufP.numEntries = 1024; /* 256 entries = 8 KB of memory */
loggerBufP.bufType = LoggerBuf.BufType_CIRCULAR;
var appLogger = LoggerBuf.create(loggerBufP);
appLogger.instance.name = "TaskLogBuf";
Task.common$.logger = appLogger;
var appLogger2 = LoggerBuf.create(loggerBufP);
appLogger2.instance.name = "SemLogBuf";
Semaphore.common$.logger = appLogger2;

In the CCS ROV classic viewer I am able to see the contents of the TaskLogBuf and the SemLogBuf. However, the timestampRaw field in the output of these two buffers are not in sync.

For example, the time stamp of the TaskLogBuf shows the timestampraw as starting from 1267096108 (as shown below)

57202 1267096108 ti.sysbios.knl.Task LD_ready: tsk: 0x87293264 func: 0x852335a0
57203 1267096150 ti.sysbios.knl.Task LM_switch: oldtsk: 0x872ca0c8 oldfunc: 0x85249720
57204 1267096192 ti.sysbios.knl.Task LD_block: tsk: 0x87293264 func: 0x852335a0
57206 1267096237 ti.sysbios.knl.Task LM_switch: oldtsk: 0x87293264 oldfunc: 0x852335a0
57207 1267116103 ti.sysbios.knl.Task LD_ready: tsk: 0x87293264 func: 0x852335a0
57208 1267116145 ti.sysbios.knl.Task LM_switch: oldtsk: 0x872ca0c8 oldfunc: 0x85249720

and the SemLogBuf shows a completely different time window:

16762 2548036642 ti.sysbios.knl.Semaphore LM_post: sem: 0x8726449c count: 1 6324 ti.sysbios.knl.Semaphore.LM_post
16763 2548616494 ti.sysbios.knl.Semaphore LM_post: sem: 0x87265ea0 count: 1 6324 ti.sysbios.knl.Semaphore.LM_post
16764 2548616560 ti.sysbios.knl.Semaphore LM_post: sem: 0x872644c0 count: 1 6324 ti.sysbios.knl.Semaphore.LM_post
16765 2548616581 ti.sysbios.knl.Semaphore LM_post: sem: 0x8726449c count: 1 6324 ti.sysbios.knl.Semaphore.LM_post
16766 2548636531 ti.sysbios.knl.Semaphore LM_post: sem: 0x87265090 count: 1 6324 ti.sysbios.knl.Semaphore.LM_post
16767 2548636609 ti.sysbios.knl.Semaphore LM_post: sem: 0x872644c0 count: 1 6324 ti.sysbios.knl.Semaphore.LM_post

My goal is to have a single time base view of all the task and semaphore events. I am not using default because I have a lot of HWI, clock tick events which drown the task and semaphore events.

However, if there is a way to either synchronize the loggerBuf timestamps or allow both logging to happen in the same buffer, kindly let me know.

Thanks and Regards,

Piyali

  • 0
    TI__Guru* 96960 points

    Hi Piyali,

    I have a few questions for you.

    1. What version of SYS/BIOS/XDCtools are you using?

    2. Can you try using the default timestamp provider? So basically just comment out LoggerBuf.TimestampProxy = DMTimestampProvider; in the .cfg file

    3. Can you use the same logger instance for both Semaphores and Task? So

    loggerBufP.numEntries = 2048; /* 512 entries = 16 KB of memory */
loggerBufP.bufType = LoggerBuf.BufType_CIRCULAR;
var appLogger = LoggerBuf.create(loggerBufP);
appLogger.instance.name = "TaskSemLogBuf";
Task.common$.logger = appLogger;
Semaphore.common$.logger = appLogger;

    You can use the Diags_setMask to enable/disable logging at runtime. The granularity is very fine. Note, you need to have runtime support enable, so the places you use Diags.ALWAYS_ON, you'll need to use Diags.RUNTIME_ON or Diags.RUNTIME_OFF, depending on what initial state you want.

    Todd

  • 0 in reply to ToddMullanix
    TI__Mastermind 30235 points

    Hi Todd,

    I did some more experiments today and realized why I was seeing the time base for Semaphore and Tasks are off. The Semaphores are firing more often than the Tasks. When I set the buffer type to FIXED, then I start seeing the time bases to match. This works with 2 buffers. I dumped out the 2 buffers and then did a sort of the timestamp and I go the interleaved output I was looking for.  When I redirect both to the same buffer, even then the logs are interleaved.

    1109469844 ti.sysbios.knl.Task LD_ready: tsk: 0x872a3264 func: 0x852335a0 pri: 1 6615 ti.sysbios.knl.Task.LD_ready
    1109469901 ti.sysbios.knl.Task <-- construct: @872a3264('System main') 5853 xdc.runtime.Log.L_construct -2027277724 -2026877459
    1109470255 ti.sysbios.knl.Task LM_switch: oldtsk: 0x0 oldfunc: 0x0 newtsk: 0x872a3264 newfunc: 0x852335a0 6502
    1109472700 ti.sysbios.knl.Semaphore <-- construct: @87283eb4('(null)') 5853 xdc.runtime.Log.L_construct -2027405644 0
    1109475739 ti.sysbios.knl.Semaphore <-- construct: @87283ed8('(null)') 5853 xdc.runtime.Log.L_construct -2027405608 0
    1109476546 ti.sysbios.knl.Semaphore LM_pend: sem: 0x87283ed8 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109476678 ti.sysbios.knl.Semaphore LM_post: sem: 0x87283ed8 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027405608
    1109477311 ti.sysbios.knl.Semaphore LM_pend: sem: 0x87283ed8 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109477353 ti.sysbios.knl.Semaphore LM_post: sem: 0x87283ed8 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027405608
    1109477941 ti.sysbios.knl.Semaphore LM_pend: sem: 0x87283ed8 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109477977 ti.sysbios.knl.Semaphore LM_post: sem: 0x87283ed8 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027405608
    1109478559 ti.sysbios.knl.Semaphore LM_pend: sem: 0x87283ed8 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109478598 ti.sysbios.knl.Semaphore LM_post: sem: 0x87283ed8 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027405608
    1109479174 ti.sysbios.knl.Semaphore LM_pend: sem: 0x87283ed8 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109479210 ti.sysbios.knl.Semaphore LM_post: sem: 0x87283ed8 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027405608
    1109479780 ti.sysbios.knl.Semaphore LM_pend: sem: 0x87283ed8 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109479810 ti.sysbios.knl.Semaphore LM_post: sem: 0x87283ed8 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027405608
    1109480728 ti.sysbios.knl.Semaphore <-- construct: @87283efc('(null)') 5853 xdc.runtime.Log.L_construct -2027405572 0
    1109480797 ti.sysbios.knl.Semaphore <-- construct: @87283f20('(null)') 5853 xdc.runtime.Log.L_construct -2027405536 0
    1109480878 ti.sysbios.knl.Semaphore <-- construct: @87283f44('(null)') 5853 xdc.runtime.Log.L_construct -2027405500 0
    1109480944 ti.sysbios.knl.Semaphore <-- construct: @87283f68('(null)') 5853 xdc.runtime.Log.L_construct -2027405464 0
    1109481166 ti.sysbios.knl.Semaphore LM_pend: sem: 0x872d8008 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109481274 ti.sysbios.knl.Semaphore LM_post: sem: 0x872d8008 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027061240
    1109482477 ti.sysbios.knl.Semaphore LM_pend: sem: 0x872d8008 count: 1 timeout: -1 6354 ti.sysbios.knl.Semaphore.LM_pend
    1109482558 ti.sysbios.knl.Semaphore LM_post: sem: 0x872d8008 count: 0 6324 ti.sysbios.knl.Semaphore.LM_post -2027061240
    1109482672 ti.sysbios.knl.Task LD_ready: tsk: 0x872a32b8 func: 0x85227820 pri: 13 6615 ti.sysbios.knl.Task.LD_ready
    1109482777 ti.sysbios.knl.Task LM_switch: oldtsk: 0x872a3264 oldfunc: 0x852335a0 newtsk: 0x872a32b8 newfunc: 0x85227820 6502

    Thanks so much for the help and the debug directions!

    Thanks and Regards,

    Piyali