• State Resolved
  • Locked Locked
  • Replies 13 replies
  • Subscribers 98 subscribers
  • Views 1418 views
  • Users 0 members are here
Support feedback
Options
Options
Related

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.

C6472 BIOS 6 Timer period does not match Log_print

Eddie3909
Guru 10385 points
Other Parts Discussed in Thread: SYSBIOS

Hi

BIOS 6.32.2.39

CGT 7.05

CCS 4.2.4

C6472

I added a timer to the mutex example by adding the code below. When I run it, the log prints do not match the 1000 usec period I configured the timer for.

(assuming that the log_print units are in nsec.)

I also output the freq that the timer is using and it matches the 700 MHz (i.e. divide by 6 gives 116,666,666 freq)

Time           SeqID  Formatted Msg                                  Logger

--------         ---------  ----------------------------------------        ------------------------------------------------

"44,918",          1,Timer freq is high 0 low 116666666,xdc.runtime.LoggerBuf.Instance#0
"51,844,940",92,Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
"52,544,946",93,Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
"53,244,934",94,Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
"53,944,938",95,Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0

Note that the time between "Timer ISR fired" is not 1000 usec. Its exactly 700 usec. Maybe the timer units aren't in usec in the mutex example?

I've measured the accuracy of the log_print time by toggling LEDs based external events. Consequently, I feel its pretty reliable. I'd like to be able to rely on the timer period too as this module is easy to use.

Also note that the sequence ID in the log is not sequencial.

I stole the configuration code below from the BIOS6 Users Guide spruex3j.pdf (p7-15)

void configureTimer()
{
    Types_FreqHz freq;
    Error_Block eb;
    Timer_Params timerParams;
    Task_Handle taskHandle;
    Error_init(&eb);
    Timer_Params_init(&timerParams);
    timerParams.period = 1000; /* 1 ms */
    timerParams.periodType = Timer_PeriodType_MICROSECS;
    timerHandle = Timer_create(Timer_ANY, timerIsr, &timerParams, &eb);
    if (timerHandle == NULL)
    {
        System_abort("Timer create failed");
    }
    Timer_getFreq(timerHandle, &freq);
    Log_print2(Diags_USER1, "Timer freq is high %d low %d", freq.hi, freq.lo);
}


Any ideas what I should check to debug the discrepancy between the timer period and the log_print time?

I've attached the .c and .cfg files7384.mutex.zip

