ASoC: SOF: Intel: remove misleading error trace from IRQ thread

[kv2019i]

Fixes #1047

Downgrade "nothing to do in IRQ thread" message from error to a debug
message in the IPC interrupt handler thread.

The spurious wake-up can happen if a HDA stream interrupt is
raised while the IPC interrupt thread is running. IPC functionality
is not impacted by this condition, so debug is a more appropriate
trace level.

[ranj063]

looksgood. Thanks!

[ranj063]

@kv2019i could you please rebase?

[kv2019i]

@kv2019i could you please rebase?

ack @ranj063 , done

[ranj063]

Need one more approval

[ranj063]

@lyakh @keyonjie @juimonen could you please review this one?

[keyonjie]

@ranj063 @kv2019i I am still curious about:

1. if it is not an IPC IRQ, why the ipc_irq_thread() is called, is it better to fix by not calling ipc_irq_thread() in this case?
2. if it is an IPC IRQ, actually this "nothing to do in IRQ thread" should never happen?

[ranj063]

@keyonjie as explained in the description this happens because the HDA interrupt is raised while we're in the IPC thread and we have not cleared that interrupt just yet. I'm not sure we can avoid this situation.

[keyonjie]

@ranj063 if "while we're in the IPC thread", that means the HDA_DSP_ADSPIS_IPC is set, and then HDA_DSP_REG_HIPCIE_DONE or HDA_DSP_REG_HIPCT_BUSY should be 1, how can the HDA stream interrupt impact the IPC registers?

[kv2019i]

@keyonjie wrote

@ranj063 if "while we're in the IPC thread", that means the HDA_DSP_ADSPIS_IPC is set, and then
HDA_DSP_REG_HIPCIE_DONE or HDA_DSP_REG_HIPCT_BUSY should be 1, how can the HDA stream
interrupt impact the IPC registers?

This is related to how we chose to fix the IPC stress test timeouts. We had multiple race conditions where a hardware interrupt was raised while CPU was executing the threaded handler, and we missed IPC processing in some corner case. To combat this, the hard handler now wakes the thread whenever the the status bits are set when the hard irq handler is called.

In this case, following happens:

• when the IPC event happen, irq is raised and both ADSPIS and and HIPC* bits are set
• IPC thread is scheduled
• ADSPIC is disabled
• CPU returns from hirq handler
• IPC irq thread starts, run1
• HDA stream hirq happens
• ADSPIS is still set (ADSPIC=0 only control upstream propagation of ADSPIC.IPC, the status bit can still be set), so IPC thread is scheduled again (*)
• IPC irq thread resume after hirq processing
• all IPC messages are processed, HIPC* set to zero
• IPC irq thread completes, run1
• another IPC thread run was scheduled in previous step (*)
• no work as HIPC* bits are all zeroes
• IPC irq thread exits with no work done (the error trace is emitted)

