Re: SONY IR issue

[Sean Young <sean@xxxxxxxx>]

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