4.14 regression from commit d57ea877af38 media: rc: per-protocol repeat period

4.14 regression from commit d57ea877af38 media: rc: per-protocol repeat period

[Matthias Reichl]

The following commit introduced a regression

commit d57ea877af38057b0ef31758cf3b99765dc33695
Author: Sean Young <sean@mess.org>
Date:   Wed Aug 9 13:19:16 2017 -0400

    media: rc: per-protocol repeat period

    CEC needs a keypress timeout of 550ms, which is too high for the IR
    protocols. Also fill in known repeat times, with 50ms error margin.

    Also, combine all protocol data into one structure.

We received a report that an RC6 MCE remote used with the ite-cir
produces "double events" on short button presses:

https://forum.kodi.tv/showthread.php?tid=298462&pid=2667855#pid2667855

Looking at the ir-keytable -t output an additional key event is also
generated after longer button presses:

# ir-keytable -t
Testing events. Please, press CTRL-C to abort.
1510680591.697657: event type EV_MSC(0x04): scancode = 0x800f041f
1510680591.697657: event type EV_KEY(0x01) key_down: KEY_DOWN(0x006c)
1510680591.697657: event type EV_SYN(0x00).
1510680591.867355: event type EV_KEY(0x01) key_up: KEY_DOWN(0x006c)
1510680591.867355: event type EV_SYN(0x00).
1510680591.935026: event type EV_MSC(0x04): scancode = 0x800f041f
1510680591.935026: event type EV_KEY(0x01) key_down: KEY_DOWN(0x006c)
1510680591.935026: event type EV_SYN(0x00).
1510680592.104100: event type EV_KEY(0x01) key_up: KEY_DOWN(0x006c)
1510680592.104100: event type EV_SYN(0x00).

1510680597.714055: event type EV_MSC(0x04): scancode = 0x800f0405
1510680597.714055: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
1510680597.714055: event type EV_SYN(0x00).
1510680597.819939: event type EV_MSC(0x04): scancode = 0x800f0405
1510680597.819939: event type EV_SYN(0x00).
1510680597.925614: event type EV_MSC(0x04): scancode = 0x800f0405
1510680597.925614: event type EV_SYN(0x00).
1510680598.032422: event type EV_MSC(0x04): scancode = 0x800f0405
1510680598.032422: event type EV_SYN(0x00).
...
1510680598.562114: event type EV_MSC(0x04): scancode = 0x800f0405
1510680598.562114: event type EV_SYN(0x00).
1510680598.630641: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
1510680598.630641: event type EV_SYN(0x00).
1510680598.667906: event type EV_MSC(0x04): scancode = 0x800f0405
1510680598.667906: event type EV_SYN(0x00).
1510680598.760760: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
1510680598.760760: event type EV_SYN(0x00).
1510680598.837412: event type EV_KEY(0x01) key_up: KEY_NUMERIC_5(0x0205)
1510680598.837412: event type EV_SYN(0x00).
1510680598.905003: event type EV_MSC(0x04): scancode = 0x800f0405
1510680598.905003: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
1510680598.905003: event type EV_SYN(0x00).
1510680599.074092: event type EV_KEY(0x01) key_up: KEY_NUMERIC_5(0x0205)
1510680599.074092: event type EV_SYN(0x00).

Looking at the timestamps of the scancode events it seems that
signals are received every ~106ms but the last signal seems to be
received 237ms after the last-but-one - which is then interpreted
as a new key press cycle as the delay is longer than the 164ms
"repeat_period" setting of the RC6 protocol (before that commit
250ms was used).

This 237ms delay seems to be coming from the 200ms timeout value
of the ite-cir driver (237ms is in the ballpark of ~30ms rc6 signal
time plus 200ms timeout).

The original author hasn't reported back yet but others confirmed
that changing the timeout to 100ms (minimum idle timeout value
of ite-cir) using "ir-ctl -t 100000" fixes the issue.

I could locally reproduce this with gpio-ir-recv (which uses the
default 125ms timeout) and the sony protocol (repeat_period = 100ms):

1510838115.272021: event type EV_MSC(0x04): scancode = 0x110001
1510838115.272021: event type EV_KEY(0x01) key_down: KEY_2(0x0003)
1510838115.272021: event type EV_SYN(0x00).
1510838115.322014: event type EV_MSC(0x04): scancode = 0x110001
1510838115.322014: event type EV_SYN(0x00).
1510838115.362003: event type EV_MSC(0x04): scancode = 0x110001
1510838115.362003: event type EV_SYN(0x00).
1510838115.412002: event type EV_MSC(0x04): scancode = 0x110001
1510838115.412002: event type EV_SYN(0x00).
1510838115.521973: event type EV_KEY(0x01) key_up: KEY_2(0x0003)
1510838115.521973: event type EV_SYN(0x00).
1510838115.532007: event type EV_MSC(0x04): scancode = 0x110001
1510838115.532007: event type EV_KEY(0x01) key_down: KEY_2(0x0003)
1510838115.532007: event type EV_SYN(0x00).
1510838115.641972: event type EV_KEY(0x01) key_up: KEY_2(0x0003)
1510838115.641972: event type EV_SYN(0x00).

Reducing the timeout to 20ms removes the addional key_down/up event.

Another test with a rc-5 remote on gpio-ir-recv worked fine at the
default 125ms timeout but with 200ms as on the ite-cir I again
got the additional key event.