I think this is a valid case with our current stack. @lyakh is working on some improvements (#1042), but I don't think these change the behaviour.

[keyonjie]

• IPC irq thread starts, run1
• HDA stream hirq happens
• ADSPIS is still set (ADSPIC=0 only control upstream propagation of ADSPIC.IPC, the status bit can still be set), so IPC thread is scheduled again (*)

The happening of HDA stream hirq will only lead to INTSTS set(and interrupt generated), but ADSPIS won't be set?

So ipc_irq_handler() will be called, but "if (irq_status & HDA_DSP_ADSPIS_IPC)" will be false and it will return with IRQ_NONE.

• IPC irq thread resume after hirq processing
• all IPC messages are processed, HIPC* set to zero
• IPC irq thread completes, run1

[kv2019i]

• ADSPIS is still set (ADSPIC=0 only control upstream propagation of ADSPIC.IPC, the status bit can still be set), so IPC thread is scheduled again (*)

The happening of HDA stream hirq will only lead to INTSTS set(and interrupt generated), but ADSPIS won't be set?

@keyonjie ADSPIS is a logical OR of all upstream DSP status bits. As long as the IPC user thread has not completed handling all the events, ADSPIS will remain set. So if IPC user thread is interrupted by a HDA stream hda irq, the ADSPIS will be still set.

[keyonjie]

• ADSPIS is still set (ADSPIC=0 only control upstream propagation of ADSPIC.IPC, the status bit can still be set), so IPC thread is scheduled again (*)

The happening of HDA stream hirq will only lead to INTSTS set(and interrupt generated), but ADSPIS won't be set?

@keyonjie ADSPIS is a logical of all downstream DSP status bits. As long as the IPC user thread has not completed handling all the events, ADSPIS will remain set. So if IPC user thread is interrupted by a HDA stream hda irq, the ADSPIS will be still set.

Oh, really? That's bad, that means our check here "if (irq_status & HDA_DSP_ADSPIS_IPC)" is not the sufficient condition to claim that it is a new IPC interrupt.

Can we do some change like this to fix it?

--	if (irq_status & HDA_DSP_ADSPIS_IPC) {
++	if ((irq_status & HDA_DSP_ADSPIS_IPC) &&
++	   (snd_sof_dsp_read(sdev, HDA_DSP_BAR, HDA_DSP_REG_ADSPIC) &
++	    HDA_DSP_ADSPIC_IPC)) {

We don't want the thread be scheduled multiple times for the same IPC IRQ.

[kv2019i]

@keyonjie wrote:

Oh, really? That's bad, that means our check here "if (irq_status & HDA_DSP_ADSPIS_IPC)" is
not the sufficient condition to claim that it is a new IPC interrupt.

This is a very infrequent event, so the performance penalty is small. We did discuss this when ironing out fixes for the IPC timeouts and the false wake-ups of the thread seemed the more robust solution.

Can we do some change like this to fix it?

--	if (irq_status & HDA_DSP_ADSPIS_IPC) {
++	if ((irq_status & HDA_DSP_ADSPIS_IPC) &&
++	   (snd_sof_dsp_read(sdev, HDA_DSP_BAR, HDA_DSP_REG_ADSPIC) &
++	    HDA_DSP_ADSPIC_IPC)) {

... I believe this opens up the risks for races again. If some DSP status bit is set towards end of IPC irq thread, this bit will not be handled by the thread anymore but ADSPIC still remains disabled (hirq happens before user thread reenables ADSPIC). With your proposed change, we would not wake up the thread in this case and we would miss the IPC leading to IPC timeout.

Plus, if we merge PR1042, then this logic fails to work as we stop disabling the ADSPIC.

[keyonjie]

@kv2019i so it sounds like we have to choose one from two bottle of poisons.

With solution what @lyakh and you provided, sounds like we will schedule more irq thread than it actually should be, but it can help to avoid IPC missing/timeout issues.

Some concern about it remained to me:

1. Is the IRQ thread execution sequence guaranteed? e.g. the instance 1 is preempted and then instance 2 is scheduled, can we make sure instance 2 will be started after instance 1 is finished?

2. Do we have any other side effect with this thread scheduling more than it actual needed? We are seeing "nothing to do in IRQ thread" logs from time to time, that's fine, we can ignore them, but are they safe enough with multi-entrance? e.g. is it possible that the same IRQ will be handled twice?

[kv2019i]

@kv2019i so it sounds like we have to choose one from two bottle of poisons.

@keyonjie Well, to be fair, that decision was made already and merged. All this patch does is to adjusts traces so they match with current driver behaviour. But yeah, we still have many PRs open to improve the irq handling, so the discussion is valid.

With solution what @lyakh and you provided, sounds like we will schedule more irq thread than
it actually should be, but it can help to avoid IPC missing/timeout issues.

Ack, but only in the rare case that HDA irq is hit between IPC hirq and threaded handlers. And the patch to implement this was from @ranj063 btw. I had a different proposal to use irq masking (PR1011), but that was dropped (and would not change the behaviour we now discuss).

Some concern about it remained to me:

1. Is the IRQ thread execution sequence guaranteed? e.g. the instance 1 is preempted and then instance 2 is scheduled, can we make sure instance 2 will be started after instance 1 is finished?

Yes, @lyakh checked this from kernel irq code.

2. Do we have any other side effect with this thread scheduling more than it actual needed?
   We are seeing "nothing to do in IRQ thread" logs from time to time, that's fine, we can
   ignore them, but are they safe enough with multi-entrance? e.g. is it possible that the same
   IRQ will be handled twice?

We've been testing the current solution pretty extensively now and to our best knowledge it is solid. The kernel irq framework guarantees that multiple instances of the threaded handler are not run at the same time. This can be observed when triggering the scenario of this bug... the threaded handler is only rerun when the previous run completed (and thus we get the "nothing to do" message). And if no DSP status bits are set, the thread does not nothing.

[keyonjie]

OK, Thanks for detail explained, @kv2019i , it looks good to me now.