Re: SONY IR issue

Re: SONY IR issue

[Sean Young]

Hi Joakim,

On Thu, Sep 03, 2020 at 11:55:30AM +0000, Joakim Zhang wrote:
> 
> Hi Sean,
> 
> Thanks a lot for pointing me to use “ir-ctl -r”, really easy to capture the raw data. 😊
> 
> The scancode from my RC is 0x130002, the scancode decoded by SONY decoder is 0x110002. So I capture the waveform generated by IR and raw data sampled by GPIO. All attached, please have a check.

So you captured it with a logic analyzer?

> As you can see, the RC transmit repeatedly 6 times. After checking them carefully, all of them satisfied SONY 12bit protocols. SONY decoder decode the 5th signal and report the scancode 0x110002.
> According to raw data, it really should be 0x110002. So I check the waveform and raw data further, the raw data sampled by GPIO seems not correct.
> 
> e.g. for the 5th signal
> [cid:image001.jpg@01D6822C.2AD54480]
> pulse 2408
> space 549
> pulse 579
> space 581
> pulse 1188
> space 579
> pulse 579
> space 579
> pulse 579
> space 581
> pulse 577
> space 579
> pulse 579
> space 549
> pulse 610
> space 548
> pulse 1222
> space 547
> pulse 690 // this should be ~1200
> space 567
> pulse 587
> space 569
> pulse 588
> space 570
> pulse 1192
> timeout 17877
> 
> For other signals, they all have an exception value in raw data, as below, so decoder failed at these values. Strange enough, why only one value is incorrect.
> 1st: space 54
> 2nd: pulse 76
> 3rd: space 61
> 4th: space 51
> 6th: space 53
> But looking into the waveform, they are all normal, could you tell me how to look into it? Is there any specific configuration for GPIO PAD? I might have to grab some analog signals.
> One more add is that, it can improve decode correctness if I add milliseconds delay in ir_sony_decode() function.

Right, so changing the dev_dbg() to dev_info() did work, although that is
not the correct fix.

It would be interesting to know if the problem is in the gpio device, or
if there is a problem with further processing in the IR layers.

What is the device you are using?

I think it would be interesting to add a debug printk in gpio_ir_recv_irq
with the ktime and the val. We can see then if correct data is being
generated here, or if things go wrong in the IR layers.

I wouldn't be surprised if the gpio device generates two interrupts for the
broken pulse (one after 690us and another at 1200us), and if decoding happens
before the second then the wrong pulse length is used.

> I also have a question, if RC transmit repeatedly 6 times, and SONY decodes decode all raw data successfully, it will report to input subsystem 6 times, does input subsystem will still report to userspace 6 times?

If the sony decodes the same values 6 times, then scancode will reported 6
imes, but there will be only one key down event, and a key up event about
100ms after the the last decode (plus a few other milliseconds for various
timeouts).

Thanks,

Sean

RE: SONY IR issue

[Joakim Zhang]

> -----Original Message-----
> From: Sean Young <sean@mess.org>
> Sent: 2020年9月4日 2:55
> To: Joakim Zhang <qiangqing.zhang@nxp.com>
> Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>
> Subject: Re: SONY IR issue
> 
> 
> Hi Joakim,
> 
> On Thu, Sep 03, 2020 at 11:55:30AM +0000, Joakim Zhang wrote:
> >
> > Hi Sean,
> >
> > Thanks a lot for pointing me to use “ir-ctl -r”, really easy to
> > capture the raw data. 😊
> >
> > The scancode from my RC is 0x130002, the scancode decoded by SONY
> decoder is 0x110002. So I capture the waveform generated by IR and raw data
> sampled by GPIO. All attached, please have a check.
> 
> So you captured it with a logic analyzer?
Yes, with a logic analyzer yesterday. Today, change to use a analog analyzer, the signal is perfect, seems not the issue of signal generated by IR device. IR device I used is IRM-V538/TR1.


> > As you can see, the RC transmit repeatedly 6 times. After checking them
> carefully, all of them satisfied SONY 12bit protocols. SONY decoder decode the
> 5th signal and report the scancode 0x110002.
> > According to raw data, it really should be 0x110002. So I check the waveform
> and raw data further, the raw data sampled by GPIO seems not correct.
> >
> > e.g. for the 5th signal
> > [cid:image001.jpg@01D6822C.2AD54480]
> > pulse 2408
> > space 549
> > pulse 579
> > space 581
> > pulse 1188
> > space 579
> > pulse 579
> > space 579
> > pulse 579
> > space 581
> > pulse 577
> > space 579
> > pulse 579
> > space 549
> > pulse 610
> > space 548
> > pulse 1222
> > space 547
> > pulse 690 // this should be ~1200
> > space 567
> > pulse 587
> > space 569
> > pulse 588
> > space 570
> > pulse 1192
> > timeout 17877
> >
> > For other signals, they all have an exception value in raw data, as below, so
> decoder failed at these values. Strange enough, why only one value is incorrect.
> > 1st: space 54
> > 2nd: pulse 76
> > 3rd: space 61
> > 4th: space 51
> > 6th: space 53
> > But looking into the waveform, they are all normal, could you tell me how to
> look into it? Is there any specific configuration for GPIO PAD? I might have to
> grab some analog signals.
> > One more add is that, it can improve decode correctness if I add milliseconds
> delay in ir_sony_decode() function.
> 
> Right, so changing the dev_dbg() to dev_info() did work, although that is not
> the correct fix.
> 
> It would be interesting to know if the problem is in the gpio device, or if there is
> a problem with further processing in the IR layers.
> 
> What is the device you are using?
>
> I think it would be interesting to add a debug printk in gpio_ir_recv_irq with the
> ktime and the val. We can see then if correct data is being generated here, or if
> things go wrong in the IR layers.
I did below code change to print raw data generated in gpio interrupt handler. After checking the data, it is consistent to the raw data dump by the ir-ctl.

