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
