timestamped reading doesn't work proper Topic is solved

Technical questions regarding the xTIMEcomposer, xSOFTip Explorer and Programming with XMOS.
User avatar
dsteinwe
Experienced Member
Posts: 66
Joined: Wed Jun 29, 2016 8:59 am

timestamped reading doesn't work proper

Postby dsteinwe » Tue Sep 29, 2020 11:10 am

Well, I have figured out a very curious behaviour of some part of my code. I have written an own lib for i2s, because I need some more/different features. In my test project, the lib works perfect at 192kHz, even with 8 cores on a tile. In my real usb project the lib doesn't work proper. The code of the lib is like this:

Code: Select all

// sync to the word clock
while (1) {
        select {
            case p_wclk @ pt :> value @ pt1 :
               // read data and do some other stuff
                if (value != wclk_pattern) {
                   printf("value = %u, wclk_pattern = %u; pt1 = %u, pt = %u\n", value, wclk_pattern, pt1, pt);
                   return;
                }
           break;
        }
}
// do more stuff
At 44.1kHz it works fine. At 48kHz, I need 2 sync iterations. The higher the input frequency is, the more sync iterations I need. To analyse this problem, I have added output, to inspect the variable states and I have got i.e.: "value = 0, wclk_pattern = 2147483648; pt1 = 53362, pt = 53394". The surprising is that "value" doesn't match the "wclk_pattern". More suprising is that "pt1" is *lower* than "pt" (time dilation?). "pt1" is the timestamp, when it is read, and "pt" when it should be read. The difference is always 32. The timestamp difference does not match to the pattern difference. The pattern difference is odd.

The document "XS1 Ports: use and specification" (https://www.xmos.ai/download/XS1-Ports- ... (1.02).pdf) describes on page 4:
Port counters are 16-bit counters clocked by either an external
clock, or by a divided internal reference clock. Port counters are guaranteed
to perform I/O operations at precisely defined moments related to an externally
visible clock signal.
My question is: If it is guaranteed, why do I measure such a difference? What could cause such a difference? The code is not marked as distributed or combinable, but runs as a discrete thread.
View Solution
User avatar
CousinItt
XCore Addict
Posts: 179
Joined: Wed May 31, 2017 6:55 pm

Postby CousinItt » Tue Sep 29, 2020 11:45 am

I don't understand the value of using a timed operation with a timestamp. In other words I'd expect to see only one @ in your select case. Could you explain what you're trying to achieve with that?
User avatar
dsteinwe
Experienced Member
Posts: 66
Joined: Wed Jun 29, 2016 8:59 am

Postby dsteinwe » Tue Sep 29, 2020 1:39 pm

Yes, you are right. The part "@ pt1" is not necessary. I have added it during analysing the problem. I will remove it, when the problem is solved. I have added it to see, when the port reading really happens. In my test project, pt1 is (fortunately) pt.
User avatar
dsteinwe
Experienced Member
Posts: 66
Joined: Wed Jun 29, 2016 8:59 am

Postby dsteinwe » Wed Sep 30, 2020 3:29 pm

Here are some further thoughts, insight and facts about my problem.

I have identified till now following situations, that may cause my problem:
  1. The timestamped reading of the port is done inside a select-statement.
    1. If the code of the case-statement "case p_wclk @ pt :> value @ pt1 :" takes a too long time, then the (next) timestamped reading cannot be executed in time.
    2. If another case-statement in this select-statement takes a too long time, then the (next) timestamped reading cannot be executed in time.
  2. I have no experience with interrupt handlers in the xmos context, but I could imaging, that interrupt handler may also disturb the timestamped reading.
If you have further ideas, please let me know.

I have done following code modifications to identify, if one of the above situations occurs:
  1. I have removed temporarily most of the code after "case p_wclk @ pt :> value @ pt1 :". The modifications doesn't have any effect and the problem persists. Therefore and because the code works fine in the test project, I don't assume, that situation 1a is the problem.
  2. I have removed temporarily the other case-statements from the select-statement. The problem still persists (situation 1b) and they don't disturb in the test project. Therefore, I don't assume, that they causes the problem.
  3. I have think about the possibility, that other combinable or distributable functions extends the select-statement of my i2s_rx function. I don't know, how the compiler this realize. Anyhow, I have compared the assembler of my i2s_rx function inside the test and the real project. The used instructions are the same and in the same order, except of some addresses. And the code has the same length. Therefore, I assume, that no other function with further case-statements is combined with my function (situation 2b). Is my assumption correct, if another combinable function is combined with my i2s_rx function, that this changes the assembler of my i2s_rx function?
  4. I don't use interrupt handlers in my code or libraries. So far, I have seen, even XMOS doesn't use interrupt handlers in there libs. I use following XMOS libs: lib_gpio, lib_i2c, lib_logging, lib_usb, lib_assert. Therefore, I don't expect, that an interrupt handler causes my problem (situation 2). I use only the newest versions of the xmos libraries.
I have done some more desperated tests to identify the cause:
  1. I have applied all flags defined in XCC_FLAGS also to my test project. The test project works still fine.
  2. I have disabled the core with "xud(...)" and comment some code pieces like "XUD_InitEp(...)". The problem still persists, therefore I don't expect, that lib_usb causes the problem. On the other hand, the usage of usb is the main difference between my test project and the "real" project.
  3. Post my newest insights.
User avatar
dsteinwe
Experienced Member
Posts: 66
Joined: Wed Jun 29, 2016 8:59 am

Postby dsteinwe » Wed Sep 30, 2020 3:37 pm

Additional comment: I run both projects (real and test project) on the same prototype hardware. Therefore, I don't expect that it is a hardware issue.
User avatar
mon2
XCore Legend
Posts: 1835
Joined: Thu Jun 10, 2010 11:43 am

Postby mon2 » Thu Oct 01, 2020 11:33 am

Hi. Not sure I am following the logic of this block of code nor if the use of the timestamp feature is correct but try the following:

1) remove the use of the select statement and test again. What is the result?