so long,

Hias

Re: 4.14 regression from commit d57ea877af38 media: rc: per-protocol repeat period

[Sean Young]

On Thu, Nov 16, 2017 at 04:27:01PM +0100, Matthias Reichl wrote:
> The following commit introduced a regression
> 
> commit d57ea877af38057b0ef31758cf3b99765dc33695
> Author: Sean Young <sean@mess.org>
> Date:   Wed Aug 9 13:19:16 2017 -0400
> 
>     media: rc: per-protocol repeat period
> 
>     CEC needs a keypress timeout of 550ms, which is too high for the IR
>     protocols. Also fill in known repeat times, with 50ms error margin.
> 
>     Also, combine all protocol data into one structure.
> 
> We received a report that an RC6 MCE remote used with the ite-cir
> produces "double events" on short button presses:
> 
> https://forum.kodi.tv/showthread.php?tid=298462&pid=2667855#pid2667855
> 
> Looking at the ir-keytable -t output an additional key event is also
> generated after longer button presses:
> 
> # ir-keytable -t
> Testing events. Please, press CTRL-C to abort.
> 1510680591.697657: event type EV_MSC(0x04): scancode = 0x800f041f
> 1510680591.697657: event type EV_KEY(0x01) key_down: KEY_DOWN(0x006c)
> 1510680591.697657: event type EV_SYN(0x00).
> 1510680591.867355: event type EV_KEY(0x01) key_up: KEY_DOWN(0x006c)
> 1510680591.867355: event type EV_SYN(0x00).
> 1510680591.935026: event type EV_MSC(0x04): scancode = 0x800f041f
> 1510680591.935026: event type EV_KEY(0x01) key_down: KEY_DOWN(0x006c)
> 1510680591.935026: event type EV_SYN(0x00).
> 1510680592.104100: event type EV_KEY(0x01) key_up: KEY_DOWN(0x006c)
> 1510680592.104100: event type EV_SYN(0x00).
> 
> 1510680597.714055: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680597.714055: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
> 1510680597.714055: event type EV_SYN(0x00).
> 1510680597.819939: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680597.819939: event type EV_SYN(0x00).
> 1510680597.925614: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680597.925614: event type EV_SYN(0x00).
> 1510680598.032422: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680598.032422: event type EV_SYN(0x00).
> ...
> 1510680598.562114: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680598.562114: event type EV_SYN(0x00).
> 1510680598.630641: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
> 1510680598.630641: event type EV_SYN(0x00).
> 1510680598.667906: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680598.667906: event type EV_SYN(0x00).
> 1510680598.760760: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
> 1510680598.760760: event type EV_SYN(0x00).
> 1510680598.837412: event type EV_KEY(0x01) key_up: KEY_NUMERIC_5(0x0205)
> 1510680598.837412: event type EV_SYN(0x00).
> 1510680598.905003: event type EV_MSC(0x04): scancode = 0x800f0405
> 1510680598.905003: event type EV_KEY(0x01) key_down: KEY_NUMERIC_5(0x0205)
> 1510680598.905003: event type EV_SYN(0x00).
> 1510680599.074092: event type EV_KEY(0x01) key_up: KEY_NUMERIC_5(0x0205)
> 1510680599.074092: event type EV_SYN(0x00).
> 
> Looking at the timestamps of the scancode events it seems that
> signals are received every ~106ms but the last signal seems to be
> received 237ms after the last-but-one - which is then interpreted
> as a new key press cycle as the delay is longer than the 164ms
> "repeat_period" setting of the RC6 protocol (before that commit
> 250ms was used).
> 
> This 237ms delay seems to be coming from the 200ms timeout value
> of the ite-cir driver (237ms is in the ballpark of ~30ms rc6 signal
> time plus 200ms timeout).
> 
> The original author hasn't reported back yet but others confirmed
> that changing the timeout to 100ms (minimum idle timeout value
> of ite-cir) using "ir-ctl -t 100000" fixes the issue.

Right, so some of the IR decoders wait for a trailing space, as that is
the only way to know if the bit stream has ended (e.g. rc-6 can be 
16 bits, 20 or 32). The longer the timeout, the longer it will take
to receive the trailing space, pushing decoding further along and
pushing it past the keyup timeout.

For any IR which is not the "last", decoding is triggered by the IR which
follows it.

I think the resolution is to add the rcdev timeout to the keyup
timeout; else this problem will start occuring again if someone sets
a high timeout (e.g. 300ms).

> I could locally reproduce this with gpio-ir-recv (which uses the
> default 125ms timeout) and the sony protocol (repeat_period = 100ms):
> 
> 1510838115.272021: event type EV_MSC(0x04): scancode = 0x110001
> 1510838115.272021: event type EV_KEY(0x01) key_down: KEY_2(0x0003)
> 1510838115.272021: event type EV_SYN(0x00).
> 1510838115.322014: event type EV_MSC(0x04): scancode = 0x110001
> 1510838115.322014: event type EV_SYN(0x00).
> 1510838115.362003: event type EV_MSC(0x04): scancode = 0x110001
> 1510838115.362003: event type EV_SYN(0x00).
> 1510838115.412002: event type EV_MSC(0x04): scancode = 0x110001
> 1510838115.412002: event type EV_SYN(0x00).
> 1510838115.521973: event type EV_KEY(0x01) key_up: KEY_2(0x0003)
> 1510838115.521973: event type EV_SYN(0x00).
> 1510838115.532007: event type EV_MSC(0x04): scancode = 0x110001
> 1510838115.532007: event type EV_KEY(0x01) key_down: KEY_2(0x0003)
> 1510838115.532007: event type EV_SYN(0x00).
> 1510838115.641972: event type EV_KEY(0x01) key_up: KEY_2(0x0003)
> 1510838115.641972: event type EV_SYN(0x00).
> 
> Reducing the timeout to 20ms removes the addional key_down/up event.
> 
> Another test with a rc-5 remote on gpio-ir-recv worked fine at the
> default 125ms timeout but with 200ms as on the ite-cir I again
> got the additional key event.