Cheers

 

 

  • 0
    Guru 10385 points

    Hi

    I added GPIO so I could toggle an LED and measured the period on a scope. The time is exactly 1000 usec as expected yet the log_print time stamps say 700 usec.

    Time                             SeqID  Formatted Msg                                  Logger

    --------                           ---------  ----------------------------------------        ------------------------------------------------

    "27,893",                                1,  Timer freq is high 0 low 116666666,xdc.runtime.LoggerBuf.Instance#0
    "28,045",                                2,  Starting BIOS,                                        xdc.runtime.LoggerBuf.Instance#0
    "728,070",                              3,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
    "1,427,899",                          4,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
    "166,956,104,902",  238510,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
    "166,956,804,904",  238511,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
    "166,957,504,906",  238512,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
    "166,958,204,908",  238513,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0
    "166,958,904,910",  238514,  Timer ISR fired,                                     xdc.runtime.LoggerBuf.Instance#0

     

    Also, why doesn't the log overwrite the old timestamps? The sequence numbers 1,2,3,4 should be overswritten by the new log prints right?

    Cheers

  • 0
    TI__Mastermind 45025 points

    Hi Eddie3909,

    I think your timer is firing correctly.

    The time stamp in the Log_print records is actually coming from the TSCH/TSCL registers.  These registers store CPU cycles.

    So, you can convert the Log time stamp to seconds by:

    time in seconds = (t1 - t0) / (cpu freq in Hz)

    e.g.

    (52,544,946 cycles - 51,844,940 cycles) / (700,000,000 cycles / second) = 0.001000 seconds = 1000 us

    Steve

  • 0 in reply to Steven Connell
    Guru 10385 points

    Hi Steve

    Thats strange. In our production code, I'm setting the clock period to 1 and see the log

            Clock_Params_init(&clkParams);
                clkParams.period = 1;   // number of ticks (each tick = 1 msec)
            clkParams.startFlag = TRUE;
                clkParams.arg = (UArg)0x5555;
                Clock_create(OutputMgrTimerInterruptHandler_60Hz,INITIAL_CLOCK_TIMEOUT, &clkParams, NULL)

    The log show the timer firing at 394 msec, 395 msec, 396 msec etc. They are almost 1 msec as expected. I'm going to measure this signal on the scope again but I'm pretty sure it will show 1 msec.

    "394,568,844",961,"Dop nq 1: t= 252, nsamps=24 tsamps=8016"
    "395,567,635",962,"Dop nq 2: t= 380, nsamps=48 tsamps=8040"
    "396,566,827",963,"Dop nq 3: t= 508, nsamps=72 tsamps=8064"
    "397,566,178",964,"Dop nq 4: t= 636, nsamps=96 tsamps=8088"

    If it shows 1msec, it would suggest there is a way to get CCS to take the timer register values and convert them to time. Possible?

    Cheers

  • 0 in reply to Eddie3909
    TI__Mastermind 45025 points

    Hi Eddie3909,

    I've talked to the CCS guys and the problem is that they need to have the CPU frequency in order to convert ticks to time.  I'm still waiting for some more info to see if there's a way to do it, but it's sounding like this may not be available in the current version of CCS.

    Steve

  • 0 in reply to Steven Connell
    TI__Mastermind 45025 points

    Can you please attach  your your *.cfg file?

  • 0 in reply to Steven Connell
    Guru 10385 points

    Hi Steven

    The .cfg is attached to the original post.

    Cheers

    Eddie

  • 0 in reply to Eddie3909
    TI__Mastermind 45025 points

    Hi Eddie,

    Can you right click on your log window then select "columns".  Then ensure that both "time" and "ticks" are checked?  Are the values for 'ticks' and 'time' the same?

  • 0 in reply to Steven Connell
    Guru 10385 points

    Hi Steven

    Steven Connell said:
    Are the values for 'ticks' and 'time' the same?

    Yes they are the same in my mutex example. I will check in our production code.

    Cheers

  • 0 in reply to Eddie3909
    Guru 10385 points

    Hi Steven

    Eddie3909 said:
    Yes they are the same in my mutex example. I will check in our production code.

    Yes, our production code has the same settings, and it outputs time in usec whereas the mutex is doing cpu cycles.

    I also checked the "clock" module in both and each has 1000 for the tick period.

    Cheers

  • 0 in reply to Eddie3909
    TI__Mastermind 45025 points

    Eddie3909,

    I was able to look into this further.  In order to get the time displayed CCS needs to have the CPU speed.  This is achieved by printing this information into a LoggerBuf called RTASupportLog.  In order for that to happen, you must configure the RTA agent in your application configuration file (*.cfg).

    So, you would need to make sure the following have been done:

    1. Your *.cfg file has:

    var Agent = xdc.useModule("ti.sysbios.rta.Agent");

    Agent.addSupportLogger = true;

    2. confirm that your application has a valid timestamp provider (e.g. ti_sysbios_family_c64p_TimestampProvider).

    Once you run the application, you should be able to open the log called "RTASupportLog".  This log will have the CPU speed printed to it if it is working correctly.

    If all of these conditions are met, then you should see the tick value displayed in time.

    Steve

  • 0 in reply to Steven Connell
    Guru 10385 points

    Eureka!

    I have stared for hours at our production .cfg and didn't find anything related to log or timer. I had no idea to look for "agent". That said, our code does not have the

    Steven Connell said:
    Agent.addSupportLogger = true;
    code in it.

    But it does have

    var ti_sysbios_rta_Agent = xdc.useModule('ti.sysbios.rta.Agent');
    ti_sysbios_rta_Agent.configureSystemLog = false;
    ti_sysbios_rta_Agent.configureLoadLog = false;
    ti_sysbios_rta_Agent.transport = ti_sysbios_rta_Agent.Transport_STOP_MODE_ONLY;

    I added the above to a timer test app I created and viola, the log time is exactly the 1 msec I expect (it used to be 700 usec before I added the "Agent"

    "1,585,056,791",1915,Timer ISR fired,Main Logger
    "1,586,056,754",1916,Timer ISR fired,Main Logger
    "1,587,056,748",1917,Timer ISR fired,Main Logger
    "1,588,056,754",1918,Timer ISR fired,Main Logger

    Thanks a bunch for persevering with me!

    Cheers

  • 0 in reply to Eddie3909
    Guru 10385 points

    FYI

    There is no "verify answer" available on the page so you'll have to do it.

    Cheers