is it a kernel freeze

Question

We are missing interrupts in an linux embedded system having multi-core running at 1.25GHz.

Background:

• kernel version: 2.6.32.27
• we have user space processes which need real time performance.
• They operate in a 1ms boundary.
  • That is to say within 1ms they are expected to complete a set of task, which at the max may take about 800uS.
• We have a external component FPGA which provides, 1ms and 10ms interrupts to the multi-core processor through GPIO pins configured as edge triggerred interrupts.
• These interrupts are handled in kernel driver.

The software architecture is in such a way that the user process, after completing its work will do an ioctl to the GPIO driver.

In this ioctl the driver will put the process to wakeup_interruptible state. Whenever the next 1ms interrupt is received, the ISR will wakeup the process. This cycle repeats.

Both the 1ms and 10ms interrupts are routed to a single core of the processor using smp_affinity.

Problem:

• Sometimes we find that some interrupts are missed.
  • (ie ISR itself doesnt get invoked).
• After 12 to 20ms ISR's are hit normally.
• This we are able to understand by profiling the duration between consecutive ISR calls, and having counters incremented first thing in the ISR.

This mostly happens during high system load at process level, and is random and hard to reproduce.

I have attached the skeletal code.

First I have to isolate whether it is a hardware or software problem. As it is a FPGA which is giving the interrupts, we dont have much doubt on the hardware.

Is this kernel freezing? It is the most likely case since the cpu cycles are incrementing.

Can it be a case of cpu freeze due to thermal conditions? If so, then the cpu cycles wouldn't have incremented in first place.

Any pointers to debug/isolate the root cause will be of great help considering the kernel version we are working on and the profiling/debugging facilities available in this kernel version.

skeletal code:

/* Build time Configuration */

/* Macros */
DECLARE_WAIT_QUEUE_HEAD(wait);

/** Structure Definitions */
/** Global Variables */
gpio_dev_t gpio1msDev, gpio10msDev;
GpioIntProfileSectorData_t GpioSigProfileData[MAX_GPIO_INT_CONSUMERS];
GpioIntProfileSectorData_t *ProfilePtrSector;
GpioIntProfileData_t GpioProfileData;
GpioIntProfileData_t *GpioIntProfilePtr;
CurrentTickProfile_t TimeStamp;
uint64_t ModuleInitDone = 0, FirstTimePIDWrite = 0;
uint64_t PrevCycle = 0, NowCycle = 0;
volatile uint64_t TenMsFlag, OneMsFlag;
uint64_t OneMsCounter;
uint64_t OneMsIsrTime, TenMsIsrTime;
uint64_t OneMsCounter, OneMsTime, TenMsTime, SyncStarted;
uint64_t Prev = 0, Now = 0, DiffTen = 0, DiffOne, SesSyncHappened;
static spinlock_t GpioSyncLock = SPIN_LOCK_UNLOCKED;
static spinlock_t IoctlSyncLock = SPIN_LOCK_UNLOCKED;
uint64_t EventPresent[MAX_GPIO_INT_CONSUMERS];

GpioEvent_t CurrentEvent = KERN_NO_EVENT;
TickSyncSes_t *SyncSesPtr = NULL;


/** Function Declarations */

ssize_t write_pid(struct file *filep, const char __user * buf, size_t count, loff_t * ppos);
long Gpio_compat_ioctl(struct file *filep, unsigned int cmd, unsigned long arg);

static const struct file_operations my_fops = {
 write:write_pid,
 compat_ioctl:Gpio_compat_ioctl,
};




/**
 * IOCTL function for GPIO interrupt module
 *
 * @return
 */
long Gpio_compat_ioctl(struct file *filep, unsigned int cmd, unsigned long arg)
{
int len = 1, status = 0;
    uint8_t Instance;
    uint64_t *EventPtr;
    GpioIntProfileSectorData_t *SectorProfilePtr, *DebugProfilePtr;
    GpioEvent_t EventToGive = KERN_NO_EVENT;
    pid_t CurrentPid = current->pid;

    spin_lock(&IoctlSyncLock);  // Take the spinlock
    Instance = GetSector(CurrentPid);
    SectorProfilePtr = &GpioSigProfileData[Instance];
    EventPtr = &EventPresent[Instance];
    spin_unlock(&IoctlSyncLock);

    if (Instance <= MAX_GPIO_INT_CONSUMERS)
    {
        switch (cmd)
        {
        case IOCTL_WAIT_ON_EVENT:
            if (*EventPtr)
            {
                /* Dont block here since this is a case where interrupt has happened
                 * before process calling the polling API */
                *EventPtr = 0;
                /* some profiling code */
            }
            else
            {
                status = wait_event_interruptible(wait, (*EventPtr == 1));
                *EventPtr = 0;
            }

            /* profiling code */

            TimeStamp.CurrentEvent = EventToGive;
            len = copy_to_user((char *)arg, (char *)&TimeStamp, sizeof(CurrentTickProfile_t));
            break;
        default:
            break;
        }
    }
    else
    {
        return -EINVAL;
    }

    return 0;
}