2) post more info on the type of vars used in the code. Even better if you can post the portion of code that makes use of this code block.

What is wclk_pattern?

3)
The surprising is that "value" doesn't match the "wclk_pattern".
Correct. This is true (value != wclk_pattern) and that is why the if-statement triggered to print the results.

4) analyze the disassembly of your source code with the line by line disassembly of the xc source by following the attached document. Then study the differences on the code run order of statements.


app_disassembling_a_program_example-README_1.1.1rc0.a.pdf
You do not have the required permissions to view the files attached to this post.
User avatar
dsteinwe
Experienced Member
Posts: 66
Joined: Wed Jun 29, 2016 8:59 am

Postby dsteinwe » Thu Oct 01, 2020 1:52 pm

Hi, mon2. Thanks for your support. Well, I have new insights, I want to share. But, first I respond to your questions:
1.) I have test it. It doesn't make a difference.
2.) No problem. Here is the code:

Code: Select all

#pragma unsafe arrays
static inline void process_data(streaming chanend c_i2s,
                                in buffered port:32 p_wclk,
                                in buffered port:32 p_data[I2S_SLAVE_RX_COUNT_PORTS],
                                timer t,
                                unsigned transport_bit_width,
                                unsigned port_time,
                                unsigned low_sr,
                                unsigned high_sr) {
    unsigned time, last_time;
    unsigned pt;
    unsigned data;
    unsigned value;

    unsigned right_channel = 0;
    unsigned locked = 0;

    unsigned wclk_pattern = 0x80000000;
    unsigned xor_pattern = 0xffffffff << (32 - transport_bit_width);

    // Calculating new port time
    pt = port_time + transport_bit_width;

    // Calculate new timeout
    t :> time;
    time += WCLK_WAIT_TIMEOUT;

    while (true) {
        [[ordered]]
        select {
            // When a word was received
            case p_wclk @ pt :> value @ pt :
                // Check sample rate
                t :> time;
                last_time = time;
                unsigned duration = time - last_time;
                if (time < last_time) duration += 0xffffffff;
                if (locked > 1 && ((duration < low_sr) || (duration > high_sr))) {
                    log_error("Synchronization error. Sample rate has changed.");
                    return; // resync
                } else {
                    locked++;
                }
                last_time = time;

                // Calculate new timeout
                time += WCLK_WAIT_TIMEOUT;

                // Reading data from port
                #pragma loop unroll
                for (int i = 0; i < I2S_SLAVE_RX_COUNT_PORTS; i++) {
                    data = partin(p_data[i], transport_bit_width);
                    data = bitrev(data); // Incoming data is big endian, we swap it to have little endian
                    samples[i * 2 + right_channel] = data;
                }

                // Calculating new port time
                pt += transport_bit_width;

                // Validate word clock value
                if (value != wclk_pattern) {
                    log_error("Synchronization error with word clock. (Is %u, %u expected)", value, wclk_pattern);
                    return; // resync
                }

                // Prepare wclk pattern for next cycle
                wclk_pattern ^= xor_pattern;

                break;
            // When a timeout happens
            case t when timerafter(time) :> void :
                log_error("Synchronization error. Timeout reached.");
                return; // resync
        } // select

        // Send data
        if (right_channel) {
            c_i2s <: I2S_DATA;
            #pragma loop unroll
            for (int i = 0; i < I2S_SLAVE_RX_COUNT_CHANNELS; i++) c_i2s <: samples[i];
        }

        right_channel = !right_channel;
    } // while
}
I use "wclk_pattern" to verify, if I have read the sample correctly or not. If the pattern matches, the sample was successfully read. "wclk_pattern" has the 32 bit pattern "1000 0000 0000 0000 0000 0000 0000 0000", if it is the left channel, or it is inverted, if it is the right channel.
"log_error" is a own defined macro function that calls debug_printf dependent, which log level is configured for the lib.

