SRIO time measure problem

Hi Shmulik

I encounter similar problem with a multicore demo example. The way I solved it was by adding a new hot menu button and run it after I did system reset and cpu reset and before reload the code and run it again.  Why don't you try?

Use core 0 and add to the gel file  (If you use the release gel file) the following:

 
menuitem "EVMC6678L Reset Function";

hotmenu Global_Setup_Silent()
{
 Global_Default_Setup_Silent() ;
}

As I said, before I reload the code, select core 0, and run the script  EVMC6678L Reset Function->Global_Setup_Silent  and then load the code and run

It worked for me.  try it, and tell me if it works for you

Ran

Your time counter loop may work, I'm not familiar with that approach.  Here is what we currently use:

**********

#include <stdio.h>

#include<c6x.h>

unsigned int t_start_l,t_start_h;
unsigned int t_stop_l,t_stop_h;
unsigned int t_overhead_l,t_overhead_h;

int main(int argc, char *argv[])
{
   int i;
   TSCL = 0;
   TSCH = 0;
   t_start_l = TSCL;
   t_start_h = TSCH;
   for (i=0; i<100000000; i++)
   {
      ;
   }
   t_stop_l = TSCL;
   t_stop_h = TSCH;
   t_overhead_l = t_stop_l - t_start_l;
   t_overhead_h = t_stop_h - t_start_h;
   printf("done, t_overhead_h = 0x%08x\tt_overhead_l=0x%08x\n",t_overhead_h,t_overhead_l);
}
**********

Another thing that comes to mind when reading this, is the following thread regarding SRIO reset ISO.  Are you disabling before you do the reset?

http://e2e.ti.com/support/dsp/c6000_multi-core_dsps/f/639/t/124376.aspx

Regards,

Travis

Hi Ran,

I tried what you told me but it didn't solve my problem.

If you have another idea, please, let me know.

Thanks.

Hi Travis,

I disabled the related bit in the ISO.

I used the TI's routines for time measurement (I attached them below) and I know they work ok:

;------------------------------------

;Enables the counter

TSC_enable:

     RETNOP     B3, 4

     MVC            B4,  TSCL

;------------------------------------ 

;Reads the TSC registers pair

TSC_read:

     RETNOP      B3, 2

     DINT

||   MVC  TSCL,     B4

      MVC  TSCH,    B5

||   RINT

||   MV     B4,         A4

;    MVC   DNUM,   B5

     MV      B5,         A5

;---------------------------------------

Perhaps if somebody in TI could run the modified example, you could see the problem.

Thanks.

Shmulik

I might have time to try your modifications tomorrow.  You could zip it up and post the project.  First I want to make sure you are going through the correct proceedure.  So after modifying the code for the SRIO ISO fix, you load and run the program, then you should do the following from within the CCS Debug window:

1) click on the "terminate" icon, which is the red square

2) Hit the rst_Full1 push button on the EVM

3) click on the "debug" icon, which is the bug icon

4) click RUN --> Reset-->System Reset

5) Connect to target

6) load program

7) rerun

Hi Travis,

I attached the modified Loopback folder

These files are installed in my pc in the path:

C:\Program Files\Texas Instruments\pdk_C6678_1_0_0_11\packages\ti\drv\srio\test\Loopback

Please, add to the project also the file TSC.asm found in the attached zip.

I used the emvc6678l.gel from the last ccs version.

I want to tell you also that the same problem was observed for Ftype 9.

Thanks.

Shmulik.

I run your code, with some minor changes (deleted some of the other printf so it is easy to see the measurements) and I run it the following way which is similar to what you saw:

First I reboot the EVM

Load the code on 4 cores and run

I get the following results:

C66xx_0]

[C66xx_0] SRIO Transference for DirectIO 4096 Bytes, Average Time: 12.319 uSec, Min= 12.012 uSec, Max= 12.445 uSec

[C66xx_0]

[C66xx_0] SRIO Socket Average Send =639.7 nSec

[C66xx_0] SRIO Socket Send Min =631.0 nSec

[C66xx_0] SRIO Socket Send Max =713.0 nSec

Next I stop the run, do system reset, do CPU reset to all four cores, and re-load and run again. The results are as follows:

C66xx_0]

[C66xx_0] SRIO Transference for DirectIO 4096 Bytes, Average Time: 3.365 uSec, Min= 3.353 uSec, Max= 3.455 uSec

[C66xx_0]

[C66xx_0] SRIO Socket Average Send =640.2 nSec

[C66xx_0] SRIO Socket Send Min =630.0 nSec

[C66xx_0] SRIO Socket Send Max =711.0 nSec

Next I did some changes.  I change the clock variables to int and compensate on overflow, I moved the timers outside of processing to the send and receive only, and I did some other minor changes like averaging on 16 elements instead of 10 so I use integer and not floating point arithmetic, and printed out all the time measurements.

Now I get the same numbers (more or less) in the first run and consecutive runs.

It is conceivable that I did not run the code enough time,  but in anyway, I would like you to run the code that is attached and compare it with your code

Ran

Ran, Travis,

After several times I ran your modified routine and I saw the same problem.

Besides, I used the clock() routine using the header time.h and enabling it using run->clock->Enable instead of using the TSC routines.

Thanks.

Shmulik.

OK  So this is what I want you to do

1. Describe in details  what you do when you see the same results.  I want to be able to repeat it here

2. We need to simplify the code as much as we can and still see the problem.  Can you delete as much as possible  (all other tests, run on a single core, etc.)  and still see the problem?  (and of course tell me exactly how to reproduce it)

Thanks

Ran

Hi,

Thanks for your answer, but it seems that we need your help.

I want to remark that the same problem exists not only in Direct IO, but also in Ftype 9 as we wrote in the first letter of this post.