Thanks for the excellent analysis.


Sean

[PATCH] media: rc: double keypresses due to timeout expiring to early

[Sean Young]

Since commit d57ea877af38 ("media: rc: per-protocol repeat period"),
double keypresses are reported on the ite-cir driver. This is due
two factors: that commit reduced the timeout used for some protocols
(it became protocol dependant) and the high default IR timeout used
by the ite-cir driver.

Some of the IR decoders wait for a trailing space, as that is
the only way to know if the bit stream has ended (e.g. rc-6 can be
16, 20 or 32 bits). The longer the IR timeout, the longer it will take
to receive the trailing space, delaying decoding and pushing it past the
keyup timeout.

So, add the IR timeout to the keyup timeout.

Cc: <stable@vger.kernel.org> # 4.14
Reported-by: Matthias Reichl <hias@horus.com>
Signed-off-by: Sean Young <sean@mess.org>
---
 drivers/media/rc/rc-main.c | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/drivers/media/rc/rc-main.c b/drivers/media/rc/rc-main.c
index 17950e29d4e3..fae721534517 100644
--- a/drivers/media/rc/rc-main.c
+++ b/drivers/media/rc/rc-main.c
@@ -672,7 +672,8 @@ void rc_repeat(struct rc_dev *dev)
 	input_event(dev->input_dev, EV_MSC, MSC_SCAN, dev->last_scancode);
 	input_sync(dev->input_dev);
 
-	dev->keyup_jiffies = jiffies + msecs_to_jiffies(timeout);
+	dev->keyup_jiffies = jiffies + msecs_to_jiffies(timeout) +
+					nsecs_to_jiffies(dev->timeout);
 	mod_timer(&dev->timer_keyup, dev->keyup_jiffies);
 
 out:
