[PATCH] media: m88ds3103: serialize reset messages in m88ds3103_set_frontend

[PATCH] media: m88ds3103: serialize reset messages in m88ds3103_set_frontend

[James Hutchinson]

Ref: https://bugzilla.kernel.org/show_bug.cgi?id=199323

Users are experiencing problems with the DVBSky S960/S960C USB devices
since the following commit:

9d659ae: ("locking/mutex: Add lock handoff to avoid starvation")

The device malfunctions after running for an indeterminable period of
time, and the problem can only be cleared by rebooting the machine.

It is possible to encourage the problem to surface by blocking the
signal to the LNB.

Further debugging revealed the cause of the problem.

In the following capture:
- thread #1325 is running m88ds3103_set_frontend
- thread #42 is running ts2020_stat_work

a> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 80
   [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 08
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 68 3f
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 08 ff
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 3d
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
b> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 00
   [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 21
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
   [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 66
   [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
   [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
   [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
   [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 60 02 10 0b
   [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07

Two i2c messages are sent to perform a reset in m88ds3103_set_frontend:

  a. 0x07, 0x80
  b. 0x07, 0x00

However, as shown in the capture, the regmap mutex is being handed over
to another thread (ts2020_stat_work) in between these two messages.

From here, the device responds to every i2c message with an 07 message,
and will only return to normal operation following a power cycle.

Use regmap_multi_reg_write to group the two reset messages, ensuring
both are processed before the regmap mutex is unlocked.

Signed-off-by: James Hutchinson <jahutchinson99@googlemail.com>
---
 drivers/media/dvb-frontends/m88ds3103.c | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/drivers/media/dvb-frontends/m88ds3103.c b/drivers/media/dvb-frontends/m88ds3103.c
index 123f2a3..77fe3dc 100644
--- a/drivers/media/dvb-frontends/m88ds3103.c
+++ b/drivers/media/dvb-frontends/m88ds3103.c
@@ -309,6 +309,7 @@ static int m88ds3103_set_frontend(struct dvb_frontend *fe)
 	u16 u16tmp;
 	u32 tuner_frequency_khz, target_mclk;
 	s32 s32tmp;
+	static const struct reg_sequence reset_buf[] = {{0x07, 0x80}, {0x07, 0x00}};
 
 	dev_dbg(&client->dev,
 		"delivery_system=%d modulation=%d frequency=%u symbol_rate=%d inversion=%d pilot=%d rolloff=%d\n",
@@ -321,11 +322,7 @@ static int m88ds3103_set_frontend(struct dvb_frontend *fe)
 	}
 
 	/* reset */
-	ret = regmap_write(dev->regmap, 0x07, 0x80);
-	if (ret)
-		goto err;
-
-	ret = regmap_write(dev->regmap, 0x07, 0x00);
+	ret = regmap_multi_reg_write(dev->regmap, reset_buf, 2);
 	if (ret)
 		goto err;
 
-- 
2.7.4

Re: [PATCH] media: m88ds3103: serialize reset messages in m88ds3103_set_frontend

[Antti Palosaari]

On 1/13/19 11:13 PM, James Hutchinson wrote:
> Ref: https://bugzilla.kernel.org/show_bug.cgi?id=199323
> 
> Users are experiencing problems with the DVBSky S960/S960C USB devices
> since the following commit:
> 
> 9d659ae: ("locking/mutex: Add lock handoff to avoid starvation")
> 
> The device malfunctions after running for an indeterminable period of
> time, and the problem can only be cleared by rebooting the machine.
> 
> It is possible to encourage the problem to surface by blocking the
> signal to the LNB.
> 
> Further debugging revealed the cause of the problem.
> 
> In the following capture:
> - thread #1325 is running m88ds3103_set_frontend
> - thread #42 is running ts2020_stat_work
> 
> a> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 80
>     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 08
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 68 3f
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 08 ff
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 3d
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
> b> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 00
>     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 21
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 66
>     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
>     [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>     [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 60 02 10 0b
>     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> 
> Two i2c messages are sent to perform a reset in m88ds3103_set_frontend:
> 
>    a. 0x07, 0x80
>    b. 0x07, 0x00
> 
> However, as shown in the capture, the regmap mutex is being handed over
> to another thread (ts2020_stat_work) in between these two messages.
> 
>>From here, the device responds to every i2c message with an 07 message,
> and will only return to normal operation following a power cycle.
> 
> Use regmap_multi_reg_write to group the two reset messages, ensuring
> both are processed before the regmap mutex is unlocked.

I tried to reproduce that issue with pctv 461e, which has em28xx 
usb-interface, but without success. Even when I added some sleep between 
reset commands and increased tuner statistic polling interval such that 
it polls all the time, it works correctly. Device has tuner is connected 
to demod i2c bus, which I think is same for your device (it calls demod 
i2c mux select for every tuner i2c access).

Taking into account tests I made it is probably issue with usb-interface 
i2c adapter instead - for some reason it stops working and starts 
returning 07 error all the time. Did any other I2C command succeed after 
failure? I mean is there any other i2c client on that bus you could test 
if it fails too on error situation?

All in all, fix should be done to usb-interface i2c adapter if possible 
unless it has proven issue is somewhere else. You could try to add some 
sleep or repeat to i2c adapter in order to see if it helps.

regards
Antti

-- 
http://palosaari.fi/

Re: [PATCH] media: m88ds3103: serialize reset messages in m88ds3103_set_frontend

[James Hutchinson]

On Sun, Jan 20, 2019 at 04:43:08PM +0200, Antti Palosaari wrote:
> On 1/13/19 11:13 PM, James Hutchinson wrote:
> > Ref: https://bugzilla.kernel.org/show_bug.cgi?id=199323
> > 
> > Users are experiencing problems with the DVBSky S960/S960C USB devices
> > since the following commit:
> > 
> > 9d659ae: ("locking/mutex: Add lock handoff to avoid starvation")
> > 
> > The device malfunctions after running for an indeterminable period of
> > time, and the problem can only be cleared by rebooting the machine.
> > 
> > It is possible to encourage the problem to surface by blocking the
> > signal to the LNB.
> > 
> > Further debugging revealed the cause of the problem.
> > 
> > In the following capture:
> > - thread #1325 is running m88ds3103_set_frontend
> > - thread #42 is running ts2020_stat_work
> > 
> > a> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 80
> >     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 08
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 68 3f
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 08 ff
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 3d
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
> > b> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 00
> >     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 21
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> >     [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 66
> >     [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
> >     [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
> >     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> >     [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 60 02 10 0b
> >     [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
> > 
> > Two i2c messages are sent to perform a reset in m88ds3103_set_frontend:
> > 
> >    a. 0x07, 0x80
> >    b. 0x07, 0x00
> > 
> > However, as shown in the capture, the regmap mutex is being handed over
> > to another thread (ts2020_stat_work) in between these two messages.
> > 
> > > From here, the device responds to every i2c message with an 07 message,
> > and will only return to normal operation following a power cycle.
> > 
> > Use regmap_multi_reg_write to group the two reset messages, ensuring
> > both are processed before the regmap mutex is unlocked.
> 
> I tried to reproduce that issue with pctv 461e, which has em28xx
> usb-interface, but without success. Even when I added some sleep between
> reset commands and increased tuner statistic polling interval such that it
> polls all the time, it works correctly. Device has tuner is connected to
> demod i2c bus, which I think is same for your device (it calls demod i2c mux
> select for every tuner i2c access).
> 
> Taking into account tests I made it is probably issue with usb-interface i2c
> adapter instead - for some reason it stops working and starts returning 07
> error all the time. Did any other I2C command succeed after failure? I mean
> is there any other i2c client on that bus you could test if it fails too on
> error situation?
> 
> All in all, fix should be done to usb-interface i2c adapter if possible
> unless it has proven issue is somewhere else. You could try to add some
> sleep or repeat to i2c adapter in order to see if it helps.
> 
> regards
> Antti
> 
> -- 
> http://palosaari.fi/

Thanks for taking the time to review my patch.

My device is the dvbsky usb s960 which is a pretty popular device and hasn't
been working for several users since commit 9d659ae.

I did some further investigation and can now see that the issue likely only
affects adapters which use the m88ds3103_get_agc_pwm function to get the AGC
from the demodulator as part of ts2020_stat_work.

This is the 3f message in my original capture, which gets an ff response.
    [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 68 3f
    [42] usb 1-1: dvb_usb_v2_generic_io: <<< 08 ff

The m88ds3103_get_agc_pwm function looks to be used by a subset of devices and
their variants from the dvbsky usb-interface (s960 & s960c), and the cx23885-dvb
pci-interface (s950, s950c, s952).

The problem does NOT occur if I disable auto-gain correction by removing the
following line from dvbsky_s960_attach:

    ts2020_config.get_agc_pwm = m88ds3103_get_agc_pwm;

I then have the same experience as you; I can add a sleep between the reset
commands and increase the tuner statistic polling interval, and it still
works correctly.

I can also reproduce the issue on older kernels (pre-commit 9d659ae) by adding
a sleep between the two reset commands and leaving the agc read enabled.

Whilst my original patch works around the issue, I'm not sure it's really
addressing the root cause, and I do wonder whether other areas of the m88ds3103
module may end up needing to be protected in a similar way.

Afterall, the ts2020 stat work thread runs every 2000ms, and there's currently
no guarantee what state the demodulator is going to be in at that time.

Regards,
James.

Re: [PATCH] media: m88ds3103: serialize reset messages in m88ds3103_set_frontend

[Antti Palosaari]

On 1/22/19 1:08 PM, James Hutchinson wrote:
> On Sun, Jan 20, 2019 at 04:43:08PM +0200, Antti Palosaari wrote:
>> On 1/13/19 11:13 PM, James Hutchinson wrote:
>>> Ref: https://bugzilla.kernel.org/show_bug.cgi?id=199323
>>>
>>> Users are experiencing problems with the DVBSky S960/S960C USB devices
>>> since the following commit:
>>>
>>> 9d659ae: ("locking/mutex: Add lock handoff to avoid starvation")
>>>
>>> The device malfunctions after running for an indeterminable period of
>>> time, and the problem can only be cleared by rebooting the machine.
>>>
>>> It is possible to encourage the problem to surface by blocking the
>>> signal to the LNB.
>>>
>>> Further debugging revealed the cause of the problem.
>>>
>>> In the following capture:
>>> - thread #1325 is running m88ds3103_set_frontend
>>> - thread #42 is running ts2020_stat_work
>>>
>>> a> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 80
>>>      [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 08
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 68 3f
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 08 ff
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 3d
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
>>> b> [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 07 00
>>>      [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 21
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 60 66
>>>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 07 ff
>>>      [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 68 02 03 11
>>>      [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>>>      [1325] usb 1-1: dvb_usb_v2_generic_io: >>> 08 60 02 10 0b
>>>      [1325] usb 1-1: dvb_usb_v2_generic_io: <<< 07
>>>
>>> Two i2c messages are sent to perform a reset in m88ds3103_set_frontend:
>>>
>>>     a. 0x07, 0x80
>>>     b. 0x07, 0x00
>>>
>>> However, as shown in the capture, the regmap mutex is being handed over
>>> to another thread (ts2020_stat_work) in between these two messages.
>>>
>>>>  From here, the device responds to every i2c message with an 07 message,
>>> and will only return to normal operation following a power cycle.
>>>
>>> Use regmap_multi_reg_write to group the two reset messages, ensuring
>>> both are processed before the regmap mutex is unlocked.
>>
>> I tried to reproduce that issue with pctv 461e, which has em28xx
>> usb-interface, but without success. Even when I added some sleep between
>> reset commands and increased tuner statistic polling interval such that it
>> polls all the time, it works correctly. Device has tuner is connected to
>> demod i2c bus, which I think is same for your device (it calls demod i2c mux
>> select for every tuner i2c access).
>>
>> Taking into account tests I made it is probably issue with usb-interface i2c
>> adapter instead - for some reason it stops working and starts returning 07
>> error all the time. Did any other I2C command succeed after failure? I mean
>> is there any other i2c client on that bus you could test if it fails too on
>> error situation?
>>
>> All in all, fix should be done to usb-interface i2c adapter if possible
>> unless it has proven issue is somewhere else. You could try to add some
>> sleep or repeat to i2c adapter in order to see if it helps.
>>
>> regards
>> Antti
>>
>> -- 
>> http://palosaari.fi/
> 
> Thanks for taking the time to review my patch.
> 
> My device is the dvbsky usb s960 which is a pretty popular device and hasn't
> been working for several users since commit 9d659ae.
> 
> I did some further investigation and can now see that the issue likely only
> affects adapters which use the m88ds3103_get_agc_pwm function to get the AGC
> from the demodulator as part of ts2020_stat_work.
> 
> This is the 3f message in my original capture, which gets an ff response.
>      [42] usb 1-1: dvb_usb_v2_generic_io: >>> 09 01 01 68 3f
>      [42] usb 1-1: dvb_usb_v2_generic_io: <<< 08 ff
> 
> The m88ds3103_get_agc_pwm function looks to be used by a subset of devices and
> their variants from the dvbsky usb-interface (s960 & s960c), and the cx23885-dvb
> pci-interface (s950, s950c, s952).
> 
> The problem does NOT occur if I disable auto-gain correction by removing the
> following line from dvbsky_s960_attach:
> 
>      ts2020_config.get_agc_pwm = m88ds3103_get_agc_pwm;
> 
> I then have the same experience as you; I can add a sleep between the reset
> commands and increase the tuner statistic polling interval, and it still
> works correctly.
> 
> I can also reproduce the issue on older kernels (pre-commit 9d659ae) by adding
> a sleep between the two reset commands and leaving the agc read enabled.
> 
> Whilst my original patch works around the issue, I'm not sure it's really
> addressing the root cause, and I do wonder whether other areas of the m88ds3103
> module may end up needing to be protected in a similar way.
> 
> Afterall, the ts2020 stat work thread runs every 2000ms, and there's currently
> no guarantee what state the demodulator is going to be in at that time.

Now I can reproduce the issue. It is easy to just add read reg 0x3f 
between reset and it starts failing. And I tested some 100ms sleeps 
there too to leave some time for settle reset, but it does not help. 
Denying any i2c access during reset sounds correct solution.

Anyhow, just to be clear in my understanding locks here are:

regmap_write()
-> demod regmap lock
--> i2c adapter lock
**i2c access here
<-- i2c adapter unlock
<- demod regmap lock

regmap_multi_reg_write()
-> demod regmap lock
--> i2c adapter lock
**i2c access here
<-- i2c adapter unlock
--> i2c adapter lock
**i2c access here
<-- i2c adapter unlock
<- demod regmap lock

So that use regmap_multi_reg_write() prevents any other reg access to 
that device withing demod regmap lock context and fixes issue.

Patch is valid:
Reviewed-by: Antti Palosaari <crope@iki.fi>


regards
Antti

-- 
http://palosaari.fi/