Real Life Picture of an I2C - I2C Linux Driver

Issue which brought this insight:
========================

I2C transactions are taking longer than expected. For reading an I2C slave register at 100Khz, it is taking nearly 5ms.

In Theory
========
If i2c speed is at 100KHz, it takes 10 us/bit(ie 1/100KHz).
So for a single i2c register read which has 4 sets of transactions as show below.

                                                                          Fig. 1

4 sets of 9 bit = 36 bits, approx 40 bits.
so 10 us * 40 = 400 us.

ie for a read from a 8-bit register of i2c chip should take only 400 us. But it took 5 ms..Really bad...

Before explaining the real problem. Let me tell you how an i2c bus driver works.

How i2c bus driver works.
====================

1) I2C client driver initiates tranfer using funciton like i2c_transfer, i2c_master_send etc.

2) It comes to the master_xfer function in the bus driver (drivers/i2c/busses/*).
3) Bus driver splits the entire transaction into Start, Stop, address, read with ack, read with nack etc.. these conditions has to be created on the real i2c bus. Bus driver writes to I2C hardware adaptor to generate these conditions on I2C bus one by one, sleeping on a wait queue in between (basically giving the cpu to some other task to do some useful job rather than polling until hardware finishes).

4) Once the hardware has finished a transaction on the bus (for eg a start condition), interrupt will be generated and the ISR will wake up the sleeping master_xfer.

5) Once master_xfer wakes up, he will go and advice the hardware adaptor to send the second condition (for eg address of the chip).

6) This continues till whole transactions are over and return back to client driver.

master_xfer function asks the hardware to generate all the condition shown in the above figure in the similar fashion. By waking and sleeping.  The point to note here is sleep done by the thread in between each  condtions. This is why I2C transactions cannot be used from ISRs. For client driver it is just a simple function like i2c_transfer. But it is implemented in bus driver as explained above.

Below is just a dummy xfer and isr function for complete understanding,

static irqreturn_t isr(int irq, void *devid)
{
    ack_interrupt();
    complete(cmd_done);
}

xfer(){

generate_start();
wait_for_completion(cmd_done);

generate_address();
wait_for_completion(cmd_done);

    ......
    .....
    .....

generate_stop();

}

Now back to issue
==============

So when I probed the i2c transactions, saw a lot of gap between each conditons generated.

                                                                  FIG. 2


So from the fig 2 you can see that to transfer 9 bits, time taken is 670 us.
Ideally it should be 90us when bus speed is 100Hz (90 us= 9 bits * 10 us).

Then why this delay?

Possible reasons:
=============
1.   Interrupt from the hardware (i2c adaptor) might be delayed even after the completion of cmd.
2.  Consider that the interrupt has come in time. Now in ISR we will wake up the master_xfer to send the next cmd. After wake up, your thread will be in runnable state and it takes time for the scheduler to schedule master_xfer. Is it this a scheduler delay?
3.  Or is the interrupts disabled system wide by software. In that case your interrupt servicing will be delayed.

Now let’s go one by one.

Reason 1: Interrupt generation delayed by the i2c adaptor.
You may be thinking why I m suspecting hardware. My hardware is in a development phase. I m working on the first tape out of chip. So you know I have to.
To remove this doubt, I tried polling for interrupt flag. It is coming very fast (nearly 100 us, which is close to our ideal time 90 us). So we can rule out reason1

Reason 2:  Scheduler delay.
To rule this out, I probed time difference when wake up is called from ISR and when the thread really woke up. Apparently that was very less.

Reason 3:
Lets use irqsnoff functionality of ftrace. From this experiment I found that enter_cpu_idle is disabling interrupts in system for longer time. This delayed our i2c ISR.

cat /sys/devices/system/cpu/cpu0/cpuidle/state3/latency

is showing 400 usecs, which is far more than what it should be(nearly 50-60 us is ideal).

So actual reason is cpu idle latency.