@@ -744,7 +745,8 @@ void rc_keydown(struct rc_dev *dev, enum rc_proto protocol, u32 scancode,
 
 	if (dev->keypressed) {
 		dev->keyup_jiffies = jiffies +
-			msecs_to_jiffies(protocols[protocol].repeat_period);
+			msecs_to_jiffies(protocols[protocol].repeat_period) +
+			nsecs_to_jiffies(dev->timeout);
 		mod_timer(&dev->timer_keyup, dev->keyup_jiffies);
 	}
 	spin_unlock_irqrestore(&dev->keylock, flags);
-- 
2.14.3

Re: [PATCH] media: rc: double keypresses due to timeout expiring to early

[Matthias Reichl]

Hi Sean!

On Thu, Nov 16, 2017 at 09:54:51PM +0000, Sean Young wrote:
> Since commit d57ea877af38 ("media: rc: per-protocol repeat period"),
> double keypresses are reported on the ite-cir driver. This is due
> two factors: that commit reduced the timeout used for some protocols
> (it became protocol dependant) and the high default IR timeout used
> by the ite-cir driver.
> 
> Some of the IR decoders wait for a trailing space, as that is
> the only way to know if the bit stream has ended (e.g. rc-6 can be
> 16, 20 or 32 bits). The longer the IR timeout, the longer it will take
> to receive the trailing space, delaying decoding and pushing it past the
> keyup timeout.
> 
> So, add the IR timeout to the keyup timeout.

Thanks a lot for the patch, I've asked the people with ite-cir
receivers to test it.

In the meanwhile I ran some tests with gpio-ir-recv and timeout
set to 200ms with a rc-5 remote (that's as close to the original
setup as I can test right now).

While the patch fixes the additional key down/up event on longer
presses, I still get a repeated key event on a short button
press - which makes it hard to do a single click with the
remote.

Test on kernel 4.14 with your patch:
1510927844.292126: event type EV_MSC(0x04): scancode = 0x1015
1510927844.292126: event type EV_KEY(0x01) key_down: KEY_ENTER(0x001c)
1510927844.292126: event type EV_SYN(0x00).
1510927844.498773: event type EV_MSC(0x04): scancode = 0x1015
1510927844.498773: event type EV_SYN(0x00).
1510927844.795410: event type EV_KEY(0x01) key_down: KEY_ENTER(0x001c)
1510927844.795410: event type EV_SYN(0x00).
1510927844.875412: event type EV_KEY(0x01) key_up: KEY_ENTER(0x001c)
1510927844.875412: event type EV_SYN(0x00).

Same signal received on kernel 4.9:
1510927844.280350: event type EV_MSC(0x04): scancode = 0x1015
1510927844.280350: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
1510927844.280350: event type EV_SYN(0x00).
1510927844.506477: event type EV_MSC(0x04): scancode = 0x1015
1510927844.506477: event type EV_SYN(0x00).
1510927844.763111: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
1510927844.763111: event type EV_SYN(0x00).

If I understand it correctly it's the input layer repeat (500ms delay)
kicking in, because time between initial scancode and timeout is
now signal time + 200ms + 164ms + 200ms (about 570-580ms).
On older kernels this was signal time + 200ms + 250ms, so typically
just below the 500ms default repeat delay.

I'm still trying to wrap my head around the timeout code in the
rc layer. One problem seems to be that we apply the rather large
timeout twice. Maybe detecting scancodes generated via timeout
(sth like timestamp - last_timestamp > protocol_repeat_period)
and in that case immediately signalling keyup could help? Could well
be that I'm missing somehting important and this is a bad idea.
I guess I'd better let you figure something out :)

so long,

Hias

> 
> Cc: <stable@vger.kernel.org> # 4.14
> Reported-by: Matthias Reichl <hias@horus.com>
> Signed-off-by: Sean Young <sean@mess.org>
> ---
>  drivers/media/rc/rc-main.c | 6 ++++--
>  1 file changed, 4 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/media/rc/rc-main.c b/drivers/media/rc/rc-main.c
> index 17950e29d4e3..fae721534517 100644
> --- a/drivers/media/rc/rc-main.c
> +++ b/drivers/media/rc/rc-main.c
> @@ -672,7 +672,8 @@ void rc_repeat(struct rc_dev *dev)
>  	input_event(dev->input_dev, EV_MSC, MSC_SCAN, dev->last_scancode);
>  	input_sync(dev->input_dev);
>  
> -	dev->keyup_jiffies = jiffies + msecs_to_jiffies(timeout);
> +	dev->keyup_jiffies = jiffies + msecs_to_jiffies(timeout) +
> +					nsecs_to_jiffies(dev->timeout);
>  	mod_timer(&dev->timer_keyup, dev->keyup_jiffies);
>  
>  out:
> @@ -744,7 +745,8 @@ void rc_keydown(struct rc_dev *dev, enum rc_proto protocol, u32 scancode,
>  
>  	if (dev->keypressed) {
>  		dev->keyup_jiffies = jiffies +
> -			msecs_to_jiffies(protocols[protocol].repeat_period);
> +			msecs_to_jiffies(protocols[protocol].repeat_period) +
> +			nsecs_to_jiffies(dev->timeout);
>  		mod_timer(&dev->timer_keyup, dev->keyup_jiffies);
>  	}
>  	spin_unlock_irqrestore(&dev->keylock, flags);
> -- 
> 2.14.3
> 

Re: [PATCH] media: rc: double keypresses due to timeout expiring to early

[Matthias Reichl]

On Fri, Nov 17, 2017 at 03:52:50PM +0100, Matthias Reichl wrote:
> Hi Sean!
> 
> On Thu, Nov 16, 2017 at 09:54:51PM +0000, Sean Young wrote:
> > Since commit d57ea877af38 ("media: rc: per-protocol repeat period"),
> > double keypresses are reported on the ite-cir driver. This is due
> > two factors: that commit reduced the timeout used for some protocols
> > (it became protocol dependant) and the high default IR timeout used
> > by the ite-cir driver.
> > 
> > Some of the IR decoders wait for a trailing space, as that is
> > the only way to know if the bit stream has ended (e.g. rc-6 can be
> > 16, 20 or 32 bits). The longer the IR timeout, the longer it will take
> > to receive the trailing space, delaying decoding and pushing it past the
> > keyup timeout.
> > 
> > So, add the IR timeout to the keyup timeout.
> 
> Thanks a lot for the patch, I've asked the people with ite-cir
> receivers to test it.

Just got the first test results from ite-cir + rc-6 remote back,
events were the same as I was seeing with gpio-ir-recv with 200ms
timeout - key repeat event from input layer.

Kernel 4.14 + your patch:
Event: time 1510938801.797335, type 4 (EV_MSC), code 4 (MSC_SCAN), value 800f041f
Event: time 1510938801.797335, type 1 (EV_KEY), code 108 (KEY_DOWN), value 1
Event: time 1510938801.797335, -------------- SYN_REPORT ------------
Event: time 1510938802.034331, type 4 (EV_MSC), code 4 (MSC_SCAN), value 800f041f
Event: time 1510938802.034331, -------------- SYN_REPORT ------------
Event: time 1510938802.301333, type 1 (EV_KEY), code 108 (KEY_DOWN), value 2
Event: time 1510938802.301333, -------------- SYN_REPORT ------------
Event: time 1510938802.408003, type 1 (EV_KEY), code 108 (KEY_DOWN), value 0
Event: time 1510938802.408003, -------------- SYN_REPORT ------------

Kernel 4.13.2:
Event: time 1510938637.791450, type 4 (EV_MSC), code 4 (MSC_SCAN), value 800f041f
Event: time 1510938637.791450, type 1 (EV_KEY), code 108 (KEY_DOWN), value 1
Event: time 1510938637.791450, -------------- SYN_REPORT ------------
Event: time 1510938638.028301, type 4 (EV_MSC), code 4 (MSC_SCAN), value 800f041f
Event: time 1510938638.028301, -------------- SYN_REPORT ------------
Event: time 1510938638.292323, type 1 (EV_KEY), code 108 (KEY_DOWN), value 0
Event: time 1510938638.292323, -------------- SYN_REPORT ------------

so long,

Hias

> 
> In the meanwhile I ran some tests with gpio-ir-recv and timeout
> set to 200ms with a rc-5 remote (that's as close to the original
> setup as I can test right now).
> 
> While the patch fixes the additional key down/up event on longer
> presses, I still get a repeated key event on a short button
> press - which makes it hard to do a single click with the
> remote.
> 
> Test on kernel 4.14 with your patch:
> 1510927844.292126: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.292126: event type EV_KEY(0x01) key_down: KEY_ENTER(0x001c)
> 1510927844.292126: event type EV_SYN(0x00).
> 1510927844.498773: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.498773: event type EV_SYN(0x00).
> 1510927844.795410: event type EV_KEY(0x01) key_down: KEY_ENTER(0x001c)
> 1510927844.795410: event type EV_SYN(0x00).
> 1510927844.875412: event type EV_KEY(0x01) key_up: KEY_ENTER(0x001c)
> 1510927844.875412: event type EV_SYN(0x00).
> 
> Same signal received on kernel 4.9:
> 1510927844.280350: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.280350: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
> 1510927844.280350: event type EV_SYN(0x00).
> 1510927844.506477: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.506477: event type EV_SYN(0x00).
> 1510927844.763111: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
> 1510927844.763111: event type EV_SYN(0x00).
> 
> If I understand it correctly it's the input layer repeat (500ms delay)
> kicking in, because time between initial scancode and timeout is
> now signal time + 200ms + 164ms + 200ms (about 570-580ms).
> On older kernels this was signal time + 200ms + 250ms, so typically
> just below the 500ms default repeat delay.
> 
> I'm still trying to wrap my head around the timeout code in the
> rc layer. One problem seems to be that we apply the rather large
> timeout twice. Maybe detecting scancodes generated via timeout
> (sth like timestamp - last_timestamp > protocol_repeat_period)
> and in that case immediately signalling keyup could help? Could well
> be that I'm missing somehting important and this is a bad idea.
> I guess I'd better let you figure something out :)
> 
> so long,
> 
> Hias
> 
> > 
> > Cc: <stable@vger.kernel.org> # 4.14
> > Reported-by: Matthias Reichl <hias@horus.com>
> > Signed-off-by: Sean Young <sean@mess.org>
> > ---
> >  drivers/media/rc/rc-main.c | 6 ++++--
> >  1 file changed, 4 insertions(+), 2 deletions(-)
> > 
> > diff --git a/drivers/media/rc/rc-main.c b/drivers/media/rc/rc-main.c
> > index 17950e29d4e3..fae721534517 100644
> > --- a/drivers/media/rc/rc-main.c
> > +++ b/drivers/media/rc/rc-main.c
> > @@ -672,7 +672,8 @@ void rc_repeat(struct rc_dev *dev)
> >  	input_event(dev->input_dev, EV_MSC, MSC_SCAN, dev->last_scancode);
> >  	input_sync(dev->input_dev);
> >  
> > -	dev->keyup_jiffies = jiffies + msecs_to_jiffies(timeout);
> > +	dev->keyup_jiffies = jiffies + msecs_to_jiffies(timeout) +
> > +					nsecs_to_jiffies(dev->timeout);
> >  	mod_timer(&dev->timer_keyup, dev->keyup_jiffies);
> >  
> >  out:
> > @@ -744,7 +745,8 @@ void rc_keydown(struct rc_dev *dev, enum rc_proto protocol, u32 scancode,
> >  
> >  	if (dev->keypressed) {
> >  		dev->keyup_jiffies = jiffies +
> > -			msecs_to_jiffies(protocols[protocol].repeat_period);
> > +			msecs_to_jiffies(protocols[protocol].repeat_period) +
> > +			nsecs_to_jiffies(dev->timeout);
> >  		mod_timer(&dev->timer_keyup, dev->keyup_jiffies);
> >  	}
> >  	spin_unlock_irqrestore(&dev->keylock, flags);
> > -- 
> > 2.14.3
> > 

Re: [PATCH] media: rc: double keypresses due to timeout expiring to early

[Sean Young]

On Fri, Nov 17, 2017 at 03:52:50PM +0100, Matthias Reichl wrote:
> Hi Sean!
> 
> On Thu, Nov 16, 2017 at 09:54:51PM +0000, Sean Young wrote:
> > Since commit d57ea877af38 ("media: rc: per-protocol repeat period"),
> > double keypresses are reported on the ite-cir driver. This is due
> > two factors: that commit reduced the timeout used for some protocols
> > (it became protocol dependant) and the high default IR timeout used
> > by the ite-cir driver.
> > 
> > Some of the IR decoders wait for a trailing space, as that is
> > the only way to know if the bit stream has ended (e.g. rc-6 can be
> > 16, 20 or 32 bits). The longer the IR timeout, the longer it will take
> > to receive the trailing space, delaying decoding and pushing it past the
> > keyup timeout.
> > 
> > So, add the IR timeout to the keyup timeout.
> 
> Thanks a lot for the patch, I've asked the people with ite-cir
> receivers to test it.
> 
> In the meanwhile I ran some tests with gpio-ir-recv and timeout
> set to 200ms with a rc-5 remote (that's as close to the original
> setup as I can test right now).
> 
> While the patch fixes the additional key down/up event on longer
> presses, I still get a repeated key event on a short button
> press - which makes it hard to do a single click with the
> remote.

Yes, I've started to notice that too.

> Test on kernel 4.14 with your patch:
> 1510927844.292126: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.292126: event type EV_KEY(0x01) key_down: KEY_ENTER(0x001c)
> 1510927844.292126: event type EV_SYN(0x00).
> 1510927844.498773: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.498773: event type EV_SYN(0x00).
> 1510927844.795410: event type EV_KEY(0x01) key_down: KEY_ENTER(0x001c)
> 1510927844.795410: event type EV_SYN(0x00).
> 1510927844.875412: event type EV_KEY(0x01) key_up: KEY_ENTER(0x001c)
> 1510927844.875412: event type EV_SYN(0x00).

There is 875 - 498 = 378ms, which is 200ms IR timeout + 164ms protocol
repeat. This is so long that the repeat delay expired, and that's
where the second keydown comes from.

> Same signal received on kernel 4.9:
> 1510927844.280350: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.280350: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
> 1510927844.280350: event type EV_SYN(0x00).
> 1510927844.506477: event type EV_MSC(0x04): scancode = 0x1015
> 1510927844.506477: event type EV_SYN(0x00).
> 1510927844.763111: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
> 1510927844.763111: event type EV_SYN(0x00).

There it is simply 763 - 506 = 250ms.

> If I understand it correctly it's the input layer repeat (500ms delay)
> kicking in, because time between initial scancode and timeout is
> now signal time + 200ms + 164ms + 200ms (about 570-580ms).
> On older kernels this was signal time + 200ms + 250ms, so typically
> just below the 500ms default repeat delay.
> 
> I'm still trying to wrap my head around the timeout code in the
> rc layer. One problem seems to be that we apply the rather large
> timeout twice. Maybe detecting scancodes generated via timeout
> (sth like timestamp - last_timestamp > protocol_repeat_period)
> and in that case immediately signalling keyup could help? Could well
> be that I'm missing somehting important and this is a bad idea.
> I guess I'd better let you figure something out :)

So there is a few complications. For rc-6, if you hold a button down,
there IR repeated every 110ms, which means there is a 69ms space between
the IR keypresses. The trailing space is needed for IR decode.

So with IR timeout of 200ms this will happen:

0.000 rc-6 IR message 1 begins
0.041 rc-6 IR message 1 ends
space
0.110 rc-6 IR message 2 begins; this means that message 1 is decoded now
0.151 rc-6 IR message 2 ends;
space
0.220 rc-6 IR message 3 begins; this means that message 2 is decoded now
0.261 rc-6 IR message 3 ends 
space
0.461 IR timeout occurs; this means that message 3 is decoded now

So really the timeout should be length of IR message + IR timeout + error 
margin (e.g. rc thread scheduling), unless that is less than the repeat
time.

But this only applies for raw IR decoding; different rules apply for
hardware decoders.

I think for now the best solution is to revert to 250ms for all protocols
(except for cec which needs 550ms), and reconsider for another kernel.

Thanks,
Sean
----
>From 2f1135f3f9873778ca5c013d1118710152840cb2 Mon Sep 17 00:00:00 2001
From: Sean Young <sean@mess.org>
Date: Sun, 19 Nov 2017 21:11:17 +0000
Subject: [PATCH] media: rc: partial revert of "media: rc: per-protocol repeat
 period"

Since commit d57ea877af38 ("media: rc: per-protocol repeat period"), most
IR protocols have a lower keyup timeout. This causes problems on the
ite-cir, which has default IR timeout of 200ms.

Since the IR decoders read the trailing space, with a IR timeout of 200ms,
the last keydown will have at least a delay of 200ms. This is more than
the protocol timeout of e.g. rc-6 (which is 164ms). As a result the last
IR will be interpreted as a new keydown event, and we get two keypresses.

Revert the protocol timeout to 250ms, except for cec which needs a timeout
of 550ms.

Fixes: d57ea877af38 ("media: rc: per-protocol repeat period")
Cc: <stable@vger.kernel.org> # 4.14
Signed-off-by: Sean Young <sean@mess.org>
---
 drivers/media/rc/rc-main.c | 32 ++++++++++++++++----------------
 1 file changed, 16 insertions(+), 16 deletions(-)

diff --git a/drivers/media/rc/rc-main.c b/drivers/media/rc/rc-main.c
index 17950e29d4e3..5057b2ba0c10 100644
--- a/drivers/media/rc/rc-main.c
+++ b/drivers/media/rc/rc-main.c
@@ -39,41 +39,41 @@ static const struct {
 	[RC_PROTO_UNKNOWN] = { .name = "unknown", .repeat_period = 250 },
 	[RC_PROTO_OTHER] = { .name = "other", .repeat_period = 250 },
 	[RC_PROTO_RC5] = { .name = "rc-5",
-		.scancode_bits = 0x1f7f, .repeat_period = 164 },
+		.scancode_bits = 0x1f7f, .repeat_period = 250 },
 	[RC_PROTO_RC5X_20] = { .name = "rc-5x-20",
-		.scancode_bits = 0x1f7f3f, .repeat_period = 164 },
+		.scancode_bits = 0x1f7f3f, .repeat_period = 250 },
 	[RC_PROTO_RC5_SZ] = { .name = "rc-5-sz",
-		.scancode_bits = 0x2fff, .repeat_period = 164 },
+		.scancode_bits = 0x2fff, .repeat_period = 250 },
 	[RC_PROTO_JVC] = { .name = "jvc",
 		.scancode_bits = 0xffff, .repeat_period = 250 },
 	[RC_PROTO_SONY12] = { .name = "sony-12",
-		.scancode_bits = 0x1f007f, .repeat_period = 100 },
+		.scancode_bits = 0x1f007f, .repeat_period = 250 },
 	[RC_PROTO_SONY15] = { .name = "sony-15",
-		.scancode_bits = 0xff007f, .repeat_period = 100 },
+		.scancode_bits = 0xff007f, .repeat_period = 250 },
 	[RC_PROTO_SONY20] = { .name = "sony-20",
-		.scancode_bits = 0x1fff7f, .repeat_period = 100 },
+		.scancode_bits = 0x1fff7f, .repeat_period = 250 },
 	[RC_PROTO_NEC] = { .name = "nec",
-		.scancode_bits = 0xffff, .repeat_period = 160 },
+		.scancode_bits = 0xffff, .repeat_period = 250 },
 	[RC_PROTO_NECX] = { .name = "nec-x",
-		.scancode_bits = 0xffffff, .repeat_period = 160 },
+		.scancode_bits = 0xffffff, .repeat_period = 250 },
 	[RC_PROTO_NEC32] = { .name = "nec-32",
-		.scancode_bits = 0xffffffff, .repeat_period = 160 },
+		.scancode_bits = 0xffffffff, .repeat_period = 250 },
 	[RC_PROTO_SANYO] = { .name = "sanyo",
 		.scancode_bits = 0x1fffff, .repeat_period = 250 },
 	[RC_PROTO_MCIR2_KBD] = { .name = "mcir2-kbd",
-		.scancode_bits = 0xffff, .repeat_period = 150 },
+		.scancode_bits = 0xffff, .repeat_period = 250 },
 	[RC_PROTO_MCIR2_MSE] = { .name = "mcir2-mse",
-		.scancode_bits = 0x1fffff, .repeat_period = 150 },
+		.scancode_bits = 0x1fffff, .repeat_period = 250 },
 	[RC_PROTO_RC6_0] = { .name = "rc-6-0",
-		.scancode_bits = 0xffff, .repeat_period = 164 },
+		.scancode_bits = 0xffff, .repeat_period = 250 },
 	[RC_PROTO_RC6_6A_20] = { .name = "rc-6-6a-20",
-		.scancode_bits = 0xfffff, .repeat_period = 164 },
+		.scancode_bits = 0xfffff, .repeat_period = 250 },
 	[RC_PROTO_RC6_6A_24] = { .name = "rc-6-6a-24",
-		.scancode_bits = 0xffffff, .repeat_period = 164 },
+		.scancode_bits = 0xffffff, .repeat_period = 250 },
 	[RC_PROTO_RC6_6A_32] = { .name = "rc-6-6a-32",
-		.scancode_bits = 0xffffffff, .repeat_period = 164 },
+		.scancode_bits = 0xffffffff, .repeat_period = 250 },
 	[RC_PROTO_RC6_MCE] = { .name = "rc-6-mce",
-		.scancode_bits = 0xffff7fff, .repeat_period = 164 },
+		.scancode_bits = 0xffff7fff, .repeat_period = 250 },
 	[RC_PROTO_SHARP] = { .name = "sharp",
 		.scancode_bits = 0x1fff, .repeat_period = 250 },
 	[RC_PROTO_XMP] = { .name = "xmp", .repeat_period = 250 },
