Re: [PATCHv3] w1: omap-hdq: Simplify driver with PM runtime autosuspend

[H. Nikolaus Schaller]

Hi,

> Am 24.04.2020 um 18:52 schrieb H. Nikolaus Schaller <hns@xxxxxxxxxxxxx>:
> 
> Hi Tony and Andreas,
> 
>> Am 22.04.2020 um 18:06 schrieb H. Nikolaus Schaller <hns@xxxxxxxxxxxxx>:
>> 
>> Hi,
>> 
>>> Am 22.04.2020 um 12:04 schrieb Andreas Kemnade <andreas@xxxxxxxxxxxx>:
>>> 
>>> On Tue, 21 Apr 2020 22:40:39 +0200
>>> "H. Nikolaus Schaller" <hns@xxxxxxxxxxxxx> wrote:
>>> 
>>>> Hi Tony,
>>>> 
>>>> 
>>>> I have added that and there might be a slightly different pattern
>>>> (unless that is just by luck): the first two or three attempts to
>>>> read the bq27xx/uevent did still time out. But then the next ones
>>>> worked fine (with a response time of ca. 65 .. 230 ms).
> 
> Now I have focussed on the hdq_read_byte() timeout and enabled more
> driver debugging.
> 
> Yes, there are a lot of "timeout waiting for RXCOMPLETE" reports.
> Sometimes with ",0" and sometimes with ",1" (hdq_data->hdq_irqstatus).
> 
...

> So I have no idea why it sometimes fails. A race?
> Something not locked? Interrupt not delivered in time?
> 
> The only thing I noticed in code is that hdq_write_byte() doesn't
> use the hdq_mutex although they share the hdq_irqstatus.
> 
> But hdq_write_byte() doesn't seem to be used for booting and
> reading the bq27xxx.

It is. I had a bug in my printk.

> 
> Another idea: there may occur two interrupts between call
> to wait_event_timeout(hdq_data->hdq_irqstatus) and
> status = hdq_data->hdq_irqstatus; and calling hdq_reset_irqstatus().
> 
> These changes hdq_irqstatus. And at the end of the read
> process hdq_irqstatus is set to 0 potentially wiping
> out interrupt flags.
> 
> Just two ideas where we may have missing some locking.
> 
> There is one more observation: the hdq_read_byte()
> code now also calls hdq_reset_irqstatus(hdq_data);
> in the success case which the old code didn't. So
> there may be an additional risk of loosing interrupts.

After enabling more debugging I got this interesting snapshot:

[ 1659.330627] omap_hdq 480b2000.1w: hdq_write_byte
[ 1659.349914] omap_hdq 480b2000.1w: hdq_isr: 0
[ 1659.563903] omap_hdq 480b2000.1w: TX wait elapsed
[ 1659.568939] omap_hdq 480b2000.1w: TX failure:Ctrl status 0
[ 1659.583831] omap_hdq 480b2000.1w: hdq_read_byte
[ 1659.588684] omap_hdq 480b2000.1w: hdq_isr: 0
[ 1659.793945] omap_hdq 480b2000.1w: timeout waiting for RXCOMPLETE, 0
[ 1659.800659] omap_hdq 480b2000.1w: hdq_write_byte
[ 1659.813812] omap_hdq 480b2000.1w: hdq_isr: 0
[ 1660.023956] omap_hdq 480b2000.1w: TX wait elapsed
[ 1660.028961] omap_hdq 480b2000.1w: TX failure:Ctrl status 0
[ 1660.043823] omap_hdq 480b2000.1w: hdq_read_byte
[ 1660.048675] omap_hdq 480b2000.1w: hdq_isr: 6
[ 1660.053253] omap_hdq 480b2000.1w: hdq_write_byte
[ 1660.074371] omap_hdq 480b2000.1w: hdq_isr: 2
[ 1660.078948] omap_hdq 480b2000.1w: timeout waiting for TXCOMPLETE/RXCOMPLETE, 2
[ 1660.103851] omap_hdq 480b2000.1w: TX failure:Ctrl status 2
[ 1660.109710] omap_hdq 480b2000.1w: hdq_read_byte
[ 1660.124267] omap_hdq 480b2000.1w: hdq_isr: 1
[ 1660.333953] omap_hdq 480b2000.1w: timeout waiting for RXCOMPLETE, 1
[ 1660.340637] omap_hdq 480b2000.1w: hdq_write_byte
[ 1660.355957] omap_hdq 480b2000.1w: hdq_isr: 4
[ 1660.360565] omap_hdq 480b2000.1w: hdq_read_byte
[ 1660.373809] omap_hdq 480b2000.1w: hdq_isr: 2
[ 1660.378356] omap_hdq 480b2000.1w: hdq_write_byte
[ 1660.385345] omap_hdq 480b2000.1w: hdq_isr: 4
[ 1660.394287] omap_hdq 480b2000.1w: hdq_read_byte
[ 1660.399078] omap_hdq 480b2000.1w: hdq_isr: 2
[ 1660.413787] omap_hdq 480b2000.1w: hdq_write_byte
[ 1660.420776] omap_hdq 480b2000.1w: hdq_isr: 4
[ 1660.425537] omap_hdq 480b2000.1w: hdq_read_byte
[ 1660.430297] omap_hdq 480b2000.1w: hdq_isr: 2

It looks as if the hdq_write_byte commands fail!
Then, there is of course no response from the bq27xxx
and a hdq_read_byte will also fail.

The things start to get "fixed" when the hdq_isr
jumps to 6 indicating

OMAP_HDQ_INT_STATUS_RXCOMPLETE | OMAP_HDQ_INT_STATUS_TXCOMPLETE

So I am getting more inclined to believe that it is
not a power management issue but some piggybacked
change to how interrupts are handled.
Especially hdq_reset_irqstatus.

So I will add a printk to hdq_reset_irqstatus
to see what value it had before being reset.

And I wonder what the spinlock around setting
hdq_reset_irqstatus = 0 is good for. This should
be an atomic operation anyways.

One more code observation: the goto out_err
in omap_w1_write_byte is not needed.

BR,
Nikolaus