/**
 * Send signals to registered PID's.
 *
 * @return
 */
static void WakeupWaitQueue(GpioEvent_t Event)
{
    int i;

    /* some profile code */

    CurrentEvent = Event;

    // we dont wake up debug app hence "< MAX_GPIO_INT_CONSUMERS" is used in for loop
    for (i = 0; i < MAX_GPIO_INT_CONSUMERS; i++)
    {
        EventPresent[i] = 1;
    }
    wake_up_interruptible(&wait);
}

/**
 * 1ms Interrupt handler
 *
 * @return
 */
static irqreturn_t gpio_int_handler_1ms(int irq, void *irq_arg)
{
    uint64_t reg_read, my_core_num;
    unsigned long flags;
    GpioEvent_t event = KERN_NO_EVENT;

    /* code to clear the interrupt registers */


    /************ profiling start************/
    NowCycle = get_cpu_cycle();
    GpioIntProfilePtr->TotalOneMsInterrupts++;

    /* Check the max diff between consecutive interrupts */
    if (PrevCycle)
    {
        DiffOne = NowCycle - PrevCycle;
        if (DiffOne > GpioIntProfilePtr->OneMsMaxDiff)
            GpioIntProfilePtr->OneMsMaxDiff = DiffOne;
    }
    PrevCycle = NowCycle;

    TimeStamp.OneMsCount++; /* increment the counter */

    /* Store the timestamp */

    GpioIntProfilePtr->Gpio1msTimeStamp[GpioIntProfilePtr->IndexOne] = NowCycle;
    TimeStamp.OneMsTimeStampAtIsr = NowCycle;
    GpioIntProfilePtr->IndexOne++;
    if (GpioIntProfilePtr->IndexOne == GPIO_PROFILE_ARRAY_SIZE)
        GpioIntProfilePtr->IndexOne = 0;
    /************ profiling end************/

    /*
     * Whenever 10ms Interrupt happens we send only one event to the upper layers.
     * Hence it is necessary to sync between 1 & 10ms interrupts.
     * There is a chance that sometimes 1ms can happen at first and sometimes 10ms.
     *
     */
    /******** Sync mechanism ***********/
    spin_lock_irqsave(&GpioSyncLock, flags);    // Take the spinlock
    OneMsCounter++;
    OneMsTime = NowCycle;
    DiffOne = OneMsTime - TenMsTime;

    if (DiffOne < MAX_OFFSET_BETWEEN_1_AND_10MS)    //ten ms has happened first
    {
        if (OneMsCounter == 10)
        {
            event = KERN_BOTH_EVENT;
            SyncStarted = 1;
        }
        else
        {
            if (SyncStarted)
            {
                if (OneMsCounter < 10)
                {
                    GpioIntProfilePtr->TickSyncErrAt1msLess++;
                }
                else if (OneMsCounter > 10)
                {
                    GpioIntProfilePtr->TickSyncErrAt1msMore++;
                }
            }
        }
        OneMsCounter = 0;
    }
    else
    {
        if (OneMsCounter < 10)
        {
            if (SyncStarted)
            {
                event = KERN_ONE_MS_EVENT;
            }
        }
        else if (OneMsCounter > 10)
        {
            OneMsCounter = 0;
            if (SyncStarted)
            {
                GpioIntProfilePtr->TickSyncErrAt1msMore++;
            }
        }
    }
    TimeStamp.SFN = OneMsCounter;
    spin_unlock_irqrestore(&GpioSyncLock, flags);
    /******** Sync mechanism ***********/

    if(event != KERN_NO_EVENT)
        WakeupWaitQueue(event);

    OneMsIsrTime = get_cpu_cycle() - NowCycle;
    if (GpioIntProfilePtr->Max1msIsrTime < OneMsIsrTime)
        GpioIntProfilePtr->Max1msIsrTime = OneMsIsrTime;
    return IRQ_HANDLED;
}

/**
 * 10ms Interrupt handler
 *
 * @return
 */