-- 
2.14.3

Re: [PATCH] media: rc: double keypresses due to timeout expiring to early

[Matthias Reichl]

Hi Sean!

On Sun, Nov 19, 2017 at 09:57:27PM +0000, Sean Young wrote:
> I think for now the best solution is to revert to 250ms for all protocols
> (except for cec which needs 550ms), and reconsider for another kernel.

Thanks, this sounds like a good idea!

> >>From 2f1135f3f9873778ca5c013d1118710152840cb2 Mon Sep 17 00:00:00 2001
> From: Sean Young <sean@mess.org>
> Date: Sun, 19 Nov 2017 21:11:17 +0000
> Subject: [PATCH] media: rc: partial revert of "media: rc: per-protocol repeat
>  period"
> 
> Since commit d57ea877af38 ("media: rc: per-protocol repeat period"), most
> IR protocols have a lower keyup timeout. This causes problems on the
> ite-cir, which has default IR timeout of 200ms.
> 
> Since the IR decoders read the trailing space, with a IR timeout of 200ms,
> the last keydown will have at least a delay of 200ms. This is more than
> the protocol timeout of e.g. rc-6 (which is 164ms). As a result the last
> IR will be interpreted as a new keydown event, and we get two keypresses.
> 
> Revert the protocol timeout to 250ms, except for cec which needs a timeout
> of 550ms.
> 
> Fixes: d57ea877af38 ("media: rc: per-protocol repeat period")
> Cc: <stable@vger.kernel.org> # 4.14
> Signed-off-by: Sean Young <sean@mess.org>