--- a/drivers/media/rc/rc-ir-raw.c
+++ b/drivers/media/rc/rc-ir-raw.c
@@ -76,7 +76,7 @@ int ir_raw_event_store(struct rc_dev *dev, struct ir_raw_event *ev)
        if (!dev->raw)
                return -EINVAL;

-       dev_dbg(&dev->dev, "sample: (%05dus %s)\n",
+       trace_printk("sample: (%05dus %s)\n",
                TO_US(ev->duration), TO_STR(ev->pulse));

        if (!kfifo_put(&dev->raw->kfifo, *ev)) {


> I wouldn't be surprised if the gpio device generates two interrupts for the
> broken pulse (one after 690us and another at 1200us), and if decoding happens
> before the second then the wrong pulse length is used.
I also check the number of interrupt generated by gpio. After I press the key, RC transmits 7 frames, it should contain 182 falling/rising edges.
It indeed reports 182 interrupts and go through ir_raw_event_store function 182 times. Since the number of interrupt is accurate, just a few falling/rising interrupt
comes much quickly than others, but the analog signal is perfect. It is really out of my understanding. It should not an issue in IR layer.

> > I also have a question, if RC transmit repeatedly 6 times, and SONY decodes
> decode all raw data successfully, it will report to input subsystem 6 times, does
> input subsystem will still report to userspace 6 times?
> 
> If the sony decodes the same values 6 times, then scancode will reported 6
> imes, but there will be only one key down event, and a key up event about
> 100ms after the the last decode (plus a few other milliseconds for various
> timeouts).
Thanks for your details. Does this mean input subsystem will still report scancode 6 times, but only report keycode once if it is matched?

Sean, based on your experience, where else do you suggest me to look into this further? Have you came across such case, a few interrupt responded so quickly so that front pulse/space is much shorten?

Best Regards,
Joakim Zhang
> Thanks,
> 
> Sean

Re: SONY IR issue

[Sean Young]

Hi Joakim,

On Fri, Sep 04, 2020 at 10:43:23AM +0000, Joakim Zhang wrote:
> > On Thu, Sep 03, 2020 at 11:55:30AM +0000, Joakim Zhang wrote:
> > > Thanks a lot for pointing me to use “ir-ctl -r”, really easy to
> > > capture the raw data. 😊
> > >
> > > The scancode from my RC is 0x130002, the scancode decoded by SONY
> > decoder is 0x110002. So I capture the waveform generated by IR and raw data
> > sampled by GPIO. All attached, please have a check.
> > 
> > So you captured it with a logic analyzer?
> Yes, with a logic analyzer yesterday. Today, change to use a analog analyzer, the signal is perfect, seems not the issue of signal generated by IR device. IR device I used is IRM-V538/TR1.

Ok, makes sense.
 
> > > As you can see, the RC transmit repeatedly 6 times. After checking them
> > carefully, all of them satisfied SONY 12bit protocols. SONY decoder decode the
> > 5th signal and report the scancode 0x110002.
> > > According to raw data, it really should be 0x110002. So I check the waveform
> > and raw data further, the raw data sampled by GPIO seems not correct.
> > >
> > > e.g. for the 5th signal
> > > [cid:image001.jpg@01D6822C.2AD54480]
> > > pulse 2408
> > > space 549
> > > pulse 579
> > > space 581
> > > pulse 1188
> > > space 579
> > > pulse 579
> > > space 579
> > > pulse 579
> > > space 581
> > > pulse 577
> > > space 579
> > > pulse 579
> > > space 549
> > > pulse 610
> > > space 548
> > > pulse 1222
> > > space 547
> > > pulse 690 // this should be ~1200
> > > space 567
> > > pulse 587
> > > space 569
> > > pulse 588
> > > space 570
> > > pulse 1192
> > > timeout 17877
> > >
> > > For other signals, they all have an exception value in raw data, as below, so
> > decoder failed at these values. Strange enough, why only one value is incorrect.
> > > 1st: space 54
> > > 2nd: pulse 76
> > > 3rd: space 61
> > > 4th: space 51
> > > 6th: space 53
> > > But looking into the waveform, they are all normal, could you tell me how to
> > look into it? Is there any specific configuration for GPIO PAD? I might have to
> > grab some analog signals.
> > > One more add is that, it can improve decode correctness if I add milliseconds
> > delay in ir_sony_decode() function.
> > 
> > Right, so changing the dev_dbg() to dev_info() did work, although that is not
> > the correct fix.
> > 
> > It would be interesting to know if the problem is in the gpio device, or if there is
> > a problem with further processing in the IR layers.
> > 
> > What is the device you are using?
> >
> > I think it would be interesting to add a debug printk in gpio_ir_recv_irq with the
> > ktime and the val. We can see then if correct data is being generated here, or if
> > things go wrong in the IR layers.
> I did below code change to print raw data generated in gpio interrupt handler. After checking the data, it is consistent to the raw data dump by the ir-ctl.
> 
> --- a/drivers/media/rc/rc-ir-raw.c
> +++ b/drivers/media/rc/rc-ir-raw.c
> @@ -76,7 +76,7 @@ int ir_raw_event_store(struct rc_dev *dev, struct ir_raw_event *ev)
>         if (!dev->raw)
>                 return -EINVAL;
> 
> -       dev_dbg(&dev->dev, "sample: (%05dus %s)\n",
> +       trace_printk("sample: (%05dus %s)\n",
>                 TO_US(ev->duration), TO_STR(ev->pulse));
> 
>         if (!kfifo_put(&dev->raw->kfifo, *ev)) {
> 
> 
> > I wouldn't be surprised if the gpio device generates two interrupts for the
> > broken pulse (one after 690us and another at 1200us), and if decoding happens
> > before the second then the wrong pulse length is used.
> I also check the number of interrupt generated by gpio. After I press the key, RC transmits 7 frames, it should contain 182 falling/rising edges.
> It indeed reports 182 interrupts and go through ir_raw_event_store function 182 times. Since the number of interrupt is accurate, just a few falling/rising interrupt
> comes much quickly than others, but the analog signal is perfect. It is really out of my understanding. It should not an issue in IR layer.

I think the next step would be to put dev_dbg/printk in gpio-ir-recv.c,
and see if the results are the same there. I suspect they will be.

> > > I also have a question, if RC transmit repeatedly 6 times, and SONY decodes
> > decode all raw data successfully, it will report to input subsystem 6 times, does
> > input subsystem will still report to userspace 6 times?
> > 
> > If the sony decodes the same values 6 times, then scancode will reported 6
> > imes, but there will be only one key down event, and a key up event about
> > 100ms after the the last decode (plus a few other milliseconds for various
> > timeouts).
> Thanks for your details. Does this mean input subsystem will still report scancode 6 times, but only report keycode once if it is matched?

Exactly. The keycode is only reported once, so that if the user press e.g.
"1" they will get just get one "1". 

> Sean, based on your experience, where else do you suggest me to look into this further? Have you came across such case, a few interrupt responded so quickly so that front pulse/space is much shorten?

To be honest I've never seen this before.

I'm not sure what the cause could be. On the raspberry pi it is known that
lots usb traffic causes delays in the gpio interrupt handlers due to
some hardware issue, but this causes some interrupts to arrive late. This
causes some of the pulse/space timings to be longer, and then later ones
are shorter again as it catches up.

Similarly if the kernel is running with interrupts off for too long, some
of the timings will be longer and others shorter.

Is there anything you can tell us about the gpio hardware?

Thanks,

Sean

RE: SONY IR issue

[Joakim Zhang]

> -----Original Message-----
> From: Sean Young <sean@mess.org>
> Sent: 2020年9月4日 20:31
> To: Joakim Zhang <qiangqing.zhang@nxp.com>
> Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>;
> linux-gpio@vger.kernel.org; Bartosz Golaszewski <bgolaszewski@baylibre.com>
> Subject: Re: SONY IR issue
> 
> Hi Joakim,
> 
> On Fri, Sep 04, 2020 at 10:43:23AM +0000, Joakim Zhang wrote:
> > > On Thu, Sep 03, 2020 at 11:55:30AM +0000, Joakim Zhang wrote:
> > > > Thanks a lot for pointing me to use “ir-ctl -r”, really easy to
> > > > capture the raw data. 😊
> > > >
> > > > The scancode from my RC is 0x130002, the scancode decoded by SONY
> > > decoder is 0x110002. So I capture the waveform generated by IR and
> > > raw data sampled by GPIO. All attached, please have a check.
> > >
> > > So you captured it with a logic analyzer?
> > Yes, with a logic analyzer yesterday. Today, change to use a analog analyzer,
> the signal is perfect, seems not the issue of signal generated by IR device. IR
> device I used is IRM-V538/TR1.
> 
> Ok, makes sense.
> 
> > > > As you can see, the RC transmit repeatedly 6 times. After checking
> > > > them
> > > carefully, all of them satisfied SONY 12bit protocols. SONY decoder
> > > decode the 5th signal and report the scancode 0x110002.
> > > > According to raw data, it really should be 0x110002. So I check
> > > > the waveform
> > > and raw data further, the raw data sampled by GPIO seems not correct.
> > > >
> > > > e.g. for the 5th signal
> > > > [cid:image001.jpg@01D6822C.2AD54480]
> > > > pulse 2408
> > > > space 549
> > > > pulse 579
> > > > space 581
> > > > pulse 1188
> > > > space 579
> > > > pulse 579
> > > > space 579
> > > > pulse 579
> > > > space 581
> > > > pulse 577
> > > > space 579
> > > > pulse 579
> > > > space 549
> > > > pulse 610
> > > > space 548
> > > > pulse 1222
> > > > space 547
> > > > pulse 690 // this should be ~1200
> > > > space 567
> > > > pulse 587
> > > > space 569
> > > > pulse 588
> > > > space 570
> > > > pulse 1192
> > > > timeout 17877
> > > >
> > > > For other signals, they all have an exception value in raw data,
> > > > as below, so
> > > decoder failed at these values. Strange enough, why only one value is
> incorrect.
> > > > 1st: space 54
> > > > 2nd: pulse 76
> > > > 3rd: space 61
> > > > 4th: space 51
> > > > 6th: space 53
> > > > But looking into the waveform, they are all normal, could you tell
> > > > me how to
> > > look into it? Is there any specific configuration for GPIO PAD? I
> > > might have to grab some analog signals.
> > > > One more add is that, it can improve decode correctness if I add
> > > > milliseconds
> > > delay in ir_sony_decode() function.
> > >
> > > Right, so changing the dev_dbg() to dev_info() did work, although
> > > that is not the correct fix.
> > >
> > > It would be interesting to know if the problem is in the gpio
> > > device, or if there is a problem with further processing in the IR layers.
> > >
> > > What is the device you are using?
> > >
> > > I think it would be interesting to add a debug printk in
> > > gpio_ir_recv_irq with the ktime and the val. We can see then if
> > > correct data is being generated here, or if things go wrong in the IR layers.
> > I did below code change to print raw data generated in gpio interrupt handler.
> After checking the data, it is consistent to the raw data dump by the ir-ctl.
> >
> > --- a/drivers/media/rc/rc-ir-raw.c
> > +++ b/drivers/media/rc/rc-ir-raw.c
> > @@ -76,7 +76,7 @@ int ir_raw_event_store(struct rc_dev *dev, struct
> ir_raw_event *ev)
> >         if (!dev->raw)
> >                 return -EINVAL;
> >
> > -       dev_dbg(&dev->dev, "sample: (%05dus %s)\n",
> > +       trace_printk("sample: (%05dus %s)\n",
> >                 TO_US(ev->duration), TO_STR(ev->pulse));
> >
> >         if (!kfifo_put(&dev->raw->kfifo, *ev)) {
> >
> >
> > > I wouldn't be surprised if the gpio device generates two interrupts
> > > for the broken pulse (one after 690us and another at 1200us), and if
> > > decoding happens before the second then the wrong pulse length is used.
> > I also check the number of interrupt generated by gpio. After I press the key,
> RC transmits 7 frames, it should contain 182 falling/rising edges.
> > It indeed reports 182 interrupts and go through ir_raw_event_store
> > function 182 times. Since the number of interrupt is accurate, just a few
> falling/rising interrupt comes much quickly than others, but the analog signal is
> perfect. It is really out of my understanding. It should not an issue in IR layer.
> 
> I think the next step would be to put dev_dbg/printk in gpio-ir-recv.c, and see if
> the results are the same there. I suspect they will be.
Yes, as you suspected, the result is the same there. It seems to be a system or gpio issue.


> > > > I also have a question, if RC transmit repeatedly 6 times, and
> > > > SONY decodes
> > > decode all raw data successfully, it will report to input subsystem
> > > 6 times, does input subsystem will still report to userspace 6 times?
> > >
> > > If the sony decodes the same values 6 times, then scancode will
> > > reported 6 imes, but there will be only one key down event, and a
> > > key up event about 100ms after the the last decode (plus a few other
> > > milliseconds for various timeouts).
> > Thanks for your details. Does this mean input subsystem will still report
> scancode 6 times, but only report keycode once if it is matched?
> 
> Exactly. The keycode is only reported once, so that if the user press e.g.
> "1" they will get just get one "1".
> 
> > Sean, based on your experience, where else do you suggest me to look into
> this further? Have you came across such case, a few interrupt responded so
> quickly so that front pulse/space is much shorten?
> 
> To be honest I've never seen this before.
> 
> I'm not sure what the cause could be. On the raspberry pi it is known that lots
> usb traffic causes delays in the gpio interrupt handlers due to some hardware
> issue, but this causes some interrupts to arrive late. This causes some of the
> pulse/space timings to be longer, and then later ones are shorter again as it
> catches up.
> 
> Similarly if the kernel is running with interrupts off for too long, some of the
> timings will be longer and others shorter.
Yes, we can understand the interrupt arrives late and cause the timings incorrect. At my side, a few interrupt arrives too faster.

> Is there anything you can tell us about the gpio hardware?
GPIO is from our SoC, power supply with extern 3.3V, and I configured it internal pull-up. 

Thanks.

Best Regards,
Joakim Zhang
> Thanks,
> 
> Sean

Re: SONY IR issue

[Sean Young]

On Mon, Sep 07, 2020 at 06:58:43AM +0000, Joakim Zhang wrote:

-snip-

> > > > I wouldn't be surprised if the gpio device generates two interrupts
> > > > for the broken pulse (one after 690us and another at 1200us), and if
> > > > decoding happens before the second then the wrong pulse length is used.
> > > I also check the number of interrupt generated by gpio. After I press the key,
> > RC transmits 7 frames, it should contain 182 falling/rising edges.
> > > It indeed reports 182 interrupts and go through ir_raw_event_store
> > > function 182 times. Since the number of interrupt is accurate, just a few
> > falling/rising interrupt comes much quickly than others, but the analog signal is
> > perfect. It is really out of my understanding. It should not an issue in IR layer.
> > 
> > I think the next step would be to put dev_dbg/printk in gpio-ir-recv.c, and see if
> > the results are the same there. I suspect they will be.
> Yes, as you suspected, the result is the same there. It seems to be a system or gpio issue.
> 
> 
> > > > > I also have a question, if RC transmit repeatedly 6 times, and
> > > > > SONY decodes
> > > > decode all raw data successfully, it will report to input subsystem
> > > > 6 times, does input subsystem will still report to userspace 6 times?
> > > >
> > > > If the sony decodes the same values 6 times, then scancode will
> > > > reported 6 imes, but there will be only one key down event, and a
> > > > key up event about 100ms after the the last decode (plus a few other
> > > > milliseconds for various timeouts).
> > > Thanks for your details. Does this mean input subsystem will still report
> > scancode 6 times, but only report keycode once if it is matched?
> > 
> > Exactly. The keycode is only reported once, so that if the user press e.g.
> > "1" they will get just get one "1".
> > 
> > > Sean, based on your experience, where else do you suggest me to look into
> > this further? Have you came across such case, a few interrupt responded so
> > quickly so that front pulse/space is much shorten?
> > 
> > To be honest I've never seen this before.
> > 
> > I'm not sure what the cause could be. On the raspberry pi it is known that lots
> > usb traffic causes delays in the gpio interrupt handlers due to some hardware
> > issue, but this causes some interrupts to arrive late. This causes some of the
> > pulse/space timings to be longer, and then later ones are shorter again as it
> > catches up.
> > 
> > Similarly if the kernel is running with interrupts off for too long, some of the
> > timings will be longer and others shorter.
> Yes, we can understand the interrupt arrives late and cause the timings incorrect. At my side, a few interrupt arrives too faster.

I'm wondering where you captured the IR signal. If you captured the IR signal
on the transmitter led, make sure the resolution is high enough so you can
see the carrier. Then you can make sure there are no errors in there.

It might be better to capture the IR signal on the gpio signal going into
the SoC.

> > Is there anything you can tell us about the gpio hardware?
> GPIO is from our SoC, power supply with extern 3.3V, and I configured it internal pull-up. 

Thanks
Sean

RE: SONY IR issue

[Joakim Zhang]

> -----Original Message-----
> From: Sean Young <sean@mess.org>
> Sent: 2020年9月7日 16:41
> To: Joakim Zhang <qiangqing.zhang@nxp.com>
> Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>;
> linux-gpio@vger.kernel.org; Bartosz Golaszewski <bgolaszewski@baylibre.com>
> Subject: Re: SONY IR issue
> 
> On Mon, Sep 07, 2020 at 06:58:43AM +0000, Joakim Zhang wrote:
> 
> -snip-
> 
> > > > > I wouldn't be surprised if the gpio device generates two
> > > > > interrupts for the broken pulse (one after 690us and another at
> > > > > 1200us), and if decoding happens before the second then the wrong
> pulse length is used.
> > > > I also check the number of interrupt generated by gpio. After I
> > > > press the key,
> > > RC transmits 7 frames, it should contain 182 falling/rising edges.
> > > > It indeed reports 182 interrupts and go through ir_raw_event_store
> > > > function 182 times. Since the number of interrupt is accurate,
> > > > just a few
> > > falling/rising interrupt comes much quickly than others, but the
> > > analog signal is perfect. It is really out of my understanding. It should not an
> issue in IR layer.
> > >
> > > I think the next step would be to put dev_dbg/printk in
> > > gpio-ir-recv.c, and see if the results are the same there. I suspect they will
> be.
> > Yes, as you suspected, the result is the same there. It seems to be a system
> or gpio issue.
> >
> >
> > > > > > I also have a question, if RC transmit repeatedly 6 times, and
> > > > > > SONY decodes
> > > > > decode all raw data successfully, it will report to input
> > > > > subsystem
> > > > > 6 times, does input subsystem will still report to userspace 6 times?
> > > > >
> > > > > If the sony decodes the same values 6 times, then scancode will
> > > > > reported 6 imes, but there will be only one key down event, and
> > > > > a key up event about 100ms after the the last decode (plus a few
> > > > > other milliseconds for various timeouts).
> > > > Thanks for your details. Does this mean input subsystem will still
> > > > report
> > > scancode 6 times, but only report keycode once if it is matched?
> > >
> > > Exactly. The keycode is only reported once, so that if the user press e.g.
> > > "1" they will get just get one "1".
> > >
> > > > Sean, based on your experience, where else do you suggest me to
> > > > look into
> > > this further? Have you came across such case, a few interrupt
> > > responded so quickly so that front pulse/space is much shorten?
> > >
> > > To be honest I've never seen this before.
> > >
> > > I'm not sure what the cause could be. On the raspberry pi it is
> > > known that lots usb traffic causes delays in the gpio interrupt
> > > handlers due to some hardware issue, but this causes some interrupts
> > > to arrive late. This causes some of the pulse/space timings to be
> > > longer, and then later ones are shorter again as it catches up.
> > >
> > > Similarly if the kernel is running with interrupts off for too long,
> > > some of the timings will be longer and others shorter.
> > Yes, we can understand the interrupt arrives late and cause the timings
> incorrect. At my side, a few interrupt arrives too faster.
> 
> I'm wondering where you captured the IR signal. If you captured the IR signal
> on the transmitter led, make sure the resolution is high enough so you can see
> the carrier. Then you can make sure there are no errors in there.
> 
> It might be better to capture the IR signal on the gpio signal going into the SoC.

Yes, the signal I captured is the output of the IR device, i.e. the gpio signal going into the SoC.

Best Regards,
Joakim Zhang
> > > Is there anything you can tell us about the gpio hardware?
> > GPIO is from our SoC, power supply with extern 3.3V, and I configured it
> internal pull-up.
> 
> Thanks
> Sean

RE: SONY IR issue

[Joakim Zhang]

Hi Sean,

GPIO IR Recv extremely rely on the real-time performance of the interrupt response, after turn off cpuidle, IR can work steadily now.

Much thanks for your kindly help. 😊

Best Regards,
Joakim Zhang
> -----Original Message-----
> From: Joakim Zhang
> Sent: 2020年9月7日 16:52
> To: Sean Young <sean@mess.org>
> Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>;
> linux-gpio@vger.kernel.org; Bartosz Golaszewski <bgolaszewski@baylibre.com>
> Subject: RE: SONY IR issue
> 
> 
> > -----Original Message-----
> > From: Sean Young <sean@mess.org>
> > Sent: 2020年9月7日 16:41
> > To: Joakim Zhang <qiangqing.zhang@nxp.com>
> > Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>;
> > linux-gpio@vger.kernel.org; Bartosz Golaszewski
> > <bgolaszewski@baylibre.com>
> > Subject: Re: SONY IR issue
> >
> > On Mon, Sep 07, 2020 at 06:58:43AM +0000, Joakim Zhang wrote:
> >
> > -snip-
> >
> > > > > > I wouldn't be surprised if the gpio device generates two
> > > > > > interrupts for the broken pulse (one after 690us and another
> > > > > > at 1200us), and if decoding happens before the second then the
> > > > > > wrong
> > pulse length is used.
> > > > > I also check the number of interrupt generated by gpio. After I
> > > > > press the key,
> > > > RC transmits 7 frames, it should contain 182 falling/rising edges.
> > > > > It indeed reports 182 interrupts and go through
> > > > > ir_raw_event_store function 182 times. Since the number of
> > > > > interrupt is accurate, just a few
> > > > falling/rising interrupt comes much quickly than others, but the
> > > > analog signal is perfect. It is really out of my understanding. It
> > > > should not an
> > issue in IR layer.
> > > >
> > > > I think the next step would be to put dev_dbg/printk in
> > > > gpio-ir-recv.c, and see if the results are the same there. I
> > > > suspect they will
> > be.
> > > Yes, as you suspected, the result is the same there. It seems to be
> > > a system
> > or gpio issue.
> > >
> > >
> > > > > > > I also have a question, if RC transmit repeatedly 6 times,
> > > > > > > and SONY decodes
> > > > > > decode all raw data successfully, it will report to input
> > > > > > subsystem
> > > > > > 6 times, does input subsystem will still report to userspace 6 times?
> > > > > >
> > > > > > If the sony decodes the same values 6 times, then scancode
> > > > > > will reported 6 imes, but there will be only one key down
> > > > > > event, and a key up event about 100ms after the the last
> > > > > > decode (plus a few other milliseconds for various timeouts).
> > > > > Thanks for your details. Does this mean input subsystem will
> > > > > still report
> > > > scancode 6 times, but only report keycode once if it is matched?
> > > >
> > > > Exactly. The keycode is only reported once, so that if the user press e.g.
> > > > "1" they will get just get one "1".
> > > >
> > > > > Sean, based on your experience, where else do you suggest me to
> > > > > look into
> > > > this further? Have you came across such case, a few interrupt
> > > > responded so quickly so that front pulse/space is much shorten?
> > > >
> > > > To be honest I've never seen this before.
> > > >
> > > > I'm not sure what the cause could be. On the raspberry pi it is
> > > > known that lots usb traffic causes delays in the gpio interrupt
> > > > handlers due to some hardware issue, but this causes some
> > > > interrupts to arrive late. This causes some of the pulse/space
> > > > timings to be longer, and then later ones are shorter again as it catches
> up.
> > > >
> > > > Similarly if the kernel is running with interrupts off for too
> > > > long, some of the timings will be longer and others shorter.
> > > Yes, we can understand the interrupt arrives late and cause the
> > > timings
> > incorrect. At my side, a few interrupt arrives too faster.
> >
> > I'm wondering where you captured the IR signal. If you captured the IR
> > signal on the transmitter led, make sure the resolution is high enough
> > so you can see the carrier. Then you can make sure there are no errors in
> there.
> >
> > It might be better to capture the IR signal on the gpio signal going into the
> SoC.
> 
> Yes, the signal I captured is the output of the IR device, i.e. the gpio signal
> going into the SoC.
> 
> Best Regards,
> Joakim Zhang
> > > > Is there anything you can tell us about the gpio hardware?
> > > GPIO is from our SoC, power supply with extern 3.3V, and I
> > > configured it
> > internal pull-up.
> >
> > Thanks
> > Sean

RE: SONY IR issue

[Joakim Zhang]

Hi Sean,

We have already found the root cause, unbalanced interrupt response cause timing incorrect when cpuidle active. After disable cpuidle, GPIO IR works fine.
However, that's a barbaric practice. It's impossible for us to disable cpuidle in a real system. 

Now two issues in front of me:
One is high cpu loading, after testing, GPIO IR can always decode, it seems not a severe problem. Another is cpuidle, it leads to a high probability of decoding failed.

I have a half-baked idea, can you help evaluate it? Is it possible to dynamically disable and enable cpuidle from gpio_ir_recv_irq? Or do this somewhere else in IR framework?

When first entering gpio_ir_recv_irq, invokes cpu_latency_qos_add_request to disable cpuidle, concurrently start a timer. Then entering gpio_ir_recv_irq again and again,
check the timer. If timer value smaller than VALUE_TIMEOUT, just reset the timer. If timer value large than VALUE_TIMEOUT, means one loop finish, invokes 
cpu_latency_qos_remove_request to enable the cpuidle. The VALUE_TIMEOUT is the gap between continuous signals. The difficult is how to tune VALUE_TIMEOUT to satisfy all IR protocols.

I wrote a draft, and it can work fine at my side:
--- a/drivers/media/rc/gpio-ir-recv.c
+++ b/drivers/media/rc/gpio-ir-recv.c
@@ -11,6 +11,7 @@
 #include <linux/of.h>
 #include <linux/of_gpio.h>
 #include <linux/platform_device.h>
+#include <linux/pm_qos.h>
 #include <linux/irq.h>
 #include <media/rc-core.h>

@@ -20,13 +21,32 @@ struct gpio_rc_dev {
        struct rc_dev *rcdev;
        struct gpio_desc *gpiod;
        int irq;
+       struct timer_list cpuidle_change;
+       bool cpuidle_active;
+       struct pm_qos_request qos;
 };

+static void gpio_ir_cpuidle_change(struct timer_list *t)
+{
+       struct gpio_rc_dev *gpio_dev = from_timer(gpio_dev, t, cpuidle_change);
+
+       if (!(gpio_dev->cpuidle_active)) {
+               pm_qos_remove_request(&gpio_dev->qos);
+               gpio_dev->cpuidle_active = true;
+       }
+}
+
 static irqreturn_t gpio_ir_recv_irq(int irq, void *dev_id)
 {
        int val;
        struct gpio_rc_dev *gpio_dev = dev_id;

+       if (gpio_dev->cpuidle_active) {
+               pm_qos_add_request(&gpio_dev->qos, 1, 0);
+               gpio_dev->cpuidle_active = false;
+       }
+       mod_timer(&gpio_dev->cpuidle_change, jiffies + msecs_to_jiffies(125));
+
        val = gpiod_get_value(gpio_dev->gpiod);
        if (val >= 0)
                ir_raw_event_store_edge(gpio_dev->rcdev, val == 1);
@@ -61,6 +81,9 @@ static int gpio_ir_recv_probe(struct platform_device *pdev)
        if (gpio_dev->irq < 0)
                return gpio_dev->irq;

+       gpio_dev->cpuidle_active = true;
+       timer_setup(&gpio_dev->cpuidle_change, gpio_ir_cpuidle_change, 0);
+
        rcdev = devm_rc_allocate_device(dev, RC_DRIVER_IR_RAW);
        if (!rcdev)
                return -ENOMEM;

Indeed, to a certain degree, it cannot ensure the first signal to be decoded, since at that point cpuidle is active, interrupt may be delayed, so the header may not satisfy the protocol.
Actually, I have not meet such case under my test. Luckily, it would transmit multiple signals at once press.

Best Regards,
Joakim Zhang

> -----Original Message-----
> From: Joakim Zhang
> Sent: 2020年9月8日 16:41
> To: Sean Young <sean@mess.org>
> Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>;
> linux-gpio@vger.kernel.org; Bartosz Golaszewski <bgolaszewski@baylibre.com>
> Subject: RE: SONY IR issue
> 
> 
> Hi Sean,
> 
> GPIO IR Recv extremely rely on the real-time performance of the interrupt
> response, after turn off cpuidle, IR can work steadily now.
> 
> Much thanks for your kindly help. 😊
> 
> Best Regards,
> Joakim Zhang

Re: SONY IR issue

[Sean Young]

Hi Joakhim,


On Thu, Sep 10, 2020 at 11:52:18AM +0000, Joakim Zhang wrote:
> 
> Hi Sean,
> 
> We have already found the root cause, unbalanced interrupt response cause timing incorrect when cpuidle active. After disable cpuidle, GPIO IR works fine.
> However, that's a barbaric practice. It's impossible for us to disable cpuidle in a real system. 

Yes, that's a non-starter ofcourse.

> Now two issues in front of me:
> One is high cpu loading, after testing, GPIO IR can always decode, it seems not a severe problem. Another is cpuidle, it leads to a high probability of decoding failed.
> 
> I have a half-baked idea, can you help evaluate it? Is it possible to dynamically disable and enable cpuidle from gpio_ir_recv_irq? Or do this somewhere else in IR framework?
> 
> When first entering gpio_ir_recv_irq, invokes cpu_latency_qos_add_request to disable cpuidle, concurrently start a timer. Then entering gpio_ir_recv_irq again and again,
> check the timer. If timer value smaller than VALUE_TIMEOUT, just reset the timer. If timer value large than VALUE_TIMEOUT, means one loop finish, invokes 
> cpu_latency_qos_remove_request to enable the cpuidle. The VALUE_TIMEOUT is the gap between continuous signals. The difficult is how to tune VALUE_TIMEOUT to satisfy all IR protocols.

So my problem with this solution is that I get the impression that it papers
over cracks in another area. With cpuidle enabled, interrupts are delayed by
over by 500 microseconds, or half a millisecond. Those sorts of latencies
are not very good. 

For example in realtime, latencies should not exceed anything in the order
of 50 microseconds, a tenth of what you're seeing here. If it takes 
up to half a millisecond to service e.g. ssd or network interrupts, does
that not take a toll?

As for your implementation, the timeout could be based on the IR timeout
itself. When IR timeout occurs we are not expecting any more IR for the
current message, so this would be a perfect place to restore cpuidle. The
gpio-ir-recv driver could implement its own timeout, rather than using
rc-core for this. The driver used to do this, so it should be in git
history.

Thanks,

Sean

> 
> I wrote a draft, and it can work fine at my side:
> --- a/drivers/media/rc/gpio-ir-recv.c
> +++ b/drivers/media/rc/gpio-ir-recv.c
> @@ -11,6 +11,7 @@
>  #include <linux/of.h>
>  #include <linux/of_gpio.h>
>  #include <linux/platform_device.h>
> +#include <linux/pm_qos.h>
>  #include <linux/irq.h>
>  #include <media/rc-core.h>
> 
> @@ -20,13 +21,32 @@ struct gpio_rc_dev {
>         struct rc_dev *rcdev;
>         struct gpio_desc *gpiod;
>         int irq;
> +       struct timer_list cpuidle_change;
> +       bool cpuidle_active;
> +       struct pm_qos_request qos;
>  };
> 
> +static void gpio_ir_cpuidle_change(struct timer_list *t)
> +{
> +       struct gpio_rc_dev *gpio_dev = from_timer(gpio_dev, t, cpuidle_change);
> +
> +       if (!(gpio_dev->cpuidle_active)) {
> +               pm_qos_remove_request(&gpio_dev->qos);
> +               gpio_dev->cpuidle_active = true;
> +       }
> +}
> +
>  static irqreturn_t gpio_ir_recv_irq(int irq, void *dev_id)
>  {
>         int val;
>         struct gpio_rc_dev *gpio_dev = dev_id;
> 
> +       if (gpio_dev->cpuidle_active) {
> +               pm_qos_add_request(&gpio_dev->qos, 1, 0);
> +               gpio_dev->cpuidle_active = false;
> +       }
> +       mod_timer(&gpio_dev->cpuidle_change, jiffies + msecs_to_jiffies(125));
> +
>         val = gpiod_get_value(gpio_dev->gpiod);
>         if (val >= 0)
>                 ir_raw_event_store_edge(gpio_dev->rcdev, val == 1);
> @@ -61,6 +81,9 @@ static int gpio_ir_recv_probe(struct platform_device *pdev)
>         if (gpio_dev->irq < 0)
>                 return gpio_dev->irq;
> 
> +       gpio_dev->cpuidle_active = true;
> +       timer_setup(&gpio_dev->cpuidle_change, gpio_ir_cpuidle_change, 0);
> +
>         rcdev = devm_rc_allocate_device(dev, RC_DRIVER_IR_RAW);
>         if (!rcdev)
>                 return -ENOMEM;
> 
> Indeed, to a certain degree, it cannot ensure the first signal to be decoded, since at that point cpuidle is active, interrupt may be delayed, so the header may not satisfy the protocol.
> Actually, I have not meet such case under my test. Luckily, it would transmit multiple signals at once press.
> 
> Best Regards,
> Joakim Zhang
> 
> > -----Original Message-----
> > From: Joakim Zhang
> > Sent: 2020年9月8日 16:41
> > To: Sean Young <sean@mess.org>
> > Cc: linux-media@vger.kernel.org; Andy Duan <fugang.duan@nxp.com>;
> > linux-gpio@vger.kernel.org; Bartosz Golaszewski <bgolaszewski@baylibre.com>
> > Subject: RE: SONY IR issue
> > 
> > 
> > Hi Sean,
> > 
> > GPIO IR Recv extremely rely on the real-time performance of the interrupt
> > response, after turn off cpuidle, IR can work steadily now.
> > 
> > Much thanks for your kindly help. 😊
> > 
> > Best Regards,
> > Joakim Zhang