static irqreturn_t gpio_int_handler_10ms(int irq, void *irq_arg)
{
    uint64_t reg_read, my_core_num;
    unsigned long flags;
    GpioEvent_t event = KERN_NO_EVENT;

    /* clear the interrupt */

    /************ profiling start************/
    GpioIntProfilePtr->TotalTenMsInterrupts++;
    Now = get_cpu_cycle();
    if (Prev)
    {
        DiffTen = Now - Prev;
        if (DiffTen > GpioIntProfilePtr->TenMsMaxDiff)
            GpioIntProfilePtr->TenMsMaxDiff = DiffTen;
    }
    Prev = Now;
    TimeStamp.OneMsCount++; /* increment the counter */
    TimeStamp.TenMsCount++;
    GpioIntProfilePtr->Gpio10msTimeStamp[GpioIntProfilePtr->IndexTen] = Now;
    TimeStamp.TenMsTimeStampAtIsr = Now;
    //do_gettimeofday(&TimeOfDayAtIsr.TimeAt10MsIsr);
    GpioIntProfilePtr->IndexTen++;
    if (GpioIntProfilePtr->IndexTen == GPIO_PROFILE_ARRAY_SIZE)
        GpioIntProfilePtr->IndexTen = 0;
    /************ profiling end************/

    /******** Sync mechanism ***********/
    spin_lock_irqsave(&GpioSyncLock, flags);
    TenMsTime = Now;
    DiffTen = TenMsTime - OneMsTime;

    if (DiffTen < MAX_OFFSET_BETWEEN_1_AND_10MS)    //one ms has happened first
    {
        if (OneMsCounter == 10)
        {
            TimeStamp.OneMsTimeStampAtIsr = Now;
            event = KERN_BOTH_EVENT;
            SyncStarted = 1;
        }
        OneMsCounter = 0;
    }
    else
    {
        if (SyncStarted)
        {
            if (OneMsCounter < 9)
            {
                GpioIntProfilePtr->TickSyncErrAt10msLess++;
                OneMsCounter = 0;
            }
            else if (OneMsCounter > 9)
            {
                GpioIntProfilePtr->TickSyncErrAt10msMore++;
                OneMsCounter = 0;
            }
        }
        else
        {
            if (OneMsCounter != 9)
                OneMsCounter = 0;
        }
    }
    TimeStamp.SFN = OneMsCounter;
    spin_unlock_irqrestore(&GpioSyncLock, flags);
    /******** Sync mechanism ***********/

    if(event != KERN_NO_EVENT)
        WakeupWaitQueue(event);

    TenMsIsrTime = get_cpu_cycle() - Now;
    if (GpioIntProfilePtr->Max10msIsrTime < TenMsIsrTime)
        GpioIntProfilePtr->Max10msIsrTime = TenMsIsrTime;

    return IRQ_HANDLED;
}

Answer 1

This was not a kernel freeze. We had a free core in the system which was running baremetal. We routed the 1ms interrupts to this baremetal core as well. When the issue occurs, we compared with the baremetal core profile info. In baremetal core ISRs were hit properly linear to the time elapsed. By this we ruled out that there are not HW issues or thermal issues.

Next on close look of the code, we started suspecting whether spinlock is causing to miss the interrupts. To experiment, we changed the logic to run the ISRs without spinlock. Now we see that there are not missed interrupts.

So the issues seems solved, however with spinlock present also the system was working properly under normal load conditions. This issue arises only during very high CPU load. This is something for which i dont have an answer though ie only during high load condition, why calling spinlock makes the other interrupt to be missed.

Answer 2

Reseting EventPresent after waiting the event in wait_event_interruptible()

EventPtr = &EventPresent[Instance];
...
status = wait_event_interruptible(wait, (*EventPtr == 1));
*EventPtr = 0;

looks suspicious.

If WakeupWaitQueue() will be executed concurrently, then setting of the event

for (i = 0; i < MAX_GPIO_INT_CONSUMERS; i++)
    {
        EventPresent[i] = 1;
    }
wake_up_interruptible(&wait);

will be lost.

It is better to have two independent counters for raised events and for processed events:

uint64_t EventPresent[MAX_GPIO_INT_CONSUMERS]; // Number if raised events
uint64_t EventProcessed[MAX_GPIO_INT_CONSUMERS]; // Number of processed events

In that case condition could be a comparision of these counters:

Gpio_compat_ioctl()
{
    ...
    EventPresentPtr = &EventPresent[Instance];
    EventProcessedPtr = &EventProcessed[Instance];
    ...
    status = wait_event_interruptible(wait, (*EventPresentPtr != *EventProcessedPtr));
    (*EventProcessedPtr)++;
    ...
}

WakeupWaitQueue()
{
    ...
    for (i = 0; i < MAX_GPIO_INT_CONSUMERS; i++)
    {
        EventPresent[i]++;
    }
    wake_up_interruptible(&wait);
}