I2C does not send correct data

[ghost]

Details about Problem

When writing to an eeprom (I2C device), no data is written (resulting in no data read in this case).
The SDA line does not show any activity.

Quail firmware : preview617
Worked before? Yes, but can't remember which firmware version was ok.

Detailed repro steps so we can see the same problem

The following code was working "before" and is currently working as is on the same board with TinyCLR.

public override void ReadData(Int32 address, Byte[] data, Int32 index, Int32 count)
{
  _eeprom.Write(new[] { (Byte)(address >> 8), (Byte)(address & 0xFF) });
  Thread.Sleep(5);
  var buffer = new Byte[count];
  _eeprom.Read(buffer);
  Array.Copy(buffer, 0, data, index, count);
}

Screenshot (if applicable/relevant)

Screenshot using nanoFramework :

Screenshot using TinyCLR :

[ghost]

On the F429 with fw617, a Read command is issued after a Write, which is not expected :

The code is this one :

public override void WriteData(Int32 address, Byte[] data, Int32 index, Int32 count)
        {
            var buffer = new Byte[data.Length + 2];
            buffer[0] = (Byte)(address >> 8);
            buffer[1] = (Byte)(address & 0xFF);

            Array.Copy(data, index, buffer, 2, count);
            _eeprom.Write(buffer);
            Thread.Sleep(5);
        }

The call is done this way : WriteData(0, new[] { 200 }, 0, 1);

Same for readings, there seem to be "duplicated" buffers or something like that. Here is the result for a single Read command :

The normal sequence should have been the first "Setup Write" and "Setup Read". The other one has not been sent.

[ghost]

Last informations about this issue. Here are two outputs, one expected (1st one, produced by TinyCLR) and the one produced by nanoFramework. They should be identical, which is obviously not the case.

The code that generated those outputs is exactly the same for both systems.

Output from TinyCLR (expected result) :

Time [s], Analyzer Name, Decoded Protocol Result
0.003925850000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.004015850000000,I2C,'0' (0x00) + ACK
0.004105850000000,I2C,'0' (0x00) + ACK
0.010171150000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.010261150000000,I2C,'200' (0xC8) + NAK
0.012168650000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.012258650000000,I2C,'0' (0x00) + ACK
0.012348650000000,I2C,'0' (0x00) + ACK
0.012438650000000,I2C,'200' (0xC8) + ACK
0.018408750000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.018498750000000,I2C,'0' (0x00) + ACK
0.018588750000000,I2C,'0' (0x00) + ACK
0.024602400000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.024692400000000,I2C,'200' (0xC8) + NAK
0.026559200000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.026649200000000,I2C,'0' (0x00) + ACK
0.026739200000000,I2C,'231' (0xE7) + ACK
0.032752750000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.032842750000000,I2C,'200' (0xC8) + NAK
0.034732250000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.034822200000000,I2C,'0' (0x00) + ACK
0.034912250000000,I2C,'231' (0xE7) + ACK
0.035002200000000,I2C,'200' (0xC8) + ACK
0.040972150000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.041062150000000,I2C,'0' (0x00) + ACK
0.041152150000000,I2C,'231' (0xE7) + ACK
0.047165700000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.047255700000000,I2C,'200' (0xC8) + NAK
0.049147650000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.049237650000000,I2C,'1' (0x01) + ACK
0.049327650000000,I2C,'144' (0x90) + ACK
0.049417650000000,I2C,'200' (0xC8) + ACK
0.049507650000000,I2C,'201' (0xC9) + ACK
0.049597600000000,I2C,'202' (0xCA) + ACK
0.055375800000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.055465800000000,I2C,'1' (0x01) + ACK
0.055555800000000,I2C,'144' (0x90) + ACK
0.061568000000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.061658000000000,I2C,'200' (0xC8) + ACK
0.061748000000000,I2C,'201' (0xC9) + ACK
0.061838000000000,I2C,'202' (0xCA) + NAK

And the one produced by nf :