We have no way to easily recreate the problem. It occurs randomly. Sometimes it appears in the first attempt but other timesit takes a long time before it appears.

This behavior exists in the example provided by TI and also appeared when you yourself ran it.

As we don't have enough experience in the C6678 technology in order to understand the roots of the problem we would greatly appreciate t if you help us in isolating and determining the cause of it (and from there to its solution).

Thanks in advance.Shmulik.

Hi,

I sent the previous post some days ago but I didn't receive any answer. I'll be grateful for your anwer.

Shmulik

Hi,

Thanks for your answer, but it seems that we need your help.

I want to remark that the same problem exists not only in Direct IO, but also in Ftype 9 as we wrote in the first letter of this post.

We have no way to easily recreate the problem. It occurs randomly. Sometimes it appears in the first attempt but other timesit takes a long time before it appears.

This behavior exists in the example provided by TI and also appeared when you yourself ran it.

As we don't have enough experience in the C6678 technology in order to understand the roots of the problem we would greatly appreciate t if you help us in isolating and determining the cause of it (and from there to its solution).

Thanks in advance.Shmulik.

Shmulik

 My observations:

The problem is not the SRIO, rather it is in the storage of the  to the array  TSC_SendSocket[counter] =TSC_Middle1 -TSC_Initial1 -TSC_TimeError;

This takes variable time.  To prove this I did the following changes:

After the send call:

      TSC_Middle1 =TSC_read();

        System_printf ("send %d time %d \n", counter, TSC_Middle1 -TSC_Initial1 -TSC_TimeError)  ;

        TSC_SendSocket[counter] =TSC_Middle1 -TSC_Initial1 -TSC_TimeError;

        TSC_Middle2 =TSC_read();

That is,  I separated the Middle1 and Middle2 before and after the storage of the Tsc_SendSocket array,  and of course, when the total time is calculated I changed it to:

     TSC_Receive[counter] =

                         ((double)TSC_Final1 - (double)TSC_Middle2 + (double)TSC_Middle1 - (double)TSC_Initial1)/1000.0

                             -(double)TSC_TimeError/1000.0;

Which really adds the send and receive time.

Now why the storage into the array consumes different times, I did not follow, but I have some hints:

• 1. The cache status, I suggest you disable the cache and see if you get consistent (longer) numbers,
• 2. I notice that the project is built without optimization and with full debug. This force the compiler to keep intermediate values, again, different cache condition may change the timing

Try it and report back to me if it solved your problem

Ran

Hi Ran and Travis,

Due to your september 27th reply , I commented the line in code you told me causes the problem:

//TSC_SendSocket[counter] = TSC_Middle1- TSC_Initial1 -TSC_TimeError;

I run several times and I saw the same problem.

After that, I commented also the line

//TSC_Middle2 =TSC_read();

I run several times and again I saw the same problem:

For 4K Bytes T_measured = 3.1 usec. After few evm RESETS T_measured = 11.9 usec.!!!!!!!  (as I wrote in the first post).

I'll be grateful if you can help me.

Shmulik.

Shmulik

We try to find the cause of the problem.  Is it the SRIO or the way we measure the time

Please run it exactly the way I described,  separate clocks for the send and receive and tell me if you see the same problem

I can not produce the prblem if it runs the code as I sent you before.  If you see the same problem when you run the code that I gave you, tell me so

If you do not see the same problem,  tell me so

Hi Ran, Travis

We did as you asked us, we disabled the CACHE and it didn't solve the problem.

Also, we tested with your changes, but we removed the system_printf line code between transmit and receive because

system_printf changes the measured time significantly, and it is not necessary in our test. The result is the time measurement problem persists.

In your previous post, you thought that the following line code is the cause of the problem: TSC_SendSocket[counter] =TSC_Middle1 -TSC_Initial1 -TSC_TImeError;

We removed this line code and also the measurement time of TSC_Middle1 and TSC_Middle2, and the time measurement problem persists.

The purpose of our test is to measure the time between transmit and receive without adding code in the middle, that could influence in the measure:

(TotalTime =TSC_Final1 -TSC_Initial1 ), and we expect to receive similar time for all the measures sending the same message.

Thanks,

Shmulik.

Here is my understanding:

When you measure the SRIO send only (time function before and after the send) you get consistent results

When you measure the SRIO receive only (time function before and after the receive and some other code between send and receive) you get consistent results

When you measure the complete transaction - send and receive without any code in between, the results are not consistent.

If you agree with my statement, I will forward the problem to engineering

If you do not agree, tell me which statement is not correct

Hi Ran, Travis
 
In principle you are right. I want to point that there is a whole explanation for this phenomena, from previous posts including the zip code; it is the TI's example with minor changes(please see previous posts).
 
Additionaly, we changed the SerdesConfigPLL to 3.125Gb (0x229) and we received measured time fo 5.2usec or 36usec (for 8KB data).
 
Again, please take in account that the same different time measurement behaviour occurs also with FType 9.
 
Thanks.
 
Shmulik.

Hi Ran,

Do you have any news from the Engineerng team?

Thanks,

Shmulik

Hi Travis, Ran

Two months before you told me that the problem was forwarded to your engineering team.

I asked you on october 26th if you have any news, but I didn't receive any answer.

Please, could you tell me what is the situation now?

Thanks,

Shmulik

The following is a link to a public area where you can follow the engineering activity in this IR

https://cqweb.ext.ti.com/cqweb/main?test=1&command=GenerateMainFrame&service=CQ&schema=SDO-Web&contextid=SDOWP&username=readonly&password=readonly&entityDefName=IncidentReport&entityID=SDOCM00085769

When there is progress, it will be document in this URL

Ran

Shmulik

Send me your email and telephone number to

(edit) removed email address.

Thanks