Tested-by: Matthias Reichl <hias@horus.com>

I tested this locally with gpio-ir configured to 200ms timeout and
we also received feedback from 2 users that this change fixed the
issue with the ite-cir receiver.

https://forum.kodi.tv/showthread.php?tid=298462&pid=2670637#pid2670637

Thanks a lot for fixing this so quickly!

so long,

Hias
> ---
>  drivers/media/rc/rc-main.c | 32 ++++++++++++++++----------------
>  1 file changed, 16 insertions(+), 16 deletions(-)
> 
> diff --git a/drivers/media/rc/rc-main.c b/drivers/media/rc/rc-main.c
> index 17950e29d4e3..5057b2ba0c10 100644
> --- a/drivers/media/rc/rc-main.c
> +++ b/drivers/media/rc/rc-main.c
> @@ -39,41 +39,41 @@ static const struct {
>  	[RC_PROTO_UNKNOWN] = { .name = "unknown", .repeat_period = 250 },
>  	[RC_PROTO_OTHER] = { .name = "other", .repeat_period = 250 },
>  	[RC_PROTO_RC5] = { .name = "rc-5",
> -		.scancode_bits = 0x1f7f, .repeat_period = 164 },
> +		.scancode_bits = 0x1f7f, .repeat_period = 250 },
>  	[RC_PROTO_RC5X_20] = { .name = "rc-5x-20",
> -		.scancode_bits = 0x1f7f3f, .repeat_period = 164 },
> +		.scancode_bits = 0x1f7f3f, .repeat_period = 250 },
>  	[RC_PROTO_RC5_SZ] = { .name = "rc-5-sz",
> -		.scancode_bits = 0x2fff, .repeat_period = 164 },
> +		.scancode_bits = 0x2fff, .repeat_period = 250 },
>  	[RC_PROTO_JVC] = { .name = "jvc",
>  		.scancode_bits = 0xffff, .repeat_period = 250 },
>  	[RC_PROTO_SONY12] = { .name = "sony-12",
> -		.scancode_bits = 0x1f007f, .repeat_period = 100 },
> +		.scancode_bits = 0x1f007f, .repeat_period = 250 },
>  	[RC_PROTO_SONY15] = { .name = "sony-15",
> -		.scancode_bits = 0xff007f, .repeat_period = 100 },
> +		.scancode_bits = 0xff007f, .repeat_period = 250 },
>  	[RC_PROTO_SONY20] = { .name = "sony-20",
> -		.scancode_bits = 0x1fff7f, .repeat_period = 100 },
> +		.scancode_bits = 0x1fff7f, .repeat_period = 250 },
>  	[RC_PROTO_NEC] = { .name = "nec",
> -		.scancode_bits = 0xffff, .repeat_period = 160 },
> +		.scancode_bits = 0xffff, .repeat_period = 250 },
>  	[RC_PROTO_NECX] = { .name = "nec-x",
> -		.scancode_bits = 0xffffff, .repeat_period = 160 },
> +		.scancode_bits = 0xffffff, .repeat_period = 250 },
>  	[RC_PROTO_NEC32] = { .name = "nec-32",
> -		.scancode_bits = 0xffffffff, .repeat_period = 160 },
> +		.scancode_bits = 0xffffffff, .repeat_period = 250 },
>  	[RC_PROTO_SANYO] = { .name = "sanyo",
>  		.scancode_bits = 0x1fffff, .repeat_period = 250 },
>  	[RC_PROTO_MCIR2_KBD] = { .name = "mcir2-kbd",
> -		.scancode_bits = 0xffff, .repeat_period = 150 },
> +		.scancode_bits = 0xffff, .repeat_period = 250 },
>  	[RC_PROTO_MCIR2_MSE] = { .name = "mcir2-mse",
> -		.scancode_bits = 0x1fffff, .repeat_period = 150 },
> +		.scancode_bits = 0x1fffff, .repeat_period = 250 },
>  	[RC_PROTO_RC6_0] = { .name = "rc-6-0",
> -		.scancode_bits = 0xffff, .repeat_period = 164 },
> +		.scancode_bits = 0xffff, .repeat_period = 250 },
>  	[RC_PROTO_RC6_6A_20] = { .name = "rc-6-6a-20",
> -		.scancode_bits = 0xfffff, .repeat_period = 164 },
> +		.scancode_bits = 0xfffff, .repeat_period = 250 },
>  	[RC_PROTO_RC6_6A_24] = { .name = "rc-6-6a-24",
> -		.scancode_bits = 0xffffff, .repeat_period = 164 },
> +		.scancode_bits = 0xffffff, .repeat_period = 250 },
>  	[RC_PROTO_RC6_6A_32] = { .name = "rc-6-6a-32",
> -		.scancode_bits = 0xffffffff, .repeat_period = 164 },
> +		.scancode_bits = 0xffffffff, .repeat_period = 250 },
>  	[RC_PROTO_RC6_MCE] = { .name = "rc-6-mce",
> -		.scancode_bits = 0xffff7fff, .repeat_period = 164 },
> +		.scancode_bits = 0xffff7fff, .repeat_period = 250 },
>  	[RC_PROTO_SHARP] = { .name = "sharp",
>  		.scancode_bits = 0x1fff, .repeat_period = 250 },
>  	[RC_PROTO_XMP] = { .name = "xmp", .repeat_period = 250 },
> -- 
> 2.14.3
>