Time [s], Analyzer Name, Decoded Protocol Result
0.000005000000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.000095000000000,I2C,'0' (0x00) + ACK
0.000185000000000,I2C,'0' (0x00) + ACK
0.020188000000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.020278000000000,I2C,'0' (0x00) + ACK
0.020368000000000,I2C,'0' (0x00) + ACK
0.020474500000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.020564500000000,I2C,'200' (0xC8) + NAK
0.030856200000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.030946200000000,I2C,'0' (0x00) + ACK
0.031036200000000,I2C,'0' (0x00) + ACK
0.031126200000000,I2C,'200' (0xC8) + ACK
0.031232700000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.031322700000000,I2C,'1' (0x01) + NAK
0.051030850000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.051120850000000,I2C,'0' (0x00) + ACK
0.051210850000000,I2C,'0' (0x00) + ACK
0.051317350000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.051407350000000,I2C,'200' (0xC8) + NAK
0.071187350000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.071277350000000,I2C,'0' (0x00) + ACK
0.071367350000000,I2C,'0' (0x00) + ACK
0.071473850000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.071563850000000,I2C,'200' (0xC8) + NAK
0.081687200000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.081777200000000,I2C,'0' (0x00) + ACK
0.081867200000000,I2C,'231' (0xE7) + ACK
0.081973700000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.082063700000000,I2C,'200' (0xC8) + NAK
0.101887000000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.101977000000000,I2C,'0' (0x00) + ACK
0.102067000000000,I2C,'231' (0xE7) + ACK
0.102173500000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.102263500000000,I2C,'200' (0xC8) + NAK
0.112406600000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.112496600000000,I2C,'0' (0x00) + ACK
0.112586600000000,I2C,'231' (0xE7) + ACK
0.112676600000000,I2C,'200' (0xC8) + ACK
0.112783100000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.112873100000000,I2C,'255' (0xFF) + NAK
0.132629950000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.132719950000000,I2C,'0' (0x00) + ACK
0.132809950000000,I2C,'231' (0xE7) + ACK
0.132916450000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.133006450000000,I2C,'200' (0xC8) + NAK
0.152786250000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.152876250000000,I2C,'0' (0x00) + ACK
0.152966250000000,I2C,'231' (0xE7) + ACK
0.153072750000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.153162750000000,I2C,'200' (0xC8) + NAK
0.163333650000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.163423650000000,I2C,'1' (0x01) + ACK
0.163513650000000,I2C,'144' (0x90) + ACK
0.163603650000000,I2C,'200' (0xC8) + ACK
0.163693650000000,I2C,'201' (0xC9) + ACK
0.163783650000000,I2C,'202' (0xCA) + ACK
0.163890150000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.163980150000000,I2C,'255' (0xFF) + NAK
0.183513950000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.183603950000000,I2C,'1' (0x01) + ACK
0.183693950000000,I2C,'144' (0x90) + ACK
0.183800450000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.183890450000000,I2C,'200' (0xC8) + NAK
0.203688100000000,I2C,Setup Write to ['160' (0xA0)] + ACK
0.203778100000000,I2C,'1' (0x01) + ACK
0.203868100000000,I2C,'144' (0x90) + ACK
0.203974600000000,I2C,Setup Read to ['161' (0xA1)] + ACK
0.204064600000000,I2C,'200' (0xC8) + ACK
0.204154600000000,I2C,'201' (0xC9) + ACK
0.204244600000000,I2C,'202' (0xCA) + NAK

I think that there is something wrong in the buffers handling, here.

[ghost]

Same behaviour on Quail, F429iDiscovery and Nucleo F746ZG.

[ghost]

I would now add another issue raised by Stefan Falk on Slack : a simple Write() operation is taking between 8 and 11 ms to achieve !
More precisely : it takes 10 ms for the managed app to get control back. The timings on the I²C line are correct, given the frequency used. So this is not the transfer itself that takes time but rather code around it.
SPI does not show this behaviour at all. Granted, SPI is faster than I²C but this does not explain this huge difference, to me. It takes much less than 1ms for SPI with the same data size sent.

[josesimoes]

That's explained by the new workflow with CLR events.
The SPI implementation has an "improved" algorithm that figures out if the transaction fits in thread execution slot. If it does it will skip setting up the continuation and event.
This same algorithm is still to be ported to the I2C code.

[ghost]

I don't think that this applies, here. The 10ms timing is for 2 bytes sent... If 2 bytes don't fit in an execution slot, then we have another problem.

[josesimoes]

Please read again the above.

The smart algorithm is NOT implemented in the I2C code. Yet.
That means that it doesn't matter if the buffer is 2 byte or 2000 bytes: it will take the same time to start the transaction.
Plus ChibiOS I2C async API works differently of the other drivers there: it requires a thread on its own. Setting up that thread and starting it requires relinquish control from the CLR ChibiOS thread and waiting for that I2C to get it's execution time.
All this accounts for what you guys are seeing here.

If you have a different understanding please point the code line (or code block) that you see that is causing this behaviour.

[ghost]

What I understand here is that when the "smart algorithm" will be coded, we will have such a 10ms penalty if the code decides that the data to be transferred won't fit in an execution slot.
Am I right ?

[josesimoes]

The penalty will depend on cpu clock and execution time, but yes, it will exist.

[josesimoes]

Just found root cause for those 10ms between thread re-scheduling that weren't there when you've tested the previous implementation:

1. Fix to events here

2. And later here

As you can see it's not caused by the recent changes in the code.