3.) You are so right ;-). I must be tired, when I have wrote that.

4.) I haven't done it till now, because I have new insights. Maybe that the analyse of the assembler code is no more required. Mon2, don't hesitate to ask for it, if you think it is necessary despite my new insights.

Now and finally, I describe my new insights:

First, I tried to figure out, when the read error occurs. Therefore I add a counter var and output the number of iterations in the printf:

Code: Select all

// sync to the word clock
int counter = 0;
while (1) {
        select {
            case p_wclk @ pt :> value @ pt1 :
		counter++;
               // read data and do some other stuff
                if (value != wclk_pattern) {
                   printf("value = %u, wclk_pattern = %u; pt1 = %u, pt = %u, counter: %u\n", value, wclk_pattern, pt1, pt, counter);
                   return;
                }
           break;
        }
}
// do more stuff
The resulting output is interesting: 124 iterations at 48kHz and 249 at 96kHz. The number of iterations is stable and independent from the program start or i2s stream start. That means, the read error happens after nearly 1,3ms after entering the while loop. This may be an evidence, that the read error is not directly caused by the code above.
Then, I have reduced the code of my real project. The final version was only a thread for i2s reading and a dummy sample receiving thread without any processing or output and a thread for i2c for initializing the i2s hardware. That was less logic than the test project. In my test project, I additionally output the samples to spdif. Anyhow, even the reduced version of the real project has the read error. I haven't expect this result! Therefore, I replaced the code of the main.xc in my real project with the code from the test project. The problem doesn't occur any more! That means, that the workspace/build environment doesn't causes the problem. It must be anyhow the code. You may have seen in my lib list, I use lib_logging. I don't really use printf but debug_printf. I have added the following function to have a high-speed output per xscope:

Code: Select all

void xscope_user_init(void) {
    xscope_register (0);
    xscope_config_io(XSCOPE_IO_BASIC);
}
If I disable this functions with comments, then the read error doesn't occur anymore! That's surprising, because I use it also in my test project and there it works without any problems. Well, the problem is not solved yet, but I suppose, that the solution is near. It isn't solved, because I want to keep the xscope output. I don't understand, why the xscope output disturbs the timestamped reading -- up to now!
Last edited by dsteinwe on Thu Oct 01, 2020 4:03 pm, edited 2 times in total.
User avatar
mon2
XCore Legend
Posts: 1835
Joined: Thu Jun 10, 2010 11:43 am

Postby mon2 » Thu Oct 01, 2020 2:00 pm

What and where is the definition for the var t?
User avatar
dsteinwe
Experienced Member
Posts: 66
Joined: Wed Jun 29, 2016 8:59 am

Postby dsteinwe » Thu Oct 01, 2020 2:25 pm

"t" is a parameter of the type timer. Originally, I intended to publish a shortened version of my function. In that version, the parameter was omitted. I have fixed my post, above. Sorry for that.
User avatar
mon2
XCore Legend
Posts: 1835
Joined: Thu Jun 10, 2010 11:43 am

Postby mon2 » Thu Oct 01, 2020 2:32 pm

The var last_time is used but not assigned a value in the posted code.

Who is online

Users browsing this forum: No registered users and 5 guests